Requesting help for diagnosing ES issue on Pi4B

roslof · 18 Jul 2022, 12:23

System:

Linux retropie 5.10.103-v7l+ #1529 SMP Tue Mar 8 12:24:00 GMT 2022 armv7l GNU/Linux
Good morning,

Symptom: ES temporarily hangs on "Favorites" for about 55 seconds on a particular SDCard, but not on another with the same version of ES (mostly the same content).

I'm trying to diagnose an issue I'm having with EmulationStation and my particular setup. For me, on my primary MicroSD card, when ES is booting, eventually "Favorites" is displayed (and the blue status bar appears full).

At this time, ES exhibits odd behavior, as it hangs for about 50 seconds. During this window of time, the CPU is pegged at 100% for exactly one (1) CPU core (seen with htop). Eventually, the system will load, but will sometimes result in "EmulationStation has crashed". I have a slightly older card with proper behavior (~5-10 sec. while "Favorites" is displayed and it never crashes), and its running same version of ES, so I know the issue has to do with my configuration/content and not with ES itself.

I used emulationstation --debug while helped me determine that ES is doing something after my three (3) primary Favorites have been parsed, but before the Joystick is read.

es_log.txt tail looks like this:

Jul 18 05:02:12 lvl2: 	Loading custom collection config file at /home/pi/.emulationstation/collections/custom-cave.cfg
Jul 18 05:02:16 lvl2: 	Loading custom collection config file at /home/pi/.emulationstation/collections/custom-neogeo.cfg
Jul 18 05:02:16 lvl2: 	Loading custom collection config file at /home/pi/.emulationstation/collections/custom-vector.cfg
Jul 18 05:03:11 lvl2: 	Added known joystick Sony Interactive Entertainment Wireless Controller (instance ID: 0, device index: 0)

Note the 55 second gap in time in the last two (2) lines. With my other sdcard with the same collection, the log looks identical, but the gap is closer to 10 seconds.

Was wondering if anybody knew what ES is doing during this time, so I can better diagnose what my issue is. I don't believe ES has verbose logging, or at least not around this area.

Steps I used to troubleshoot, so far:

Tried latest ES and ES-Dev (same results)
Tried removing certain systems and/or removing some rom folders to no avail
Tried Removing Favorites, but the issue actually seems unrelated

Any help understanding ES behavior during this window of time could help me figure out the root cause.

Cheers!
-ros

mitu · 18 Jul 2022, 18:01

If I were to guess, I'd say you have too many ROMs.

After systems are parsed/added in EmulationStation, there's a Preloading UI shown which creates each system's view based on the theme and the ROMs included. I may be wrong on the order, but preloading may be the place where EmulationStation's startup is spending the most time.

Are both systems using the same theme ? Do they have the same number of ROMs ?

roslof · 18 Jul 2022, 19:53

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

Are both systems using the same theme ? Do they have the same number of ROMs ?

With the same theme and roughly the same # of roms, there is this speed delta. If I nuke all but one rom folder or edit es_systems.cfg to only load one system, it's zippy. Still trying to figure out why my full set is so much slower on one setup than the other.

Note that "Preloading UI" with bar appears after the long delay. That isn't shown in the debug logs though.

Clarifying: Order is:

UI shows "Favorites"
Debug shows "Favorites" dirs being parsed (quickly)
UI holds on "Favorites" and status bar is at 100% . Waits for another 50 seconds with CPU spiked on 1-core
UI shows "Preloading UI" and status bar moves swiftly.
UI shows "Done" with an expected delay

mitu · 19 Jul 2022, 04:03

OK, so the slowdown is before the system views are being rendered. I'll have to take a look to confirm if the collections are the ones that are checked at that point (Favorites dirs).

Do you have ThreadedLoading enabled in either of the systems ? Does the slowdown occurs if you toggle the Parse Gamelists Only option ?

mitu · 21 Jul 2022, 03:58

I've looked briefly at the code behind the 'Favorites' splashscreen section and it only checks for the collections that need to be enabled, in order to create views for them (in the next phase, when 'Preloading UI' is shown). Doesn't seem to do much work at that stage.
How many (enabled) collections do you have ?

roslof · 21 Jul 2022, 04:10

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

How many (enabled) collections do you have ?

Only three (on both systems). I've also tried removing collections and there is no noticeable speed change.

roslof · 21 Jul 2022, 04:12

@mitu thank you as always for your help. I'll play around with other setttings as you mentioned a couple of days ago. The issue is definitely with my setup (somehow) and not with ES. If I figure it out, I'll report back in case others experience this in the future.

mitu · 21 Jul 2022, 04:20

You trace what ES is doing during that time using strace (needs to be installed with sudo apt install strace).

When the slowdown/freeze starts, run

strace -f -p `pidof emulationstation` -o $HOME/es_trace.log

and leave it for a few seconds. Interrupt with Ctrl + C and post the log on pastebin.com.

roslof · 21 Jul 2022, 04:48

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

You trace what ES is doing during that time using strace (needs to be installed with sudo apt install strace).

When the slowdown/freeze starts, run
strace -f -p `pidof emulationstation` -o $HOME/es_trace.log
and leave it for a few seconds. Interrupt with Ctrl + C and post the log on pastebin.com.

PASTEBIN HERE

Useful. It's stuck in a temp loop.
You'll note 100,000 Pyramid.png repeats.

This was the last game played and the matching screenshot image. Subsequent restarts of ES yield the same. I confirmed that launching any other game from any system will display that game's screenshot in the log repeatedly.

EDIT/WORKAROUND: Found the configuration diff. Current system has the Automatic Game Collection "Last Played" enabled. Older (faster system) does not. Turning off "Last Played" solves.

mitu · 21 Jul 2022, 04:56

@roslof said in Requesting help for diagnosing ES issue on Pi4B:

You'll note 100,000 Pyramid.png repeats.

Well, you need to get to that 100,000 somehow :).

Turning off "Last Played" solves.

Yeah, there's something fishy with that loop for the last played collection.

Can you zip your gamelists (the .xml files) and attach them somewhere ? I could try to reproduce the issue on my end and see where's the bug.

roslof · 21 Jul 2022, 05:00

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

@roslof said in Requesting help for diagnosing ES issue on Pi4B:

You'll note 100,000 Pyramid.png repeats.

Well, you need to get to that 100,000 somehow :).

Turning off "Last Played" solves.

Yeah, there's something fishy with that loop for the last played collection.

Can you zip your gamelists (the .xml files) and attach them somewhere ? I could try to reproduce the issue on my end and see where's the bug.

Can do. Confirming: Since they're all named gamelist.xml, should I place each one in it's own <system_name> folder?

mitu · 21 Jul 2022, 05:06

Use this:

# if gamelists are in the rom folders
cd $HOME/RetroPie/roms
find -type f -name gamelist.xml | zip -@ zippy1.zip

# if gamelists are in the ES config folder, then
cd $HOME/.emulationstation/gamelists
find -type f -name gamelist.xml | zip -@ zippy2.zip

and upload the .zip files somewhere.

roslof · 21 Jul 2022, 05:14

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

and upload the .zip files somewhere.

Yeah, you make this too easy.
somewhere (feeling cheeky)
UPDATE: ZIP is now password protected. PW is my complete email.

mitu · 21 Jul 2022, 19:34

You can remove the file, I've downloaded it.

After creating files from the gamelists and loading them in ES, I can see the issue also. Note that some games haven't been added, the ones in sub-folders.

The problem is indeed related to the Recent games collection, you have a lot of ~~them~~ games with lastplayed set. Now, the Recent collection is a bit more special than the others, it's picking up all games where lastplayed is set, then sorts it and finally shrinks it to 50 items. The issue is in the shrinking stage, since removing has more checks then simply adding the file, here's a rundown (note the timestamp on each operation):

[...]
Jul 21 20:23:54 lvl1: 	File "/home/pi/RetroPie/roms/zxspectrum/Snoopy & Peanuts (1989)(Softek International)(128k).zip" does not exist! Ignoring.
Jul 21 20:23:57 lvl2: 	Finished collecting: all, size: 50702
Jul 21 20:23:58 lvl2: 	Finished collecting: favorites, size: 295
Jul 21 20:23:58 lvl2: 	Finished collecting: recent, size: 6199
Jul 21 20:23:58 lvl2: 	 Begin trimming
Jul 21 20:24:28 lvl2: 	 Ended trimming
Jul 21 20:24:28 lvl2: 	Finished triming: recent
Jul 21 20:24:35 lvl3: 	SystemView::getViewElements()
Jul 21 20:24:35 lvl3: 	fireEvent: system-select 3do gotostart

Most of the time is spent in the trimming code, which looks to be inefficient when called 6000+ times to remove 1 game at a time.

While not a bug, I think there's some optimizations that can be done to make this go faster.

EDIT: did you really started 6000+ games or is this some sort of scraping fluke ?

roslof · 21 Jul 2022, 19:38

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

While not a bug, I think there's some optimizations that can be done to make this go faster.

Makes sense and understood. I could easily scrub the XML files and remove the recent flags, but this will slow over time. Best for me, for now, to simply turn off the Recent collection.

Cheers, @mitu !

roslof · 21 Jul 2022, 19:39

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

EDIT: did you really started 6000+ games or is this some sort of scraping fluke ?

I have, and not a fluke. Working on this since 2017 and never stopped. You can see by the most 'recent recents' that there are frequently many game tests a day.

mitu · 21 Jul 2022, 19:43

@roslof said in Requesting help for diagnosing ES issue on Pi4B:

Best for me, for now, to simply turn off the Recent collection.

Yeah, that's unfortunate (for now), but it's best to keep lastplayed saved. I myself use it as a start system, this way when ES starts, you're back to your last played games and start again.

mitu · 27 Aug 2022, 04:11

@roslof when you have the chance, can you try installing the latest emulationstation-dev from source ? There's a fix added that should help speed up the initial loading.

roslof · 27 Aug 2022, 19:44

@mitu said in Requesting help for diagnosing ES issue on Pi4B:

@roslof when you have the chance, can you try installing the latest emulationstation-dev from source ? There's a fix added that should help speed up the initial loading.

@mitu as you would expect, with Last Played toggled true, load times are no longer in excess of 50 seconds for me. Cheers to you for the fix!