I’ve been trying to get the Overdue Tasks lists in Arc Mini to clear by leaving my phone plugged in with display always on overnight and when I’m home during the day. (But Arc seems to last longer when the display is off. It gets killed multiple times an hour it seems when the display is always on, which I can re-open in the daytime but obviously not overnight. Though perhaps it’s not allowed to do as much when the display is off which is why it doesn’t get killed so quickly?)
The tasks that are tenaciously hanging on:
coreMLModelUpdates: overdue by 1 mth
monthlyAutoExportUpdate: overdue by 20 days
sanitiseStore: overdue by 16 days (but this one does show in the Debug Log as scheduled and as running)
I’ve noticed some repeated errors in the Logs as well:
[ERROR] Failed to schedule coreMLModelUpdates
A place that I frequent (like Home!) trying to update, returning an error, then updating. It’ll happen again with the same places within other debug log sessions:
[09:14:51.8791 UPDATING: Place Name
[09:14:54.0371 [ERROR] [MISC] [ERROR] Key not found in table placeRTree: [rowid:NULL]
[09:14:54.039] UPDATED: Place Name
Out of curiosity, what do the numbers between dashes mean in the Debug Log? (Eg --1–, --2-- etc) and what do “Grew a full head” and “Went fully headless” mean? They amuse me every single time but I’d love to know the meaning.
For this one, the thing to look out for is how many CD2 models are listed as pending. If it’s only one or two, then things are going fine, but if it’s more than a small handful then iOS is being a dick.
What I see happen most of the time with the coreMLModelUpdates task is iOS starts the task, then immediately stops it. No idea why - makes no sense - but there it is. Anyway, once Arc (or Mini) has started updating one of the models, that update continues to completion - the update can’t be stopped part way through. So even if iOS starts the task then immediately stops it, one model will still get updated.
That means that most of the time the pending models do tend to get all updated soon enough, even though iOS continues to do that weird thing of starting then immediately stopping the task most of the time. (Oh, the debug view will list the task as overdue based on the last date it finished, so because iOS is stopping the task before it finishes, that’s why it keeps showing as overdue.)
This one’s more difficult. The monthly auto exports are really time expensive, so they’re the most difficult to get finished, even more so than the iCloud backups. That then has the knock on effect of using up a lot of the app’s good will with iOS, in that the app spends more time doing scheduled background tasks, specifically the auto export tasks, leaving less free time for the other tasks.
So I tend to recommend turning off the monthly auto exports, and only doing manual monthly exports as needed. Not ideal, but until I find time to have another go at optimising that task, it’s all I’ve got.
Though there also might not be much I can do to optimise the task further The difference between the monthly auto export tasks and the iCloud backups is the auto exports have to load (and write to disk) all the samples data for the entire month, even if only one of the samples changed. The iCloud backups instead only have to load and write to disk a week of samples, because the backups collate the samples into weekly files.
Actually I wonder if it would make sense to ditch the monthly auto exports feature and replace it with weekly auto exports. That might be the path to greater efficiency. Hmm.
That one’s weird. The store sanitise task is a very simple and quick one. Not sure why that’d end up being overdue. Unless iOS doing its mean spirited thing of starting the task then immediately stopping it, same as it does with the coreMLModelUpdates task. Hmm.
I’m hoping that’s a red herring, and it’s just an occasional weird iOS quirk and doesn’t indicate an ongoing problem. If the number of pending CD2 models shown in the debug view is low, then it’ll be safe to ignore it.
Oh I really need to remove that one from the debug logging. It’s totally harmless, and just a thing I had there for debugging the database’s r-tree indexing of places when I first implemented it. I can’t remember exactly why the error pops up, but I’m 100% sure it’s harmless. I’ll make a note to remove it from the logs.
I sometimes use the debug logs to work out whether the app had been suspended in the background (something that iOS should never do, but sometimes it does. grr). The only way to do that is to look for time gaps in the log lines. But a gap with nothing logged could also mean that the app simply wasn’t doing anything for a while. So I added those “nothing happened for a while” log lines.
But adding a log line like that every minute would bulk out the log files massively, and be super uncool. So they’re added instead in a Fibonacci sequence of minutes since last, ie 1, 1, 2, 3, 5, 8, 13, 21, 34, 55 minutes apart. That way the first handful of log lines will happen fairly soon after the app last did something worthy of logging, but then get spaced longer apart the longer the “nothing happened” continues. In practice it tends to only get up to a handful of “nothing happened” lines before something happens, at which point it’ll reset to 1 again.
Looking through my most recent decent length log file, I see most of them getting up to --3--, so 1 + 1 + 2 minutes of “nothing happened, but app was still alive”. Oh and one case of --5--, which means … 1 + 1 + 2 + 3 + 5 = 12 minutes. Hmm. Not all that long either. Oh there’s one for 7! So… 1 + 1 + 2 + 3 + 5 + 8 + 13 = 33 minutes. Ok, still not all that long. I guess Arc is almost always doing something
Anyway, from those lines I can tell that if it got to --2-- then there’s nothing in the logs until 10 minutes later, the app must’ve been suspended within a couple of minutes after, because there should’ve been a --3-- two minutes after.
Hah! A “head” in this case means the app’s UI. So when the app “goes headless” it’s discarding its entire UI from memory, and becoming just a purely background app. That allows it to shrink down its memory use to around 50MB, which is I think Apple’s recommended safe limit for being at low risk of getting ejected from memory when iOS wants memory for something else. It also means there’s no risk of the app spending energy accidentally updating any UI while in the background.
Then when you bring the app into the foreground it’ll have to “grow a head”, and it either grows a “full head” which is the full normal UI, or a “little head” which is the Low Power UI.
Oh, Arc will go headless once it’s been in the background for … 8 minutes. It’ll also go headless if Arc Mini takes over recording (and likewise Mini will if Arc takes over), to avoid the app trying to hold onto any data in memory that the UI was using, when the other app is now in charge of the data. That gets rid of the risk of the UI showing out of date data when you switch back to it, due to it having held onto the UI (and associated data) and not realising that that data had been changed by the other app.
I also use that as a little trick to get rid of stuck UI in Arc sometimes. Instead of spending an hour trying to find the bug that caused the UI to get stuck, I’ll flick over to Mini then back again, which will trigger Arc to immediately go headless / discard its UI, then rebuild it again. One of my dirty little tricks for avoiding difficult work
Done! And your idea to switch to weekly auto exports makes sense to me!
This one does successfully schedule and run at least, but it just doesn’t finish. (I se the “[ERROR] unfinished” line at the beginning of quite a few Session Logs. It has been running for 7 hrs 12 min, buuuut “Last updated” and “Last started” say 7hrs 13 min ago so maybe running doesn’t mean anything. I’ve also been out and about so my phone hasn’t been plugged in if that makes a difference.
Unfortunately this is a frequent message that pops up multiple times within the same session log!
Whoa that’s so cool! Mine goes up to --9-- and I think the longest/highest I’ve noticed is --10–
HA HA! That’s awesome. I might need to set my phone to Low Power Mode for awhile just to see “little head” pop up in the logs because that’s just entertaining. (I am admittedly very easily entertained.)
OH ok interesting I’ve been running into Arc crashing and when I open it again, it hangs on a black screen. This morning I did that flick over to Mini and back again and I think it worked.
On the subject of what things mean in logs, what do “currentItemChanged” and “currentItemTitleChanged” refer to? I would guess wherever I currently am, but then I’m home and not moving, so why would things be changing?
Oooh, I bet it’s because of the restore from backup. Well, I guess in that case the thing to look for is whether the number is going down each day or not As long as it’s going down, eventually it’ll get through it.
And in one of the updates a month or two back I changed it so that it always tries to update first the model for the area you’re currently in. To make sure that even if it doesn’t get through everything, at least it’s got the most important model (ie the currently in use model) updated.
Hmm. I tend to never worry about the store sanitise task, because it’s not super vital, and it looks after itself. But if it hasn’t finished in a long time, I wonder if I should pay attention. Just looking through the list of things it does, it’s actually quite a long list now. Though almost all of them are trivially simple and quick, and/or not really very important.
orphanSamplesFromDeadParents
adoptOrphanedSamples
detachDeadmenEdges
hardDeleteSoftDeletedObjects
deleteStaleSharedModels
deleteUnusedWorkoutImports
pruneSampleRTreeRows
backfillSampleRTree
deleteOldTempFiles
The first three should complete in seconds. The next three are deletes of cruft, and will complete in less than a second total, and are also not very important. Of the last three the only one that should take any time is the backfillSampleRTree, which I bet is what’s making it take a bit of time. With millions of samples in the database, and the r-tree index being empty after a restore, that’ll take a while.
Though the r-tree index doesn’t need to be complete. Each time the sanitiseStore task runs it only tries to backfill 50k samples. It’s just trying to chip away at the workload gradually over time. The CD2 model updates want that r-tree index, for finding samples inside each model. So as the index fills out, the model updates will produce better results. But it’s not vital, so being not finished isn’t a big deal.
I guess I’d only worry about that store sanitise not finishing if it’s getting hung up on one of the first three. Which I can’t imagine ever happening. And I guess even if it did get hung up on those, it wouldn’t be a big deal for the timeline processing - the timeline processor does those same tasks each time it does a processing loop, just constrained to the small piece of the timeline it’s working on, instead of trying to do it for the entire database.
Eh, I’m still leaning towards “it’s not a big deal”, but now I’m curious which part is taking a long time! Though there’s probably no easy way to figure that out.
Hmm. That doesn’t feel great. But I guess as long as the pending CD2s count is going down, it’s a “shrug” instead of a “oh fuck”. So yeah… please tell me that number is going down
I enjoyed writing that code far more than I should have Also easily amused.
If it hangs with a black screen on opening, that’s a bug that’s been bothering me or a while. That typically means that the database is locked, so the app is stuck not being able to load data for building the UI, leaving it hanging while trying to “grow a head” until the database unlocks. That shouldn’t happen.
I think what might be going on is one of the apps happens to be running a scheduled background task at the time, like iCloud backups or something else that really hammers the database. And that’s consuming all of the database threads in the thread pool (or however it works), meaning that the other app is being told that the database is locked and it needs to wait.
I usually only notice that black screen on opening when I’ve got the phone plugged in to power, which is another clue that it could be database locked / some hefty scheduled task running, because those tasks are all scheduled to only run when the phone is plugged in.
But unfortunately it’s something that I can only debug when the phone is also connected to the Xcode debugger, which it never is when I see it happen. So I’m left just making wild guesses, which is annoying.
Oh interesting, I haven’t seen those in ages. Oh it looks like only Mini is logging those - I took out those log lines in Arc App. Hmm. Let’s see what they mean…
Ok, looks like they do mostly mean what they sound like. It means there’s a new current item, or the current item’s title changed, respectively. For the current item changing even when you’re stationary at home, that can happen if the recording engine came out to sleep mode and started recording for a little bit, due to drifting location data. It should then realise within a couple of minutes that it was nonsense, then go back to sleep, and the timeline processor will merge it all back together and tidy it up like nothing happened.
For the title changing, I guess that could be something like it changing from “Brief Stop” to “Home” or whatever, once the Place classifier has been run and a Place assigned. The recording engine needs to broadcast that change, because other things elsewhere might need to update, like the widgets or the iOS Home Screen long press menu, or… dunno what else. Heh.
Aside: All those debug views also exist in Arc App’s TestFlight beta builds. If you want to get at them there too, let me know and I’ll add you to the TestFlight! There’s nothing interesting happening in the beta builds at the moment (I’m working on a This & That update instead for the next week or so). But the TestFlight builds at least do have those debug views, and they become addictive once you’ve got them
It technically is, but very very slowly. It’s at 6,719 now. The “Failed to schedule coreMLModelUpdates” message is still cropping up frequently in Session Logs.
sanitiseStore completed 2 days ago! It’s got that double exclamation mark symbol next to it under “OTHER TASKS” but hey, at least it completed more recently than the 16 days overdue as before.
Oh ok, that’s interesting! And a much better scenario than my internal monologue that immediately jumps to “something is dying!”
That would be great! Thanks! What info do you need from me if anything?
Hmm. I’m still nervous about that “failed to schedule”, but if the number is going down then I think we’re okay. What you’ll probably see is some days it makes little to no progress, then some days it makes massive leaps. Like, probably the overwhelming majority of those models will be for regions where you only flew over quickly in airplane. Those model builds/updates take milliseconds, so as long as iOS actually lets Arc keep doing them, it can churn through tens or even hundreds of them extremely quickly.
It’s only the big models that take time, like for neighbourhoods where you’ve actually lived or worked for extended periods of time. Although even those ones should typically only take a handful of seconds each. But it seems like that handful of seconds is enough to start angering iOS, making it more likely to call a halt to the task sooner. I think iOS’s reasoning is that if an app is doing sustained CPU/GPU usage over a number of seconds, that’s bad, and it should be stopped, even if it’s doing that inside a properly scheduled background task, and even if that processing work is technically being done by iOS itself (given that the CD2 models are Core ML models, which are all entirely built and managed by iOS).
So yeah, an awkward situation, in conflict with a not entirely kind or understanding iOS, but it’ll get there eventually. And it’ll also always be update the most important model first, ie the model for where you are right now. So the backlog shouldn’t impact the app’s accuracy.
Well ok, there is one case where it might get annoying. If for example you live in one neighbourhood and work in another, with the two neighbourhoods falling into different CD2 model regions. If iOS decides to only ever run the CD2 updates while you’re at home, the model for home’s neighbourhood will be all nice and up to date, but the work one potentially not so much. The hope there is that if your phone is plugged in at work, iOS will also run the model updates task at that location sometimes. Otherwise it’s just a matter of chance whether the work neighbourhood model gets picked during an updates run.
Aside: I had that exact problem at my last condo in Bangkok - my house was right on the border between two CD2 regions But in practice it wasn’t a problem as long as there wasn’t a massive backlog of models to update. And whenever I have had one of those massive backlogs (like when doing frequent full restores from backup while testing the backup/restore code), typically the backlog has cleared up within a week or two.
Cool I’ll add your email from your support forum account to the TestFlight. Assuming that email is suitable, otherwise DM me another
Yay WFH then, I suppose! I wonder if my Moves import has anything to do with it. Because Moves’s data is a total mess that I’m slowly chipping away at, plus I lived in a completely different city.
I think Moves data isn’t used by the CD2 models (or any of the models apart from the Places classifier), because it’s too low detail / missing important fields the models need. Though I should double check that.
I suspect something like 95% of those pending CD2s will be from airplane flights. When you’re flying you pass over hundreds of CD2 sized regions (with perhaps only one or two samples recorded in each, before you fly into the next). So each time you fly there’ll be usually be hundreds of models pending update afterwards. But thankfully updating those models is absurdly fast. It’s just a matter of iOS letting it happen!
The difference between the monthly auto export tasks and the iCloud backups is the auto exports have to load (and write to disk) all the samples data for the entire month, even if only one of the samples changed. The iCloud backups instead only have to load and write to disk a week of samples, because the backups collate the samples into weekly files.
As long as it’s going down, eventually it’ll get through it.
But in practice it wasn’t a problem as long as there wasn’t a massive backlog of models to update. And whenever I have had one of those massive backlogs (like when doing frequent full restores from backup while testing the backup/restore code), typically the backlog has cleared up within a week or two.
I’ll add your email from your support forum account to the TestFlight. Assuming that email is suitable, otherwise DM me another 