1004825 - enable prioritized tagged logging from JS

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Myk Melez [:myk] [@mykmelez]]

Attachment: work-in-progress Log module

It'd be useful to support prioritized, tagged logging from JavaScript in Fennec, since Android's logs are structured by priority and tag, and they're easier to read when log messages have the appropriate values for those attributes.

Here's a work in progress that demonstrates the kind of interface we could expose to JavaScript code.  It's a mapping of a subset of android.util.Log <http://developer.android.com/reference/android/util/Log.html> to a JavaScript module named log, such that a script can do:

  Cu.import("resource://gre/modules/Log.jsm");
  …
  Log.d("WebappManager", "downloading APK to filesystem");


Mark: this is the "more we can do to improve JavaScript logging in Fennec overall" that I mentioned in bug 1003469.  I think it'd improve the readability of messages that use it significantly, especially with tools like logcat-color <https://github.com/marshall/logcat-color>, which structures and colorizes logcat output.

Comment 1

[Myk Melez [:myk] [@mykmelez]]

Comment on attachment 8416231 [details] [diff] [review]
work-in-progress Log module

Cancelling this feedback request, per bug 1003469, comment 4, while I look into alternative implementations.

Comment 2

[Myk Melez [:myk] [@mykmelez]]

Attachment: another approach: use js-ctypes

Ok, here's another approach: use js-ctypes to call liblog's __android_log_write, which provides an android.util.Log-like interface for native code.  It should be faster than using the Messaging module to send a message to Java.

But I'm unsure about the expense of opening the library for each message, which seems like it could be noticeable.  I haven't found good guidance on lifecycle management for libraries frequently accessed using ctypes, but I suspect we should maintain a singleton reference to the library until browser shutdown (at which point it should be collected automatically).

Also, it isn't clear if we should define the ANDROID_LOG_* constants on some native interface reflected into JS, like OSFileConstants.cpp does for some libc constants with OS.File.Constants, so we can access them in the JS module.  They don't vary across platforms like the libc constants do, and log.h <https://android.googlesource.com/platform/system/core/+/master/include/android/log.h> strongly suggests they will never change, so I think we're ok defining their equivalents in the JS module.

Note: the module is called AndroidLog.jsm to avoid conflicts with toolkit/modules/Log.jsm (which is for cross-platform logging to files in addition to consoles).  And thus it exports the "AndroidLog" symbol to align the name of the symbol with the name of the module (a common practice for modules that export a single symbol).

But most consumers should assign it to a "Log" variable for ease of use, and that's what the docs suggest.  They also suggest assigning bespoke dump/log/debug functions to Log.d.bind(Log, "MyModule"), and the patch includes such conversions for browser.js, WebappManager.jsm, Webapps.jsm, and WebappManagerWorker.js, which resolves bug 1003469.

(I could have gone further and replaced all bespoke function calls with "Log.d" calls, but that would litter history/blame, and it probably isn't what the coders who created those functions would want anyway.)

Comment 3

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 8419070 [details] [diff] [review]
another approach: use js-ctypes

Very interesting. I wonder if we should even care about saely closing the ctypes library on Android. Fennec is rarely ever cleanly closed.

Many of the other JSMs using ctypes never close the library.

Perhaps we could hold onto the library as a global in the JSM and listen for xpcom-shutdown to close the library?

I don't know the performance characteristics of opening/closing on each use.

r+, but consider just opening, but not closing the library

Comment 4

[Mark Finkle (:mfinkle) (use needinfo?)]

NI'ing myself to remember to run some profiles after this lands.

Comment 5

[Myk Melez [:myk] [@mykmelez]]

Attachment: open the native library only once

Here's an updated patch that opens the library only once and leaves it open.

mfinkle: you granted review on the previous patch, and this one does what you suggested in your review comments, so I'm carrying forward your review.

Marco: I'm requesting review from you for the code in Webapps.js, as this patch also incorporates an updated fix for bug 1003469, taking your previous review comments in that bug into account:

> Nit: A comment explaining why we always print debug messages on Android
> would be useful, otherwise people looking at the code could be confused by
> the two unrelated branches (#ifdef ANDROID, #elifdef DEBUG).

Fixed!  Note that it uses #ifdef MOZ_WIDGET_ANDROID to avoid enabling this codepath on B2G, for which #ifdef ANDROID should also be true (if I remember correctly).


> Are these messages showing up in the tbpl logs? I guess so, but it's always
> better to ask!

Without this fix, they should show up only for debug builds of Fennec; with the fix, they should show up for all Fennec builds.


Regarding performance, I did some primitive testing that suggests that the original implementation is several times slower than logStringMessage/dump, while this implementation, which leaves the library open, is comparable.

The test measured the time it took to log one thousand messages, and I took the average of five or ten test runs for each of four potential implementations of a debug logger: the original implementation of the AndroidLog module, this implementation, Services.console.logStringMessage, and "dump".

The original implementation of AndroidLog averaged 378ms across five runs; logStringMessage and dump averaged 121ms and 102ms, respectively, across ten runs; and this implementation of AndroidLog averaged 112ms across ten runs.

Loading the module on startup takes another 5-6ms, most of which appears to be the inherent cost of loading any JSM, as a stub module takes 4ms.


Note: this patch doesn't close the library on xpcom-shutdown, because "Using js-ctypes - After you're done" <https://developer.mozilla.org/en-US/docs/Mozilla/js-ctypes/Using_js-ctypes#After_you%27re_done> says "If you fail to close the library, it will be automatically closed when it is garbage collected."  So we shouldn't have to do it ourselves.

It also says "When you're finished using a library, you should close it."  But we aren't finished using it until around the time the module is unloaded anyway.  Plus it isn't clear if an API call could occur between xpcom-shutdown and unloading of the module, in which case we'd be unable to log the message.

So it seems both reasonable and preferable to let the library get closed and garbage-collected automatically.


Note: the patch also changes the docs, tests, and usage to recommend, test, and implement passing a "null" value for the "thisArg" parameter to AndroidLog.D.bind calls, which makes it possible to import the module and bind the function in one statement (and without also importing AndroidLog):

  let debug = Cu.import("resource://gre/modules/AndroidLog.jsm", {})
                .AndroidLog.d.bind(null, "Webapps");

That's useful for cross-platform consumers like Webapps.js, which won't use AndroidLog other than to bind that function and shouldn't expose it.


https://tbpl.mozilla.org/?tree=Try&rev=64a36b1b474b

Comment 6

[Mark Finkle (:mfinkle) (use needinfo?)]

Thanks for the testing and the changes. I'm sold.

Comment 7

[Myk Melez [:myk] [@mykmelez]]

(In reply to Myk Melez [:myk] [@mykmelez] from comment #5)
> Marco: I'm requesting review from you for the code in Webapps.js, as this
> patch also incorporates an updated fix for bug 1003469, taking your previous
> review comments in that bug into account:

Marco: I suppose technically your review isn't necessary, as you granted review in bug 1003469!  But I'd still prefer to have you take a look at the new way this patch defines the "debug" function in Webapps.jsm.  And any feedback you have about other parts of the patch would also be welcome!

Comment 8

[Marco Castelluccio [:marco]]

Comment on attachment 8419745 [details] [diff] [review]
open the native library only once

Review of attachment 8419745 [details] [diff] [review]:
-----------------------------------------------------------------

(In reply to Myk Melez [:myk] [@mykmelez] from comment #5)
> Without this fix, they should show up only for debug builds of Fennec; with
> the fix, they should show up for all Fennec builds.

Awesome!

Comment 9

[Myk Melez [:myk] [@mykmelez]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/626698fe5f8b

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/626698fe5f8b

Comment 11

[Richard Newman [:rnewman]]

Note that the tag length should be no more than 23 characters (a limit which only isLoggable enforces via an exception, but hey, Android!), which after prepending "Gecko" means that AndroidLog.jsm should enforce an 18-char limit.

Worth a 3-line follow-up to either truncate or err, I think.

Comment 12

[Myk Melez [:myk] [@mykmelez]]

(In reply to Richard Newman [:rnewman] from comment #11)
> Note that the tag length should be no more than 23 characters (a limit which
> only isLoggable enforces via an exception, but hey, Android!), which after
> prepending "Gecko" means that AndroidLog.jsm should enforce an 18-char limit.
> 
> Worth a 3-line follow-up to either truncate or err, I think.

Filed as bug 1009311!