725512 - Reduce Content Provider log spew

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Richard Newman [:rnewman]]

02-07 00:26:21.510 D/GeckoBrowserProvider( 9987): Getting readable database for URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.510 D/GeckoBrowserProvider( 9987): Query is on bookmarks: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.510 D/GeckoBrowserProvider( 9987): Running built query.

and

02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Calling update on URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Getting writable database for URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Beginning update transaction: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Calling update in transaction on URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Updating bookmark: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Updating bookmarks on URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Getting writable database for URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Quering bookmarks to update on URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Extracting image values for URI: null
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Updating bookmark with ID: 2951
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Updated 1 rows for URI: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=true
02-07 00:26:21.420 D/GeckoBrowserProvider( 9987): Successful update transaction: content://org.mozilla.fennec_rnewman.db.browser/bookmarks?sync=true&show_deleted=tru


on every single operation isn't too helpful.

I will take a machete to this.

Comment 1

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v1

Here's a first stab. I'm building and testing this now, but might as well upload it.

We can use the existing preprocessing in this file to adjust whether trace logging gets turned on or not. If it's off, the compiler should be smart enough to make the trace statements 0-cost, which is a nice win.

Comment 2

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v2

This patch does three things:

* Introduce two simple static methods, "debug" and "trace". These do the correct thing for Android: check whether we should log at the requested level, and then do so.

* Replace all uses of Log.d(LOGTAG…) with debug(…).

* Replace the most repetitive uses of debug(…) with trace(…). This has the effect of eliminating thousands of lines of useless log output for routine syncs, making everyone happy — from the phone's IO subsystem all the way up to our execs. Logging can be re-enabled at runtime over ADB if so desired.

Comment 3

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v3

… and here's a version that actually compiles, thanks to me remembering to qref :)

The command to tweak log levels, by the way, is:

  adb shell setprop log.tag.GeckoBrowserProvider VERBOSE

Comment 4

[Richard Newman [:rnewman]]

Oh, Android, why are you so inefficient?

  https://github.com/android/platform_frameworks_base/blob/master/core/jni/android_util_Log.cpp#L59

isLoggable calls through JNI, does some string checking, and hits the System property store to retrieve the log level as a string. No caching, no opportunity for JIT here.

I'm not happy having this in the call path for every log statement. Time to make things less dynamic…

Comment 5

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v4

This version computes isLoggable once during static initialization. To change log levels, the app must be quit and restarted.

Comment 6

[Lucas Rocha (:lucasr)]

Comment on attachment 595678 [details] [diff] [review]
Proposed patch. v4

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

Looks good. I actually expected Log.d and Log.v to do what your patch does. i.e. Log.d and Log.v would be noop depending on the current log level. It's surprising that this is not the case. I wonder if you should add trace() and log() to a separate LogUtils class. For instance, I'd be interested in the same type of functionality for Favicons.java. Giving a r+ anyway.

Comment 7

[Richard Newman [:rnewman]]

(In reply to Lucas Rocha (:lucasr) from comment #6)
 
> Looks good. I actually expected Log.d and Log.v to do what your patch does.
> i.e. Log.d and Log.v would be noop depending on the current log level.

Me too. Kinda like every other logging framework in the world, mm? Curse you, Android.

> I wonder if you should add trace() and
> log() to a separate LogUtils class. For instance, I'd be interested in the
> same type of functionality for Favicons.java. Giving a r+ anyway.

I did this for Sync, which will also add a really handy location for Syncorro, logging to stdout, blocking of sensitive information regardless of log level, etc.

Will file a follow-up for the Fennec side.

Comment 8

[Richard Newman [:rnewman]]

(In reply to Richard Newman [:rnewman] from comment #7)

> Will file a follow-up for the Fennec side.

Actually, Bug 721461 will probably take care of centralizing some of this where it makes sense.

Comment 9

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

Adding Chris since he was looking at some ways to trim back logging in bug 721461

Comment 10

[Richard Newman [:rnewman]]

Inbound:

https://hg.mozilla.org/integration/mozilla-inbound/rev/6eeb8efc079f

Will request approval when this has had a day on m-c.

Comment 11

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/6eeb8efc079f

Comment 12

[Richard Newman [:rnewman]]

Comment on attachment 595678 [details] [diff] [review]
Proposed patch. v4

[Approval Request Comment]
Regression caused by (bug #): 
User impact if declined: 
 -- excessive log output, possible IO slowdown.
Testing completed (on m-c, etc.): 
 -- running locally, time on m-i and now m-c.
Risk to taking this patch (and alternatives if risky):
 -- slim.
String changes made by this patch:
 -- none.

Comment 13

[Alex Keybl [:akeybl]]

Comment on attachment 595678 [details] [diff] [review]
Proposed patch. v4

[Triage Comment]
Mobile only - approved for Aurora 12 and Beta 11.

Comment 14

[Richard Newman [:rnewman]]

Thanks Alex.

Added to blassey's patch queues for Beta and Aurora.

Comment 15

[Tracy Walker [:tracy]]

no longer seeing content provider spew in log

Comment 16

[Matt Brubeck (:mbrubeck)]

Comment on attachment 595678 [details] [diff] [review]
Proposed patch. v4

Clearing approval for Aurora 12 and Beta 11 because we are not currently planning a Native Fennec release of these versions.  If this changes in the future, we will likely do a mass uplift of all native fennec changes.  For now, let's get these bugs off the channel triage radar.

[Filter on the string "mbrubeck-bugspam" if you want to delete all of these emails at once.]