Reduce logging, dump stacks before wtf().
Jeff Sharkey [Mon, 25 Mar 2013 20:54:29 +0000 (13:54 -0700)]
Most wtf() are looking like network timeouts, not threading bugs, so
disable verbose debugging and add more targeted thread logging before
calling wtf().

Bug: 8233041
Change-Id: I8e276bffd7880cfe13b65e7e81f5507cab627692

src/com/android/providers/downloads/DownloadInfo.java
src/com/android/providers/downloads/DownloadNotifier.java
src/com/android/providers/downloads/DownloadService.java

index e6ed059..7a912d5 100644 (file)
@@ -247,7 +247,10 @@ public class DownloadInfo {
      * {@link #startDownloadIfReady(ExecutorService)}.
      */
     @GuardedBy("this")
-    private Future<?> mActiveDownload;
+    private Future<?> mSubmittedTask;
+
+    @GuardedBy("this")
+    private DownloadThread mTask;
 
     private final Context mContext;
     private final SystemFacade mSystemFacade;
@@ -455,7 +458,7 @@ public class DownloadInfo {
     public boolean startDownloadIfReady(ExecutorService executor) {
         synchronized (this) {
             final boolean isReady = isReadyToDownload();
-            final boolean isActive = mActiveDownload != null && !mActiveDownload.isDone();
+            final boolean isActive = mSubmittedTask != null && !mSubmittedTask.isDone();
             if (isReady && !isActive) {
                 if (mStatus != Impl.STATUS_RUNNING) {
                     mStatus = Impl.STATUS_RUNNING;
@@ -464,9 +467,9 @@ public class DownloadInfo {
                     mContext.getContentResolver().update(getAllDownloadsUri(), values, null, null);
                 }
 
-                final DownloadThread task = new DownloadThread(
+                mTask = new DownloadThread(
                         mContext, mSystemFacade, this, mStorageManager, mNotifier);
-                mActiveDownload = executor.submit(task);
+                mSubmittedTask = executor.submit(mTask);
             }
             return isReady;
         }
index 0af9cb8..f832eae 100644 (file)
@@ -20,6 +20,7 @@ import static android.app.DownloadManager.Request.VISIBILITY_VISIBLE;
 import static android.app.DownloadManager.Request.VISIBILITY_VISIBLE_NOTIFY_COMPLETED;
 import static android.app.DownloadManager.Request.VISIBILITY_VISIBLE_NOTIFY_ONLY_COMPLETION;
 import static android.provider.Downloads.Impl.STATUS_RUNNING;
+import static com.android.providers.downloads.Constants.TAG;
 
 import android.app.DownloadManager;
 import android.app.Notification;
@@ -30,9 +31,11 @@ import android.content.Context;
 import android.content.Intent;
 import android.content.res.Resources;
 import android.net.Uri;
+import android.os.SystemClock;
 import android.provider.Downloads;
 import android.text.TextUtils;
 import android.text.format.DateUtils;
+import android.util.Log;
 import android.util.LongSparseLongArray;
 
 import com.google.common.collect.ArrayListMultimap;
@@ -75,6 +78,13 @@ public class DownloadNotifier {
     @GuardedBy("mDownloadSpeed")
     private final LongSparseLongArray mDownloadSpeed = new LongSparseLongArray();
 
+    /**
+     * Last time speed was reproted, mapped from {@link DownloadInfo#mId} to
+     * {@link SystemClock#elapsedRealtime()}.
+     */
+    @GuardedBy("mDownloadSpeed")
+    private final LongSparseLongArray mDownloadTouch = new LongSparseLongArray();
+
     public DownloadNotifier(Context context) {
         mContext = context;
         mNotifManager = (NotificationManager) context.getSystemService(
@@ -86,15 +96,17 @@ public class DownloadNotifier {
     }
 
     /**
-     * Notify the current speed of an active download, used for calcuating
+     * Notify the current speed of an active download, used for calculating
      * estimated remaining time.
      */
     public void notifyDownloadSpeed(long id, long bytesPerSecond) {
         synchronized (mDownloadSpeed) {
             if (bytesPerSecond != 0) {
                 mDownloadSpeed.put(id, bytesPerSecond);
+                mDownloadTouch.put(id, SystemClock.elapsedRealtime());
             } else {
                 mDownloadSpeed.delete(id);
+                mDownloadTouch.delete(id);
             }
         }
     }
@@ -302,6 +314,17 @@ public class DownloadNotifier {
         return ids;
     }
 
+    public void dumpSpeeds() {
+        synchronized (mDownloadSpeed) {
+            for (int i = 0; i < mDownloadSpeed.size(); i++) {
+                final long id = mDownloadSpeed.keyAt(i);
+                final long delta = SystemClock.elapsedRealtime() - mDownloadTouch.get(id);
+                Log.d(TAG, "Download " + id + " speed " + mDownloadSpeed.valueAt(i) + "bps, "
+                        + delta + "ms ago");
+            }
+        }
+    }
+
     /**
      * Build tag used for collapsing several {@link DownloadInfo} into a single
      * {@link Notification}.
index 0764109..6c61193 100644 (file)
@@ -49,6 +49,7 @@ import com.google.common.collect.Sets;
 import java.io.File;
 import java.io.FileDescriptor;
 import java.io.PrintWriter;
+import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
 import java.util.Map;
@@ -71,7 +72,7 @@ public class DownloadService extends Service {
     // TODO: migrate WakeLock from individual DownloadThreads out into
     // DownloadReceiver to protect our entire workflow.
 
-    private static final boolean DEBUG_LIFECYCLE = true;
+    private static final boolean DEBUG_LIFECYCLE = false;
 
     @VisibleForTesting
     SystemFacade mSystemFacade;
@@ -237,6 +238,17 @@ public class DownloadService extends Service {
             }
 
             if (msg.what == MSG_FINAL_UPDATE) {
+                // Dump thread stacks belonging to pool
+                for (Map.Entry<Thread, StackTraceElement[]> entry :
+                        Thread.getAllStackTraces().entrySet()) {
+                    if (entry.getKey().getName().startsWith("pool")) {
+                        Log.d(TAG, entry.getKey() + ": " + Arrays.toString(entry.getValue()));
+                    }
+                }
+
+                // Dump speed and update details
+                mNotifier.dumpSpeeds();
+
                 Log.wtf(TAG, "Final update pass triggered, isActive=" + isActive
                         + "; someone didn't update correctly.");
             }