Closed Bug 86396 Opened 23 years ago Closed 15 years ago

Adding timestamp to NSPR_LOG

Categories

(NSPR :: NSPR, enhancement, P2)

Product:
NSPR
Component:
NSPR
Type:
enhancement

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: bugzilla, Assigned: hiro)

References

Details

Attachments

(4 files, 6 obsolete files)

v1 patch
1.87 KB, patch
wtc
: review-
Details | Diff | Splinter Review
Revised patch (as checked in)
4.64 KB, patch
Details | Diff | Splinter Review
Following up patch addressed wtc's suggestion
840 bytes, patch
wtc
: review+
Details | Diff | Splinter Review
Change the special log module name to "timestamp"
1.19 KB, patch
Details | Diff | Splinter Review 
Sometimes it could be nice it there was a timemark to all LOGs made by NSPR_LOG.

If you do this:
SET NSPR_LOG_MODULES=IMAP:5
Set NSPR_LOG_FILE=C:\TMP\imap.log

you get:
852[41bd0b8]: imap.mail.dk:S-INBOX:CreateNewLineFromSocket: 61 OK UID FETCH 
completed

It could be nice if NSPR automatilly added the current time to the log ala:
10:39:20 - 852[41bd0b8]: imap.mail.dk:S-INBOX:CreateNewLineFromSocket: 61 OK UID 
FETCH completed
Changing the format of the data written by PR_LOG() may impact programs that 
depend on the existing format. The suggestion for a timestamp is good. Marking 
this for the next major release (5.0) of NSPR.
Status: NEW → RESOLVED
Closed: 23 years ago
Resolution: --- → LATER
Severity: normal → enhancement
Priority: -- → P2
Target Milestone: --- → Future
future stuff. is that labels "resolve later" ?
Should this be verified ot just reopenen and assigned?
We can't make this change until NSPR 5.0.  Right now there
is no plan for NSPR 5.0.
LATER is deprecated per bug 35839.
Status: RESOLVED → REOPENED
Resolution: LATER → ---
Please consider this soon. I'd like to use timestamps as part of debugging
Mail/News IMAP/POP3, etc. conversations.
jubal+mozillabugs@cheeze.org: use debugview (set NSPR_LOG_FILE=WinDebug) and you
should get datestamps automatically.

personally i'd get really annoyed if i ended up with two datestamps in debugview.
As of today, DebugView is available at http://www.sysinternals.com/Utilities/DebugView.html

(Rough/simple procedure to get NSPR log with DebugView. See 'Help' for detail.)
 (0) Download DebugView and unzip it.
 (1) Start DebugView
    (1-1) Computer Menu : Choose my PC(Local)
    (1-2) Capture Menu  : Disable 'Capture Win32' (stop capturing)
    (1-3) Option Menu   : Enable 'Clock Time' and 'Show Milliseconds'
    (1-4) Edit Menu     : Set 'History Depth' to 0 (No limit)
    (1-5) Edit Menu     : Clear Display
 (2) SET NSPR_LOG_FILE=WinDebug
     SET NSPR_LOGMODULES=xxx:5,yyy:5,...
 (3) Start Firefox or Thunderbird or Seamonkey.
 (4) DebugView/Capture Menu : Enable 'Capture Win32' (start capturing)
 (5) Execute test procedure for which NSPR log is required
 (6) DebugView/Capture Menu : Disable 'Capture Win32' (stop capturing)
 (7) DebugView/File Menu : Save As

(Log example. Record number and timestamp are prepended to NSPR log.)
00000073	10:04:59.272	[2112] 2168[11a96f0]: poll timeout: 60060
Correction(sorry for spam)
"NSPR_LOGMODULES" should be "NSPR_LOG_MODULES".
Attached patch v1 patch — — Splinter Review 
Why can't we do this now?  Why do we have to defer until NSPR 5.0?
Assignee: wtchang → darin
Status: REOPENED → ASSIGNED
Attachment #225813 - Flags: review?(wtchang)
Comment on attachment 225813 [details] [diff] [review]
v1 patch

Comment 1 explains why this change breaks backward compatibility.
Please add a new special log module, say timestamp or timemark,
that turns on this feature.  Examples of special log modules are
"sync", "bufsize", and "all".  See
http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25306.

Please move 'startTime' to the file scope and initialize it in
_PR_InitLog.
Attachment #225813 - Flags: review?(wtchang) → review-
at the risk of option explosion, it might be a good idea to add another env var or have some way of indicating whether the timestamps should be used or not.  Either way, this looks pretty good -- I was going to hack in some sort of explicit support for timestamp logging, but maybe this is all that's needed (and having people choose easily-parsed timestamp messages for things that are 'time interesting', e.g. adopt a convention that things starting with @ are interesting times to consider).

Vlad, I think you and I suggested the same thing.
Target Milestone: Future → 4.7
OK.. that sounds reasonable.
QA Contact: larryh → nspr
-> reassign to default owner
Assignee: darin.moz → wtc
Status: ASSIGNED → NEW
Is 4.7 still a valid target, ir is going to be delayed to NSPR 5.0?

wrt comment 7, DebugView is now at http://www.microsoft.com/technet/sysinternals/utilities/debugview.mspx
Attached patch Proposed patch (obsolete) — — Splinter Review 
Output time stamp formatted by ISO 8601 if NSPR_LOG_OUTPUT_TIME_STAMP is set.
Attachment #356883 - Flags: review?(wtc)
Comment on attachment 356883 [details] [diff] [review]
Proposed patch

Thanks for the patch.  The patch is basically good.
I'd like to suggest two changes.

1. Use a special log module "timestamp" to enable
this feature, as I suggested in comment 10.  Do you
have a strong preference to use an environment
variable to enable this feature?

2. nb_tid means "number of bytes for the thread id".
So it's better to not use nb_tid also for the number
of bytes for the timestamp.

We can either add another variable nb_time, or just
use nb for everything.
DebugView has following capabilities.
a. Relative timestamp form start of logging, in addition to absolute timestap.
b. Log sequence number, for ease of sort, for ease of log analysis.
Ikezoe san, can such function be easily added?
(In reply to comment #18)
> 1. Use a special log module "timestamp" to enable
> this feature, as I suggested in comment 10.  Do you
> have a strong preference to use an environment
> variable to enable this feature?

I was just afraid that the name conflicts other modules name, 
but as far as I can see there is no module which uses "timestamp".
So I will revise my patch to use "timestamp" module name.
Attached patch Address wtc comments. (obsolete) — — Splinter Review 
Use "timestamp" module name and add nb_time value.
Attachment #356883 - Attachment is obsolete: true
Attachment #356883 - Flags: review?(wtc)
Attachment #357595 - Flags: review?(wtc)
(In reply to comment #19)
> DebugView has following capabilities.
> a. Relative timestamp form start of logging, in addition to absolute timestap.

I can add the feature as Darin's patch does, but I do not think the time value is useful.
Please account for the situation that the time value can be useful.

> b. Log sequence number, for ease of sort, for ease of log analysis.

I do not think LSN is useful for Firefox/Thunderbid too but anyway you should open a new bug?
Attachment #357595 - Flags: review?(wtc) → review+
Comment on attachment 357595 [details] [diff] [review]
Address wtc comments.

r=wtc.

I'll see if it's possible to use just 'nb'
when I check in this patch.  I believe it's
not possible (see below).

It may be cheaper to call PR_ExplodeTime with
PR_GMTParameters than with RR_LocalTimeParameters.
But I think outputting GMT may be a little
confusing.

>         /* Write out the thread id and the malloc'ed buffer. */
>-        _PUT_LOG(logFile, line, nb_tid);
>+        _PUT_LOG(logFile, line, nb_time+nb_tid);

We should update this comment to also mention
the optional timestamp.

This _PUT_LOG statement is why I think we can't
use just 'nb'.
Folks, some of us don't use Windoze and could not care less what "DebugView" can or cannot do!

One thing that seems missed in this discussion is that sometimes the long delay between two events -- which is only provable if there's a time mark in the log -- is the primary evidence of the bug one is hunting.

Curiously, I believe I've seen in the code that the first field in the log line is, or was at some time in the distant past, a time indicator.  The only reason I'm sure it is not now is that it is not monotonically increasing.  When last I looked, time was.
Wan-Teh, besides updating the code comment, as you suggested in comment 23,
is there anything else that must be done before this patch gets committed?
Target Milestone: 4.7 → 4.8
Attached patch Update comment (obsolete) — — Splinter Review 
I am sorry for my delay response. 

I updated the comment as the following, if the English sentence is wrong, please correct it.

-        /* Write out the thread id and the malloc'ed buffer. */
-        _PUT_LOG(logFile, line, nb_tid);
+        /*
+         * Write out the thread id and time stamp if "timestamp" is specified
+         * in NSPR_LOG_MODULES and the malloc'ed buffer.
+         */
+        _PUT_LOG(logFile, line, nb_time+nb_tid);
Assignee: wtc → ikezoe
Attachment #357595 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #373268 - Flags: review?(wtc)
(In reply to comment #23)
> It may be cheaper to call PR_ExplodeTime with
> PR_GMTParameters than with RR_LocalTimeParameters.
> But I think outputting GMT may be a little
> confusing.

If nspr has a method to get timezone offset, we can get it in _PR_InitLog and use it in PR_LogPrint, but I could not find a such method.
Attached patch Update patch (obsolete) — — Splinter Review 
I found previous patch causes a crash due to stack overflow.

This patch avoid the crash with workaround.
Attachment #373268 - Attachment is obsolete: true
Attachment #373268 - Flags: review?(wtc)
Attachment #373517 - Flags: review?(wtc)
The crash can reproduce with NSPR_LOG_MODULES=all:5,timestamp.
Attached patch Revised patch (obsolete) — — Splinter Review 
Oops, I used PR_GMTParameters in attachment 373517 [details] [diff] [review].
Attachment #373517 - Attachment is obsolete: true
Attachment #373517 - Flags: review?(wtc)
Attachment #373518 - Flags: review?(wtc)
Comment on attachment 373518 [details] [diff] [review]
Revised patch

Thanks for the patch.  I will review it more carefully
next week.

> PR_IMPLEMENT(void) PR_Assert(const char *s, const char *file, PRIntn ln)
> {
>-    PR_LogPrint("Assertion failure: %s, at %s:%d\n", s, file, ln);
>+    if (!outputTimeStamp)
>+        PR_LogPrint("Assertion failure: %s, at %s:%d\n", s, file, ln);

This change is new.  Do you really need it?  It seems
wrong.
(In reply to comment #31)

> > PR_IMPLEMENT(void) PR_Assert(const char *s, const char *file, PRIntn ln)
> > {
> >-    PR_LogPrint("Assertion failure: %s, at %s:%d\n", s, file, ln);
> >+    if (!outputTimeStamp)
> >+        PR_LogPrint("Assertion failure: %s, at %s:%d\n", s, file, ln);
> 
> This change is new.  Do you really need it?  It seems
> wrong.

Yes, it is needed. Without this change, NSPR_LOG_MODULES=all:5,timestamp causes infinite loop.

#0  0x404bb147 in PR_LogPrint (fmt=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:447
#1  0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#2  0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#3  0x404d1375 in MT_safe_localtime (clock=0x9b03b224, result=0x9b03b1b4) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#4  0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03b298) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#5  0x404d062a in PR_ExplodeTime (usecs=1240114092472384, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03b298) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#6  0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#7  0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#8  0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#9  0x404d1375 in MT_safe_localtime (clock=0x9b03b604, result=0x9b03b594) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#10 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03b678) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#11 0x404d062a in PR_ExplodeTime (usecs=1240114092472382, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03b678) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#12 0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#13 0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#14 0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#15 0x404d1375 in MT_safe_localtime (clock=0x9b03b9e4, result=0x9b03b974) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#16 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03ba58) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#17 0x404d062a in PR_ExplodeTime (usecs=1240114092472380, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03ba58) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#18 0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#19 0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#20 0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#21 0x404d1375 in MT_safe_localtime (clock=0x9b03bdc4, result=0x9b03bd54) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#22 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03be38) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#23 0x404d062a in PR_ExplodeTime (usecs=1240114092472379, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03be38) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#24 0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#25 0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#26 0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#27 0x404d1375 in MT_safe_localtime (clock=0x9b03c1a4, result=0x9b03c134) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#28 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03c218) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#29 0x404d062a in PR_ExplodeTime (usecs=1240114092472366, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03c218) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#30 0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#31 0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#32 0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#33 0x404d1375 in MT_safe_localtime (clock=0x9b03c584, result=0x9b03c514) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#34 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03c5f8) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#35 0x404d062a in PR_ExplodeTime (usecs=1240114092472364, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03c5f8) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#36 0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#37 0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#38 0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#39 0x404d1375 in MT_safe_localtime (clock=0x9b03c964, result=0x9b03c8f4) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#40 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03c9d8) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
#41 0x404d062a in PR_ExplodeTime (usecs=1240114092472362, params=0x404d1452 <PR_LocalTimeParameters>, exploded=0x9b03c9d8) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:244
#42 0x404bb1cc in PR_LogPrint (fmt=0x404e4430 "Assertion failure: %s, at %s:%d\n") at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:463
#43 0x404bb667 in PR_Assert (s=0x404e80c4 "lock != NULL", file=0x404e7ff4 "/home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c", ln=205)
    at /home/zoe/hg/mozilla-central/nsprpub/pr/src/io/prlog.c:564
#44 0x404d4a7a in PR_Lock (lock=0x0) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/pthreads/ptsynch.c:205
#45 0x404d1375 in MT_safe_localtime (clock=0x9b03cd44, result=0x9b03ccd4) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:547
#46 0x404d1485 in PR_LocalTimeParameters (gmt=0x9b03cdb8) at /home/zoe/hg/mozilla-central/nsprpub/pr/src/misc/prtime.c:643
....
(In reply to comment #31)
> (From update of attachment 373518 [details] [diff] [review])
> Thanks for the patch.  I will review it more carefully
> next week.
> 
> > PR_IMPLEMENT(void) PR_Assert(const char *s, const char *file, PRIntn ln)
> > {
> >-    PR_LogPrint("Assertion failure: %s, at %s:%d\n", s, file, ln);
> >+    if (!outputTimeStamp)
> >+        PR_LogPrint("Assertion failure: %s, at %s:%d\n", s, file, ln);
> 
> This change is new.  Do you really need it?  It seems
> wrong.

You are right. 
The reason of the crash is _PR_InitTime is after _PR_InitLinker (PR_LOG is invoked in _PR_InitLinker).
Attached patch Revised patch (obsolete) — — Splinter Review 
Invoke _PR_InitTime before _PR_InitLog.
Attachment #373518 - Attachment is obsolete: true
Attachment #373518 - Flags: review?(wtc)
Attachment #373554 - Flags: review?(wtc)
I checked in Hiroyuki's patch on the NSPR trunk (NSPR 4.8).

Checking in io/prlog.c;
/cvsroot/mozilla/nsprpub/pr/src/io/prlog.c,v  <--  prlog.c
new revision: 3.47; previous revision: 3.46
done
Checking in misc/prinit.c;
/cvsroot/mozilla/nsprpub/pr/src/misc/prinit.c,v  <--  prinit.c
new revision: 3.51; previous revision: 3.50
done

I made the following changes to Hiroyuki's patch.

1. I went back to just using nb_tid for the length in bytes of
the optional timestamp and the thread id.

2. I removed the "T" from the timestamp.  I know the "T" comes
from the ISO standard, but it looks strange.

3. I renamed the special log module "__timestamp", with a double
underscore prefix, to indicate that the timestamp format may
change.

The current timestamp format has the following issues:

1. It doesn't have sub-second resolution.  This means we
can't simply use this to measure short time intervals.
Does the ISO standard allow us to display microseconds?

2. PR_Now is a system call, so it can be more expensive
than PR_IntervalNow.

3. PR_Now may jump if the system administrator changes
the system clock.

4. The timestamp is in the local timezone but doesn't
have the timezone offset.  So the timestamps could be
confusing when we have a daylight saving time switchover.
We may want to consider using timestamps in UTC (and
print "UTC") or display the local timezone offset.

In any case, I'd like to check this in first so that
people can start using it.  I think it will be very
valuable to Mozilla developers.  Thank you, Hiroyuki!
Attachment #373554 - Attachment is obsolete: true
Attachment #373554 - Flags: review?(wtc)
wtc, thank you very much. I appreciate your review and corrections.

By the way, is there any chance the patch is checked in stable branch?
In other words, we can use this timestamp option on Firefox 3.0 or 3.5?
Comment on attachment 376138 [details] [diff] [review]
Revised patch (as checked in)

I pushed this patch to mozilla-central in changeset 515054a2dc43:
http://hg.mozilla.org/mozilla-central/rev/515054a2dc43
Hiroyuki, I expect that this patch will appear in Firefox 3.5.
I plan to push a new NSPR update to mozilla-1.9.1 soon.

For Firefox 3.0 this is more difficult because they only take
security fixes by default.

Do you need sub-second resolution in the timestamps?  I suggest
that we add a decimal fraction with three digits to represent
milliseconds.  We will need to use PR_snprintf to print the
timestamp because PR_FormatTimeUSEnglish can't print a decimal
fraction of second.  PRExplodedTime has microsecond resolution
(tm_usec), but I think a decision fraction with six digits may
be too long.  What do you think?

We may also want to switch to PR_GMTParameters because it is
slightly faster than PR_LocalTimeParameters, and avoids the
daylight saving time switchover issue.  But we will need to
use add either "Z" (ISO 8601) or " UTC" (more human readable)
at the end.
I documented the special log module __timestamp in the NSPR Reference:
http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25328
(In reply to comment #38)
> Hiroyuki, I expect that this patch will appear in Firefox 3.5.
> I plan to push a new NSPR update to mozilla-1.9.1 soon.
>
> For Firefox 3.0 this is more difficult because they only take
> security fixes by default.

I understand, I hope Firefox 3.5 will be released soon.

> Do you need sub-second resolution in the timestamps?  I suggest
> that we add a decimal fraction with three digits to represent
> milliseconds.  We will need to use PR_snprintf to print the
> timestamp because PR_FormatTimeUSEnglish can't print a decimal
> fraction of second.  PRExplodedTime has microsecond resolution
> (tm_usec), but I think a decision fraction with six digits may
> be too long.  What do you think?

Yes, I need sub-second resolution now. And I think millisecond resolution is sufficient too. But I am not 100% sure because I think there are some people who want microsecond resolution in some case. We need a new option for time resolution?

> We may also want to switch to PR_GMTParameters because it is
> slightly faster than PR_LocalTimeParameters, and avoids the
> daylight saving time switchover issue.  But we will need to
> use add either "Z" (ISO 8601) or " UTC" (more human readable)
> at the end.

I prefer "UTC" since I am not familiar with "Z".
We don't want too many options.  Let's give this format a try:

  2009-05-08 15:28:29.573682 UTC -

It's not as long as I thought.
I just make tow test, the one is millisecond resolution, the other is microsecond.

a) millisecond log
2009-04-10 12:59:30.429 - -1209894704[97ff580]: Loaded library a.out (init)
2009-04-10 12:59:30.607 - -1209894704[97ff580]: ./logger logging into (null)
2009-04-10 12:59:30.636 - -1209894704[97ff580]: ./logger creating new thread
2009-04-10 12:59:30.865 - -1209898096[9800080]: ./logger logging creating mutex
2009-04-10 12:59:30.907 - -1209898096[9800080]: ./logger logging creating condition variable
2009-04-10 12:59:30.935 - -1209898096[9800080]: ./logger waiting on condition timeout 10 times
2009-04-10 12:59:30.430 - -1209894704[97ff580]: ./logger joining thread
2009-04-10 12:59:30.543 - -1209894704[97ff580]: Log a Notice 1
2009-04-10 12:59:30.616 - -1209894704[97ff580]: Log Debug number: 0
2009-04-10 12:59:31.021 - -1209894704[97ff580]: Log Debug number: 1
2009-04-10 12:59:31.012 - -1209894704[97ff580]: Log Debug number: 2
2009-04-10 12:59:31.010 - -1209894704[97ff580]: Log Debug number: 3
2009-04-10 12:59:32.010 - -1209894704[97ff580]: Log Debug number: 4
2009-04-10 12:59:32.008 - -1209894704[97ff580]: Log Debug number: 5
2009-04-10 12:59:32.009 - -1209894704[97ff580]: Log Debug number: 6
2009-04-10 12:59:32.009 - -1209894704[97ff580]: Log Debug number: 7

b) microsecond log
zoe-laptop% NSPR_LOG_MODULES=all:5,__timestamp ./logger
2009-04-10 13:00:10.754573 - -1209964336[9232580]: Loaded library a.out (init)
2009-04-10 13:00:10.754753 - -1209964336[9232580]: ./logger logging into (null)
2009-04-10 13:00:10.754782 - -1209964336[9232580]: ./logger creating new thread
2009-04-10 13:00:10.755015 - -1209967728[9233080]: ./logger logging creating mutex
2009-04-10 13:00:10.755058 - -1209967728[9233080]: ./logger logging creating condition variable
2009-04-10 13:00:10.755086 - -1209967728[9233080]: ./logger waiting on condition timeout 10 times
2009-04-10 13:00:10.755542 - -1209964336[9232580]: ./logger joining thread
2009-04-10 13:00:10.755651 - -1209964336[9232580]: Log a Notice 1
2009-04-10 13:00:10.755723 - -1209964336[9232580]: Log Debug number: 0
2009-04-10 13:00:11.056024 - -1209964336[9232580]: Log Debug number: 1
2009-04-10 13:00:11.357011 - -1209964336[9232580]: Log Debug number: 2
2009-04-10 13:00:11.658010 - -1209964336[9232580]: Log Debug number: 3
2009-04-10 13:00:11.959012 - -1209964336[9232580]: Log Debug number: 4
2009-04-10 13:00:12.260011 - -1209964336[9232580]: Log Debug number: 5
2009-04-10 13:00:12.561009 - -1209964336[9232580]: Log Debug number: 6
2009-04-10 13:00:12.862008 - -1209964336[9232580]: Log Debug number: 7
2009-04-10 13:00:13.163011 - -1209964336[9232580]: Log Debug number: 8
2009-04-10 13:00:13.464011 - -1209964336[9232580]: Log Debug number: 9
After these test, I agree your opinion in comment #41. Microsecond is not so long.

And moreover the timestamp of the last log in test a) is the same time stamp the previoos one even if each timestamp seemed to be the same.
Use PR_GMTParameters and PR_snprintf with microsecond.

Thank you, wtc. The output log looks better.
Comment on attachment 376600 [details] [diff] [review]
Following up patch addressed wtc's suggestion

r=wtc.  Thanks!  I checked this in on the NSPR trunk (NSPR 4.8).

Checking in prlog.c;
/cvsroot/mozilla/nsprpub/pr/src/io/prlog.c,v  <--  prlog.c
new revision: 3.49; previous revision: 3.48
done
Attachment #376600 - Flags: review+
I suspect the results displayed for the "millisecond" long in comment 42 
were incorrectly computed.

The timestamps in successive entries are not monotonically increasing.
In fact, they are DECREASING.
> 2009-04-10 12:59:31.021 - -1209894704[97ff580]: Log Debug number: 1
> 2009-04-10 12:59:31.012 - -1209894704[97ff580]: Log Debug number: 2
> 2009-04-10 12:59:31.010 - -1209894704[97ff580]: Log Debug number: 3
                      ^^^

The microsecond log shows that the events were happening with a regular  periodicity of 250-300 milliseconds, but the numbers displayed in the millisecond log don't show that AT ALL.
(In reply to comment #46)
> I suspect the results displayed for the "millisecond" long in comment 42 
> were incorrectly computed.
> 
> The timestamps in successive entries are not monotonically increasing.
> In fact, they are DECREASING.
> > 2009-04-10 12:59:31.021 - -1209894704[97ff580]: Log Debug number: 1
> > 2009-04-10 12:59:31.012 - -1209894704[97ff580]: Log Debug number: 2
> > 2009-04-10 12:59:31.010 - -1209894704[97ff580]: Log Debug number: 3
>                       ^^^

Urgh, my bad. I used "%" to get millisecond. I had to use "/". I am sorry for confusion.
May we see the result of a millisecond log with the corrected computations?
Here it is.

zoe-laptop% NSPR_LOG_MODULES=all:5,__timestamp ./logger
2009-04-10 23:53:59.112 UTC - -1209165616[91a2580]: Loaded library a.out (init)
2009-04-10 23:53:59.112 UTC - -1209165616[91a2580]: ./logger logging into (null)
2009-04-10 23:53:59.112 UTC - -1209165616[91a2580]: ./logger creating new thread
2009-04-10 23:53:59.113 UTC - -1209169008[91a3080]: ./logger logging creating mutex
2009-04-10 23:53:59.113 UTC - -1209169008[91a3080]: ./logger logging creating condition variable
2009-04-10 23:53:59.113 UTC - -1209169008[91a3080]: ./logger waiting on condition timeout 10 times
2009-04-10 23:53:59.113 UTC - -1209165616[91a2580]: ./logger joining thread
2009-04-10 23:53:59.113 UTC - -1209165616[91a2580]: Log a Notice 1
2009-04-10 23:53:59.114 UTC - -1209165616[91a2580]: Log Debug number: 0
2009-04-10 23:53:59.415 UTC - -1209165616[91a2580]: Log Debug number: 1
2009-04-10 23:53:59.716 UTC - -1209165616[91a2580]: Log Debug number: 2
2009-04-10 23:54:00.017 UTC - -1209165616[91a2580]: Log Debug number: 3
2009-04-10 23:54:00.318 UTC - -1209165616[91a2580]: Log Debug number: 4
2009-04-10 23:54:00.619 UTC - -1209165616[91a2580]: Log Debug number: 5
2009-04-10 23:54:00.920 UTC - -1209165616[91a2580]: Log Debug number: 6
2009-04-10 23:54:01.221 UTC - -1209165616[91a2580]: Log Debug number: 7
2009-04-10 23:54:01.522 UTC - -1209165616[91a2580]: Log Debug number: 8
2009-04-10 23:54:01.823 UTC - -1209165616[91a2580]: Log Debug number: 9
I changed the name of the special log module
from "__timestamp" to "timestamp", in preparation
for NSPR 4.8 RTM, which must be released by May 20.

Checking in prlog.c;
/cvsroot/mozilla/nsprpub/pr/src/io/prlog.c,v  <--  prlog.c
new revision: 3.50; previous revision: 3.49
done
Comment on attachment 376600 [details] [diff] [review]
Following up patch addressed wtc's suggestion

I pushed the new timestamp format and the special log module name
"timestamp" to mozilla-central in changeset c77fa4f80825:
http://hg.mozilla.org/mozilla-central/rev/c77fa4f80825
The current timestamp format is illustrated with the following example:

2009-04-10 13:00:10.754573 UTC - -1209964336[9232580]: Loaded library a.out (init)

If you have any concerns about this format, please speak up now.
I need to release NSPR 4.8 RTM in a few days.

The issues to consider:

1. Calendar time (PR_Now) vs. interval time (PR_IntervalNow).

We use calendar time now, which is more human-readable but
may be more expensive (a system call).  One issue with
PR_IntervalNow is that it has a platform-dependent unit
(returned by PR_TicksPerSecond()) and it may wrap around
in about 12 hours.

2. Local time vs. UTC.

We use UTC now.

3. Sub-second resolution: milliseconds vs. microseconds.

We use microseconds now.  Using milliseconds saves
three characters per log message but some events appear
simultaneous (see the example in comment 49).

4. Delimiter: '-' vs. ':' (or even none)

We use '-' now.
(In reply to comment #52)
> The current timestamp format is illustrated with the following example:
> 
> 2009-04-10 13:00:10.754573 UTC - -1209964336[9232580]: Loaded library a.out
> (init)
> 
> If you have any concerns about this format, please speak up now.
> I need to release NSPR 4.8 RTM in a few days.

To be honest, I think local time is better than UTC since UTC is unconfusable, but the time can be converted after logging, so I do not care about it now.

Anyway, I am looking forward to use this timestamp option with next Firefox and Thunderbid. Thank you, wtc!
Hiroyuki, using local time is fine as long as we add the timezone offset.
So an example of the US Pacific Daylight Time (PDT) would look like:

2009-04-14 22:33:06.362447-07:00 - -137111872[98d7580]: Loaded library a.out (init)
2009-04-14 22:33:06.373456-07:00 - -137114736[98dcaa0]: thread exiting
2009-04-14 22:33:06.373457-07:00 - -145507440[98dcc10]: thread exiting
2009-04-14 22:33:06.380086-07:00 - -145507440[98dcaa0]: thread exiting
2009-04-14 22:33:06.380193-07:00 - -153900144[98dcd80]: thread exiting
2009-04-14 22:33:06.392163-07:00 - -137114736[98dcaa0]: thread exiting
2009-04-14 22:33:06.392270-07:00 - -145507440[98dcc10]: thread exiting
2009-04-14 22:33:06.392294-07:00 - -137111872[98d7580]: PR_Cleanup: shutting down NSPR
I am sorry for my delay. 

(In reply to comment #54)
> Hiroyuki, using local time is fine as long as we add the timezone offset.
> So an example of the US Pacific Daylight Time (PDT) would look like:
> 
> 2009-04-14 22:33:06.362447-07:00 - -137111872[98d7580]: Loaded library a.out

The time (22:33:06.362447) is a local time on PDT? If so, with offset log is pretty good to me.
wct, does the localtime is converted by PR_NormalizeTime? If the cost of PR_NormalizeTime is cheaper than PR_ExplodeTime with PR_GMTParameters?
(In reply to comment #56)
> If the cost of
> PR_NormalizeTime is cheaper than PR_ExplodeTime with PR_GMTParameters?

Oops! I posted the comment while I am writing... I meant that is the cost of PR_NormalizeTime cheaper than PR_ExplodeTime with PR_GMTParameters?
Hiroyuki: PR_NormalizeTime won't do the job because it
takes a PRExplodedTime as input.  We need to use PR_ExplodeTime,
and PR_GMTParameters and PR_LocalTimeParameters are the only
two timezone functions we can use with PR_ExplodeTime.
(In reply to comment #58)
> Hiroyuki: PR_NormalizeTime won't do the job because it
> takes a PRExplodedTime as input.  We need to use PR_ExplodeTime,
> and PR_GMTParameters and PR_LocalTimeParameters are the only
> two timezone functions we can use with PR_ExplodeTime.

OK, then UTC is fine to me. Thank you for your clarification.
Let's go ahead with the current timestamp format then.
Marked the bug fixed.
Status: ASSIGNED → RESOLVED
Closed: 23 years ago → 15 years ago
Resolution: --- → FIXED
Summary: Adding time mark to NSPR_LOG → Adding timestamp to NSPR_LOG
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: