Popcon not working

[ticalc-travis]

Is anyone still using Popcon to sort the app list? I noticed recently that it doesn't appear to be storing any new entries at all, neither with Desktop Launcher nor the system Launcher. Maybe something to do with fast load or the loader mechanism changing? I added some debug code and can confirm that Popcon doesn't see the apps getting loaded at all from the launchers. But if I manually call the load function in the console, Popcon logs it fine.

[ticalc-travis]

So, since I can't resist tinkering with things, I looked into it and see that the current launchers appear to use the launch_utils library, and that library uses Bangle.load to launch apps. Popcon modifies the global load function to record the launch of the app, but not Bangle.load. If I add code to Popcon to amend Bangle.load in the same way as global.load, it appears to work. But is this a good idea?

I notice that it does slow down app launching a fair bit (by about a full second), which is not too surprising because it has to do the extra work of compiling stats and sorting, etc. For me, not having to scroll through several pages every time I want to launch my most-used apps makes up for the extra delay, though.

Only thing is that it takes a second before the “Loading” message is displayed, which is a little confusing. Ideally I could make a loading message appear just before Popcon does its thing, to provide immediate user feedback.

Or, if there was a way to manually arrange the app list by hand, I could put all my favorite apps at the top and not need all the overhead of Popcon's automatic arrangement algorithm, and app launching would be faster. Is this possible? I'd only have to rearrange the list whenever I added an app or changed my habits, which wouldn't be too bad, I think.

[thyttan]

which is not too surprising because it has to do the extra work of compiling stats and sorting, etc.

If you wrap the compiling/sorting stuff in a zero second timeout will that make it so the next app displays faster? I imagine then maybe it will run after the next app has been set up? 🤔 At least for the Bangle.load case. Not sure though.

I think we could probably merge what you already got going though. It's still an improvement over status quo.

[thyttan]

Or, if there was a way to manually arrange the app list by hand

You can do this as well, yes. A watch app or an app loader interface that modifies the sortorder attribute of apps on the watch.

[gfwilliams]

If you wrap the compiling/sorting stuff in a zero second timeout will that make it so the next app displays faster? I imagine then maybe it will run after the next app has been set up?

... not if you're doing a full load rather than a fast one though.

If popcon is overloading load then overloading Bangle.load too doesn't seem like a big problem. I'd just do that for now.

You could call https://www.espruino.com/Reference#l_Bangle_showLoadingScreen - on recent-ish firmwares that can display the loading message (or something from the loadingscreen app).

If it's taking 1 sec then I guess that would apply to load() as well. It might be worth looking into why it takes so long in the future though - I feel like it shouldn't. It's possible that it only takes that long when it re-arranges apps, and that when you're starting off and launching stuff, app order changes almost every time. After a while it might calm down.

Another option is to have it just keep track of how often apps are launched (which should be decently fast) and to then use the midnight event to check at midnight when likely the watch isn't being used and re-arrange stuff then

[ticalc-travis]

Okay, I'll do it the safer way, then, and maybe call showLoadingScreen.

But I'm thinking maybe I'm mistaken. I thought Popcon was slowing launch down, but it turns out the delay isn't consistent and doesn't always take that long. Sometimes it seems to take a bit longer than others? At any rate, it looks like the delay might actually be somewhere other than Popcon after all, because even with the showLoadingScreen call first I often see at least a brief delay from the time I tap to when the loading message appears. This is both with the system Launcher as well as Desktop Launcher.

Do we happen to have any profiling tools available?

[gfwilliams]

Well, it might be the delay is only when Popcon decides it needs to reorder the apps, and then it causes the launcher cache to be re-written?

There are some options to checking speeds at https://www.espruino.com/Bangle.js+Performance - plus there's https://banglejs.com/apps/?id=performance - but it may not help with launcher issues

[ticalc-travis]

I started to have a feeling that Popcon might not have been contributing much to the delay. I ended up just doing some tests the old-fashioned way, by throwing in a bunch of console.debug(new Date().getTime()) in various places in the launcher and launch_utils and comparing the timestamps to get a feel for what step was taking the longest.

The slowest potential line I found was actually in cacheWidgetsCheck in launch_utils, specifically this one:

app.wid = (src!==undefined)&&src.includes("Bangle.loadWidgets");

I assume it's the search for “Bangle.loadWidgets” in the app's source code that can take a little while, especially for large apps. Usually, it's not that long, but for the largest .js file currently on my Bangle (NES Clock), the delay is fairly noticeable. I think the “Loading…” message gets printed by Bangle.load, which doesn't get called until after cacheWidgetsCheck finishes, so it appears that the loader is not responding for perhaps about half a second or so in the worst case I was able to find. Adding a call to Bangle.showLoadingScreen at the very top of launch_utils.loadApp seems to hide this delay nicely by providing more immediate feedback.

Optionally, perhaps it might be worth caching the result of src.includes("Bangle.loadWidgets") for each app in order to shave a little more time off of loading?

[thyttan]

Optionally, perhaps it might be worth caching the result of src.includes("Bangle.loadWidgets") for each app in order to shave a little more time off of loading?

It should already do that - doesn't it?

    app.wid = (src!==undefined)&&src.includes("Bangle.loadWidgets");
    // Now update the launch cache to save having to do this again
    let a = launchCache.apps.find(a=>a.src===app.src);
    if (a) a.wid = app.wid;
  });
  s.writeJSON("launch.cache.json", launchCache);

https://github.com/espruino/BangleApps/blob/master/modules/launch_utils.js#L70-L74

[thyttan]

The way it's supposed to work in operation is the first time an app is launched (or if the hash changed) it does the widget check for that app and then caches it. Following that launch_utils should just look at the cache to see if the .wid attribute is true or false.

Reference:

However it took ages to load the launcher after new apps were installed. Cutting edge firmware is a bit better, but still slow, so what I've done is I check for the presence of loadWidgets when the app is loaded the first time, which I think is ok.

Originally posted by @gfwilliams in #4099

[gfwilliams]

So hopefully if you load an app a second time this check shouldn't happen? Or is there an issue here?

Or maybe when popcon invalidates the cache when apps change order, it inadvertantly wipes out all that data about widgets?

[ticalc-travis]

Yes, I believe once I deleted and rewrote the app cache file in storage, the app widget information was getting written and actually sticking this time, so it's not reexecuting the caching code anymore.

I am quite sure the problem has nothing to do with Popcon.

What was happening before was that apparently the system was in a confused state, and code on the Bangle itself was reading a different version of launch.cache.json from the one that appeared in the IDE when I loaded it. And apparently when apps on the Bangle tried to write over the file, those changes weren't showing up on a read, but instead they kept getting the old version of the file again and again.

Only when I manually deleted the file and then resend it from the IDE did things start working normally again. At that point, I could load the file in the console and see that the changes the launcher had been trying to write to it were appearing with each app launch, unlike before when the file was behaving as if it were read-only and writes were being silently discarded.

Before my wipe and reload from backup, I had seen this kind of behavior occasionally on other files, including one case where the IDE did list the same filename twice. But in this case, I did not see launch.cache.json listed twice, yet it was still behaving oddly until I removed and rewrote it. I still have no idea what's going on. This just seems to come up at random every few weeks, and it's only when I encounter weird glitches like this that I discover something off.

[gfwilliams]

Glad it's fixed now anyway. It's hard to know exactly why it'd be an issue, but perhaps if you encounter it again I can have a go at coming up with something to image your flash contents so we can see if there's anything obvious wrong.

Otherwise it might just be a matter of doing a check after write for file erases to ensure that the file really was erased.

[ticalc-travis]

Okay, I seem to have missed the forest for the trees here, but there's apparently something fishy going on in my Bangle. In my tests, the work of determining whether the app uses widgets and trying to cache the result is being executed on every single launch, every time.

I checked my launch.cache.json storage file, and it doesn't seem like there's anything wrong, but if I run print(require('Storage').readJSON('launch.cache.json')) in the console, the result is rather strange and doesn't quite match the file. Many entries are missing the wid key (actually, some of them are missing in the Storage file itself, but even more are not getting read back after parsing for some reason).

Edit: Even if I use require('Storage').read, I'm getting different file contents displayed than when I open the file in the IDE. Huh?

Does anyone see any problems with the contents of this launch.cache.json file?

{hash:-1043183609,apps:[{name:"Triangle timer",icon:"triangletimer.img",src:"triangletimer.app.js"},{name:"tev's timer",icon:"tevtimer.img",src:"tevtimer.app.js",wid:true},{name:"Timestamp log",icon:"timestamplog.img",src:"timestamplog.app.js"},{name:"Settings",icon:"setting.img",src:"setting.app.js",wid:true},{name:"NES Clock",type:"clock",icon:"nesclock.img",src:"nesclock.app.js",wid:true},{name:"Keypad Timer",icon:"keytimer.img",src:"keytimer.app.js"},{name:"Alarms",icon:"alarm.img",src:"alarm.app.js"},{name:"Health",icon:"health.img",src:"health.app.js"},{name:"Stopwatch",icon:"stlap.img",src:"stlap.app.js"},{name:"About",icon:"about.img",src:"about.app.js"},{name:"Heart Rate Monitor",icon:"hrm.img",src:"hrm.app.js"},{name:"Stopwatch laps",icon:"stlapview.img",src:"stlapview.app.js"},{name:"Anton Clock+",type:"clock",icon:"antonclkplus.img",src:"antonclkplus.app.js"},{name:"GPS Navigation",icon:"gpsnav.img",src:"gpsnav.app.js"},{name:"Adjust Clock",icon:"widadjust.img",src:"widadjust.app.js"},{name:"Waypoints",icon:"waypoints.img",src:"waypoints.app.js"}]}

Edit 2: This seems to be another Storage issue. Compacting flash did not solve the issue, but deleting the cache file and writing it back from the IDE did. There seems to have been a glitch where an old version of the file was somehow hidden in memory and new changes were not being saved. This just happened after I completely wiped the flash and reloaded from a backup, so I'm getting a bit concerned. Could the flash on my Bangle be somehow dying? Or maybe there's some kind of storage bug?

[thyttan]

What firmware is this on? EDIT: version number and regular/iflash/noflash build?

Does the problem persist if you use the reinstall all apps function of the app loader (do a backup first)?

[thyttan]

Do you use the IDE at https://www.espruino.com/ide/# or https://espruino.github.io/EspruinoWebIDE/#?

The latter one seems to have some problems for me (not decoding all files or even presenting the option).

But the former ( "official") one works fine as far as I can tell.

EDIT: Actually now both seems to suffer from not being able to decode some files (e.g. my .widcache file).

[gfwilliams]

If you do print(require("Storage").list()), do you see launch.cache.json in there twice? That's a sure sign that something isn't right!

Doing a reload from backup should totally fix that though.

[ticalc-travis]

I didn't get a chance to try that diagnostic, and I'm afraid I probably nuked the evidence by deleting and resending the affected file trying to get things working again, which seems to have cleared the glitch, at least for now. (I did try it after the fact but didn't see any duplicates in the result.)

If it ever happens again and it's not happening to a mission-critical file, maybe we can try to do more investigation then.

[ticalc-travis]

FYI: I added an update to the end of my last post, possibly right after you responded.

This is on 2v29. You reminded me, though, that I'm running a local version of the IDE that I haven't remembered to pull updates from in a long time, so maybe I'd better do that.

[thyttan]

Off topic: Having the noflash build available for those with corrupted flash storage is good. But maybe the iflash build being on the app loader is more cumbersome than useful? As much as I like to get as much speed as possible, it does introduce a variable for potential bugs and debugging.

Just a thought.

[gfwilliams]

Having it flashable by the app loader is handy - but maybe it should be hidden under an 'advanced' drop-down or something?

[thyttan]

Yeah that could make sense!

I also wonder, could the firmware version string include " iflash" or " noflash" so when the Espruino logo is shown in the console it's very apparent it's not the regular build? Or something like that. Maybe it doesn't make sense to append it to the actual version string for other reasons.

[gfwilliams]

I guess it could be added - but have we hit any issues so far caused by people using " iflash" or " noflash" builds and not mentioning it?

[thyttan]

When you put it like that it doesn't come to mind, no. It's probably mostly me who jumps between regular and iflash builds from time to time and sometimes I forget which one is on my watch.

So no immediate need for changes 🙂‍↕️

[ticalc-travis]

Just regular. No cutting edge.

[ticalc-travis]

Okay, so I think the app caching is working on my end again, so there is a very minimal delay between tap and loading screen. Occasionally I can still notice a very brief delay. I'm probably nitpicking a bit, but I like the result of putting an extra Bangle.showLoadingScreen() at the beginning of launch_utils.loadApp. It may not be strictly necessary, but the “Loading…” message feels perfectly instantaneous when I do this, even with Popcon installed. It's nice because it makes the UI at least feel even more responsive, even if the actual loading time hasn't changed.