include service delay stats for DEBUG builds

A start at determining of often there's a problem with Service not
scheduling work quickly enough.

xwords4/android/app/src/main/java/org/eehouse/android/xw4/BTService.java

@@ -88,7 +88,8 @@ public class BTService extends XWJIService {
 
     private final static int sJobID = 218719979;
     static {
-        XWJIService.register( BTService.class, sJobID );
+        XWJIService.register( BTService.class, sJobID,
+                              CommsConnType.COMMS_CONN_BT );
     }
 
     // half minute for testing; maybe 15 on ship? Or make it a debug config.

xwords4/android/app/src/main/java/org/eehouse/android/xw4/ConnStatusHandler.java

@@ -37,13 +37,16 @@ import org.eehouse.android.xw4.jni.CommsAddrRec;
 import org.eehouse.android.xw4.jni.XwJNI;
 import org.eehouse.android.xw4.loc.LocUtils;
 
+import java.util.ArrayList;
 import java.util.HashMap;
 import java.util.Iterator;
+import java.util.List;
 import java.util.Map;
 
 public class ConnStatusHandler {
     private static final String TAG = ConnStatusHandler.class.getSimpleName();
     private static final String RECS_KEY = TAG + "/recs";
+    private static final String STALL_STATS_KEY = TAG + "/stall_stats";
 
     public interface ConnStatusCBacks {
         public void invalidateParent();
@@ -214,6 +217,13 @@ public class ConnStatusHandler {
                     } else {
                         sb.append( LocUtils.getString( context, R.string.connstat_noreceipt) );
                     }
+
+                    if ( BuildConfig.DEBUG ) {
+                        String stallStats = stallStatsFor( context, typ );
+                        if ( null != stallStats ) {
+                            sb.append( stallStats );
+                        }
+                    }
                 }
             }
             msg = sb.toString();
@@ -221,6 +231,95 @@ public class ConnStatusHandler {
         return msg;
     }
 
+    private static class StallStats implements java.io.Serializable {
+        private static final int MAX_STALL_DATA_LEN = 100;
+        long[] mData = new long[MAX_STALL_DATA_LEN];
+        long[] mStamps = new long[MAX_STALL_DATA_LEN];
+        int mUsed = 0;          // <= MAX_STALL_DATA_LEN
+
+        private static HashMap<CommsConnType, StallStats> sStallStatsMap;
+
+        static StallStats get( Context context, CommsConnType typ )
+        {
+            if ( null == sStallStatsMap ) {
+                sStallStatsMap = (HashMap<CommsConnType, StallStats>)DBUtils
+                    .getSerializableFor( context, STALL_STATS_KEY );
+                if ( null == sStallStatsMap ) {
+                    sStallStatsMap = new HashMap<>();
+                }
+            }
+
+            StallStats result = sStallStatsMap.get( typ );
+            if ( result == null ) {
+                result = new StallStats();
+                sStallStatsMap.put( typ, result );
+            }
+            return result;
+        }
+
+        private static void save( Context context )
+        {
+            DBUtils.setSerializableFor( context, STALL_STATS_KEY, sStallStatsMap );
+        }
+
+        synchronized void append( Context context, long ageMS )
+        {
+            if ( MAX_STALL_DATA_LEN == mUsed ) {
+                --mUsed;
+                System.arraycopy( mData, 1, mData, 0, mUsed );
+                System.arraycopy( mStamps, 1, mStamps, 0, mUsed );
+            }
+            mData[mUsed] = ageMS;
+            mStamps[mUsed] = System.currentTimeMillis();
+            ++mUsed;
+
+            save( context );
+        }
+
+        synchronized String toString( Context context )
+        {
+            StringBuffer sb = new StringBuffer()
+                .append("\n\nService delay stats:\n");
+            if ( mUsed > 0 ) {
+                long dataSum10 = 0;
+                long dataSum100 = 0;
+                final int last10Indx = Math.max( 0, mUsed - 10 );
+                for ( int ii = 0; ii < mUsed; ++ii ) {
+                    long datum = mData[ii];
+                    dataSum100 += datum;
+                    if ( ii >= last10Indx ) {
+                        dataSum10 += datum;
+                    }
+                }
+
+                long firstStamp100 = mStamps[0];
+                long firstStamp10 = mStamps[last10Indx];
+
+                int num = Math.min(10, mUsed);
+                append( context, sb, num, dataSum10 / num, firstStamp10 );
+                append( context, sb, mUsed, dataSum100 / mUsed, firstStamp100 );
+            }
+            return sb.toString();
+        }
+
+        private void append( Context context, StringBuffer sb, int len, long avg, long stamp )
+        {
+            sb.append( String.format( "For last %d: %dms avg. (oldest: %s)\n", len, avg,
+                                      DateUtils.getRelativeDateTimeString( context, stamp,
+                                                                           DateUtils.SECOND_IN_MILLIS,
+                                                                           DateUtils.HOUR_IN_MILLIS,
+                                                                           0 ) ) );
+        }
+    }
+
+    private static String stallStatsFor( Context context, CommsConnType typ )
+    {
+        // long[] nums = StallStats.get( context, typ ).averages();
+        // return "Average for last 10 Intents (spanning %s): %dms";;
+        StallStats stats = StallStats.get( context, typ );
+        return stats == null ? null : stats.toString( context );
+    }
+
     private static void invalidateParent()
     {
         if ( null != s_cbacks ) {
@@ -286,6 +385,20 @@ public class ConnStatusHandler {
         showSuccessOut( s_cbacks );
     }
 
+    // public static void noteStall( CommsConnType connType, long ageMS )
+    // {
+    //     Log.d( TAG, "noteStall(%s, age=%s)", connType, age / 1000 );
+
+    //     StallStats
+    // }
+
+    public static void noteIntentHandled( Context context, CommsConnType connType,
+                                          long ageMS )
+    {
+        // Log.d( TAG, "noteIntentHandled(%s, ageMS=%d)", connType, ageMS );
+        StallStats.get( context, connType ).append( context, ageMS );
+    }
+
     public static void draw( Context context, Canvas canvas, Resources res,
                              CommsConnTypeSet connTypes, boolean isSolo )
     {

xwords4/android/app/src/main/java/org/eehouse/android/xw4/RelayService.java

@@ -80,7 +80,8 @@ public class RelayService extends XWJIService
     // and found older jobs in the JobIntentService's work queue.
     private final static int sJobID = 218719978;
     static {
-        XWJIService.register( RelayService.class, sJobID );
+        XWJIService.register( RelayService.class, sJobID,
+                              CommsConnType.COMMS_CONN_RELAY );
     }
 
     // One day, in seconds.  Probably should be configurable.

xwords4/android/app/src/main/java/org/eehouse/android/xw4/Utils.java

@@ -320,6 +320,14 @@ public class Utils {
         }
     }
 
+    // If the OS starts delivering Intents before the user notices the
+    // notification, remove it. PENDING: should I replace it with something
+    // that tells how long the stall was?
+    public static void clearStallNotification( Context context, long age )
+    {
+        cancelNotification( context, R.string.notify_stall_title );
+    }
+
     public static void cancelNotification( Context context, int id )
     {
         NotificationManager nm = (NotificationManager)

xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWJIService.java

@@ -20,7 +20,6 @@
 
 package org.eehouse.android.xw4;
 
-
 import android.content.Context;
 import android.content.Intent;
 import android.os.Bundle;
@@ -34,6 +33,8 @@ import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
 
+import org.eehouse.android.xw4.jni.CommsAddrRec.CommsConnType;
+
 abstract class XWJIService extends JobIntentService {
     private static final String TAG = XWJIService.class.getSimpleName();
     private static final boolean LOG_INTENT_COUNTS = false;
@@ -50,22 +51,25 @@ abstract class XWJIService extends JobIntentService {
     abstract XWJICmds[] getCmds();
 
     private static Map<Class, Integer> sJobIDs = new HashMap<>();
-    static void register( Class clazz, int jobID ) {
+    private static Map<Class, CommsConnType> sTypes = new HashMap<>();
+    static void register( Class clazz, int jobID, CommsConnType typ )
+    {
         sJobIDs.put( clazz, jobID );
+        sTypes.put( clazz, typ );
     }
     
     @Override
     public final void onHandleWork( Intent intent )
     {
-        forget( this, getClass(), intent );
-
         long timestamp = getTimestamp(intent);
+        long ageMS = System.currentTimeMillis() - timestamp;
+        forget( this, getClass(), intent, ageMS );
+
         XWJICmds cmd = cmdFrom( intent );
         if ( LOG_PACKETS ) {
             Log.d( getClass().getSimpleName(),
                    "onHandleWork(): cmd=%s; age=%dms; threadCount: %d)",
-                   cmd, System.currentTimeMillis() - timestamp,
+                   cmd, ageMS, Thread.activeCount() );
-                   Thread.activeCount() );
         }
 
         onHandleWorkImpl( intent, cmd, timestamp );
@@ -75,7 +79,7 @@ abstract class XWJIService extends JobIntentService {
     {
         remember( context, clazz, intent );
         enqueueWork( context, clazz, sJobIDs.get(clazz), intent );
-        checkForStall( context );
+        checkForStall( context, clazz );
     }
 
     static XWJICmds cmdFrom( Intent intent, XWJICmds[] values )
@@ -123,7 +127,7 @@ abstract class XWJIService extends JobIntentService {
     }
 
     private static final long AGE_THRESHOLD_MS = 1000 * 60; // one minute to start
-    private static void checkForStall( Context context )
+    private static void checkForStall( Context context, Class clazz )
     {
         if ( stallCheckEnabled( context ) ) {
             long now = System.currentTimeMillis();
@@ -143,12 +147,15 @@ abstract class XWJIService extends JobIntentService {
             }
 
             if ( maxAge > AGE_THRESHOLD_MS ) {
+                // ConnStatusHandler.noteStall( sTypes.get( clazz ), maxAge );
                 Utils.showStallNotification( context, maxAge );
             }
         }
     }
 
-    private static void forget( Context context, Class clazz, Intent intent )
+    // Called when an intent is successfully delivered
+    private static void forget( Context context, Class clazz,
+                                Intent intent, long ageMS )
     {
         if ( stallCheckEnabled( context ) ) {
             String name = clazz.getSimpleName();
@@ -177,6 +184,9 @@ abstract class XWJIService extends JobIntentService {
                     }
                 }
             }
+
+            ConnStatusHandler.noteIntentHandled( context, sTypes.get( clazz ), ageMS );
+            Utils.clearStallNotification( context, ageMS );
         }
     }