AVRCP: reduce PLAY_INTERVAL_TIMEOUT logspam
Before:
06-10 20:38:36.926 1002 1520 2053 V Avrcp : MSG_NATIVE_REQ_REGISTER_NOTIFICATION:event=5 param=1
06-10 20:38:36.926 1002 1520 2053 D Avrcp : sendPlayPosNotificationRsp: (true) 193004 <=? 194015 <=? 195004
06-10 20:38:36.926 1002 1520 2053 D Avrcp : sendPlayPosNotificationRsp: currentPlayState PlaybackState {state=3, position=698, buffered position=0, speed=1.0, updated=76557851, actions=794551, custom actions=[Action:mName='Thumbs up, mIcon=2130838014, mExtras=Bundle[mParcelledData.dataSize=40], Action:mName='Thumbs down, mIcon=2130838013, mExtras=Bundle[mParcelledData.dataSize=44], Action:mName='Start radio, mIcon=2130837971, mExtras=Bundle[mParcelledData.dataSize=648], Action:mName='Shuffle, mIcon=2130837998, mExtras=null], active item id=27596, error=null}
06-10 20:38:36.926 1002 1520 2053 D Avrcp : PLAY_INTERVAL_TIMEOUT set for 1000ms from now
06-10 20:38:37.928 1002 1520 2053 V Avrcp : MSG_PLAY_INTERVAL_TIMEOUT
06-10 20:38:37.928 1002 1520 2053 D Avrcp : sendPlayPosNotificationRsp: (false) 193015 <=? 195017 <=? 195015
06-10 20:38:37.928 1002 1520 2053 D Avrcp : sendPlayPosNotificationRsp: currentPlayState PlaybackState {state=3, position=698, buffered position=0, speed=1.0, updated=76557851, actions=794551, custom actions=[Action:mName='Thumbs up, mIcon=2130838014, mExtras=Bundle[mParcelledData.dataSize=40], Action:mName='Thumbs down, mIcon=2130838013, mExtras=Bundle[mParcelledData.dataSize=44], Action:mName='Start radio, mIcon=2130837971, mExtras=Bundle[mParcelledData.dataSize=648], Action:mName='Shuffle, mIcon=2130837998, mExtras=null], active item id=27596, error=null}
After:
06-12 14:27:38.217 1217 1807 V Avrcp : MSG_NATIVE_REQ_REGISTER_NOTIFICATION:event=5 param=5
06-12 14:27:38.218 1217 1807 D Avrcp : sendPlayPosNotificationRsp: (true) 56305 <=? 61489 <=? 66305 Playing State: 3 Timeout 5000ms
06-12 14:27:43.225 1217 1807 D Avrcp : sendPlayPosNotificationRsp: (false) 56489 <=? 66495 <=? 66489 Playing State: 3
Test: adb logcat when playing music and connected to a device
Bug: 36802046
Change-Id: Icb3623c51ceaf0e70f3da9beb1f0a2896b4cfd65
diff --git a/src/com/android/bluetooth/avrcp/Avrcp.java b/src/com/android/bluetooth/avrcp/Avrcp.java
index 1b3ce68..b5122fe 100644
--- a/src/com/android/bluetooth/avrcp/Avrcp.java
+++ b/src/com/android/bluetooth/avrcp/Avrcp.java
@@ -489,7 +489,6 @@
break;
case MSG_PLAY_INTERVAL_TIMEOUT:
- if (DEBUG) Log.v(TAG, "MSG_PLAY_INTERVAL_TIMEOUT");
sendPlayPosNotificationRsp(false);
break;
@@ -1164,15 +1163,19 @@
}
long playPositionMs = getPlayPosition();
+ String debugLine = "sendPlayPosNotificationRsp: ";
// mNextPosMs is set to -1 when the previous position was invalid
// so this will be true if the new position is valid & old was invalid.
// mPlayPositionMs is set to -1 when the new position is invalid,
// and the old mPrevPosMs is >= 0 so this is true when the new is invalid
// and the old was valid.
- if (DEBUG) Log.d(TAG, "sendPlayPosNotificationRsp: (" + requested + ") "
- + mPrevPosMs + " <=? " + playPositionMs + " <=? " + mNextPosMs);
- if (DEBUG) Log.d(TAG, "sendPlayPosNotificationRsp: currentPlayState " + mCurrentPlayState);
+ if (DEBUG) {
+ debugLine += "(" + requested + ") " + mPrevPosMs + " <=? " + playPositionMs + " <=? "
+ + mNextPosMs;
+ if (isPlayingState(mCurrentPlayState)) debugLine += " Playing";
+ debugLine += " State: " + mCurrentPlayState.getState();
+ }
if (requested || ((mLastReportedPosition != playPositionMs) &&
(playPositionMs >= mNextPosMs) || (playPositionMs <= mPrevPosMs))) {
if (!requested) mPlayPosChangedNT = AvrcpConstants.NOTIFICATION_TYPE_CHANGED;
@@ -1194,9 +1197,10 @@
if (mNextPosMs != -1) {
delay = mNextPosMs - (playPositionMs > 0 ? playPositionMs : 0);
}
- if (DEBUG) Log.d(TAG, "PLAY_INTERVAL_TIMEOUT set for " + delay + "ms from now");
+ if (DEBUG) debugLine += " Timeout " + delay + "ms";
mHandler.sendMessageDelayed(msg, delay);
}
+ if (DEBUG) Log.d(TAG, debugLine);
}
/**
