search

nightscout / AndroidAPS

Opensource automated insulin delivery system (closed loop)
https://wiki.aaps.app
GNU Affero General Public License v3.0
694 stars 1.7k forks source link

v2.8.2 - Loop not executing every 5 mins even when a TB needs changing #1024

Closed AureliaJohanna closed 2 years ago

AureliaJohanna commented 2 years ago

Hi,

Loop is not executing every 5 mins even though a TB needs changing. This is obviously a safety issue if I cannot resolve.

If I manually press 'run now' in the loop tab, then loop runs. Or if I set a new action, such as a TT, then loop will run. It is connecting to the pump just fine when it runs. BGs are being pulled from BYOD app fine.

I've also noticed that Autsens seems to be changing value with each new BG. For example, I saw it change from 120 to 100 to 109 to 115 to 116 consecutively

Actions taken:

-restared phone multiple times -cleared AAPS cache -swapped out battery on pump and changed battery cap -double checked battery saving is off

Running version 2.8.2 of AAPS on Cubot King Kong mini 2 running android 10. Most manual commands are done via Smartwatch (Fossil SE)

I've attached some log files and a screenshot. Please let me know what other info you need. It has been happening for two days now.

Thanks,

Steve

Reporting bugs

AureliaJohanna commented 2 years ago

Adding more logs AndroidAPS._2021-12-02_08-42-56_11.log AndroidAPS.log s

AureliaJohanna commented 2 years ago

Clearing cache and restarting phone seems to fix temporarily but it then starts missing loop cycles again. Looking at the logs, there seems to be a profile switch event spamming but I could be wrong and have no idea where that's coming from

MilosKozak commented 2 years ago

same as https://github.com/nightscout/AndroidAPS/issues/1021

AureliaJohanna commented 2 years ago

same as #1021

my phone storage is not full though (and never has been)? I've only used 40% of its storage capacity

AureliaJohanna commented 2 years ago

@MilosKozak i spoke to the person that raised the other issue you closed and her phone storage was only 30% full so I’m confused as to how that’s the underlying issue and how I therefore resolve it?

MilosKozak commented 2 years ago

what time in logs it was not executed?

MilosKozak commented 2 years ago

sorry, you are right. i didn't realize it's 2.8 version and compared to 3.0 but the reason is not visible from logs. i see this loop invocation

15:23:40.846 [RxCachedThreadScheduler-4] D/APS: [LoopPlugin.invoke():352]: invoke from EventTempTargetChange
15:23:41.268 [RxCachedThreadScheduler-4] D/APS: [LoopPlugin.invoke():583]: invoke end
15:31:48.348 [RxCachedThreadScheduler-4] D/APS: [LoopPlugin.invoke():352]: invoke from EventTempTargetChange
15:31:48.757 [RxCachedThreadScheduler-4] D/APS: [LoopPlugin.invoke():583]: invoke end
15:37:24.490 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638459425000, date=02/12/2021 15:37, value=126.0, direction=Flat, raw=0.0}
15:37:24.942 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
15:42:16.799 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638459725000, date=02/12/2021 15:42, value=123.0, direction=Flat, raw=0.0}
15:42:17.242 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
15:47:17.938 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638460025000, date=02/12/2021 15:47, value=119.0, direction=Flat, raw=0.0}
15:47:18.357 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
15:52:33.456 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638460325000, date=02/12/2021 15:52, value=115.0, direction=Flat, raw=0.0}
15:52:33.861 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
15:57:25.012 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638460625000, date=02/12/2021 15:57, value=114.0, direction=Flat, raw=0.0}
15:57:25.404 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
16:02:18.145 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638460925000, date=02/12/2021 16:02, value=115.0, direction=Flat, raw=0.0}
16:02:18.564 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
16:07:18.074 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638461225000, date=02/12/2021 16:07, value=115.0, direction=Flat, raw=0.0}
16:07:18.481 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
16:12:19.442 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638461525000, date=02/12/2021 16:12, value=112.0, direction=Flat, raw=0.0}
16:12:19.857 [RxCachedThreadScheduler-7] D/APS: [LoopPlugin.invoke():583]: invoke end
16:19:08.864 [RxCachedThreadScheduler-4] D/APS: [LoopPlugin.invoke():352]: invoke from EventTempTargetChange
AureliaJohanna commented 2 years ago

@MilosKozak I believe it failed run at 20.52 in this log (so I ran a TT to get bit to run) but its been happening for two days for me

AndroidAPS._2021-12-0216-24-17.log

AureliaJohanna commented 2 years ago

@MilosKozak I also noticed autosens was behaving in usual way. Changing every new BG but I didn't note the exact time when that happened unfortunately

MilosKozak commented 2 years ago

no reason visible in new log as well, sorry you may try to turn on AUTOSENS logging and provide new logs

AureliaJohanna commented 2 years ago

@MilosKozak okay I have turned on AUTOSENS logging. Can you confirm that you'd like me to upload another log that includes autosens when I see another missed BG?

MilosKozak commented 2 years ago

yes

MilosKozak commented 2 years ago

autosens logging is generating huge amount of data. maybe there will be needed upload more files turn it off afterwards

AureliaJohanna commented 2 years ago

@MilosKozak sods law it stopped happening consistently once I turned on autosens log last night!!! However, I think I had two missed loop runs at 11.07 and 11.32 today. Please note that I wasn't with mu daughter at the time so couldn't confirm on Loop Tab of her AAPS phone. I was monitoring via NS Client and NS.

I've added the logs.

AndroidAPS._2021-12-03_00-00-11_68.log

AndroidAPS._2021-12-03_00-00-11_64.log

AureliaJohanna commented 2 years ago

It may not be related but I also noticed the pump connect time in NS Client said 18m ago at 11.36 and 9m ago at 11.37. I will attach screensho Screenshot_20211203-113630 Screenshot_20211203-113740 ts

AureliaJohanna commented 2 years ago

Adding additional logs around that time in case you need/want them AndroidAPS._2021-12-03_00-00-11_65.log AndroidAPS._2021-12-03_00-00-11_66.log AndroidAPS._2021-12-03_00-00-11_67.log AndroidAPS._2021-12-03_00-00-11_69.log

AureliaJohanna commented 2 years ago

Hey

The phone is used exclusively for AAPS so the only apps I personally initialise are the BYOD app and AndroidAPS.

Chrome will sometimes be running in the background.

I once installed an app called OpenSignal to test her schools WiFi but I don’t open that app now.

Did the other user who had similar issue (#1021) have a similar gap in her logs?

Thanks

Steve

On Fri, 3 Dec 2021 at 20:50, Savek-CC @.***> wrote:

Looking at the hh:mm entries in the log: 11:07 11:08 +1 11:09 +1 11:10 +1 11:11 +1 11:12 +1 11:13 +1 11:14 +1 11:15 +1 11:16 +1 11:17 +1 11:18 +1 11:19 +1 11:20 +1 11:21 +1 11:22 +1 11:32 +10 !!! 11:33 +1 11:34 +1 11:35 +1 11:36 +1 11:37 +1 11:38 +1 11:39 +1 11:40 +1 11:41 +1 11:42 +1 so there is a gap of a full 10 minutes of nothing in those logs where absolutely nothing (not a single log entry) happened - even tough you say battery saving is disabled - there still is a 10 minute gap there; what kind of other apps are running on the device?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/nightscout/AndroidAPS/issues/1024#issuecomment-985819123, or unsubscribe https://github.com/notifications/unsubscribe-auth/AQFSNOA3CZG2ALLCPXHE5YLUPEUSTANCNFSM5JHPX6DA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

savek-cc commented 2 years ago

Just combining all the logs, I don't see a missing loop-plugin invocation at the times mentioned? (combined "new bg event" and "loop invocation")

11:07:22.001 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638529627000, date=03/12/2021 11:07, value=151.0, direction=Flat, raw=0.0}
11:07:25.060 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638529627000, date=03/12/2021 11:07, value=151.0, direction=Flat, raw=0.0}
11:07:31.964 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:12:23.081 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638529927000, date=03/12/2021 11:12, value=154.0, direction=FortyFiveUp, raw=0.0}
11:12:25.666 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638529927000, date=03/12/2021 11:12, value=154.0, direction=FortyFiveUp, raw=0.0}
11:12:26.124 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:17:19.167 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638530227000, date=03/12/2021 11:17, value=146.0, direction=Flat, raw=0.0}
11:17:21.772 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638530227000, date=03/12/2021 11:17, value=146.0, direction=Flat, raw=0.0}
11:17:22.221 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:22:22.936 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638530527000, date=03/12/2021 11:22, value=142.0, direction=Flat, raw=0.0}
11:22:25.531 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638530527000, date=03/12/2021 11:22, value=142.0, direction=Flat, raw=0.0}
11:22:26.000 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:27:20.497 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638530827000, date=03/12/2021 11:27, value=150.0, direction=Flat, raw=0.0}
11:27:23.109 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638530827000, date=03/12/2021 11:27, value=150.0, direction=Flat, raw=0.0}
11:27:23.575 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:32:25.617 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638531127000, date=03/12/2021 11:32, value=153.0, direction=Flat, raw=0.0}
11:32:28.197 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638531127000, date=03/12/2021 11:32, value=153.0, direction=Flat, raw=0.0}
11:32:35.135 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:37:21.699 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638531427000, date=03/12/2021 11:37, value=147.0, direction=Flat, raw=0.0}
11:37:24.272 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638531427000, date=03/12/2021 11:37, value=147.0, direction=Flat, raw=0.0}
11:37:24.712 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

11:42:23.048 [IntentService[DataService]] D/DATABASE: [DatabaseHelper.createIfNotExists():396]: BG: New record from: DexcomG6 BgReading{date=1638531727000, date=03/12/2021 11:42, value=138.0, direction=Flat, raw=0.0}
11:42:25.686 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638531727000, date=03/12/2021 11:42, value=138.0, direction=Flat, raw=0.0}
11:42:26.144 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

But if you compare what is happening, you can see that it just "ends" more or less directly after "getMealData" when it is "not executed" - but "getMealData" takes virtually "forever" at this stage:

11:07:25.060 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638529627000, date=03/12/2021 11:07, value=151.0, direction=Flat, raw=0.0}
11:07:25.063 [RxCachedThreadScheduler-8] D/APS: [OpenAPSSMBPlugin.invoke():161]: invoke from AutosenseCalculation for BgReading{date=1638529627000, date=03/12/2021 11:07, value=151.0, direction=Flat, raw=0.0} tempBasalFallback: false
11:07:31.962 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> getMealData() <<< executed in 6521 miliseconds
11:07:31.964 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end

compared to a complete run:

11:12:25.666 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():352]: invoke from AutosenseCalculation for BgReading{date=1638529927000, date=03/12/2021 11:12, value=154.0, direction=FortyFiveUp, raw=0.0}
11:12:25.670 [RxCachedThreadScheduler-8] D/APS: [OpenAPSSMBPlugin.invoke():161]: invoke from AutosenseCalculation for BgReading{date=1638529927000, date=03/12/2021 11:12, value=154.0, direction=FortyFiveUp, raw=0.0} tempBasalFallback: false
11:12:25.759 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> getMealData() <<< executed in 11 miliseconds
11:12:25.998 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> calculateIobArrayInDia() <<< executed in 237 miliseconds
11:12:26.000 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> detectSensitivityandCarbAbsorption() <<< executed in 1 miliseconds
11:12:26.001 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> SMB data gathering <<< executed in 253 miliseconds
11:12:26.009 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():94]: >>> Invoking detemine_basal <<<
11:12:26.010 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():95]: Glucose status: {"glucose":154,"noise":0,"delta":5,"short_avgdelta":6.44,"long_avgdelta":2.37,"date":1638529927000}
11:12:26.013 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():96]: IOB data:       [{"iob":0.568,"basaliob":0.018,"bolussnooze":0.2509,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:12:25Z","iobWithZeroTemp":{"iob":0.568,"basaliob":0.018,"bolussnooze":0.2509,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:12:25Z"}},{"iob":0.549,"basaliob":0.016,"bolussnooze":0.2352,"activity":0.0039,"lastBolusTime":16385284
21000,"time":"2021-12-03T11:17:25Z","iobWithZeroTemp":{"iob":0.529,"basaliob":-0.004,"bolussnooze":0.2352,"activity":0.0039,"lastBolusTime":1638528421000,"time":"2021-12-03T11:17:25Z"}},{"iob":0.53,"basaliob":0.014,"bolussnooze":0.219,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:22:25Z","iobWithZeroTemp":{"iob":0.485,"basaliob":-0.031,"bolussnooze":0.219,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:22:25Z"}},{"iob":0.51,"bas
aliob":0.012,"bolussnooze":0.2027,"activity":0.0039,"lastBolusTime":1638528421000,"time":"2021-12-03T11:27:25Z","iobWithZeroTemp":{"iob":0.44,"basaliob":-0.058,"bolussnooze":0.2027,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:27:25Z"}},{"iob":0.491,"basaliob":0.011,"bolussnooze":0.1865,"activity":0.0039,"lastBolusTime":1638528421000,"time":"2021-12-03T11:32:25Z","iobWithZeroTemp":{"iob":0.397,"basaliob":-0.083,"bolussnooze":0.1865,"activity":0.0038,
"lastBolusTime":1638528421000,"time":"2021-12-03T11:32:25Z"}},{"iob":0.472,"basaliob":0.01,"bolussnooze":0.1706,"activity":0.0039,"lastBolusTime":1638528421000,"time":"2021-12-03T11:37:25Z","iobWithZeroTemp":{"iob":0.354,"basaliob":-0.108,"bolussnooze":0.1706,"activity":0.0037,"lastBolusTime":1638528421000,"time":"2021-12-03T11:37:25Z"}},{"iob":0.452,"basaliob":0.008,"bolussnooze":0.1554,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:42:25Z","iobWithZ
eroTemp":{"iob":0.31,"basaliob":-0.134,"bolussnooze":0.1554,"activity":0.0035,"lastBolusTime":1638528421000,"time":"2021-12-03T11:42:25Z"}},{"iob":0.433,"basaliob":0.007,"bolussnooze":0.1408,"activity":0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T11:47:25Z","iobWithZeroTemp":{"iob":0.268,"basaliob":-0.158,"bolussnooze":0.1408,"activity":0.0034,"lastBolusTime":1638528421000,"time":"2021-12-03T11:47:25Z"}},{"iob":0.414,"basaliob":0.006,"bolussnooze":0.127,"activity
":0.0037,"lastBolusTime":1638528421000,"time":"2021-12-03T11:52:25Z","iobWithZeroTemp":{"iob":0.226,"basaliob":-0.182,"bolussnooze":0.127,"activity":0.0032,"lastBolusTime":1638528421000,"time":"2021-12-03T11:52:25Z"}},{"iob":0.395,"basaliob":0.005,"bolussnooze":0.1141,"activity":0.0037,"lastBolusTime":1638528421000,"time":"2021-12-03T11:57:25Z","iobWithZeroTemp":{"iob":0.185,"basaliob":-0.205,"bolussnooze":0.1141,"activity":0.0031,"lastBolusTime":1638528421000,"time":"2021-
12-03T11:57:25Z"}},{"iob":0.377,"basaliob":0.004,"bolussnooze":0.102,"activity":0.0036,"lastBolusTime":1638528421000,"time":"2021-12-03T12:02:25Z","iobWithZeroTemp":{"iob":0.146,"basaliob":-0.227,"bolussnooze":0.102,"activity":0.0028,"lastBolusTime":1638528421000,"time":"2021-12-03T12:02:25Z"}},{"iob":0.359,"basaliob":0.003,"bolussnooze":0.0908,"activity":0.0036,"lastBolusTime":1638528421000,"time":"2021-12-03T12:07:25Z","iobWithZeroTemp":{"iob":0.107,"basaliob":-0.249,"bol
ussnooze":0.0908,"activity":0.0027,"lastBolusTime":1638528421000,"time":"2021-12-03T12:07:25Z"}},{"iob":0.343,"basaliob":0.003,"bolussnooze":0.0805,"activity":0.0034,"lastBolusTime":1638528421000,"time":"2021-12-03T12:12:25Z","iobWithZeroTemp":{"iob":0.071,"basaliob":-0.269,"bolussnooze":0.0805,"activity":0.0024,"lastBolusTime":1638528421000,"time":"2021-12-03T12:12:25Z"}},{"iob":0.325,"basaliob":0.002,"bolussnooze":0.071,"activity":0.0033,"lastBolusTime":1638528421000,"tim
e":"2021-12-03T12:17:25Z","iobWithZeroTemp":{"iob":0.033,"basaliob":-0.29,"bolussnooze":0.071,"activity":0.0021,"lastBolusTime":1638528421000,"time":"2021-12-03T12:17:25Z"}},{"iob":0.308,"basaliob":0.001,"bolussnooze":0.0623,"activity":0.0032,"lastBolusTime":1638528421000,"time":"2021-12-03T12:22:25Z","iobWithZeroTemp":{"iob":-0.002,"basaliob":-0.309,"bolussnooze":0.0623,"activity":0.0019,"lastBolusTime":1638528421000,"time":"2021-12-03T12:22:25Z"}},{"iob":0.293,"basaliob":
0.001,"bolussnooze":0.0544,"activity":0.0031,"lastBolusTime":1638528421000,"time":"2021-12-03T12:27:25Z","iobWithZeroTemp":{"iob":-0.036,"basaliob":-0.328,"bolussnooze":0.0544,"activity":0.0017,"lastBolusTime":1638528421000,"time":"2021-12-03T12:27:25Z"}},{"iob":0.278,"basaliob":0.001,"bolussnooze":0.0473,"activity":0.003,"lastBolusTime":1638528421000,"time":"2021-12-03T12:32:25Z","iobWithZeroTemp":{"iob":-0.068,"basaliob":-0.345,"bolussnooze":0.0473,"activity":0.0014,"last
BolusTime":1638528421000,"time":"2021-12-03T12:32:25Z"}},{"iob":0.263,"basaliob":0,"bolussnooze":0.0409,"activity":0.0029,"lastBolusTime":1638528421000,"time":"2021-12-03T12:37:25Z","iobWithZeroTemp":{"iob":-0.1,"basaliob":-0.363,"bolussnooze":0.0409,"activity":0.0012,"lastBolusTime":1638528421000,"time":"2021-12-03T12:37:25Z"}},{"iob":0.249,"basaliob":0,"bolussnooze":0.0351,"activity":0.0028,"lastBolusTime":1638528421000,"time":"2021-12-03T12:42:25Z","iobWithZeroTemp":{"io
b":-0.13,"basaliob":-0.379,"bolussnooze":0.0351,"activity":0.001,"lastBolusTime":1638528421000,"time":"2021-12-03T12:42:25Z"}},{"iob":0.234,"basaliob":-0.001,"bolussnooze":0.03,"activity":0.0027,"lastBolusTime":1638528421000,"time":"2021-12-03T12:47:25Z","iobWithZeroTemp":{"iob":-0.16,"basaliob":-0.395,"bolussnooze":0.03,"activity":7.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T12:47:25Z"}},{"iob":0.221,"basaliob":-0.001,"bolussnooze":0.0254,"activity":0.0025,"last
BolusTime":1638528421000,"time":"2021-12-03T12:52:25Z","iobWithZeroTemp":{"iob":-0.188,"basaliob":-0.41,"bolussnooze":0.0254,"activity":4.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T12:52:25Z"}},{"iob":0.209,"basaliob":-0.001,"bolussnooze":0.0214,"activity":0.0024,"lastBolusTime":1638528421000,"time":"2021-12-03T12:57:25Z","iobWithZeroTemp":{"iob":-0.214,"basaliob":-0.424,"bolussnooze":0.0214,"activity":2.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T12:57
:25Z"}},{"iob":0.197,"basaliob":-0.001,"bolussnooze":0.0179,"activity":0.0023,"lastBolusTime":1638528421000,"time":"2021-12-03T13:02:25Z","iobWithZeroTemp":{"iob":-0.24,"basaliob":-0.438,"bolussnooze":0.0179,"activity":-1.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T13:02:25Z"}},{"iob":0.186,"basaliob":-0.001,"bolussnooze":0.0148,"activity":0.0022,"lastBolusTime":1638528421000,"time":"2021-12-03T13:07:25Z","iobWithZeroTemp":{"iob":-0.264,"basaliob":-0.451,"bolussno
oze":0.0148,"activity":-3.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T13:07:25Z"}},{"iob":0.175,"basaliob":-0.001,"bolussnooze":0.0121,"activity":0.0022,"lastBolusTime":1638528421000,"time":"2021-12-03T13:12:25Z","iobWithZeroTemp":{"iob":-0.287,"basaliob":-0.463,"bolussnooze":0.0121,"activity":-4.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T13:12:25Z"}},{"iob":0.163,"basaliob":-0.002,"bolussnooze":0.0098,"activity":0.0021,"lastBolusTime":1638528421000,"ti
me":"2021-12-03T13:17:25Z","iobWithZeroTemp":{"iob":-0.311,"basaliob":-0.476,"bolussnooze":0.0098,"activity":-6.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T13:17:25Z"}},{"iob":0.153,"basaliob":-0.002,"bolussnooze":0.0078,"activity":0.002,"lastBolusTime":1638528421000,"time":"2021-12-03T13:22:25Z","iobWithZeroTemp":{"iob":-0.332,"basaliob":-0.487,"bolussnooze":0.0078,"activity":-8.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T13:22:25Z"}},{"iob":0.143,"basa
liob":-0.002,"bolussnooze":0.0061,"activity":0.0019,"lastBolusTime":1638528421000,"time":"2021-12-03T13:27:25Z","iobWithZeroTemp":{"iob":-0.352,"basaliob":-0.497,"bolussnooze":0.0061,"activity":-0.0011,"lastBolusTime":1638528421000,"time":"2021-12-03T13:27:25Z"}},{"iob":0.134,"basaliob":-0.002,"bolussnooze":0.0047,"activity":0.0018,"lastBolusTime":1638528421000,"time":"2021-12-03T13:32:25Z","iobWithZeroTemp":{"iob":-0.371,"basaliob":-0.507,"bolussnooze":0.0047,"activity":-0
.0013,"lastBolusTime":1638528421000,"time":"2021-12-03T13:32:25Z"}},{"iob":0.126,"basaliob":-0.002,"bolussnooze":0.0035,"activity":0.0017,"lastBolusTime":1638528421000,"time":"2021-12-03T13:37:25Z","iobWithZeroTemp":{"iob":-0.389,"basaliob":-0.517,"bolussnooze":0.0035,"activity":-0.0015,"lastBolusTime":1638528421000,"time":"2021-12-03T13:37:25Z"}},{"iob":0.117,"basaliob":-0.002,"bolussnooze":0.0025,"activity":0.0016,"lastBolusTime":1638528421000,"time":"2021-12-03T13:42:25Z
","iobWithZeroTemp":{"iob":-0.407,"basaliob":-0.526,"bolussnooze":0.0025,"activity":-0.0017,"lastBolusTime":1638528421000,"time":"2021-12-03T13:42:25Z"}},{"iob":0.11,"basaliob":-0.002,"bolussnooze":0.0017,"activity":0.0015,"lastBolusTime":1638528421000,"time":"2021-12-03T13:47:25Z","iobWithZeroTemp":{"iob":-0.422,"basaliob":-0.534,"bolussnooze":0.0017,"activity":-0.0019,"lastBolusTime":1638528421000,"time":"2021-12-03T13:47:25Z"}},{"iob":0.102,"basaliob":-0.002,"bolussnooze
":0.0011,"activity":0.0014,"lastBolusTime":1638528421000,"time":"2021-12-03T13:52:25Z","iobWithZeroTemp":{"iob":-0.438,"basaliob":-0.542,"bolussnooze":0.0011,"activity":-0.0021,"lastBolusTime":1638528421000,"time":"2021-12-03T13:52:25Z"}},{"iob":0.095,"basaliob":-0.002,"bolussnooze":7.0E-4,"activity":0.0014,"lastBolusTime":1638528421000,"time":"2021-12-03T13:57:25Z","iobWithZeroTemp":{"iob":-0.452,"basaliob":-0.549,"bolussnooze":7.0E-4,"activity":-0.0021,"lastBolusTime":163
8528421000,"time":"2021-12-03T13:57:25Z"}},{"iob":0.089,"basaliob":-0.002,"bolussnooze":4.0E-4,"activity":0.0013,"lastBolusTime":1638528421000,"time":"2021-12-03T14:02:25Z","iobWithZeroTemp":{"iob":-0.465,"basaliob":-0.556,"bolussnooze":4.0E-4,"activity":-0.0023,"lastBolusTime":1638528421000,"time":"2021-12-03T14:02:25Z"}},{"iob":0.082,"basaliob":-0.002,"bolussnooze":1.0E-4,"activity":0.0012,"lastBolusTime":1638528421000,"time":"2021-12-03T14:07:25Z","iobWithZeroTemp":{"iob
":-0.479,"basaliob":-0.563,"bolussnooze":1.0E-4,"activity":-0.0025,"lastBolusTime":1638528421000,"time":"2021-12-03T14:07:25Z"}},{"iob":0.076,"basaliob":-0.002,"bolussnooze":0,"activity":0.0011,"lastBolusTime":1638528421000,"time":"2021-12-03T14:12:25Z","iobWithZeroTemp":{"iob":-0.491,"basaliob":-0.569,"bolussnooze":0,"activity":-0.0027,"lastBolusTime":1638528421000,"time":"2021-12-03T14:12:25Z"}},{"iob":0.071,"basaliob":-0.002,"bolussnooze":0,"activity":0.0011,"lastBolusTi
me":1638528421000,"time":"2021-12-03T14:17:25Z","iobWithZeroTemp":{"iob":-0.502,"basaliob":-0.575,"bolussnooze":0,"activity":-0.0028,"lastBolusTime":1638528421000,"time":"2021-12-03T14:17:25Z"}},{"iob":0.066,"basaliob":-0.002,"bolussnooze":0,"activity":0.001,"lastBolusTime":1638528421000,"time":"2021-12-03T14:22:25Z","iobWithZeroTemp":{"iob":-0.513,"basaliob":-0.581,"bolussnooze":0,"activity":-0.0029,"lastBolusTime":1638528421000,"time":"2021-12-03T14:22:25Z"}},{"iob":0.061
,"basaliob":-0.002,"bolussnooze":0,"activity":0.001,"lastBolusTime":1638528421000,"time":"2021-12-03T14:27:25Z","iobWithZeroTemp":{"iob":-0.523,"basaliob":-0.586,"bolussnooze":0,"activity":-0.003,"lastBolusTime":1638528421000,"time":"2021-12-03T14:27:25Z"}},{"iob":0.056,"basaliob":-0.002,"bolussnooze":0,"activity":9.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T14:32:25Z","iobWithZeroTemp":{"iob":-0.533,"basaliob":-0.591,"bolussnooze":0,"activity":-0.0032,"lastBolus
Time":1638528421000,"time":"2021-12-03T14:32:25Z"}},{"iob":0.051,"basaliob":-0.002,"bolussnooze":0,"activity":9.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T14:37:25Z","iobWithZeroTemp":{"iob":-0.542,"basaliob":-0.595,"bolussnooze":0,"activity":-0.0032,"lastBolusTime":1638528421000,"time":"2021-12-03T14:37:25Z"}},{"iob":0.047,"basaliob":-0.002,"bolussnooze":0,"activity":8.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T14:42:25Z","iobWithZeroTemp":{"iob":-0.5
5,"basaliob":-0.599,"bolussnooze":0,"activity":-0.0034,"lastBolusTime":1638528421000,"time":"2021-12-03T14:42:25Z"}},{"iob":0.043,"basaliob":-0.002,"bolussnooze":0,"activity":8.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T14:47:25Z","iobWithZeroTemp":{"iob":-0.558,"basaliob":-0.603,"bolussnooze":0,"activity":-0.0034,"lastBolusTime":1638528421000,"time":"2021-12-03T14:47:25Z"}},{"iob":0.04,"basaliob":-0.002,"bolussnooze":0,"activity":7.0E-4,"lastBolusTime":163852842
1000,"time":"2021-12-03T14:52:25Z","iobWithZeroTemp":{"iob":-0.565,"basaliob":-0.607,"bolussnooze":0,"activity":-0.0036,"lastBolusTime":1638528421000,"time":"2021-12-03T14:52:25Z"}},{"iob":0.036,"basaliob":-0.002,"bolussnooze":0,"activity":7.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T14:57:25Z","iobWithZeroTemp":{"iob":-0.572,"basaliob":-0.61,"bolussnooze":0,"activity":-0.0037,"lastBolusTime":1638528421000,"time":"2021-12-03T14:57:25Z"}},{"iob":0.033,"basaliob":-
0.002,"bolussnooze":0,"activity":6.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T15:02:25Z","iobWithZeroTemp":{"iob":-0.578,"basaliob":-0.613,"bolussnooze":0,"activity":-0.0038,"lastBolusTime":1638528421000,"time":"2021-12-03T15:02:25Z"}},{"iob":0.03,"basaliob":-0.002,"bolussnooze":0,"activity":6.0E-4,"lastBolusTime":1638528421000,"time":"2021-12-03T15:07:25Z","iobWithZeroTemp":{"iob":-0.584,"basaliob":-0.616,"bolussnooze":0,"activity":-0.0038,"lastBolusTime":163852
8421000,"time":"2021-12-03T15:07:25Z"}}]
11:12:26.015 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():97]: Current temp:   {"temp":"absolute","duration":20,"rate":0.27,"minutesrunning":10}
11:12:26.015 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():98]: Profile:        {"max_iob":1.7,"type":"current","max_daily_basal":0.3,"max_basal":0.89,"min_bg":90,"max_bg":90,"target_bg":90,"carb_ratio":12,"sens":162,"max_daily_safety_multiplier":3,"current_basal_safety_multiplier":4,"high_temptarget_raises_sensitivity":false,"low_temptarget_lowers_sensitivity":false,"sensitivity_raises_target":true,"resistance_lowers_target":false,"adv_target_adju
stments":false,"exercise_mode":false,"half_basal_exercise_target":160,"maxCOB":120,"skip_neutral_temps":false,"remainingCarbsCap":90,"enableUAM":true,"A52_risk_enable":false,"SMBInterval":3,"enableSMB_with_COB":true,"enableSMB_with_temptarget":false,"allowSMB_with_high_temptarget":false,"enableSMB_always":true,"enableSMB_after_carbs":true,"maxSMBBasalMinutes":30,"maxUAMSMBBasalMinutes":15,"bolus_increment":0.1,"carbsReqThreshold":1,"current_basal":0.3,"temptargetSet":true,"
autosens_max":1.2,"out_units":"mmol\/L"}
11:12:26.016 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():99]: Meal data:      {"carbs":18,"boluses":0,"mealCOB":4.1113333333333335,"slopeFromMaxDeviation":0,"slopeFromMinDeviation":3.5946666666666665,"lastBolusTime":1638528421000,"lastCarbTime":1638529275000}
11:12:26.016 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():101]: Autosens data:  {"ratio":1}
11:12:26.017 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():104]: Reservoir data: undefined
11:12:26.017 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():105]: MicroBolusAllowed:  true
11:12:26.017 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():106]: SMBAlwaysAllowed:  true
11:12:26.018 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():107]: CurrentTime: 1638529946002
11:12:26.018 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():108]: isSaveCgmSource: true
11:12:26.055 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: Autosens ratio: 1;
11:12:26.056 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: Basal unchanged: 0.3;
11:12:26.057 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: ISF unchanged: 162
11:12:26.058 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: ; CR: 12
11:12:26.059 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: currenttemp: {"temp":"absolute","duration":20,"rate":0.27,"minutesrunning":10} lastTempAge: 0 m tempModulus: 20 m
11:12:26.060 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: SMB enabled due to enableSMB_always
11:12:26.061 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: profile.sens: 162 sens: 162 CSF: 13.5
11:12:26.062 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: Last carbs 11 minutes ago; remainingCATime: 3.3 hours; 77% carbs absorbed
11:12:26.063 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: Carb Impact: 8.1 mg/dL per 5m; CI Duration: 1.1 hours; remaining CI (~2h peak): 0 mg/dL per 5m
11:12:26.075 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: predCIs (mg/dL/5m): 8 7 6 6 5 5 4 3 3 2 2 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
11:12:26.076 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: remainingCIs:       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
11:12:26.082 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: UAM Impact: 8.1 mg/dL per 5m; UAM Duration: 0.6 hours
11:12:26.083 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: minPredBG: 110 minIOBPredBG: 110 minZTGuardBG: 110
11:12:26.084 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: minCOBPredBG: 117
11:12:26.085 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: minUAMPredBG: 89
11:12:26.086 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: avgPredBG: 110 COB: 4.1113333333333335 / 18
11:12:26.088 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: BG projected to remain above 5.0 for 240 minutes
11:12:26.089 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: naive_eventualBG: 62 bgUndershoot: 3 zeroTempDuration: 240 zeroTempEffect: 194 carbsReq: -14
11:12:26.090 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: IOB 0.568 > COB 4.1113333333333335; mealInsulinReq = 0.343
11:12:26.091 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: profile.maxUAMSMBBasalMinutes: 15 profile.current_basal: 0.3
11:12:26.092 [RxCachedThreadScheduler-8] D/APS: [LoggerCallback.jsFunction_log():42]: naive_eventualBG 62, 0m 0U/h temp needed; last bolus 25.4m ago; maxBolus: 0.1
11:12:26.094 [RxCachedThreadScheduler-8] D/APS: [DetermineBasalAdapterSMBJS.invoke():162]: Result: {"temp":"absolute","bg":154,"tick":"+5","eventualBG":117,"targetBG":90,"insulinReq":0.12,"deliverAt":"2021-12-03T11:12:26.002Z","sensitivityRatio":1,"predBGs":{"IOB":[154,158,162,165,167,169,170,170,170,169,167,165,162,159,156,154,151,149,146,144,142,140,138,136,134,133,131,129,128,126,125,124,122,121,120,119,118,117,116,116,115,114,113,113,112,111,111,110],"ZT":[154,151,148,1
45,142,139,136,133,130,127,125,123,120,118,117,115,114,113,112,111,110,110,110,110,110,110],"COB":[154,158,162,165,168,170,171,172,173,172,172,170,168,166,163,161,158,156,153,151,149,147,145,143,141,140,138,136,135,133,132,131,129,128,127,126,125,124,123,122,122,121,120,120,119,118,118,117],"UAM":[154,158,160,162,162,161,159,156,153,150,147,144,141,138,135,133,130,128,125,123,121,119,117,115,113,112,110,108,107,105,104,103,101,100,99,98,97,96,95,94,94,93,92,92,91,90,90,89]}
,"COB":4.1113333333333335,"IOB":0.568,"reason":"COB: 4.1, Dev: 2.7, BGI: -0.2, ISF: 9.0, CR: 12, Target: 5.0, minPredBG 6.1, minGuardBG 5.3, IOBpredBG 6.1, COBpredBG 6.5, UAMpredBG 4.9; Eventual BG 6.5 >= 5.0,  insulinReq 0.12. temp 0.27<0.54U/hr. ","duration":30,"rate":0.54}
11:12:26.098 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> SMB calculation <<< executed in 96 miliseconds
11:12:26.118 [RxCachedThreadScheduler-8] D/APS: [APSResult.isChangeRequested():338]: DEFAULT: Closed mode
11:12:26.120 [RxCachedThreadScheduler-8] D/APS: [APSResult.isChangeRequested():338]: DEFAULT: Closed mode
11:12:26.120 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.applyTBRRequest():678]: applyAPSRequest: Rate: 0.54 U/h (180.00%) 
11:12:26.121 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.applyTBRRequest():731]: applyAPSRequest: setTempBasalAbsolute()
11:12:26.124 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end
savek-cc commented 2 years ago

@MilosKozak I wonder if it's throwing an exception somewhere (shortly after, as the only thing from the contraints that is checked is the IOB) after https://github.com/nightscout/AndroidAPS/blob/2.8.2/app/src/main/java/info/nightscout/androidaps/plugins/aps/openAPSSMB/OpenAPSSMBPlugin.java#L204 The complete output in the log there is:

11:07:31.962 [RxCachedThreadScheduler-8] D/APS: [Profiler.log():13]: >>> getMealData() <<< executed in 6521 miliseconds
11:07:31.962 [RxCachedThreadScheduler-8] D/CONSTRAINTS: [Constraint.setIfSmaller():60]: Setting because of smaller value 1111111.0 -> 1.7 (Limiting IOB to 1.7 U because of max value in preferences)[Safety]
11:07:31.963 [RxCachedThreadScheduler-8] D/AUTOSENS: [IobCobCalculatorPlugin.getLastAutosensData():714]: AUTOSENSDATA null: data is old (OpenAPSPlugin) size()=390 lastdata=03/12/2021 01:33:00
11:07:31.964 [RxCachedThreadScheduler-8] D/APS: [LoopPlugin.invoke():583]: invoke end
MilosKozak commented 2 years ago

the root cause is too much concurrent changes in DB which is preventing AS calculation to finish. I'm unable to resolve it in 2.8 In 3.0 this has been improved a lot and there is more usefull logging in this area. Wait for 3.0 and then create new issue if the problem persists.

AureliaJohanna commented 2 years ago

Okay - thanks Milos - much appreciated.

If there could be some sort of post ‘Loop Run’ check that could send a notification if it hasn’t executed, I think that would be helpful. Not sure if that would be possible.

Thanks again for all you do

Steve

On Tue, 7 Dec 2021 at 11:02, Milos Kozak @.***> wrote:

the root cause is too much concurrent changes in DB which is preventing AS calculation to finish. I'm unable to resolve it in 2.8 In 3.0 this has been improved a lot and there is more usefull logging in this area. Wait for 3.0 and then create new issue if the problem persists.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/nightscout/AndroidAPS/issues/1024#issuecomment-987817065, or unsubscribe https://github.com/notifications/unsubscribe-auth/AQFSNOHE2J4ASISWLY3LVJTUPXSVDANCNFSM5JHPX6DA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.