include service delay stats for DEBUG builds

A start at determining of often there's a problem with Service not
scheduling work quickly enough.
This commit is contained in:
Eric House 2019-06-10 18:19:32 -07:00
parent 896d63bc48
commit a8c45ee0ae
5 changed files with 144 additions and 11 deletions

View file

@ -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.

View file

@ -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 )
{

View file

@ -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.

View file

@ -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)

View file

@ -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,
Thread.activeCount() );
cmd, ageMS, 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 );
}
}