Closed Bug 636382 Opened 9 years ago Closed 9 years ago

Log4Moz: avoid unnecessary object creation

Categories

(Firefox :: Sync, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
Tracking Status
fennec 2.0+ ---

People

(Reporter: philikon, Assigned: philikon)

References

Details

(Whiteboard: [fixed in fx-sync][fixed in services][qa-])

Attachments

(1 file, 3 obsolete files)

No description provided.
tracking-fennec: --- → 2.0+
I have a patch in the works that greatly reduces the number of objects Log4Moz creates.
Assignee: nobody → philipp
Attached patch v1 (obsolete) — Splinter Review
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.
Attachment #514923 - Flags: review?(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!
Attachment #514923 - Flags: review?(rnewman) → review+
Whiteboard: [has patch][has review]
(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.
(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");
Status: NEW → ASSIGNED
Attached patch v1.1 (obsolete) — Splinter Review
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)
Attachment #514923 - Attachment is obsolete: true
Blocks: 583860
Attached patch v2 (obsolete) — Splinter Review
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.
Attachment #514995 - Attachment is obsolete: true
Attachment #515009 - Flags: review?(rnewman)
Attached patch v2.1Splinter Review
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
Attachment #515009 - Attachment is obsolete: true
Attachment #515009 - Flags: review?(rnewman)
Attachment #515011 - Flags: review?(rnewman)
Attachment #515011 - Flags: review?(rnewman) → review+
Landed to fx-sync: https://hg.mozilla.org/services/fx-sync/rev/39541c988e93
Whiteboard: [has patch][has review] → [fixed in fx-sync]
Merged to s-c: http://hg.mozilla.org/services/services-central/rev/74e0d893630a
Whiteboard: [fixed in fx-sync] → [fixed in fx-sync][fixed in services]
Merged to m-c: http://hg.mozilla.org/mozilla-central/rev/74e0d893630a
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Whiteboard: [fixed in fx-sync][fixed in services] → [fixed in fx-sync][fixed in services][qa-]
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.