From 0cd3be26681e98096302f37d0ae6938afafb7038 Mon Sep 17 00:00:00 2001 From: Eric House Date: Mon, 7 Feb 2022 12:53:17 -0800 Subject: [PATCH] switch to a single alarm and job for all timers Main goal is to not fire RelayService timer when mqtt timer fires and there are not any active relay games at all. Adds new class that keeps a timer for each client, sets the closest each time, and dispatches only that one. --- .../android/app/src/main/AndroidManifest.xml | 8 +- .../java/org/eehouse/android/xw4/BTUtils.java | 31 +- .../org/eehouse/android/xw4/DlgDelegate.java | 5 +- .../android/xw4/GamesListDelegate.java | 14 + .../org/eehouse/android/xw4/MQTTUtils.java | 33 +- .../eehouse/android/xw4/NagTurnReceiver.java | 44 +- .../eehouse/android/xw4/OnBootReceiver.java | 3 +- .../org/eehouse/android/xw4/RelayService.java | 55 +- .../android/xw4/SMSResendReceiver.java | 73 ++- .../eehouse/android/xw4/TimerJobReceiver.java | 70 +++ .../eehouse/android/xw4/TimerReceiver.java | 498 ++++++++++++++++-- .../java/org/eehouse/android/xw4/XWApp.java | 4 - .../app/src/main/res/menu/games_list_menu.xml | 3 + .../app/src/main/res/values/strings.xml | 4 + 14 files changed, 726 insertions(+), 119 deletions(-) create mode 100644 xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerJobReceiver.java diff --git a/xwords4/android/app/src/main/AndroidManifest.xml b/xwords4/android/app/src/main/AndroidManifest.xml index ffeec7d38..235ec8aac 100644 --- a/xwords4/android/app/src/main/AndroidManifest.xml +++ b/xwords4/android/app/src/main/AndroidManifest.xml @@ -126,8 +126,6 @@ - - @@ -188,5 +186,11 @@ android:resource="@xml/apduservice"/> + + + diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/BTUtils.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/BTUtils.java index f8a2b0d4c..71faa315c 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/BTUtils.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/BTUtils.java @@ -64,6 +64,9 @@ public class BTUtils { private static final int MAX_PACKET_LEN = 4 * 1024; private static final int CONNECT_SLEEP_MS = 2500; private static final String KEY_OWN_MAC = TAG + ":own_mac"; + private static final long MIN_BACKOFF = 1000 * 60 * 2; // 2 minutes + private static final long MAX_BACKOFF = 1000 * 60 * 60 * 4; // 4 hours, to test + private static Set sListeners = new HashSet<>(); private static Map sSenders = new HashMap<>(); private static Map s_namesToAddrs; @@ -103,6 +106,30 @@ public class BTUtils { private static String sAppName; private static UUID sUUID; + private static TimerReceiver.TimerCallback sTimerCallbacks + = new TimerReceiver.TimerCallback() { + @Override + public void timerFired( Context context ) + { + Log.d( TAG, "timerFired()" ); + BTUtils.timerFired( context ); + } + + @Override + public long incrementBackoff( long backoff ) + { + if ( backoff < MIN_BACKOFF ) { + backoff = MIN_BACKOFF; + } else { + backoff = backoff * 150 / 100; + } + if ( MAX_BACKOFF <= backoff ) { + backoff = MAX_BACKOFF; + } + return backoff; + } + }; + public static boolean BTAvailable() { BluetoothAdapter adapter = BluetoothAdapter.getDefaultAdapter(); @@ -161,7 +188,7 @@ public class BTUtils { onResume( context ); } - static void timerFired( Context context ) + private static void timerFired( Context context ) { onResume( context ); } @@ -1310,7 +1337,7 @@ public class BTUtils { BTInviteDelegate.onHeardFromDev( socket.getRemoteDevice() ); parsePacket( proto, inStream, socket ); updateStatusIn( true ); - TimerReceiver.restartBackoff( getContext() ); + TimerReceiver.setBackoff( getContext(), sTimerCallbacks, MIN_BACKOFF ); // nBadCount = 0; } else { writeBack( socket, BTCmd.BAD_PROTO ); diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java index 7016bf1df..465150d45 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java @@ -58,6 +58,7 @@ public class DlgDelegate { LAUNCH_THEME_CONFIG, SEND_LOGS, OPEN_BYOD_DICT, + CLEAR_INT_STATS, // debug only // BoardDelegate UNDO_LAST_ACTION, @@ -415,14 +416,14 @@ public class DlgDelegate { m_dlgt.show( state ); } + // Get rid of this? public void doSyncMenuitem() { Log.d( TAG, "doSyncMenuitem()" ); if ( null == DBUtils.getRelayIDs( m_activity, null ) ) { makeOkOnlyBuilder( R.string.no_games_to_refresh ).show(); } else { - RelayService.timerFired( m_activity ); - MQTTUtils.timerFired( m_activity ); + TimerReceiver.allTimersFired( m_activity ); Utils.showToast( m_activity, R.string.msgs_progress ); } } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java index f17fbf51d..bd2b690ab 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java @@ -1554,6 +1554,10 @@ public class GamesListDelegate extends ListDelegateBase Utils.emailLogFile( m_activity, logLoc ); break; + case CLEAR_INT_STATS: + TimerReceiver.clearStats( m_activity ); + break; + case OPEN_BYOD_DICT: DictBrowseDelegate.launch( getDelegator(), (String)params[0] ); break; @@ -1719,6 +1723,9 @@ public class GamesListDelegate extends ListDelegateBase 0 < DBUtils.getGamesWithSendsPending( m_activity ).size(); Utils.setItemVisible( menu, R.id.games_menu_resend, enable ); + Utils.setItemVisible( menu, R.id.games_menu_timerStats, + BuildConfig.NON_RELEASE ); + enable = Log.getStoreLogs(); Utils.setItemVisible( menu, R.id.games_menu_enableLogStorage, !enable ); Utils.setItemVisible( menu, R.id.games_menu_disableLogStorage, enable ); @@ -1778,6 +1785,7 @@ public class GamesListDelegate extends ListDelegateBase DictsDelegate.start( getDelegator() ); break; + // Get rid of this??? case R.id.games_menu_checkmoves: makeNotAgainBuilder( R.string.not_again_sync, R.string.key_notagain_sync, @@ -1829,6 +1837,12 @@ public class GamesListDelegate extends ListDelegateBase Utils.gitInfoToClip( m_activity ); break; + case R.id.games_menu_timerStats: + makeOkOnlyBuilder( TimerReceiver.statsStr( m_activity ) ) + .setActionPair( Action.CLEAR_INT_STATS, R.string.button_clear_stats ) + .show(); + break; + case R.id.games_menu_enableLogStorage: Log.setStoreLogs( true ); break; diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/MQTTUtils.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/MQTTUtils.java index 7c63c400b..0e794a249 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/MQTTUtils.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/MQTTUtils.java @@ -55,6 +55,9 @@ public class MQTTUtils extends Thread implements IMqttActionListener, MqttCallba private static enum State { NONE, CONNECTING, CONNECTED, SUBSCRIBING, SUBSCRIBED, CLOSING }; + private static final long MIN_BACKOFF = 1000 * 60 * 2; // 2 minutes + private static final long MAX_BACKOFF = 1000 * 60 * 60 * 4; // 4 hours, to test + private static MQTTUtils[] sInstance = {null}; private static long sNextReg = 0; private static String sLastRev = null; @@ -68,6 +71,30 @@ public class MQTTUtils extends Thread implements IMqttActionListener, MqttCallba private boolean mShouldExit = false; private State mState = State.NONE; + private static TimerReceiver.TimerCallback sTimerCallbacks + = new TimerReceiver.TimerCallback() { + @Override + public void timerFired( Context context ) + { + Log.d( TAG, "timerFired()" ); + MQTTUtils.timerFired( context ); + } + + @Override + public long incrementBackoff( long backoff ) + { + if ( backoff < MIN_BACKOFF ) { + backoff = MIN_BACKOFF; + } else { + backoff = backoff * 150 / 100; + } + if ( MAX_BACKOFF <= backoff ) { + backoff = MAX_BACKOFF; + } + return backoff; + } + }; + public static void init( Context context ) { Log.d( TAG, "init(OFFER_MQTT:%b)", BuildConfig.OFFER_MQTT ); @@ -87,7 +114,7 @@ public class MQTTUtils extends Thread implements IMqttActionListener, MqttCallba getOrStart( context ); } - public static void timerFired( Context context ) + private static void timerFired( Context context ) { MQTTUtils instance; synchronized ( sInstance ) { @@ -542,7 +569,7 @@ public class MQTTUtils extends Thread implements IMqttActionListener, MqttCallba ConnStatusHandler .updateStatusIn( mContext, CommsConnType.COMMS_CONN_MQTT, true ); - TimerReceiver.restartBackoff( mContext ); + TimerReceiver.setBackoff( mContext, sTimerCallbacks, MIN_BACKOFF ); } @Override @@ -551,7 +578,7 @@ public class MQTTUtils extends Thread implements IMqttActionListener, MqttCallba Log.d( TAG, "%H.deliveryComplete(token=%s)", this, token ); ConnStatusHandler .updateStatusOut( mContext, CommsConnType.COMMS_CONN_MQTT, true ); - TimerReceiver.restartBackoff( mContext ); + TimerReceiver.setBackoff( mContext, sTimerCallbacks, MIN_BACKOFF ); } private void subscribe() diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/NagTurnReceiver.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/NagTurnReceiver.java index be3e125ee..cc728b60b 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/NagTurnReceiver.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/NagTurnReceiver.java @@ -1,6 +1,6 @@ /* -*- compile-command: "find-and-gradle.sh inXw4dDeb"; -*- */ /* - * Copyright 2010 by Eric House (xwords@eehouse.org). All rights + * Copyright 2010 - 2022 by Eric House (xwords@eehouse.org). All rights * reserved. * * This program is free software; you can redistribute it and/or @@ -20,9 +20,6 @@ package org.eehouse.android.xw4; -import android.app.AlarmManager; -import android.app.PendingIntent; -import android.content.BroadcastReceiver; import android.content.Context; import android.content.Intent; import android.text.TextUtils; @@ -36,10 +33,9 @@ import java.util.ArrayList; import java.util.Date; import java.util.Iterator; -public class NagTurnReceiver extends BroadcastReceiver { +public class NagTurnReceiver { private static final String TAG = NagTurnReceiver.class.getSimpleName(); - private static final long INTERVAL_MILLIS = 1000 * 30; // every half minute for now private static final long[] NAG_INTERVAL_SECONDS = {// 2*60, // two minutes (for testing) // 5*60, // 10*60, @@ -57,16 +53,31 @@ public class NagTurnReceiver extends BroadcastReceiver { private static Boolean s_nagsDisabledNet = null; private static Boolean s_nagsDisabledSolo = null; - @Override - public void onReceive( Context context, Intent intent ) + private static TimerReceiver.TimerCallback sTimerCallbacks + = new TimerReceiver.TimerCallback() { + @Override + public void timerFired( Context context ) + { + NagTurnReceiver.timerFired( context ); + } + + @Override + public long incrementBackoff( long prevBackoff ) + { + Assert.failDbg(); + return 0; + } + }; + + private static void timerFired( Context context ) { // loop through all games testing who's been sitting on a turn if ( !getNagsDisabled( context ) ) { NeedsNagInfo[] needNagging = DBUtils.getNeedNagging( context ); if ( null != needNagging ) { - long now = new Date().getTime(); // in milliseconds + long now = System.currentTimeMillis(); for ( NeedsNagInfo info : needNagging ) { - Assert.assertTrue( info.m_nextNag < now ); + Assert.assertTrueNR( info.m_nextNag < now ); // Skip processing if notifications disabled for this type // of game @@ -116,17 +127,10 @@ public class NagTurnReceiver extends BroadcastReceiver { setNagTimer( context ); } - private static void restartTimer( Context context, long atMillis ) + private static void restartTimer( Context context, long fireTimeMS ) { if ( !getNagsDisabled( context ) ) { - AlarmManager am = - (AlarmManager)context.getSystemService( Context.ALARM_SERVICE ); - - Intent intent = new Intent( context, NagTurnReceiver.class ); - PendingIntent pi = PendingIntent.getBroadcast( context, 0, intent, 0 ); - - long now = new Date().getTime(); // in milliseconds - am.set( AlarmManager.RTC, atMillis, pi ); + TimerReceiver.setTimer( context, sTimerCallbacks, fireTimeMS ); } } @@ -143,7 +147,7 @@ public class NagTurnReceiver extends BroadcastReceiver { public static long figureNextNag( Context context, long moveTimeMillis ) { long result = 0; - long now = new Date().getTime(); // in milliseconds + long now = System.currentTimeMillis(); if ( now >= moveTimeMillis ) { long[] intervals = getIntervals( context ); for ( long nSecs : intervals ) { diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/OnBootReceiver.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/OnBootReceiver.java index 43306abf9..96782de5f 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/OnBootReceiver.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/OnBootReceiver.java @@ -44,8 +44,7 @@ public class OnBootReceiver extends BroadcastReceiver { protected static void startTimers( Context context ) { + // should use TimerReceiver too (PENDING) NagTurnReceiver.restartTimer( context ); - TimerReceiver.setTimer( context, true ); - SMSResendReceiver.setTimer( context ); } } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/RelayService.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/RelayService.java index 7107d04f0..4a47a3963 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/RelayService.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/RelayService.java @@ -72,6 +72,9 @@ public class RelayService extends XWJIService private static final int INITIAL_BACKOFF = 5; private static final int UDP_FAIL_LIMIT = 5; + private static final long MIN_BACKOFF = 1000 * 60 * 2; // 2 minutes + private static final long MAX_BACKOFF = 1000 * 60 * 60 * 23; // 23 hours + // Must use the same jobID for all work enqueued for the same class. I // used to use the class's hashCode(), but that's different each time the // app runs. I think I was getting failures when a new instance launched @@ -147,6 +150,29 @@ public class RelayService extends XWJIService ,XWPDEV_PROTO_VERSION_1 }; + private static TimerReceiver.TimerCallback sTimerCallbacks + = new TimerReceiver.TimerCallback() { + @Override + public void timerFired( Context context ) + { + Log.d( TAG, "timerFired()" ); + RelayService.timerFired( context ); + } + + @Override + public long incrementBackoff( long backoff ) + { + if ( backoff < MIN_BACKOFF ) { + backoff = MIN_BACKOFF; + } else { + backoff *= 2; + } + if ( MAX_BACKOFF <= backoff ) { + backoff = MAX_BACKOFF; + } + return backoff; + } + }; // Must be kept in sync with eponymous enum in xwrelay.h private enum XWRelayReg { XWPDEV_NONE, @@ -248,7 +274,7 @@ public class RelayService extends XWJIService enqueueWork( context, intent ); } - public static void timerFired( Context context ) + private static void timerFired( Context context ) { Intent intent = getIntentTo( context, MsgCmds.TIMER_FIRED ); enqueueWork( context, intent ); @@ -702,6 +728,7 @@ public class RelayService extends XWJIService DatagramSocket udpSocket = s_UDPSocket; if ( null != udpSocket && packets.size() > 0 ) { + boolean skipBackoffReset = true; // Log.d( TAG, "sendViaUDP(): sending %d at once", packets.size() ); final RelayService service = this; service.noteSent( packets, true ); @@ -733,6 +760,7 @@ public class RelayService extends XWJIService } catch ( NullPointerException npe ) { Log.w( TAG, "network problem; dropping packet" ); } + skipBackoffReset = skipBackoffReset && packet.mSkipBackoffReset; if ( breakNow ) { break; } @@ -743,6 +771,9 @@ public class RelayService extends XWJIService sentLen > 0 ); Log.d( TAG, "%s.sendViaUDP(): sent %d bytes (%d packets)", this, sentLen, packets.size() ); + if ( ! skipBackoffReset ) { + TimerReceiver.setBackoff( this, sTimerCallbacks, MIN_BACKOFF ); + } } return sentLen; @@ -764,7 +795,6 @@ public class RelayService extends XWJIService private boolean startFetchThreadIfNotUDP() { - // DbgUtils.logf( "startFetchThreadIfNotUDP()" ); boolean handled = XWPrefs.getRelayEnabled( this ) && !BuildConfig.UDP_ENABLED; if ( handled && null == m_fetchThread ) { Assert.failDbg(); // NOT using this now! @@ -779,6 +809,7 @@ public class RelayService extends XWJIService }, getClass().getName() ); m_fetchThread.start(); } + // Log.d( TAG, "startFetchThreadIfNotUDP() => %b", handled ); return handled; } @@ -981,7 +1012,7 @@ public class RelayService extends XWJIService private void gotPacket( DatagramPacket packet ) { ConnStatusHandler.showSuccessIn(); - TimerReceiver.restartBackoff( this ); + TimerReceiver.setBackoff( this, sTimerCallbacks, MIN_BACKOFF ); int packetLen = packet.getLength(); byte[] data = new byte[packetLen]; @@ -1045,7 +1076,7 @@ public class RelayService extends XWJIService writeVLIString( out, Build.VERSION.RELEASE ); out.writeShort( BuildConfig.VARIANT_CODE ); - postPacket( bas, XWRelayReg.XWPDEV_REG, timestamp ); + postPacket( bas, XWRelayReg.XWPDEV_REG, timestamp, true ); s_regStartTime = now; } catch ( IOException ioe ) { Log.ex( TAG, ioe ); @@ -1070,7 +1101,7 @@ public class RelayService extends XWJIService ByteArrayOutputStream bas = new ByteArrayOutputStream(); DataOutputStream out = new DataOutputStream( bas ); writeVLIString( out, devid ); - postPacket( bas, XWRelayReg.XWPDEV_RQSTMSGS, timestamp ); + postPacket( bas, XWRelayReg.XWPDEV_RQSTMSGS, timestamp, true ); } else { Log.d(TAG, "requestMessages(): devid is null" ); } @@ -1154,7 +1185,7 @@ public class RelayService extends XWJIService try { DataOutputStream out = new DataOutputStream( bas ); un2vli( header.m_packetID, out ); - postPacket( bas, XWRelayReg.XWPDEV_ACK, -1 ); + postPacket( bas, XWRelayReg.XWPDEV_ACK, -1, true ); } catch ( IOException ioe ) { Log.ex( TAG, ioe ); } @@ -1191,7 +1222,13 @@ public class RelayService extends XWJIService private void postPacket( ByteArrayOutputStream bas, XWRelayReg cmd, long timestamp ) { - PacketData packet = new PacketData( bas, cmd, timestamp ); + postPacket( bas, cmd, timestamp, false ); + } + + private void postPacket( ByteArrayOutputStream bas, XWRelayReg cmd, + long timestamp, boolean skipBackoffReset ) + { + PacketData packet = new PacketData( bas, cmd, timestamp, skipBackoffReset ); s_queue.add( packet ); // Log.d( TAG, "postPacket(%s); (now %d in queue)", packet, // s_queue.size() ); @@ -1766,16 +1803,18 @@ public class RelayService extends XWJIService private long m_requested; // when the request came into the static API private long m_created; // when this packet was created (to service request) private long m_sentUDP; + private boolean mSkipBackoffReset; private PacketData() {} public PacketData( ByteArrayOutputStream bas, XWRelayReg cmd, - long requestTS ) + long requestTS, boolean skipBackoffReset ) { m_bas = bas; m_cmd = cmd; m_requested = requestTS; m_created = System.currentTimeMillis(); + mSkipBackoffReset = skipBackoffReset; makeHeader(); } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/SMSResendReceiver.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/SMSResendReceiver.java index 91b564842..68a0deb7f 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/SMSResendReceiver.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/SMSResendReceiver.java @@ -20,12 +20,7 @@ package org.eehouse.android.xw4; -import android.app.AlarmManager; -import android.app.PendingIntent; -import android.content.BroadcastReceiver; import android.content.Context; -import android.content.Intent; -import android.os.SystemClock; import org.eehouse.android.xw4.jni.CommsAddrRec.CommsConnType; @@ -35,34 +30,45 @@ import org.eehouse.android.xw4.jni.CommsAddrRec.CommsConnType; * send SMS, so this class handles doing it on a timer. With backoff. */ -public class SMSResendReceiver extends BroadcastReceiver { +public class SMSResendReceiver { private static final String TAG = SMSResendReceiver.class.getSimpleName(); private static final String BACKOFF_KEY = TAG + "/backoff"; private static final int MIN_BACKOFF_SECONDS = 60 * 5; private static final int MAX_BACKOFF_SECONDS = 60 * 60 * 12; - @Override - public void onReceive( Context context, Intent intent ) - { - GameUtils.resendAllIf( context, CommsConnType.COMMS_CONN_SMS, true, - new GameUtils.ResendDoneProc() { - @Override - public void onResendDone( Context context, - int nSent ) { - int backoff = -1; - if ( 0 < nSent ) { - backoff = setTimer( context, true ); - } - if ( BuildConfig.DEBUG ) { - DbgUtils.showf( context, - "%d SMS msgs resent;" - + " backoff: %d", - nSent, backoff); - } - } - } ); - } + private static TimerReceiver.TimerCallback sTimerCallbacks + = new TimerReceiver.TimerCallback() { + @Override + public void timerFired( Context context ) + { + GameUtils.resendAllIf( context, CommsConnType.COMMS_CONN_SMS, true, + new GameUtils.ResendDoneProc() { + @Override + public void onResendDone( Context context, + int nSent ) { + int backoff = -1; + if ( 0 < nSent ) { + backoff = setTimer( context, true ); + } + if ( BuildConfig.NON_RELEASE ) { + DbgUtils.showf( context, + "%d SMS msgs resent;" + + " backoff: %d", + nSent, backoff); + } + } + } ); + + } + + @Override + public long incrementBackoff( long prevBackoff ) + { + Assert.failDbg(); + return 0; + } + }; static void resetTimer( Context context ) { @@ -70,20 +76,13 @@ public class SMSResendReceiver extends BroadcastReceiver { setTimer( context ); } - static int setTimer( Context context ) + private static int setTimer( Context context ) { return setTimer( context, false ); } private static int setTimer( Context context, boolean advance ) { - AlarmManager am = - (AlarmManager)context.getSystemService( Context.ALARM_SERVICE ); - - Intent intent = new Intent( context, SMSResendReceiver.class ); - PendingIntent pi = PendingIntent.getBroadcast( context, 0, intent, 0 ); - am.cancel( pi ); - int backoff = DBUtils.getIntFor( context, BACKOFF_KEY, MIN_BACKOFF_SECONDS ); if ( advance ) { backoff = Math.min( MAX_BACKOFF_SECONDS, backoff * 2 ); @@ -91,9 +90,7 @@ public class SMSResendReceiver extends BroadcastReceiver { } long millis = 1000L * backoff; - Log.d( TAG, "set for %d seconds from now", millis / 1000 ); - millis += SystemClock.elapsedRealtime(); - am.set( AlarmManager.ELAPSED_REALTIME, millis, pi ); + TimerReceiver.setTimerRelative( context, sTimerCallbacks, millis ); return backoff; } } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerJobReceiver.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerJobReceiver.java new file mode 100644 index 000000000..b9095f1ad --- /dev/null +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerJobReceiver.java @@ -0,0 +1,70 @@ +/* -*- compile-command: "find-and-gradle.sh inXw4dDeb"; -*- */ +/* + * Copyright 2022 by Eric House (xwords@eehouse.org). All rights reserved. + * + * This program is free software; you can redistribute it and/or + * modify it under the terms of the GNU General Public License as + * published by the Free Software Foundation; either version 2 of the + * License, or (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, but + * WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU + * General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program; if not, write to the Free Software + * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA. + */ + +package org.eehouse.android.xw4; + +import android.app.job.JobInfo; +import android.app.job.JobParameters; +import android.app.job.JobScheduler; +import android.app.job.JobService; +import android.content.ComponentName; +import android.content.Context; +import android.content.Intent; +import android.os.PersistableBundle; + +public class TimerJobReceiver extends JobService { + private static final String TAG = TimerJobReceiver.class.getSimpleName(); + private static final String KEY_TIMER_ID = "timerID"; + + @Override + public boolean onStartJob( JobParameters params ) + { + PersistableBundle bundle = params.getExtras(); + long timerID = bundle.getLong( KEY_TIMER_ID ); + Log.d( TAG, "onStartJob(%s)", params ); + TimerReceiver.jobTimerFired( this, timerID, TAG ); + + return false; // job is finished + } + + @Override + public boolean onStopJob(JobParameters params) + { + Assert.failDbg(); + return true; + } + + private static final int sJobId = BuildConfig.APPLICATION_ID.hashCode(); + static void setTimer( Context context, long delayMS, long timerID ) + { + Assert.assertTrueNR( 0 < delayMS ); + ComponentName jobService = new ComponentName( context, TimerJobReceiver.class ); + PersistableBundle bundle = new PersistableBundle(); + bundle.putLong( KEY_TIMER_ID, timerID ); + JobInfo job = new JobInfo.Builder( sJobId, jobService ) + .setPersisted( true ) + .setMinimumLatency( delayMS ) + .setExtras( bundle ) + .build(); + JobScheduler scheduler = (JobScheduler)context + .getSystemService(Context.JOB_SCHEDULER_SERVICE); + scheduler.schedule( job ); + Log.d( TAG, "setTimer(delayMS=%d, id=%d): SET", delayMS, timerID ); + } +} diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerReceiver.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerReceiver.java index c6c2de5ad..0b718ad2b 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerReceiver.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/TimerReceiver.java @@ -1,6 +1,6 @@ /* -*- compile-command: "find-and-gradle.sh inXw4dDeb"; -*- */ /* - * Copyright 2010 - 2020 by Eric House (xwords@eehouse.org). All rights + * Copyright 2010 - 2022 by Eric House (xwords@eehouse.org). All rights * reserved. * * This program is free software; you can redistribute it and/or @@ -25,66 +25,488 @@ import android.app.PendingIntent; import android.content.BroadcastReceiver; import android.content.Context; import android.content.Intent; +import android.os.Build; import android.os.SystemClock; +import android.text.TextUtils; + +import java.io.Serializable; +import java.text.SimpleDateFormat; +import java.util.ArrayList; +import java.util.Date; +import java.util.HashMap; +import java.util.HashSet; +import java.util.List; +import java.util.Map; +import java.util.Set; +import java.util.TreeMap; public class TimerReceiver extends BroadcastReceiver { private static final String TAG = TimerReceiver.class.getSimpleName(); - private static final String KEY_BACKOFF = TAG + "/backoff"; - private static final String KEY_NEXT_BACKOFF = TAG + "/next_backoff"; - private static final long MIN_BACKOFF = 1000 * 10; // 10 seconds - private static final long MAX_BACKOFF = 1000 * 60 * 60 * 23; // 23 hours + private static final String DATA_KEY = TAG + "/data"; + private static final String KEY_FIREWHEN = "FIREWHEN"; + private static final String KEY_BACKOFF = "BACKOFF"; + private static final String CLIENT_STATS = "stats"; + private static final String KEY_COUNT = "COUNT"; + private static final String KEY_NEXT_FIRE = "NEXTFIRE"; + private static final String KEY_NEXT_SPAN = "SPAN"; + private static final String KEY_WORST = "WORST"; + private static final String KEY_AVG_MISS = "AVG_MISS"; + private static final String KEY_AVG_SPAN = "AVG_SPAN"; + private static final long MIN_FUTURE = 2000L; + private static final String KEY_TIMER_ID = "timerID"; + + interface TimerCallback { + public void timerFired( Context context ); + public long incrementBackoff( long prevBackoff ); + } + + private interface WithData { + void withData( Data data ); + } + + private static class Data implements Serializable { + private Map> mFields; + private transient boolean mDirty = false; + private transient int mRefcount = 0; + + Data() { mFields = new HashMap<>(); } + + Data get() + { + ++mRefcount; + // Log.d( TAG, "get(): refcount now %d", mRefcount ); + return this; + } + + void put( Context context ) + { + Assert.assertTrueNR( 0 <= mRefcount ); + --mRefcount; + // Log.d( TAG, "put(): refcount now %d", mRefcount ); + if ( 0 == mRefcount && mDirty ) { + store( context, this ); + mDirty = false; + } + } + + Set clients() { return mFields.keySet(); } + + void remove( String client ) { + mFields.remove( client ); + mDirty = true; + Log.d( TAG, "remove(%s)", client ); + } + + void setFor( TimerCallback client, String key, long val ) + { + setFor( className(client), key, val ); + } + + void setFor( String client, String key, long val ) + { + if ( ! mFields.containsKey( client ) ) { + mFields.put( client, new HashMap() ); + } + Map map = mFields.get(client); + if ( !map.containsKey( key ) || val != map.get( key ) ) { + map.put( key, val ); + mDirty = true; + } + } + + long getFor( TimerCallback client, String key, long dflt ) + { + return getFor( className(client), key, dflt ); + } + + long getFor( String client, String key, long dflt ) + { + long result = dflt; + if ( mFields.containsKey( client ) ) { + Map map = mFields.get( client ); + if ( map.containsKey( key ) ) { + result = map.get( key ); + } + } + return result; + } + } + + // If it's a number > 30 years past Epoch, format it as a date + private static final SimpleDateFormat sFmt = new SimpleDateFormat("MMM dd HH:mm:ss "); + private static String fmtLong( long dateOrNum ) + { + String result; + if ( dateOrNum < 1000 * 60 * 60 * 24 * 365 * 30 ) { + result = String.format( "%d", dateOrNum ); + } else { + result = sFmt.format( new Date(dateOrNum) ); + } + return result; + } + + private static String toString( Data data ) + { + List all = new ArrayList<>(); + for ( String client : data.mFields.keySet() ) { + List ones = new ArrayList<>(); + Map map = data.mFields.get( client ); + for ( String key : map.keySet() ) { + ones.add( String.format("%s: %s", key, fmtLong(map.get( key ))) ); + } + String one = String.format("{%s}", TextUtils.join(", ", ones ) ); + all.add( String.format("%s: %s", getSimpleName(client), one ) ); + } + return String.format("{%s}", TextUtils.join(", ", all ) ); + } @Override - public void onReceive( Context context, Intent intent ) + public void onReceive( final Context context, Intent intent ) { - Log.d( TAG, "onReceive(intent=%s)", intent ); - RelayService.timerFired( context ); - MQTTUtils.timerFired( context ); - BTUtils.timerFired( context ); + long timerID = intent.getLongExtra( KEY_TIMER_ID, -1 ); + onReceiveImpl( context, timerID, TAG ); + } - long nextBackoff = DBUtils.getLongFor( context, KEY_BACKOFF, MIN_BACKOFF ); - if ( nextBackoff == MAX_BACKOFF ) { - // at max, so no change and nothing to save - } else { - nextBackoff *= 2; - if ( nextBackoff > MAX_BACKOFF ) { - nextBackoff = MAX_BACKOFF; + static void jobTimerFired( Context context, long timerID, String src ) + { + onReceiveImpl( context, timerID, src ); + } + + private static void onReceiveImpl( final Context context, + long timerID, String src ) + { + Log.d( TAG, "onReceiveImpl(timerID=%d, src=%s)", timerID, src ); + load( context, new WithData() { + @Override + public void withData( Data data ) { + updateStats( data ); + data.setFor( CLIENT_STATS, KEY_NEXT_FIRE, 0 ); + Set fired = fireExpiredTimers( context, data ); + incrementBackoffs( data, fired ); + setNextTimer( context, data ); + } + } ); + Log.d( TAG, "onReceiveImpl(timerID=%d, src=%s) DONE", timerID, src ); + } + + static String statsStr( Context context ) + { + final StringBuffer sb = new StringBuffer(); + if ( BuildConfig.NON_RELEASE ) { + load( context, new WithData() { + @Override + public void withData( Data data ) { + // TreeMap to sort by timer fire time + TreeMap tmpMap = new TreeMap<>(); + for ( String client: data.clients() ) { + long nextFire = data.getFor( client, KEY_FIREWHEN, 0 ); + if ( 0 != nextFire ) { + tmpMap.put( nextFire, client ); + } + } + sb.append("Next timers:\n"); + for ( Map.Entry entry: tmpMap.entrySet() ) { + sb.append( getSimpleName(entry.getValue())).append(": ") + .append(fmtLong(entry.getKey())) + .append("\n"); + } + + long count = data.getFor( CLIENT_STATS, KEY_COUNT, 0 ); + sb.append( "\nTimers fired: ").append(count).append("\n"); + if ( 0 < count ) { + long avgMiss = data.getFor( CLIENT_STATS, KEY_AVG_MISS, 0 ); + sb.append("Avg delay: ") + .append(String.format( "%.1fs\n", avgMiss/1000f)); + long worst = data.getFor( CLIENT_STATS, KEY_WORST, 0 ); + sb.append("Worst delay: ") + .append(String.format( "%.1fs\n", worst/1000f)); + long avgSpan = data.getFor( CLIENT_STATS, KEY_AVG_SPAN, 0 ); + sb.append("Avg interval: ").append((avgSpan+500)/1000).append("s\n"); + } + } + } ); + } + return sb.toString(); + } + + static void clearStats( Context context ) + { + load( context, new WithData() { + @Override + public void withData( Data data ) { + data.remove( CLIENT_STATS ); + } + } ); + } + + static void setBackoff( final Context context, final TimerCallback cback, + final long backoffMS ) + { + Log.d( TAG, "setBackoff(client=%s, backoff=%ds)", className(cback), backoffMS/1000 ); + load( context, new WithData() { + @Override + public void withData( Data data ) { + data.setFor( cback, KEY_BACKOFF, backoffMS ); + setTimer( context, data, backoffMS, true, cback ); + } + } ); + } + + // This one's public. Sets a one-time timer. Any backoff or re-set the + // client has to handle + static void setTimerRelative( final Context context, final TimerCallback cback, + final long waitMS ) + { + long fireMS = waitMS + System.currentTimeMillis(); + setTimer( context, cback, fireMS ); + } + + static void setTimer( final Context context, final TimerCallback cback, + final long fireMS ) + { + load( context, new WithData() { + @Override + public void withData( Data data ) { + data.setFor( cback, KEY_FIREWHEN, fireMS ); + setNextTimer( context, data ); + } + } ); + } + + static void allTimersFired( Context context ) + { + Set callbacks = getCallbacks( context ); + for ( TimerCallback callback : callbacks ) { + callback.timerFired( context ); + } + } + + static Map sCallbacks = new HashMap<>(); + private synchronized static Set getCallbacks( Context context ) + { + Set results = new HashSet<>(); + for ( TimerCallback callback : sCallbacks.values() ) { + results.add( callback ); + } + return results; + } + + private synchronized static TimerCallback getCallback( String client ) + { + TimerCallback callback; + try { + callback = sCallbacks.get( client ); + if ( null == callback ) { + Class clazz = Class.forName( client ); + callback = (TimerCallback)clazz.newInstance(); + sCallbacks.put( client, callback ); } - DBUtils.setLongFor( context, KEY_BACKOFF, nextBackoff ); + } catch ( Exception ex ) { + callback = null; + Log.ex( TAG, ex ); } - setTimer( context, nextBackoff, true ); + + return callback; } - static void restartBackoff( Context context ) + private static Set fireExpiredTimers( Context context, Data data ) { - DBUtils.setLongFor( context, KEY_BACKOFF, MIN_BACKOFF ); - setTimer( context, MIN_BACKOFF, false ); + Set clients = new HashSet<>(); + long now = System.currentTimeMillis(); + for ( String client: data.clients() ) { + long fireTime = data.getFor( client, KEY_FIREWHEN, 0 ); + // Assert.assertTrueNR( fireTime < now ); <- firing + if ( 0 != fireTime && fireTime <= now ) { + clients.add( client ); + Log.d( TAG, "fireExpiredTimers(): firing %s %d ms late", client, + now - fireTime ); + } + } + + Set callees = new HashSet<>(); + for ( String client : clients ) { + TimerCallback callback = getCallback( client ); + if ( null == callback ) { // class no longer exists + data.remove( client ); + } else { + data.setFor( client, KEY_FIREWHEN, 0 ); + callback.timerFired( context ); + callees.add( callback ); + } + } + + return callees; } - static void setTimer( Context context, boolean force ) + private static void incrementBackoffs( Data data, Set callbacks ) { - long backoff = DBUtils.getLongFor( context, KEY_BACKOFF, MIN_BACKOFF ); - setTimer( context, backoff, force ); + long now = System.currentTimeMillis(); + for ( TimerCallback callback: callbacks ) { + long backoff = data.getFor( callback, KEY_BACKOFF, 0 ); + if ( 0 != backoff ) { + backoff = callback.incrementBackoff( backoff ); + data.setFor( callback, KEY_BACKOFF, backoff ); + data.setFor( callback, KEY_FIREWHEN, now + backoff ); + } + } } - private synchronized static void setTimer( Context context, long backoff, boolean force ) + private static void setNextTimer( Context context, Data data ) { + long firstFireTime = Long.MAX_VALUE; + String firstClient = null; + long now = System.currentTimeMillis(); + for ( String client: data.clients() ) { + long fireTime = data.getFor( client, KEY_FIREWHEN, 0 ); + if ( 0 != fireTime ) { + // Log.d( TAG, "setNextTimer(): %s: %ds from now", getSimpleName(client), + // (fireTime - now)/1000 ); + if ( fireTime < firstFireTime ) { + firstFireTime = fireTime; + firstClient = client; + } + } + } + + if ( null != firstClient ) { + final long curNextFire = data.getFor( CLIENT_STATS, KEY_NEXT_FIRE, 0 ); + if ( 1000L < Math.abs( firstFireTime - curNextFire ) ) { + if ( firstFireTime - now < MIN_FUTURE ) { // Less than a 2 seconds in the future? + Log.d( TAG, "moving firstFireTime to the future: %s -> %s", + fmtLong(firstFireTime), fmtLong(now + MIN_FUTURE) ); + firstFireTime = now + MIN_FUTURE; + data.setFor( firstClient, KEY_FIREWHEN, firstFireTime ); + } + + long delayMS = firstFireTime - now; + data.setFor( CLIENT_STATS, KEY_NEXT_FIRE, firstFireTime ); + data.setFor( CLIENT_STATS, KEY_NEXT_SPAN, delayMS ); + long timerID = 1 + data.getFor( CLIENT_STATS, KEY_TIMER_ID, 0 ); + data.setFor( CLIENT_STATS, KEY_TIMER_ID, timerID ); + + AlarmManager am = + (AlarmManager)context.getSystemService( Context.ALARM_SERVICE ); + Intent intent = new Intent( context, TimerReceiver.class ); + intent.putExtra( KEY_TIMER_ID, timerID ); + PendingIntent pi = PendingIntent.getBroadcast( context, 0, intent, + PendingIntent.FLAG_CANCEL_CURRENT ); + am.set( AlarmManager.RTC_WAKEUP, firstFireTime, pi ); + + setJobTimerIf( context, delayMS, timerID ); + + Log.d( TAG, "setNextTimer(): SET id %d for %s at %s", timerID, + getSimpleName(firstClient), fmtLong(firstFireTime) ); + // } else { + // Assert.assertTrueNR( 0 != curNextFire ); + // long diff = Math.abs( firstFireTime - curNextFire ); + // Log.d( TAG, "not setting timer for %s: firstFireTime: %d," + // + " curNextFire: %d; diff: %d", + // getSimpleName(firstClient), firstFireTime, curNextFire, diff ); + } + } + } + + private static void setJobTimerIf(Context context, long delayMS, long timerID) + { + if ( Build.VERSION_CODES.LOLLIPOP <= Build.VERSION.SDK_INT ) { + TimerJobReceiver.setTimer( context, delayMS, timerID ); + } + } + + private static void setTimer( Context context, Data data, long backoff, + boolean force, TimerCallback cback ) + { + String client = className( cback ); if ( !force ) { - long curBackoff = DBUtils.getLongFor( context, KEY_NEXT_BACKOFF, MIN_BACKOFF ); - force = backoff != curBackoff; + long curBackoff = data.getFor( client, KEY_BACKOFF, backoff ); + long nextFire = data.getFor( client, KEY_FIREWHEN, 0 ); + force = 0 == nextFire || backoff != curBackoff; } + Log.d( TAG, "setTimer(clazz=%s, force=%b, curBackoff=%d)", + getSimpleName(client), force, backoff ); if ( force ) { - long now = SystemClock.elapsedRealtime(); + long now = System.currentTimeMillis(); long fireMillis = now + backoff; - - AlarmManager am = - (AlarmManager)context.getSystemService( Context.ALARM_SERVICE ); - - Intent intent = new Intent( context, TimerReceiver.class ); - PendingIntent pi = PendingIntent.getBroadcast( context, 0, intent, 0 ); - am.set( AlarmManager.ELAPSED_REALTIME_WAKEUP, fireMillis, pi ); - Log.d( TAG, "setTimer() set for %d seconds from now (%d)", backoff / 1000, now / 1000 ); - DBUtils.setLongFor( context, KEY_NEXT_BACKOFF, backoff ); + data.setFor( client, KEY_FIREWHEN, fireMillis ); } + + setNextTimer( context, data ); + } + + // What to measure? By how much are timer fires delayed? How's that as a + // percentage of what we wanted? + private static void updateStats( Data data ) + { + if ( BuildConfig.NON_RELEASE ) { + final long target = data.getFor( CLIENT_STATS, KEY_NEXT_FIRE, 0 ); + // Ignore for stats purposes if target not yet set + if ( 0 < target ) { + final long oldCount = data.getFor( CLIENT_STATS, KEY_COUNT, 0 ); + data.setFor( CLIENT_STATS, KEY_COUNT, oldCount + 1 ); + + final long now = System.currentTimeMillis(); + + if ( 0 < target ) { + long missedByMS = now - target; + long worstMiss = data.getFor( CLIENT_STATS, KEY_WORST, 0 ); + if ( worstMiss < missedByMS ) { + data.setFor( CLIENT_STATS, KEY_WORST, missedByMS ); + } + + updateAverage( data, KEY_AVG_MISS, oldCount, missedByMS ); + final long targetSpan = data.getFor( CLIENT_STATS, KEY_NEXT_SPAN, 0 ); + updateAverage( data, KEY_AVG_SPAN, oldCount, targetSpan ); + } + } + } + } + + private static void updateAverage( Data data, String key, + long oldCount, long newVal ) + { + long avg = data.getFor( CLIENT_STATS, key, 0 ); + avg = ((avg * oldCount) + newVal) / (oldCount + 1); + data.setFor( CLIENT_STATS, key, avg ); + } + + private static String className( TimerCallback cbck ) + { + return cbck.getClass().getName(); + } + + private static String getSimpleName( String client ) + { + String[] parts = TextUtils.split( client, "\\." ); + String end = parts[parts.length-1]; + return TextUtils.split( end, "\\$" )[0]; + } + + private static Data[] sDataWrapper = {null}; + static void load( Context context, WithData proc ) + { + synchronized ( sDataWrapper ) { + Data data = sDataWrapper[0]; + if ( null == data ) { + try { + data = (Data)DBUtils.getSerializableFor( context, DATA_KEY ); + Log.d( TAG, "load(): loaded: %s", toString(data) ); + } catch ( Exception ex ) { + data = null; + } + + if ( null == data ) { + data = new Data(); + } + sDataWrapper[0] = data; + } + proc.withData( data.get() ); + data.put( context ); + } + } + + private static void store( Context context, Data data ) + { + DBUtils.setSerializableFor( context, DATA_KEY, data ); + Log.d( TAG, "store(): saved: %s", toString(data) ); } } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java index 22d1fdc06..27118c1a8 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java @@ -111,10 +111,6 @@ public class XWApp extends Application case ON_RESUME: MQTTUtils.onResume( this ); BTUtils.onResume( this ); - // Do here what checkForMoves does - if ( null != DBUtils.getRelayIDs( this, null ) ) { - RelayService.timerFired( this ); - } GameUtils.resendAllIf( this, null ); break; case ON_STOP: diff --git a/xwords4/android/app/src/main/res/menu/games_list_menu.xml b/xwords4/android/app/src/main/res/menu/games_list_menu.xml index 6d66200e5..66b177d89 100644 --- a/xwords4/android/app/src/main/res/menu/games_list_menu.xml +++ b/xwords4/android/app/src/main/res/menu/games_list_menu.xml @@ -129,6 +129,9 @@ android:title="@string/gamel_menu_logs" > + diff --git a/xwords4/android/app/src/main/res/values/strings.xml b/xwords4/android/app/src/main/res/values/strings.xml index d9441f610..3fafc7cb8 100644 --- a/xwords4/android/app/src/main/res/values/strings.xml +++ b/xwords4/android/app/src/main/res/values/strings.xml @@ -2570,6 +2570,10 @@ Open anyway Word or words not found in wordlist %2$s: %1$s. Debug logs + + Timer stats + + Clear stats Enable log storage