Adding timestamp to NSPR_LOG

RESOLVED FIXED in 4.8

Status

NSPR
NSPR
P2
enhancement
RESOLVED FIXED
17 years ago
9 years ago

People

(Reporter: Henrik Gemal, Assigned: hiro)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(4 attachments, 6 obsolete attachments)

(Reporter)

Description

17 years ago
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

Comment 1

17 years ago
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
Last Resolved: 17 years ago
Resolution: --- → LATER

Updated

17 years ago
Severity: normal → enhancement
Priority: -- → P2
Target Milestone: --- → Future
(Reporter)

Comment 2

17 years ago
future stuff. is that labels "resolve later" ?
Should this be verified ot just reopenen and assigned?

Comment 3

17 years ago
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 → ---

Comment 5

14 years ago
Please consider this soon. I'd like to use timestamps as part of debugging
Mail/News IMAP/POP3, etc. conversations.

Comment 6

14 years ago
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". 

Comment 9

12 years ago
Created attachment 225813 [details] [diff] [review]
v1 patch

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 10

12 years ago
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).

Comment 12

12 years ago
Vlad, I think you and I suggested the same thing.
Target Milestone: Future → 4.7

Comment 13

12 years ago
OK.. that sounds reasonable.
QA Contact: larryh → nspr

Comment 14

11 years ago
-> reassign to default owner
Assignee: darin.moz → wtc
Status: ASSIGNED → NEW

Comment 15

11 years ago
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

Updated

10 years ago
Duplicate of this bug: 418724
(Assignee)

Comment 17

9 years ago
Created attachment 356883 [details] [diff] [review]
Proposed patch

Output time stamp formatted by ISO 8601 if NSPR_LOG_OUTPUT_TIME_STAMP is set.
Attachment #356883 - Flags: review?(wtc)

Comment 18

9 years ago
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?
(Assignee)

Comment 20

9 years ago
(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.
(Assignee)

Comment 21

9 years ago
Created attachment 357595 [details] [diff] [review]
Address wtc comments.

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)
(Assignee)

Comment 22

9 years ago
(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?

Updated

9 years ago
Attachment #357595 - Flags: review?(wtc) → review+

Comment 23

9 years ago
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'.

Comment 24

9 years ago
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
(Assignee)

Comment 26

9 years ago
Created attachment 373268 [details] [diff] [review]
Update comment

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)
(Assignee)

Comment 27

9 years ago
(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.
(Assignee)

Comment 28

9 years ago
Created attachment 373517 [details] [diff] [review]
Update patch

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)
(Assignee)

Comment 29

9 years ago
The crash can reproduce with NSPR_LOG_MODULES=all:5,timestamp.
(Assignee)

Comment 30

9 years ago
Created attachment 373518 [details] [diff] [review]
Revised patch

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 31

9 years ago
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.
(Assignee)

Comment 32

9 years ago
(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
....
(Assignee)

Comment 33

9 years ago
(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).
(Assignee)

Comment 34

9 years ago
Created attachment 373554 [details] [diff] [review]
Revised patch

Invoke _PR_InitTime before _PR_InitLog.
Attachment #373518 - Attachment is obsolete: true
Attachment #373518 - Flags: review?(wtc)
Attachment #373554 - Flags: review?(wtc)

Comment 35

9 years ago
Created attachment 376138 [details] [diff] [review]
Revised patch (as checked in)

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)
(Assignee)

Comment 36

9 years ago
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 37

9 years ago
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

Comment 38

9 years ago
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.

Comment 39

9 years ago
I documented the special log module __timestamp in the NSPR Reference:
http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25328
(Assignee)

Comment 40

9 years ago
(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".

Comment 41

9 years ago
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.
(Assignee)

Comment 42

9 years ago
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
(Assignee)

Comment 43

9 years ago
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.
(Assignee)

Comment 44

9 years ago
Created attachment 376600 [details] [diff] [review]
Following up patch addressed wtc's suggestion

Use PR_GMTParameters and PR_snprintf with microsecond.

Thank you, wtc. The output log looks better.

Comment 45

9 years ago
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.
(Assignee)

Comment 47

9 years ago
(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?
(Assignee)

Comment 49

9 years ago
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

Comment 50

9 years ago
Created attachment 376992 [details] [diff] [review]
Change the special log module name to "timestamp"

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 51

9 years ago
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

Comment 52

9 years ago
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.
(Assignee)

Comment 53

9 years ago
(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!

Comment 54

9 years ago
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
(Assignee)

Comment 55

9 years ago
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.
(Assignee)

Comment 56

9 years ago
wct, does the localtime is converted by PR_NormalizeTime? If the cost of PR_NormalizeTime is cheaper than PR_ExplodeTime with PR_GMTParameters?
(Assignee)

Comment 57

9 years ago
(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?

Comment 58

9 years ago
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.
(Assignee)

Comment 59

9 years ago
(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.

Comment 60

9 years ago
Let's go ahead with the current timestamp format then.
Marked the bug fixed.
Status: ASSIGNED → RESOLVED
Last Resolved: 17 years ago9 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.