99580 - Various cleanup ideas for msgcompose:5 logging.

Status: VERIFIED FIXED

(MailNews Core :: Composition, defect, P3)

Description

[[e-mail] (gone - use [e-mail] instead)]

Here is a sample current log, with *my* comments as C++ style comments: 

0[a3deb0c]: 

// before we do the seperator below, we should make columns like "[process]: 
[total milliseconds] [function time in milliseconds]"

-------------------- 
0[a3deb0c]: [ 0][ 0] - Start opening the window, message size = 22518

// we should list the above '22518' bytes in kilobytes, I think

0[a3deb0c]: [ 1515][ 1515] - Start Initializing the compose window 
(ComposeLoad) 

0[a3deb0c]: [ 2364][ 849] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about::blank

0[a3deb0c]: [ 2618][ 254] - Editor is done loading about::blank. Now let mime 
do its job 

// about: blank is 'new window time', so we should comment to that effect

0[a3deb0c]: [ 3509][ 891] - done with mime. Time to insert the body 
0[a3deb0c]: [ 3852][ 343] - Finished inserting data into the editor. The window 
is almost ready! 
0[a3deb0c]: [ 4644][ 792] - addressing widget, windows title and focus are now 
set. The window is finally ready

Comment 1

[[e-mail] (gone - use [e-mail] instead)]

I should have a patch for this very soon.

Comment 2

[[e-mail] (gone - use [e-mail] instead)]

Attachment: Cleans up formatting a tiny bit

Comment 3

[[e-mail] (gone - use [e-mail] instead)]

Attachment: Sample output so far

Comment 4

[[e-mail] (gone - use [e-mail] instead)]

The 2 things remaining that I'll need help with are:

1.  Either get rid of the process at the top of the output or get rid of it on
the left side of each output line.  We only need to know the process once, since
running multiple windows or replies starts the output on a new line \n and one
process ID per output module is fine.
2.  I really would like the milliseconds to be output instead in seconds. 
Instead of rounding, we should just do:

1234 (in ms) would become 1.23 seconds.

And I'd like to see that logged as:

[ 12.7][   0.064] - Done with the initialization (ComposeLoad). Waiting on editor
to load about:blank

Comment 5

[[e-mail] (gone - use [e-mail] instead)]

I meant this line:

0[324410]: [ 1275][   64] - Done with the initialization (ComposeLoad). Waiting
on editor to load about:blank

Comment 6

[[e-mail] (gone - use [e-mail] instead)]

Typo, I meant:

it would become:

[ 1.274][   0.064] - Done with the initialization (ComposeLoad). Waiting on editor
to load about:blank

Comment 7

[Sheela Ravindran]

Stephen,
Is this fixed or still not complete?

Comment 8

[[e-mail] (gone - use [e-mail] instead)]

Sheela, nope, not yet.  Jean-Francois, do you object to anything in my patch?

Comment 9

[Jean-Francois Ducarroz]

Comment on attachment 49387 [details] [diff] [review]
Cleans up formatting a tiny bit

be award than "This is new window time" is in fact the time for a new msg
compose window! it's a little bit more than a new window time in the generic
sense of it. R=ducarroz

Comment 10

[Jean-Francois Ducarroz]

if you want ot display the time in sec rather than millisec, change the line:

  PR_LOG(MsgComposeLogModule, PR_LOG_ALWAYS, ("[%5d][%5d] - %s\n", totalTime,
deltaTime, label));

to
  PR_LOG(MsgComposeLogModule, PR_LOG_ALWAYS, ("[%3.2f][%3.2f] - %s\n",
(double)totalTime/100.0, (double)deltaTime/100.0, label));

same for the printf line above and you might have to add a column in the header.
You are welcom to reassign this bug to yourself

Comment 11

[[e-mail] (gone - use [e-mail] instead)]

Jean-Francois, can you help me declare the variables in C++?

I only know JS:

c:\moz_src\mozilla\mailnews\compose\src\nsMsgComposeService.cpp(531) : error
C2065: 'totalTime' : undeclared identifier
c:\moz_src\mozilla\mailnews\compose\src\nsMsgComposeService.cpp(531) : error
C2065: 'deltaTime' : undeclared identifier

Comment 12

[Jean-Francois Ducarroz]

Reassign to stephen. Seems a good exercise for him...

Comment 13

[[e-mail] (gone - use [e-mail] instead)]

Attachment: Patch V2.0

Comment 14

[[e-mail] (gone - use [e-mail] instead)]

New sample output

0[324470]: 
[process]: [totalTime][deltaTime]
--------------------
0[324470]: [0.01][0.01] - Start opening the window, message size = 1361
0[324470]: [0.80][0.80] - Start initializing the compose window (ComposeLoad)
0[324470]: [0.84][0.05] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[324470]: [0.94][0.10] - Editor is done loading about:blank. This is New 
Compose window time.  Time for MIME.
0[324470]: [0.96][0.03] - Done with MIME. Now we're updating the UI elements
0[324470]: [1.06][0.10] - Addressing widget, window title and focus are now 
set, time to insert the body
0[324470]: [1.11][0.06] - Finished inserting data into the editor. The window 
is finally ready!

Comment 15

[[e-mail] (gone - use [e-mail] instead)]

Jean-Francois, I think with your help yesterday, that this is ready to go.  Can 
I get another r=?  Thanks.

Comment 16

[Jean-Francois Ducarroz]

Comment on attachment 62400 [details] [diff] [review]
Patch V2.0

R=ducarroz

Comment 17

[Scott MacGregor]

Comment on attachment 62400 [details] [diff] [review]
Patch V2.0

sr=mscott

Comment 18

[[e-mail] (gone - use [e-mail] instead)]

C:\moz_src\mozilla\mailnews\compose\src>cvs commit -m "Bug 99580. 
Cleanup/formatting for msgcompose:5 logging.  r=[e-mail],
sr=[e-mail]" nsMsgCompose.cpp
Checking in nsMsgCompose.cpp;
/cvsroot/mozilla/mailnews/compose/src/nsMsgCompose.cpp,v  <--  nsMsgCompose.cpp
new revision: 1.313; previous revision: 1.312
done

C:\moz_src\mozilla\mailnews\compose\src>cvs commit -m "Bug 99580. 
Cleanup/formatting for msgcompose:5 logging.  r=[e-mail],
sr=[e-mail]" nsMsgComposeService.cpp
Checking in nsMsgComposeService.cpp;
/cvsroot/mozilla/mailnews/compose/src/nsMsgComposeService.cpp,v  <-- 
nsMsgComposeService.cpp
new revision: 1.61; previous revision: 1.60
done

Fixed.  Thanks for the help, Jean-Francois, and Mscott for the review.

Comment 19

[[e-mail] (gone - use [e-mail] instead)]

Here's a current log that I just used tonight in testing the 2002-01-03 build 
on Windows 98:

0[7b1eb0]: 
[process]: [totalTime][deltaTime]
--------------------
0[7b1eb0]: [0.01][0.01] - Start opening the window, message size = 2941
0[7b1eb0]: [2.69][2.69] - Start initializing the compose window (ComposeLoad)
0[7b1eb0]: [2.94][0.25] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[7b1eb0]: [3.30][0.37] - Editor is done loading about:blank. This is New 
Compose window time.  Time for MIME.
0[7b1eb0]: [3.38][0.09] - Done with MIME. Now we're updating the UI elements
0[7b1eb0]: [4.18][0.80] - Addressing widget, window title and focus are now 
set, time to insert the body
0[7b1eb0]: [4.34][0.16] - Finished inserting data into the editor. The window 
is finally ready!
0[7b1eb0]: 
[process]: [totalTime][deltaTime]
--------------------
0[7b1eb0]: [0.01][0.01] - Start opening the window, message size = 2941
0[7b1eb0]: [0.92][0.92] - Start initializing the compose window (ComposeLoad)
0[7b1eb0]: [1.01][0.09] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[7b1eb0]: [1.46][0.46] - Editor is done loading about:blank. This is New 
Compose window time.  Time for MIME.
0[7b1eb0]: [1.53][0.07] - Done with MIME. Now we're updating the UI elements
0[7b1eb0]: [2.28][0.75] - Addressing widget, window title and focus are now 
set, time to insert the body
0[7b1eb0]: [2.45][0.18] - Finished inserting data into the editor. The window 
is finally ready!
0[7b1eb0]: 
[process]: [totalTime][deltaTime]
--------------------
0[7b1eb0]: [0.01][0.01] - Start opening the window, message size = 2941
0[7b1eb0]: [0.92][0.92] - Start initializing the compose window (ComposeLoad)
0[7b1eb0]: [1.01][0.09] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[7b1eb0]: [1.47][0.46] - Editor is done loading about:blank. This is New 
Compose window time.  Time for MIME.
0[7b1eb0]: [1.53][0.07] - Done with MIME. Now we're updating the UI elements
0[7b1eb0]: [2.28][0.76] - Addressing widget, window title and focus are now 
set, time to insert the body
0[7b1eb0]: [2.46][0.18] - Finished inserting data into the editor. The window 
is finally ready!

Verified FIXED!