Battery drain - Githubissues

pejakm commented 8 years ago

Finally, I'm using microG two days without any signs of #31. But unfortunately, I'm experiencing occasional battery drains (perhaps related to #47?) and I would like to report it, just in case. Perhaps someone could explain to me what am I actually seeing here (pics attached).

As you can see, during night, the properly went in deep sleep state (green lines). But today I plugged it off, and left it for few hours (red lines). The phone didn't go to deep sleep state, wifi wasn't active, so some messages I received on WhatsApp few hours ago arrived only when I picked the phone up and turned the screen on. (Yes, I reinstalled WhatsApp after installation of microG). Shouldn't the whole purpose of a push service be to wake the phone up and retrieve messages? Also FWIW, BetterBatteryStats app reports com.google.android.gms.microG services partial wake lock was active 94,8%. Any thoughts?

bonanza123 commented 8 years ago

For your particular period a logcat may be useful. But overall, I also noticed some battery drain: For 21hours (including 8 hours night time with internet off) I have 613 MCS Wakelocks which accounts for 36 minutes in total.

pejakm commented 8 years ago

Well, I've compiled GmsCore with heartbeat interval of 5 minutes, and it's much better now, almost all night with minimal battery change.

mar-v-in commented 8 years ago

The red box area definitely is a bug. A logcat would be helpful but I guess it's not easy to reproduce. However there should be a way to fix it by ensuring every wakelock will time out, which is not the case yet. Do you remember how many wakelocks were detected by BBS (not only the time)

Changing the heartbeat interval will decrease battery usage in "normal" runtime (your green area), but will not help in case of a bug like the one described. Changing some logic in the wakelock for heartbeat might also have more influence to the battery usage than changing the interval. And reducing the heartbeat interval will reduce wakeups which is good for battery, but without a wakeup push messages can not be delivered.

pejakm commented 8 years ago

Do you remember how many wakelocks were detected by BBS (not only the time)

No, unfortunately, I wanted to capture a screenshot but forgot. I'll keep an eye on my battery usage, if something like this happens again, I'll try to capture as much information as I can.

pejakm commented 8 years ago

I haven't yet experienced that battery drain, but I captured a half an hour log just in case:

D/GmsWearSvc(  964): onBind: Intent { act=com.google.android.gms.wearable.BIND pkg=com.google.android.gms }
D/GmsServiceBroker(  964): onTransact [unknown]: 26, android.os.Parcel@3c5ba759, 16
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=4}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{}
D/GmsGcmMcsSvc(  964): I/O error: javax.net.ssl.SSLException: Read error: ssl=0xb4486000: I/O error during system call, Connection timed out
D/GmsGcmMcsSvc(  964): Teardown initiated, reason: javax.net.ssl.SSLException: Read error: ssl=0xb4486000: I/O error during system call, Connection timed out
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 10 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 20 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 30 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 40 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 50 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 120 seconds...
D/GmsGcmTrigger(  964): Not connected to GCM but should be, asking the service to start up
D/GmsGcmMcsSvc(  964): Connect initiated, reason: Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }
D/GmsGcmMcsSvc(  964): Starting MCS connection...
W/GmsGcmMcsSvc(  964): Exception while connecting!
D/GmsGcmMcsSvc(  964): Teardown initiated, reason: java.net.UnknownHostException: Unable to resolve host "mtalk.google.com": No address associated with hostname
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsCheckinClient(  964): -- Request --
D/GmsCheckinClient(  964): CheckinRequest{androidId=4457257940567258118, digest=1-929a0dca0eee55513280171a8585da7dcd3700f8, checkin=Checkin{build=Build{fingerprint=lge/x3_open_eu/x3:4.1.2/JZO54K/P88020c.20d4ae5fac:user/release-keys, hardware=x3, brand=LG, radio=LGP880AT-00-V20b-EUR-XXX-JUL-17-2013, bootloader=unknown, clientId=android-google, time=1445041563, device=p880, sdkVersion=22, model=Optimus 4X HD, manufacturer=LGE, product=x3, otaInstalled=false}, lastCheckinMs=1446614670138, event=[Event{tag=system_update, value=1536,0,-1,NULL, timeMs=1446666815705}], stat=[], requestedGroup=[], cellOperator=26207, simOperator=26207, roaming=mobile-notroaming, userNumber=0}, locale=sr_RS, loggingId=6100846230953175972, macAddress=[b407f936f613], meid=355031049511690, accountCookie=[], timeZone=Europe/Sarajevo, securityToken=2998311553695160968, version=3, otaCert=[71Q6Rn2DDZl1zPDVaaeEHItd], serial=008741C3771C6403, deviceConfiguration=DeviceConfig{touchScreen=3, keyboardType=1, navigation=1, screenLayout=2, hasHardKeyboard=false, hasFiveWayNavigation=false, densityDpi=320, glEsVersion=131072, sharedLibrary=[android.test.runner, com.android.future.usb.accessory, com.android.location.provider, com.android.media.remotedisplay, com.android.mediadrm.signer, com.android.nfc_extras, com.google.android.maps, com.google.android.media.effects, com.google.widevine.software.drm, javax.btobex, javax.obex, org.cyanogenmod.hardware, org.cyanogenmod.platform], availableFeature=[android.hardware.audio.low_latency, android.hardware.audio.output, android.hardware.bluetooth, android.hardware.bluetooth_le, android.hardware.camera, android.hardware.camera.any, android.hardware.camera.autofocus, android.hardware.camera.flash, android.hardware.camera.front, android.hardware.faketouch, android.hardware.location, android.hardware.location.gps, android.hardware.location.network, android.hardware.microphone, android.hardware.nfc, android.hardware.screen.landscape, android.hardware.screen.portrait, android.hardware.sensor.accelerometer, android.hardware.sensor.compass, android.hardware.sensor.gyroscope, android.hardware.sensor.light, android.hardware.sensor.proximity, android.hardware.telephony, android.hardware.telephony.gsm, android.hardware.touchscreen, android.hardware.touchscreen.multitouch, android.hardware.touchscreen.multitouch.distinct, android.hardware.touchscreen.multitouch.jazzhand, android.hardware.usb.accessory, android.hardware.usb.host, android.hardware.wifi, android.hardware.wifi.direct, android.software.app_widgets, android.software.backup, android.software.connectionservice, android.software.device_admin, android.software.home_screen, android.software.input_methods, android.software.live_wallpaper, android.software.managed_users, android.software.print, android.software.sip, android.software.sip.voip, android.software.voice_recognizers, android.software.webview, org.cyanogenmod.theme], nativePlatform=[armeabi-v7a, armeabi], widthPixels=720, heightPixels=1280, locale=[, af, af_ZA, am, am_ET, ar, ar_EG, ar_XB, ast_ES, az_AZ, bg, bg_BG, bn_BD, ca, ca_ES, cs, cs_CZ, da, da_DK, de, de_AT, de_CH, de_DE, de_LI, el, el_GR, en, en_AU, en_CA, en_GB, en_IN, en_NZ, en_SG, en_US, en_XA, eo, es, es_ES, es_US, et_EE, eu_ES, fa, fa_IR, fi, fi_FI, fil, fil_PH, fr, fr_BE, fr_CA, fr_CH, fr_FR, gl_ES, gu_IN, hi, hi_IN, hr, hr_HR, hu, hu_HU, hy_AM, in, in_ID, is_IS, it, it_CH, it_IT, iw, iw_IL, ja, ja_JP, ka_GE, kk_KZ, km_KH, kn_IN, ko, ko_KR, ku, ku_IQ, ky_KG, lb, lb_LU, lo_LA, lt, lt_LT, lv, lv_LV, mk_MK, ml_IN, mn_MN, mr_IN, ms_MY, my_MM, nb, nb_NO, ne_NP, nl, nl_BE, nl_NL, pa_IN, pl, pl_PL, pt, pt_BR, pt_PT, rm, rm_CH, ro, ro_RO, ru, ru_RU, si_LK, sk, sk_SK, sl, sl_SI, sq_AL, sr, sr_RS, sv, sv_SE, sw, sw_TZ, ta_IN, te_IN, th, th_TH, tr, tr_TR, uk, uk_UA, ur_PK, uz_UZ, vi, vi_VN, zh_CN, zh_HK, zh_TW, zu, zu_ZA], glExtension=[GL_EXT_Cg_shader, GL_EXT_bgra, GL_EXT_debug_label, GL_EXT_debug_marker, GL_EXT_occlusion_query_boolean, GL_EXT_packed_float, GL_EXT_read_format_bgra, GL_EXT_robustness, GL_EXT_separate_shader_objects, GL_EXT
D/GmsCheckinSvc(  964): Checked in as 3ddb5c7b3bccf406
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 10 seconds...
D/GmsGcmTrigger(  964): Not connected to GCM but should be, asking the service to start up
D/GmsGcmMcsSvc(  964): Connect initiated, reason: Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }
D/GmsGcmMcsSvc(  964): Starting MCS connection...
D/GmsGcmMcsSvc(  964): Connected to mtalk.google.com:5228
D/GmsGcmMcsSvc(  964): Activated SSL with mtalk.google.com:5228
D/GmsGcmMcsSvc(  964): Sending login request...
D/GmsGcmMcsOutput(  964): Outgoing message: LoginRequest{id=android-22, domain=mcs.android.com, user=4457257940567258118, resource=4457257940567258118, auth_token=2998311553695160968, device_id=android-3ddb5c7b3bccf406, setting=[Setting{name=new_vc, value=1}], received_persistent_id=[], adaptive_heartbeat=false, use_rmq2=true, auth_service=ANDROID_ID, network_type=1}
D/GmsGcmMcsOutput(  964): Write MCS version code: 41
D/GmsGcmMcsInput(  964): Reading from MCS version: 41
D/GmsGcmMcsInput(  964): Incoming message: LoginResponse{id=android-22, jid=4457257940567258118@mcs.android.com/4457257940567258118, setting=[], last_stream_id_received=1, server_timestamp=1446666827640}
D/GmsGcmMcsSvc(  964): Logged in
D/GmsGcmMcsInput(  964): Incoming message: IqStanza{type=SET, id=CF120530, from=mcs.android.com, to=4457257940567258118@mcs.android.com/4457257940567258118, extension=Extension{id=12, data=ByteString[size=0]}, account_id=-1}
W/GmsGcmMcsSvc(  964): Unknown message: IqStanza{type=SET, id=CF120530, from=mcs.android.com, to=4457257940567258118@mcs.android.com/4457257940567258118, extension=Extension{id=12, data=ByteString[size=0]}, account_id=-1}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=2}
D/GmsGcmMcsInput(  964): Incoming message: HeartbeatAck{last_stream_id_received=2}
D/GmsGcmRegisterSvc(  964): onHandleIntent: Intent { act=com.google.android.c2dm.intent.REGISTER pkg=com.google.android.gms (has extras) }
D/GmsGcmRegisterSvc(  964): register[res]: Intent { act=com.google.android.c2dm.intent.REGISTER pkg=com.google.android.gms (has extras) } extras=Bundle[{sender=197533215920, app=PendingIntent{1de87444: android.os.BinderProxy@3ffe692d}, google.messenger=android.os.Messenger@92cae62}]
D/GmsHttpFormClient(  964): -- Request --
D/GmsHttpFormClient(  964): X-GOOG.USER_AID=4457257940567258118&device=4457257940567258118&app=com.firstrowria.pushnotificationtester&cert=1acbe3831cb1827bee6a78879501d7c3bc074987&app_ver=7&sender=197533215920
D/GmsHttpFormClient(  964): -- Response --
D/GmsHttpFormClient(  964): token=APA91bGUQbTm5HoO7Qm374ozTVouOW8ZJq_NJ5dFxXUXjlNmvIetgeddb_w6Zr-G1UzfurEjzAuSSCNxvsO7diOmaCp1Fi_YH8Jx5qSlmAKpgheOkSe36w9tC-UfXlXWmo4E7kMMKyVc9GTB7zgNLQ_MgddVSe2lNA
D/GmsGcmRegisterSvc(  964): received response: RegisterResponse{token='APA91bGUQbTm5HoO7Qm374ozTVouOW8ZJq_NJ5dFxXUXjlNmvIetgeddb_w6Zr-G1UzfurEjzAuSSCNxvsO7diOmaCp1Fi_YH8Jx5qSlmAKpgheOkSe36w9tC-UfXlXWmo4E7kMMKyVc9GTB7zgNLQ_MgddVSe2lNA', retryAfter='null', deleted='null'}
D/GmsGcmRegisterSvc(  964): register[res]: Intent { act=com.google.android.c2dm.intent.REGISTRATION (has extras) } extras=Bundle[{registration_id=APA91bGUQbTm5HoO7Qm374ozTVouOW8ZJq_NJ5dFxXUXjlNmvIetgeddb_w6Zr-G1UzfurEjzAuSSCNxvsO7diOmaCp1Fi_YH8Jx5qSlmAKpgheOkSe36w9tC-UfXlXWmo4E7kMMKyVc9GTB7zgNLQ_MgddVSe2lNA}]
D/GmsGcmMcsInput(  964): Incoming message: DataMessageStanza{id=CF1364B8, from=197533215920, category=com.firstrowria.pushnotificationtester, token=do_not_collapse, app_data=[AppData{key=serverTime, value=1446666998663}, AppData{key=title, value=Test notification}], from_trusted_server=false, persistent_id=0:1446666998706965%c5da679ff9fd7ecd, sent=1446666998668}
D/GmsGcmRegisterSvc(  964): onHandleIntent: Intent { act=com.google.android.c2dm.intent.UNREGISTER pkg=com.google.android.gms (has extras) }
D/GmsGcmRegisterSvc(  964): unregister[res]: Intent { act=com.google.android.c2dm.intent.UNREGISTER pkg=com.google.android.gms (has extras) } extras=Bundle[{app=PendingIntent{f2b4eae: android.os.BinderProxy@3ffe692d}, google.messenger=android.os.Messenger@92cae62}]
D/GmsHttpFormClient(  964): -- Request --
D/GmsHttpFormClient(  964): X-GOOG.USER_AID=4457257940567258118&device=4457257940567258118&app=com.firstrowria.pushnotificationtester&cert=1acbe3831cb1827bee6a78879501d7c3bc074987&app_ver=7&delete=1
D/GmsHttpFormClient(  964): -- Response --
D/GmsHttpFormClient(  964): deleted=com.firstrowria.pushnotificationtester
D/GmsGcmRegisterSvc(  964): received response: RegisterResponse{token='null', retryAfter='null', deleted='com.firstrowria.pushnotificationtester'}
D/GmsGcmRegisterSvc(  964): unregister[res]: Intent { act=com.google.android.c2dm.intent.REGISTRATION (has extras) } extras=Bundle[{unregistered=com.firstrowria.pushnotificationtester}]
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=4}
D/GmsGcmMcsInput(  964): Incoming message: HeartbeatAck{last_stream_id_received=3}
D/GmsWearSvc(  964): onBind: Intent { act=com.google.android.gms.wearable.BIND pkg=com.google.android.gms }
D/GmsServiceBroker(  964): onTransact [unknown]: 26, android.os.Parcel@fd570fa, 16
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=5}
D/GmsGcmMcsInput(  964): Incoming message: HeartbeatAck{last_stream_id_received=4}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=6}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{}
D/GmsGcmMcsSvc(  964): I/O error: javax.net.ssl.SSLException: Read error: ssl=0xb4486000: I/O error during system call, Connection timed out
D/GmsGcmMcsSvc(  964): Teardown initiated, reason: javax.net.ssl.SSLException: Read error: ssl=0xb4486000: I/O error during system call, Connection timed out
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Not connected to GCM but should be, asking the service to start up
D/GmsGcmMcsSvc(  964): Connect initiated, reason: Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }
D/GmsGcmMcsSvc(  964): Starting MCS connection...
D/GmsGcmMcsSvc(  964): Connected to mtalk.google.com:5228
D/GmsGcmMcsSvc(  964): Activated SSL with mtalk.google.com:5228
D/GmsGcmMcsSvc(  964): Sending login request...
D/GmsGcmMcsOutput(  964): Outgoing message: LoginRequest{id=android-22, domain=mcs.android.com, user=4457257940567258118, resource=4457257940567258118, auth_token=2998311553695160968, device_id=android-3ddb5c7b3bccf406, setting=[Setting{name=new_vc, value=1}], received_persistent_id=[0:1446666998706965%c5da679ff9fd7ecd], adaptive_heartbeat=false, use_rmq2=true, auth_service=ANDROID_ID, network_type=1}
D/GmsGcmMcsOutput(  964): Write MCS version code: 41
D/GmsGcmMcsInput(  964): Reading from MCS version: 41
D/GmsGcmMcsInput(  964): Incoming message: LoginResponse{id=android-22, jid=4457257940567258118@mcs.android.com/4457257940567258118, setting=[], last_stream_id_received=1, server_timestamp=1446669102445}
D/GmsGcmMcsSvc(  964): Logged in
D/GmsGcmMcsInput(  964): Incoming message: IqStanza{type=SET, id=CF2C11AD, from=mcs.android.com, to=4457257940567258118@mcs.android.com/4457257940567258118, extension=Extension{id=12, data=ByteString[size=0]}, account_id=-1}
W/GmsGcmMcsSvc(  964): Unknown message: IqStanza{type=SET, id=CF2C11AD, from=mcs.android.com, to=4457257940567258118@mcs.android.com/4457257940567258118, extension=Extension{id=12, data=ByteString[size=0]}, account_id=-1}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=2}
D/GmsGcmMcsInput(  964): Incoming message: HeartbeatAck{last_stream_id_received=2}
D/GmsGcmMcsSvc(  964): Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
D/GmsGcmMcsOutput(  964): Outgoing message: HeartbeatPing{last_stream_id_received=3}
D/GmsGcmMcsSvc(  964): I/O error: javax.net.ssl.SSLException: Read error: ssl=0xb4486000: I/O error during system call, Connection timed out
D/GmsGcmMcsSvc(  964): Teardown initiated, reason: javax.net.ssl.SSLException: Read error: ssl=0xb4486000: I/O error during system call, Connection timed out
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsWearSvc(  964): onBind: Intent { act=com.google.android.gms.wearable.BIND pkg=com.google.android.gms }
D/GmsServiceBroker(  964): onTransact [unknown]: 26, android.os.Parcel@3c5ba759, 16
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 10 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 20 seconds...
D/GmsGcmTrigger(  964): Ignoring Intent { act=org.microg.gms.gcm.mcs.RECONNECT flg=0x14 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }: network is offline, scheduling new attempt.
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 30 seconds...
D/GmsGcmTrigger(  964): Not connected to GCM but should be, asking the service to start up
D/GmsGcmMcsSvc(  964): Connect initiated, reason: Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.gms/org.microg.gms.gcm.TriggerReceiver (has extras) }
D/GmsGcmMcsSvc(  964): Starting MCS connection...
W/GmsGcmMcsSvc(  964): Exception while connecting!
D/GmsGcmMcsSvc(  964): Teardown initiated, reason: java.net.UnknownHostException: Unable to resolve host "mtalk.google.com": No address associated with hostname
D/GmsGcmMcsSvc(  964): Scheduling reconnect in 5 seconds...
D/GmsGcmTrigger(  964): Not connected to GCM but should be, asking the service to start up
D/GmsGcmMcsSvc(  964): Connect initiated, reason: Intent { act=org.microg.gms.

Note that I'm using 5 minute beat interval. BetterBattery stats report allot of wasted time (1153s, 89,7%) on microG wakelocks (com.google.android.gms.microG services) but counts only 6 of them. (The phone is about two hours on battery, 15 hours of total turned on time.)

pejakm commented 8 years ago

Also, one thing that I don't understand: Gms should wake my phone and check for new messages, right? When I turned screen on a moment ago, few messages arrived on Viber upon connecting to wifi. Shouldn't Gms wake the phone, turn on wifi, and retrieve those messages? Option _Keep Wi-Fi on during sleep_ is set to Only when plugged in.

pejakm commented 8 years ago

I think this happened once again, last night. Pictures and log attached, I hope they will be of use. http://pastebin.com/vPTNdmDh https://framapic.org/V0l4ssg6Atfv/wW9YNLSL https://framapic.org/7DgZR4WmsJZV/g6XOOYdY https://framapic.org/rfwMfmasMTON/pAsNGTUC https://framapic.org/DC08zhd5MpUA/ygOKEQEQ

mar-v-in commented 8 years ago

Unfortunately the log does not contain any meaningful entries. I'd like to encourage you to always provide logs with timestamps, as they're crucial to find battery issues (e.g. I can't say if your log is for a timescope of 24h or just 2min). You can easily add timestamps to logcat by using the -v threadtime option (e.g. run adb logcat -v threadtime | grep GmsGcm).

Additionally, looking at the battery usage graph, it seems interesting to me, that last time the high power consumption happened when there was no wifi connection, and this time after the wifi came back... So maybe it's another issue this time?

michitux commented 8 years ago

I think one problem here is (was) that the wake lock was not released when no ack message was received after a heartbeat ping message. I had the situation that no ack messages were received anymore even though heartbeat pings were sent relatively reliably here because of relatively long intervals between heartbeats (8 minutes and above seems to trigger the problem). The SSL connection reports errors only after several further ping requests as it can also be seen in the log above.

From reading the code I think the wake lock is only released when an ack message is received. Is it really necessary to keep a wake lock for receiving the ack or couldn't the lock be released directly after sending the heart beat ping? Same question for the login request. On the other hand I wonder if microg shouldn't acquire a wake lock as soon as data is received in order to make sure that the device stays awake between the time when the data is received, dispatchMessage() is called and the message has been fully handled as I could imagine that otherwise the device goes back to sleep in between and the app receives the message only after unlocking the device as experienced by @pejakm. An interesting discussion about such issues is this Stackoverflow question.

I'm not sure about the wake locks but I've tried fixing the connectivity issues. I've done this by changing two things:

Not using inexact alarms. From my logs it seems they are delayed up to 15 minutes if no other events occur even if the interval is set to e.g. 4 minutes. In order to not to drain the battery too much an interval can be used on API level 19 and above. For API Level >= 23 probably even setExactAndAllowWhileIdle() should be used but I guess there some more testing is necessary which I can't do as don't have a device with Android 6.
Report the connection as broken much earlier when no ack-messages are received anymore. I've currently implemented this by storing the time when ack messages are received and checking if an ack message has been received at most two intervals back. A better way might be to store the stream id on the last heartbeat ping and require it to have changed between to heartbeat but this might also introduce new race conditions.

I'll test this for some more hours especially also when the phone is not connected to WiFi and the charger (where I also had these problems, there they seem to be fixed), if my tests are successful I'll open a pull request.

pejakm commented 8 years ago

@michitux I'm open to test your changes and report back. I also must point out that I haven't been able to reproduce this issue since long time. The problems I'm mostly facing now are:

very often I need to open an app (Viber or WhatsApp) to receive a message (although my phone is connected to wifi)
if my device goes to sleep, after some time wifi shuts down (option Keep WiFi off during sleep is set to Only when plugged in), and I no longer receive messages until I pick it up and unlock it (so that it can establish connection to wifi again)

michitux commented 8 years ago

@pejakm I've just created #74 with my changes. This should make the connection stabler, at least for me the connection works reliably with 5 minutes interval. However I could still reproduce your problem that WhatsApp did not receive a message, see #75.

If your device does not have an internet connection, no messages will be received. Gms won't turn your WiFi on. The idea is that the app keeps an active connection to Google and wakes the phone up when data is received on that connection - which needs a persistent internet connection of course. However when WiFi goes off and you still have an internet connection (e.g. UMTS), the connection should be re-established using that connection. This should be the same behavior with the official Google Play Services.

forkoz commented 8 years ago

I had few problems with wakelocks at Nov 17, 2015 commits. Could only use gmail 4.2.2 but with amplify I could limit wakelocks to max every 15 minutes. Now just upgrading to latest GMSCore and gmail to 4.9 I have gmail hold much longer locks... ie many minutes at a time. GCM isn't on... just pure sync.

An app automatically kills the connection when the screen is off and is supposed to sync gmail every 45 minutes. Once it does gmail prevents going back to deep sleep and amplify can't help since it holds the lock.

From this thread it sounds like gms isn't properly failing connections. So I'm not getting new mails and the phone can't sleep.

pejakm commented 8 years ago

@michitux Compiled, installed, set timeout to 300 and looking forward to report back.

pejakm commented 8 years ago

@michitux With your changes I have a feeling that I have GAPPS installed! Thanks, it really works great now!

jeekajoo commented 8 years ago

Hi, I experienced a battery drain this week with last version. I fixed it by checking-in. Next time I'll try to get the logcat, for this report to be more helpful.. ;) Thanks. J.

jfrederickson commented 8 years ago

Just saw something that looked weird in my logcat output - I had my interval set to 60 seconds and seemed to be getting heartbeats every 30 seconds instead. Not sure if this is normal. I noticed this due to high battery drain; switched to a 300 second interval and I seem to be getting heartbeats every 5 minutes now as expected.

03-14 14:20:12.033  3222  4845 D GmsGcmMcsSvc: Scheduling heartbeat in 60 seconds...
03-14 14:20:12.034  3222 25904 D GmsGcmMcsOutput: Outgoing message: HeartbeatPing{last_stream_id_received=526}
03-14 14:20:12.773  3222 25903 D GmsGcmMcsInput: Incoming message: HeartbeatAck{last_stream_id_received=526}
03-14 14:20:42.036  3222  4845 D GmsGcmMcsSvc: Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
03-14 14:20:42.036  3222  4845 D GmsGcmMcsSvc: Scheduling heartbeat in 60 seconds...
03-14 14:20:42.038  3222 25904 D GmsGcmMcsOutput: Outgoing message: HeartbeatPing{last_stream_id_received=527}
03-14 14:20:42.752  3222 25903 D GmsGcmMcsInput: Incoming message: HeartbeatAck{last_stream_id_received=527}
03-14 14:21:12.038  3222  4845 D GmsGcmMcsSvc: Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
03-14 14:21:12.038  3222  4845 D GmsGcmMcsSvc: Scheduling heartbeat in 60 seconds...
03-14 14:21:12.040  3222 25904 D GmsGcmMcsOutput: Outgoing message: HeartbeatPing{last_stream_id_received=528}
03-14 14:21:13.401  3222 25903 D GmsGcmMcsInput: Incoming message: HeartbeatAck{last_stream_id_received=528}
03-14 14:21:42.041  3222  4845 D GmsGcmMcsSvc: Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
03-14 14:21:42.041  3222  4845 D GmsGcmMcsSvc: Scheduling heartbeat in 60 seconds...
03-14 14:21:42.043  3222 25904 D GmsGcmMcsOutput: Outgoing message: HeartbeatPing{last_stream_id_received=529}
03-14 14:21:43.272  3222 25903 D GmsGcmMcsInput: Incoming message: HeartbeatAck{last_stream_id_received=529}
03-14 14:22:38.870  3222  4845 D GmsGcmMcsSvc: Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }
03-14 14:22:38.870  3222  4845 D GmsGcmMcsSvc: Scheduling heartbeat in 60 seconds...
03-14 14:22:38.872  3222 25904 D GmsGcmMcsOutput: Outgoing message: HeartbeatPing{last_stream_id_received=530}
03-14 14:22:40.223  3222 25903 D GmsGcmMcsInput: Incoming message: HeartbeatAck{last_stream_id_received=530}
03-14 14:23:08.873  3222  4845 D GmsGcmMcsSvc: Heartbeat initiated, reason: Intent { act=org.microg.gms.gcm.mcs.HEARTBEAT flg=0x4 cmp=com.google.android.gms/org.microg.gms.gcm.McsService (has extras) }

mar-v-in commented 8 years ago

@jfrederickson This is intended behaviour. The ping will be sent within the interval [heartbeatMs/2, heartbeatMs] since KitKat. The exact time will be selected based on the device wake state. This will reduce battery consumption when the cpu has less wake-ups (as the system will merge schedules from multiple apps). However when the system is awake (like when you have it connected to your pc) it will always choose heartbeatMs/2 to ensure it's not necassary to wake up later. We might want to change this behaviour a bit, maybe something like [hearbeatMs*3/4, heartbeatMs*5/4] is a better choice? As you noticed, you can freely choose heartbeat interval, however values like 300 might be a little high for "push message feeling"

michitux commented 8 years ago

I'm not using microg anymore, but when I implemented this [heartbeatMs/2, heartbeatMs] interval I tested this mainly with 300s as interval and this worked perfectly fine and I would actually suggest this as default value. Note that the connection is maintained permanently and push messages will also wake up your device when no ping is sent as long as the connection hasn't been dropped in the meantime. You can see connection drops in the log as microg reconnects as soon as it detects that the connection is not alive anymore. Depending on your internet provider and your router when you are using WiFi also longer intervals might work. Every time the connection is lost the stream id is reset, so if you see small values of the stream id in the log and you have had a stable and permanent internet connection (and did not switch between WiFi and mobile data) during the last hours, your interval might be too long.

pejakm commented 8 years ago

After update to 0.2.2-5-g6bf59b2 the microg would drain entire battery during the night, when wifi is off. Just to note, device checkin is off. I had to revert to stable 0.2.5. No logs for now, as I'm not in position to experiment these days. My best guess is that commit 2a394f98aafb28e96a1012d6976a0cdc32d93316 is the cause of this.

Catfriend1 commented 8 years ago

after update to microg 0.2.3 my battery holds very long. Checkin is on gcm too with 300 secs

pejakm commented 8 years ago

I can confirm, with 0.2.3 I cannot reproduce this anymore.

mar-v-in commented 8 years ago

Seems to be no problem anymore, closing.

microg / GmsCore

Battery drain #52