search

rahim / nightwear

NightScout standalone Wear 2.0 watchface and complication
GNU General Public License v3.0
12 stars 9 forks source link

Investigate ambient mode delayed HTTP calls #6

Open rahim opened 5 years ago

rahim commented 5 years ago

The blood glucose service doesn't do anything to change its behaviour in ambient mode - it runs on a background thread, conservatively adding requests via Volley when it's clear it's worth trying to retrieve new data.

On my Ticwatch E with always on enabled, it's evident that we end up with stale data after periods of ambient mode, after touching the screen causing an ambient mode exit we see updated data after a small pause.

rahim commented 5 years ago

Relevant logs from device:

2019-03-24 01:28:03.422 11080-11103/im.rah.nightwear D/BloodGlucoseService: Latest reading age: 490
2019-03-24 01:28:03.422 11080-11103/im.rah.nightwear D/BloodGlucoseService: nightscoutBaseUrl: https://hugo-ns.herokuapp.com
2019-03-24 01:28:03.422 11080-11103/im.rah.nightwear D/BloodGlucoseService: clearing queue, then requesting
2019-03-24 01:28:35.537 11080-11103/im.rah.nightwear D/BloodGlucoseService: refresh
2019-03-24 01:28:35.538 11080-11103/im.rah.nightwear D/BloodGlucoseService: Latest reading age: 522
2019-03-24 01:28:35.538 11080-11103/im.rah.nightwear D/BloodGlucoseService: nightscoutBaseUrl: https://hugo-ns.herokuapp.com
2019-03-24 01:28:35.538 11080-11103/im.rah.nightwear D/BloodGlucoseService: clearing queue, then requesting
2019-03-24 01:29:00.015 11080-11080/im.rah.nightwear D/BloodGlucoseService: tick received
2019-03-24 01:29:00.068 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:29:01.338 11080-11103/im.rah.nightwear D/BloodGlucoseService: refresh
2019-03-24 01:29:01.338 11080-11103/im.rah.nightwear D/BloodGlucoseService: Latest reading age: 548
2019-03-24 01:29:01.339 11080-11103/im.rah.nightwear D/BloodGlucoseService: nightscoutBaseUrl: https://hugo-ns.herokuapp.com
2019-03-24 01:29:36.949 11080-11103/im.rah.nightwear D/BloodGlucoseService: refresh
2019-03-24 01:29:36.949 11080-11103/im.rah.nightwear D/BloodGlucoseService: Latest reading age: 583
2019-03-24 01:29:36.949 11080-11103/im.rah.nightwear D/BloodGlucoseService: nightscoutBaseUrl: https://hugo-ns.herokuapp.com
2019-03-24 01:29:36.949 11080-11103/im.rah.nightwear D/BloodGlucoseService: clearing queue, then requesting
2019-03-24 01:30:00.017 11080-11080/im.rah.nightwear D/BloodGlucoseService: tick received
2019-03-24 01:30:00.082 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:10.581 11080-11103/im.rah.nightwear D/BloodGlucoseService: refresh
2019-03-24 01:30:10.581 11080-11103/im.rah.nightwear D/BloodGlucoseService: Latest reading age: 617
2019-03-24 01:30:10.581 11080-11103/im.rah.nightwear D/BloodGlucoseService: nightscoutBaseUrl: https://hugo-ns.herokuapp.com
2019-03-24 01:30:10.582 11080-11103/im.rah.nightwear D/BloodGlucoseService: clearing queue, then requesting

# Exited ambient mode here

2019-03-24 01:30:22.523 11080-11080/im.rah.nightwear D/BloodGlucoseService: tick received
2019-03-24 01:30:22.546 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:23.022 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:23.363 11080-11099/im.rah.nightwear D/Volley: [338] BasicNetwork.logSlowRequests: HTTP response for request=<[X] https://hugo-ns.herokuapp.com/api/v1/entries/current 0x6efdc47f NORMAL 431> [lifetime=137761], [size=60], [rc=200], [retryCount=1]
2019-03-24 01:30:23.523 11080-11080/im.rah.nightwear D/BloodGlucoseService: bg received, parsing...
2019-03-24 01:30:24.023 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:25.015 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:26.012 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:27.013 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:27.383 11080-11080/im.rah.nightwear D/BloodGlucoseService: tick received
2019-03-24 01:30:27.448 11080-11080/im.rah.nightwear I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib/hw/gralloc.mt2601.so from the current namespace instead.
2019-03-24 01:30:36.724 11080-11103/im.rah.nightwear D/BloodGlucoseService: refresh
2019-03-24 01:30:36.725 11080-11103/im.rah.nightwear D/BloodGlucoseService: Latest reading age: 343

My reading of this is that our background thread lives and queues requests, but that Volley or the OS is blocking the HTTP calls in ambient mode.

It's odd that volley itself logs the request as slow:

2019-03-24 01:30:23.363 11080-11099/im.rah.nightwear D/Volley: [338] BasicNetwork.logSlowRequests: HTTP response for request=<[X] https://hugo-ns.herokuapp.com/api/v1/entries/current 0x6efdc47f NORMAL 431> [lifetime=137761], [size=60], [rc=200], [retryCount=1]

Presumably lifetime is in milliseconds.