Closed Bug 804457 Opened 7 years ago Closed 7 years ago

Reduce log chattiness

Categories

(Firefox for Android :: General, defect)

ARM
Android
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 19

People

(Reporter: rnewman, Assigned: rnewman)

References

(Blocks 1 open bug)

Details

Attachments

(2 files, 3 obsolete files)

No description provided.
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Attachment #674111 - Flags: review?(mark.finkle)
Comment on attachment 674111 [details] [diff] [review]
Part 1: spelling, grammar, punctuation, and log levels in GeckoApp.java. v1

>diff --git a/mobile/android/base/GeckoApp.java b/mobile/android/base/GeckoApp.java

In general, I would skip the pure comment changes, just to minimimze bitrot to other devs. My requests to remove might be a bit aggressive, but I am considering just how useful this output is to external users. Internal devs can just add their own logs as needed... and then remove them. The "zerdatime" stuff is not helpful anymore.

>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - start of getPluginDirectories");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - start of getPluginDirectories");

I'd be happier to see these "zerdatime" logs go away. We are using telemetry to gather timing

>-                Log.w(LOGTAG, "Loading plugin: " + serviceInfo.packageName);
>-
>-
>-                // retrieve information from the plugin's manifest
>+                Log.d(LOGTAG, "Loading plugin: " + serviceInfo.packageName);


Let's remove these "You are here" logs

>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - end of getPluginDirectories");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - end of getPluginDirectories");

Remove

>     protected void onSaveInstanceState(Bundle outState) {

>-        Log.i(LOGTAG, "onSaveInstanceState");
>+        Log.d(LOGTAG, "Entered onSaveInstanceState.");

More "You are here". Remove.

>+    /**
>+     * This function might perform synchronous IO. Don't call it
>+     * from the main thread.
>+     */
>     public StartupMode getStartupMode() {
>-        // This function might touch the disk and should not
>-        // be called from UI's main thread.

Good comment change

>     public void handleMessage(String event, JSONObject message) {
>-        Log.i(LOGTAG, "Got message: " + event);
>+        Log.d(LOGTAG, "Got message: " + event);

I have not seen any value in this log. I vote to remove it.

>             for (int i = 0; i < aPermissions.length(); i++) {
>                 try {
>-                    items[i] = aPermissions.getJSONObject(i).
>-                               getString("setting");
>-                    // Make all the items checked by default
>+                    items[i] = aPermissions.getJSONObject(i).getString("setting");
>+                    // Make all the items checked by default.

Yeah. I like this too.

>         mMainHandler = new Handler();
>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onCreate");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onCreate");

Burn it.

>         if (savedInstanceState != null) {
>-            Log.i(LOGTAG, "Restoring from OOM");
>+            Log.i(LOGTAG, "Restoring from OOM.");

Burn it.

>             boolean wasInBackground =
>                 savedInstanceState.getBoolean(SAVED_STATE_IN_BACKGROUND, false);
>-            Log.i(LOGTAG, "Was in background: " + wasInBackground);
>+            Log.d(LOGTAG, "Was in background: " + wasInBackground);

Burn it.

>                 boolean wasOOM = prefs.getBoolean(PREFS_OOM_EXCEPTION, false);
>                 boolean wasStopped = prefs.getBoolean(PREFS_WAS_STOPPED, true);
>                 if (wasOOM || !wasStopped) {
>-                    Log.i(LOGTAG, "Crashed due to OOM last run");
>+                    Log.i(LOGTAG, "Crashed due to OOM on last run.");

Burn it.

>         if (mRestoreMode == GeckoAppShell.RESTORE_NONE && getProfile().shouldRestoreSession()) {
>-            Log.i(LOGTAG, "Restoring crash");
>+            Log.d(LOGTAG, "Restoring crash.");

Burn it.

>         } else if (ACTION_DEBUG.equals(action) &&
>             checkAndSetLaunchState(LaunchState.Launching, LaunchState.WaitForDebugger)) {
>             mMainHandler.postDelayed(new Runnable() {
>                 public void run() {
>-                    Log.i(LOGTAG, "Launching from debug intent after 5s wait");
>+                    Log.d(LOGTAG, "Launching from debug intent after 5s wait");
>                     setLaunchState(LaunchState.Launching);
>                     sGeckoThread.start();
>                 }
>             }, 1000 * 5 /* 5 seconds */);
>-            Log.i(LOGTAG, "Intent : ACTION_DEBUG - waiting 5s before launching");
>+            Log.d(LOGTAG, "Intent : ACTION_DEBUG - waiting 5s before launching");

These seem useless too, but we probably never see them anyway.

>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - UI almost up");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - UI almost up");

Remove

>         GeckoAppShell.getHandler().postDelayed(new Runnable() {
>             public void run() {
>-                Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - pre checkLaunchState");
>+                Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - pre checkLaunchState");

Remove

>                 // Kick off our background service to fetch product announcements.
>                 // We do this by invoking the broadcast receiver, which uses the
>                 // system alarm infrastructure to perform tasks at intervals.
>                 Log.d(LOGTAG, "Broadcasting announcements pref.");

This seems like a "You are here" debugging output.

>     protected void onNewIntent(Intent intent) {
>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onNewIntent");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onNewIntent");

Remove

>         if (Intent.ACTION_MAIN.equals(action)) {
>-            Log.i(LOGTAG, "Intent : ACTION_MAIN");
>+            Log.d(LOGTAG, "Intent: ACTION_MAIN");

Remove

>     public void onResume()
>     {
>-        Log.i(LOGTAG, "resume");
>+        Log.d(LOGTAG, "Entering onResume.");

Remove

>     public void onStop()
>     {
>-        Log.i(LOGTAG, "stop");
>+        Log.d(LOGTAG, "Entering onStop.");

Remove

>     public void onPause()
>     {
>-        Log.i(LOGTAG, "pause");
>+        Log.d(LOGTAG, "Entering onPause.");

Remove

>     public void onRestart()
>     {
>-        Log.i(LOGTAG, "restart");
>+        Log.d(LOGTAG, "Entering onRestart.");

Remove

>     public void onStart()
>     {
>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onStart");
>-
>-        Log.i(LOGTAG, "start");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onStart");

Remove

>     public void onDestroy()
>     {
>-        Log.i(LOGTAG, "destroy");
>+        Log.d(LOGTAG, "Entering onDestroy.");

Remove

>     public void onConfigurationChanged(Configuration newConfig)
>     {
>-        Log.i(LOGTAG, "configuration changed");
>+        Log.d(LOGTAG, "Configuration changed.");

Remove

>     public void doRestart(String action) {
>-        Log.i(LOGTAG, "doRestart(\"" + action + "\")");
>+        Log.d(LOGTAG, "doRestart(\"" + action + "\")");

Remove

>-            Log.i(LOGTAG, intent.toString());
>+            Log.d(LOGTAG, "Restart intent: " + intent.toString());

Remove

>-                    Log.i(LOGTAG, "Checking profile migration in: " + profileDir.getAbsolutePath());
>+                    Log.d(LOGTAG, "Checking profile migration in: " + profileDir.getAbsolutePath());

Remove

>                         long timeDiff = SystemClock.uptimeMillis() - currentTime;
>-                        Log.i(LOGTAG, "Profile migration took " + timeDiff + " ms");
>+                        Log.v(LOGTAG, "Profile migration took " + timeDiff + " ms");

Is this useful anymore? I don't think it is. Remove the log and timing code.

>             if (!profileMigrator.hasSyncMigrated()) {
>-                Log.i(LOGTAG, "Checking Sync settings in: " + profileDir.getAbsolutePath());
>+                Log.d(LOGTAG, "Checking Sync settings in: " + profileDir.getAbsolutePath());

Remove

Thoughts?
Attachment #674111 - Flags: review?(mark.finkle) → review-
Now with 300% fewer nitpicky comment changes, and ∞ less zerdatime.
Attachment #674111 - Attachment is obsolete: true
Attachment #674123 - Flags: review?(mark.finkle)
Comment on attachment 674123 [details] [diff] [review]
Part 1: spelling, grammar, punctuation, and log levels in GeckoApp.java. v2

Worth it
Attachment #674123 - Flags: review?(mark.finkle) → review+
Try run for b41d581399f0 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=b41d581399f0
Results (out of 48 total builds):
    success: 40
    warnings: 5
    failure: 3
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/rnewman@mozilla.com-b41d581399f0
https://hg.mozilla.org/integration/mozilla-inbound/rev/7b01f6cf02b4

Parts 2+ are open to community participation, unless I get to them tonight :D
Target Milestone: --- → Firefox 19
Attached patch Part 2: hit other classes. v1 (obsolete) — Splinter Review
(Still building; I'll wait for that before I land, assuming r+!)

Touched most of the other noisy classes, taking the same approach.

In a couple of spots where I broke a lot of blame/patch application, I took the opportunity to improve the code; you'll see the places. Happy to rip those out if you don't want to take them.
Attachment #674484 - Flags: review?(mark.finkle)
https://hg.mozilla.org/mozilla-central/rev/7b01f6cf02b4
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Flags: in-testsuite-
Resolution: --- → FIXED
Attached patch Part 2: hit other classes. v2 (obsolete) — Splinter Review
How 'bout I use correct Java syntax?
Attachment #674484 - Attachment is obsolete: true
Attachment #674484 - Flags: review?(mark.finkle)
Attachment #674529 - Flags: review?(mark.finkle)
Comment on attachment 674529 [details] [diff] [review]
Part 2: hit other classes. v2

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

::: mobile/android/base/BrowserToolbar.java
@@ -556,5 @@
>          if (visible) {
>              mFavicon.setImageDrawable(mProgressSpinner);
>              mProgressSpinner.start();
>              setPageActionVisibility(true);
> -            Log.i(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - Throbber start");

I think the "Throbber start" and "Throbber stop" messages are used by S1/S2 tests (http://mrcote.info/phonedash/#) - we probably need to leave them in.
(In reply to Geoff Brown [:gbrown] from comment #10)
> Comment on attachment 674529 [details] [diff] [review]
> Part 2: hit other classes. v2
> 
> Review of attachment 674529 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: mobile/android/base/BrowserToolbar.java
> @@ -556,5 @@
> >          if (visible) {
> >              mFavicon.setImageDrawable(mProgressSpinner);
> >              mProgressSpinner.start();
> >              setPageActionVisibility(true);
> > -            Log.i(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - Throbber start");
> 
> I think the "Throbber start" and "Throbber stop" messages are used by S1/S2
> tests (http://mrcote.info/phonedash/#) - we probably need to leave them in.

Indeed, but I was wondering if we could remove the "zerdatime" and millisec parts. Does phonedash use the times too, or just the "Throbber Start/Stop" text?
> > I think the "Throbber start" and "Throbber stop" messages are used by S1/S2
> > tests (http://mrcote.info/phonedash/#) - we probably need to leave them in.

Good to know, thanks Geoff.

> Indeed, but I was wondering if we could remove the "zerdatime" and millisec
> parts. Does phonedash use the times too, or just the "Throbber Start/Stop"
> text?

And also: does this have to log at INFO? And if it really is used by a test somewhere, I'll add a comment to that effect.

Is there a doc somewhere for what that test needs?
(In reply to Mark Finkle (:mfinkle) from comment #11)
> (In reply to Geoff Brown [:gbrown] from comment #10)
> Indeed, but I was wondering if we could remove the "zerdatime" and millisec
> parts. Does phonedash use the times too, or just the "Throbber Start/Stop"
> text?

It uses the times too. 

It does not look for "zerdatime" specifically, but it extracts the millisec times from the nth space-delimited word -- so "zerdatime" can be changed to something else, but it you remove it entirely, the tests will break.

Code is here: https://github.com/mozilla/autophone/blob/master/tests/s1s2test.py#L142

I don't think INFO is necessary. I don't know of any doc.
(In reply to Geoff Brown [:gbrown] from comment #13)

> It uses the times too. 

I'm going to strip that change out of this patch, add a comment about it being necessary for that test, and file a follow-up bug to do this in a less janky way.
Blocks: 805124
Attachment #674529 - Attachment is obsolete: true
Attachment #674529 - Flags: review?(mark.finkle)
Attachment #674771 - Flags: review?(mark.finkle)
Comment on attachment 674771 [details] [diff] [review]
Part 2: hit other classes. v3


>-        Log.i(LOGTAG, "post native init");
>+        Log.v(LOGTAG, "Native init spawned.");

Remove

>-        Log.i(LOGTAG, "Location provider - high accuracy: " + enable);
>+        Log.v(LOGTAG, "Location provider - high accuracy: " + enable);

>-            Log.i(LOGTAG, "Enabling SENSOR_ORIENTATION");
>+            Log.v(LOGTAG, "Enabling SENSOR_ORIENTATION");

>-            Log.i(LOGTAG, "Enabling SENSOR_ACCELERATION");
>+            Log.v(LOGTAG, "Enabling SENSOR_ACCELERATION");

>-            Log.i(LOGTAG, "Enabling SENSOR_PROXIMITY");
>+            Log.v(LOGTAG, "Enabling SENSOR_PROXIMITY");

>-            Log.i(LOGTAG, "Enabling SENSOR_LIGHT");
>+            Log.v(LOGTAG, "Enabling SENSOR_LIGHT");

>-            Log.i(LOGTAG, "Enabling SENSOR_LINEAR_ACCELERATION");
>+            Log.v(LOGTAG, "Enabling SENSOR_LINEAR_ACCELERATION");

>-            Log.i(LOGTAG, "Enabling SENSOR_GYROSCOPE");
>+            Log.v(LOGTAG, "Enabling SENSOR_GYROSCOPE");

Remove

>-            Log.i(LOGTAG, "Disabling SENSOR_ORIENTATION");
>+            Log.v(LOGTAG, "Disabling SENSOR_ORIENTATION");

>-            Log.i(LOGTAG, "Disabling SENSOR_ACCELERATION");
>+            Log.v(LOGTAG, "Disabling SENSOR_ACCELERATION");

>-            Log.i(LOGTAG, "Disabling SENSOR_PROXIMITY");
>+            Log.v(LOGTAG, "Disabling SENSOR_PROXIMITY");

>-            Log.i(LOGTAG, "Disabling SENSOR_LIGHT");
>+            Log.v(LOGTAG, "Disabling SENSOR_LIGHT");

>-            Log.i(LOGTAG, "Disabling SENSOR_LINEAR_ACCELERATION");
>+            Log.v(LOGTAG, "Disabling SENSOR_LINEAR_ACCELERATION");

>-            Log.i(LOGTAG, "Disabling SENSOR_GYROSCOPE");
>+            Log.v(LOGTAG, "Disabling SENSOR_GYROSCOPE");

Let's remove these too

>     static void scheduleRestart() {
>-        Log.i(LOGTAG, "scheduling restart");
>+        Log.v(LOGTAG, "Scheduling restart.");

Remove

>     public static void addPluginView(View view,

>-        Log.i(LOGTAG, "addPluginView:" + view + " @ x:" + x + " y:" + y + " w:" + w + " h:" + h + " fullscreen: " + isFullScreen);
>+        Log.d(LOGTAG, "addPluginView:" + view + " @ x:" + x + " y:" + y + " w:" + w + " h:" + h + " fullscreen: " + isFullScreen);

>     public static void removePluginView(View view, boolean isFullScreen) {
>-        Log.i(LOGTAG, "removePluginView:" + view + " fullscreen: " + isFullScreen);
>+        Log.d(LOGTAG, "removePluginView:" + view + " fullscreen: " + isFullScreen);
>         GeckoApp.mAppContext.removePluginView(view, isFullScreen);
>     }
> 
>     public static Class<?> loadPluginClass(String className, String libName) {
>-        Log.i(LOGTAG, "in loadPluginClass... attempting to access className, then libName.....");
>-        Log.i(LOGTAG, "className: " + className);
>-        Log.i(LOGTAG, "libName: " + libName);
>-
>+        Log.d(LOGTAG, "loadPluginClass(" + className + ", " + libName + ")");

Tempted to remove these. Seem like something we only want while debugging the app locally.
[Update: after reviewing the patch, let's remove these too]

>     static int[] initCamera(String aContentType, int aCamera, int aWidth, int aHeight) {
>-        Log.i(LOGTAG, "initCamera(" + aContentType + ", " + aWidth + "x" + aHeight + ") on thread " + Thread.currentThread().getId());
>+        Log.d(LOGTAG, "initCamera(" + aContentType + ", " + aWidth + "x" + aHeight + ") on thread " + Thread.currentThread().getId());

Same temptation. [Update: Remove]

>-            Log.i(LOGTAG, "Camera: " + params.getPreviewSize().width + "x" + params.getPreviewSize().height +
>+            Log.v(LOGTAG, "Camera: " + params.getPreviewSize().width + "x" + params.getPreviewSize().height +

More of the same.  [Update: Remove]

>     static synchronized void closeCamera() {
>-        Log.i(LOGTAG, "closeCamera() on thread " + Thread.currentThread().getId());
>+        Log.d(LOGTAG, "closeCamera() on thread " + Thread.currentThread().getId());

More (why do we do this kind of output?).  [Update: Remove]

>diff --git a/mobile/android/base/Tabs.java b/mobile/android/base/Tabs.java

>-        Log.i(LOGTAG, "Added a tab with id: " + id);
>+        Log.d(LOGTAG, "Added a tab with id: " + id);

Remove

>-            Log.i(LOGTAG, "Removed a tab with id: " + id);
>+            Log.d(LOGTAG, "Removed a tab with id: " + id);

Remove

>     public void handleMessage(String event, JSONObject message) {
>-        Log.i(LOGTAG, "Got message: " + event);
>+        Log.d(LOGTAG, "Got message: " + event);

Remove

>diff --git a/mobile/android/base/gfx/LayerView.java b/mobile/android/base/gfx/LayerView.java

>     public void setPaintState(int paintState) {
>-        Log.d(LOGTAG, "LayerView paint state set to " + paintState);
>+        Log.v(LOGTAG, "LayerView paint state set to " + paintState);

Remove
Attachment #674771 - Flags: review?(mark.finkle) → review+
You need to log in before you can comment on or make changes to this bug.