Bluetooth problems - Periodic and somehow random audio pauses and minor metadata issue - Moto G 4, Android 6.0.1 stock

[RaulDJ]

Hi.

My phone is a Lenovo Moto G 4º generation, I'm running stock Android 6.0.1 and I'm using build 588 of Poweramp. I'm having some issues while playing music through my Pioneer DEH-4600BT and the problem is that, after 15 minutes or so of playback, there's always a small pause. This pause usually lasts for about a half to almost a second and doesn't happen when using non-Bluetooth headphones. Music is stored on the real (external) SD card.

These are the settings I tried changing and did nothing to solve or mitigate the issue:

• Short Audio Focus Change
• BT Direct Volume Control
• Audio Buffer Size
• Audio Thread Priority
• Use Wakelock

I've also tried leaving Poweramp in the foreground before turning off the screen and didn't help either.

Finally, I have another small issue also Bluetooth related: no matter what settings I choose related to Bluetooth metadata, my head unit displays the phone Bluetooth name ("Moto G (4)" in my case) in the place where it should display playtime. This never happened to me with this player on Android 2 or 4 on the same unit and works as intended (displaying playtime) on other car audio systems.

Thank you for your responses and for making this great player!

 

EDIT: Managed to get some logs, pause happens at around 11:16:04:

Quote

04-19 11:15:52.561   792   792 I MSM-irqbalance: Decided to move IRQ240 from CPU6 to CPU4

04-19 11:15:54.288 19295 19318 D bt_btif : LCB lcb=1 event=6 state=2

04-19 11:15:54.288 19295 19318 D bt_btif : bta_av_rc_msg_cback handle: 0 opcode=0x0

04-19 11:15:54.288 19295 19311 D bt_btif : btif_av_state_started_handler event:BTA_AV_META_MSG_EVT flags 0

04-19 11:15:54.288 19295 19311 D bt_btif : btif_rc_handler event:BTA_AV_META_MSG_EVT

04-19 11:15:54.288 19295 19311 D bt_btif : AVRC_ParsCommand() return status:0x4

04-19 11:15:54.288 19295 19311 D bt_btif : btif_rc_upstreams_evt pdu: AVRC_PDU_GET_PLAY_STATUS handle: 0x0 ctype:1 label:a

04-19 11:15:54.288 19295 19311 I BluetoothAvrcpServiceJni: btavrcp_get_play_status_callback

04-19 11:15:54.288 19295 19326 V Avrcp   : MESSAGE_GET_PLAY_STATUS

04-19 11:15:54.289 19295 19326 V Avrcp   : position=91025

04-19 11:15:54.289 19295 19326 I BluetoothAvrcpServiceJni: getPlayStatusRspNative: sBluetoothAvrcpInterface: 0xaf89391c

04-19 11:15:54.289 19295 19318 D bt_btif : LCB lcb=1 event=2 state=2

04-19 11:15:56.442 16297 16328 D GeckoMemoryMonitor: Decreased memory pressure to 0

04-19 11:15:57.578   792   792 I MSM-irqbalance: Decided to move IRQ200 from CPU5 to CPU4

04-19 11:15:59.328 19295 19318 D bt_btif : LCB lcb=1 event=6 state=2

04-19 11:15:59.328 19295 19318 D bt_btif : bta_av_rc_msg_cback handle: 0 opcode=0x0

04-19 11:15:59.328 19295 19311 D bt_btif : btif_av_state_started_handler event:BTA_AV_META_MSG_EVT flags 0

04-19 11:15:59.328 19295 19311 D bt_btif : btif_rc_handler event:BTA_AV_META_MSG_EVT

04-19 11:15:59.328 19295 19311 D bt_btif : AVRC_ParsCommand() return status:0x4

04-19 11:15:59.328 19295 19311 D bt_btif : btif_rc_upstreams_evt pdu: AVRC_PDU_GET_PLAY_STATUS handle: 0x0 ctype:1 label:b

04-19 11:15:59.328 19295 19311 I BluetoothAvrcpServiceJni: btavrcp_get_play_status_callback

04-19 11:15:59.328 19295 19326 V Avrcp   : MESSAGE_GET_PLAY_STATUS

04-19 11:15:59.328 19295 19326 V Avrcp   : position=96065

04-19 11:15:59.328 19295 19326 I BluetoothAvrcpServiceJni: getPlayStatusRspNative: sBluetoothAvrcpInterface: 0xaf89391c

04-19 11:15:59.328 19295 19318 D bt_btif : LCB lcb=1 event=2 state=2

04-19 11:16:00.561   522   635 E ThermalEngine: vs_interrupt_wait: Time out after 10.000(sec)

04-19 11:16:00.562   522   634 E ThermalEngine: vs_interrupt_wait: Time out after 10.000(sec)

04-19 11:16:01.885  1808  7809 D BatteryService: Processing new values: chargerAcOnline=false, chargerUsbOnline=false, chargerWirelessOnline=false, maxChargingCurrent0, batteryStatus=3, batteryHealth=2, batteryPresent=true, batteryLevel=84, batteryTechnology=Li-ion, batteryVoltage=4128, batteryTemperature=280, mBatteryLevelCritical=false, mPlugType=0, mChargeRate=0, modLevel=-1, modStatus=-1, modFlag=0

04-19 11:16:01.886  1808  7809 D BatteryService: Sending ACTION_BATTERY_CHANGED.  level:84, scale:100, status:3, health:2, present:true, voltage: 4128, temperature: 280, technology: Li-ion, AC powered:false, USB powered:false, Wireless powered:false, icon:17303108, invalid charger:0, maxChargingCurrent:0, charge rate:0, MOD powered:false, mod level:-1, mod status:-1, mod flag:0

04-19 11:16:01.888  4101  4101 D KeyguardUpdateMonitor: received broadcast android.intent.action.BATTERY_CHANGED

04-19 11:16:01.892 19295 19325 D HeadsetStateMachine: Connected process message: 10, size: 1

04-19 11:16:01.892  4101  4101 D KeyguardUpdateMonitor: handleBatteryUpdate

04-19 11:16:02.014  1808  3991 D BatteryService: uevent={POWER_SUPPLY_TEMP=280, POWER_SUPPLY_STATUS=Discharging, POWER_SUPPLY_CAPACITY=84, ACTION=change, DEVPATH=/devices/soc.0/qpnp-smbcharger-f6e70600/power_supply/battery, POWER_SUPPLY_AGE=99, POWER_SUPPLY_VOLTAGE_MAX=4350, SUBSYSTEM=power_supply, POWER_SUPPLY_NUM_SYSTEM_TEMP_LEVELS=8, POWER_SUPPLY_INPUT_CURRENT_MAX=1000000, POWER_SUPPLY_VOLTAGE_MAX_DESIGN=4350000, POWER_SUPPLY_CHARGE_FULL=3029000, POWER_SUPPLY_NAME=battery, POWER_SUPPLY_FLASH_CURRENT_MAX=2842914, POWER_SUPPLY_HEALTH=Good, POWER_SUPPLY_CYCLE_COUNT=0, POWER_SUPPLY_TECHNOLOGY=Li-ion, POWER_SUPPLY_CHARGE_TYPE=N/A, POWER_SUPPLY_CONSTANT_CHARGE_CURRENT_MAX=2500000, POWER_SUPPLY_PRESENT=1, POWER_SUPPLY_TEMP_HOTSPOT=0, POWER_SUPPLY_INPUT_CURRENT_SETTLED=0, POWER_SUPPLY_SAFETY_TIMER_ENABLED=0, POWER_SUPPLY_FLASH_ACTIVE=0, POWER_SUPPLY_VOLTAGE_NOW=4127936, SEQNUM=4287, POWER_SUPPLY_CHARGE_FULL_DESIGN=3059000, POWER_SUPPLY_CURRENT_NOW=71715, POWER_SUPPLY_CHARGE_COUNTER=2526614, POWER_SUPPLY_SYSTEM_TEMP_LEVEL=0, POWER_SUPPLY_CHARGE_RATE=None, POWER_SUPPLY_CHARGING_ENABLED=1, POWER_SUPPLY_BATTERY_CHARGING_ENABLED=1}

04-19 11:16:02.015  1808  7808 D BatteryService: Processing new values: chargerAcOnline=false, chargerUsbOnline=false, chargerWirelessOnline=false, maxChargingCurrent0, batteryStatus=3, batteryHealth=2, batteryPresent=true, batteryLevel=84, batteryTechnology=Li-ion, batteryVoltage=4127, batteryTemperature=280, mBatteryLevelCritical=false, mPlugType=0, mChargeRate=0, modLevel=-1, modStatus=-1, modFlag=0

04-19 11:16:02.016  1808  7808 D BatteryService: Sending ACTION_BATTERY_CHANGED.  level:84, scale:100, status:3, health:2, present:true, voltage: 4127, temperature: 280, technology: Li-ion, AC powered:false, USB powered:false, Wireless powered:false, icon:17303108, invalid charger:0, maxChargingCurrent:0, charge rate:0, MOD powered:false, mod level:-1, mod status:-1, mod flag:0

04-19 11:16:02.020  4101  4101 D KeyguardUpdateMonitor: received broadcast android.intent.action.BATTERY_CHANGED

04-19 11:16:02.021 19295 19325 D HeadsetStateMachine: Connected process message: 10, size: 1

04-19 11:16:02.023  4101  4101 D KeyguardUpdateMonitor: handleBatteryUpdate

04-19 11:16:02.578   792   792 I MSM-irqbalance: Decided to move IRQ203 from CPU6 to CPU4

04-19 11:16:04.365 19295 19318 D bt_btif : LCB lcb=1 event=6 state=2

04-19 11:16:04.365 19295 19318 D bt_btif : bta_av_rc_msg_cback handle: 0 opcode=0x0

04-19 11:16:04.365 19295 19311 D bt_btif : btif_av_state_started_handler event:BTA_AV_META_MSG_EVT flags 0

04-19 11:16:04.365 19295 19311 D bt_btif : btif_rc_handler event:BTA_AV_META_MSG_EVT

04-19 11:16:04.365 19295 19311 D bt_btif : AVRC_ParsCommand() return status:0x4

04-19 11:16:04.365 19295 19311 D bt_btif : btif_rc_upstreams_evt pdu: AVRC_PDU_GET_PLAY_STATUS handle: 0x0 ctype:1 label:c

04-19 11:16:04.365 19295 19311 I BluetoothAvrcpServiceJni: btavrcp_get_play_status_callback

04-19 11:16:04.365 19295 19326 V Avrcp   : MESSAGE_GET_PLAY_STATUS

04-19 11:16:04.365 19295 19326 V Avrcp   : position=101102

04-19 11:16:04.365 19295 19326 I BluetoothAvrcpServiceJni: getPlayStatusRspNative: sBluetoothAvrcpInterface: 0xaf89391c

04-19 11:16:04.365 19295 19318 D bt_btif : LCB lcb=1 event=2 state=2

04-19 11:16:07.618   792   792 I MSM-irqbalance: Decided to move IRQ174 from CPU6 to CPU4

04-19 11:16:09.426 19295 19318 D bt_btif : LCB lcb=1 event=6 state=2

04-19 11:16:09.426 19295 19318 D bt_btif : bta_av_rc_msg_cback handle: 0 opcode=0x0

04-19 11:16:09.427 19295 19311 D bt_btif : btif_av_state_started_handler event:BTA_AV_META_MSG_EVT flags 0

04-19 11:16:09.427 19295 19311 D bt_btif : btif_rc_handler event:BTA_AV_META_MSG_EVT

04-19 11:16:09.427 19295 19311 D bt_btif : AVRC_ParsCommand() return status:0x4

04-19 11:16:09.427 19295 19311 D bt_btif : btif_rc_upstreams_evt pdu: AVRC_PDU_GET_PLAY_STATUS handle: 0x0 ctype:1 label:d

04-19 11:16:09.427 19295 19311 I BluetoothAvrcpServiceJni: btavrcp_get_play_status_callback

04-19 11:16:09.427 19295 19326 V Avrcp   : MESSAGE_GET_PLAY_STATUS

04-19 11:16:09.427 19295 19326 V Avrcp   : position=106164

04-19 11:16:09.428 19295 19326 I BluetoothAvrcpServiceJni: getPlayStatusRspNative: sBluetoothAvrcpInterface: 0xaf89391c

04-19 11:16:09.428 19295 19318 D bt_btif : LCB lcb=1 event=2 state=2

04-19 11:16:10.561   522   635 E ThermalEngine: vs_interrupt_wait: Time out after 10.000(sec)

04-19 11:16:10.562   522   634 E ThermalEngine: vs_interrupt_wait: Time out after 10.000(sec)

04-19 11:16:12.618   792   792 I MSM-irqbalance: Decided to move IRQ170 from CPU4 to CPU7