636382 - Log4Moz: avoid unnecessary object creation

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Comment 1

[Philipp von Weitershausen [:philikon]]

I have a patch in the works that greatly reduces the number of objects Log4Moz creates.

Comment 2

[Philipp von Weitershausen [:philikon]]

Attachment: v1

This vastly reduces the number of objects created by Log4Moz during logging:

* Logger.appenders is no longer calculated on the fly with Array.concat but pre-calculated when its parent logger is set.

* Logger.log() and the various convenience methods (info(), debug(), trace(), etc.) no longer create a LogMessage object all the time. It is now only created if the logger's level is below or equal to the message's one and if there's an appender whose level is below or equal. (This is was the 2nd biggest offender.)

* BasicFormatter.format() no longer formats the date and pads the logger name. The date formatting could be retained by doing new Date().toLocaleFormat(this._dateFormat), but even that would create a new Date object per message that's logged. That seems overkill. Instead of we now just log the timestamp and a formatted version at the beginning and end of a sync. (This was by far the biggest offender.)

* Some general cleanup: Unnecessary getters, unnecessary QueryInterface()s, etc.

Comment 3

[Richard Newman [:rnewman]]

Comment on attachment 514923 [details] [diff] [review]
v1

Re the "grab parent appenders" trick: one could store an array of our own appenders, as well as our own + inherited appenders, and then recompute the latter from the former when parent is reassigned.

It would also be nice to visit the previous parent and remove ourselves from their children array.

(All only if this._parent != parent, of course.)

I doubt it happens much in the wild, but it would be nice to be robust in this regard.

Everything else looks good to me. In the absence of unit tests, I did a side-by-side run to make sure that equivalent log output is produced before and after this patch.

I haven't verified output in the browser (e.g., that timestamps are printed). Please make sure that you have!

Comment 4

[Philipp von Weitershausen [:philikon]]

(In reply to comment #3)
> Re the "grab parent appenders" trick: one could store an array of our own
> appenders, as well as our own + inherited appenders, and then recompute the
> latter from the former when parent is reassigned.
> 
> It would also be nice to visit the previous parent and remove ourselves from
> their children array.
> 
> (All only if this._parent != parent, of course.)
> 
> I doubt it happens much in the wild, but it would be nice to be robust in this
> regard.

20:21 <@philikon> btw, i thought about the two list approach
20:21 <@philikon> but decided against it
20:21 <@philikon> seemed much simpler this way
20:21 <@rnewman> then how 'bout:
20:22 <@rnewman> on parent assignment, remove ourselves from parent.children, and set-disjoin parent.appenders from 
                 this.appenders
20:22 <@philikon> well, like i said in a comment, this code makes the assumption that parent is never re-assigned
20:22 <@rnewman> then please throw an error
20:22 <@philikon> i think that's a valid assumption given the current code
20:22 <@philikon> ok
20:22 <@philikon> good call
20:22 <@rnewman> wfm

> I haven't verified output in the browser (e.g., that timestamps are printed).
> Please make sure that you have!

I have plenty of times. It looks like this:

1298594942007	Service.Main	INFO	Starting sync at 2011-02-24 16:49:02
...
1298595244406	Service.Main	INFO	Sync completed successfully at 2011-02-24 16:54:04 after 0.51 secs.

Comment 5

[Richard Newman [:rnewman]]

(In reply to comment #4)

> I have plenty of times. It looks like this:

Sweet. Just making sure :D

For the bug record: the trivial one-liner to turn those timestamps into the old readable dates:

  new Date(1298595244406).toLocaleFormat("%Y-%m-%d %H:%M:%S");

Comment 6

[Philipp von Weitershausen [:philikon]]

Attachment: v1.1

Address review comments:
* throw if parent is assigned a value more than once (and it's not the same as the first one)
* now there's also no need for a recursive _updateParents() call

Bonus: I also ripped out the Function.caller.name thing (bug 583860)

Comment 7

[Philipp von Weitershausen [:philikon]]

Attachment: v2

Bah, I must've forgotton to rerun 'make' or something because the v1.1 patch causes a test failure in test_log4moz.js regarding the nested parent logging behaviour.

This now restores this behaviour, going with the two list approach that rnewman suggested above. Logger.parent can now be changed; this causes the logger to remove itself from its parent's children and update all appender lists accordingly.

Requesting review again for the parts that changed.

Comment 8

[Philipp von Weitershausen [:philikon]]

Attachment: v2.1

Address some IRC review comments:

23:49 <@rnewman> can you s/_appenders/directAppenders/g ? also, interdiff 231 might want to check the aggregate 
                 appender list, avoid duplicates... or updateAppenders should remove dupes
23:50 <@philikon> ownAppenders?
23:50 <@rnewman> wfm
23:51 <@rnewman> actually, dupe-removal seems like a good idea in general; setting parent could occur after adding our 
                 own

Comment 9

[Philipp von Weitershausen [:philikon]]

Landed to fx-sync: https://hg.mozilla.org/services/fx-sync/rev/39541c988e93

Comment 10

[Philipp von Weitershausen [:philikon]]

Merged to s-c: http://hg.mozilla.org/services/services-central/rev/74e0d893630a

Comment 11

[Philipp von Weitershausen [:philikon]]

Merged to m-c: http://hg.mozilla.org/mozilla-central/rev/74e0d893630a