Getting rid of log-based user communication

[RumovZ]

As discussed previously, last in #547, the log widget should not and cannot be used to reliably communicate information to the user. This issue is to track instances where log messages are currently used in such a way, and find alternatives.
Feel free to edit.

---

I've identified three categories of events that I would give user feedback for, where there's currently only a log message. Anything related to USDB and resource quality remaining solely in the log is fine with me.

Failed synchronous actions

GUI alternatives: toast, modal dialog.

• Not logged in, skipping song submission.
• Song does not exist locally anymore.
• Song does not exist locally.
• No current song.
• no files selected to import USDB IDs from
• Skipping export: no songs selected.
• export aborted
• Cannot submit: song is not remote.
• Cannot submit: remote song parsing failed.
• Cannot submit: song is not local.
• Cannot submit: song is not synchronized.
• Cannot submit: song has no local changes.
• Not downloading song as it is pinned.
• Not trashing song folder as it is pinned.
• imported USDB IDs are not available:
• Failed to import file '{path}': {error!s}
• Failed to fetch new songs; check network connection.

Successful synchronous actions

GUI alternatives: toast.

• Local changes successfully submitted to USDB.
• exported {len(selected_ids)} USDB IDs to {path}
• PDF report created at {path}.
• JSON report created at {path} ({num_of_songs} songs).
• Webserver is now running on {address()}
• Webserver was stopped.
• available _ imported USDB IDs will be selected:
• Fetched _ updated song(s) from USDB

Background errors

Here, something more involved is required: Maybe some sort of indicator that something went wrong, a searchable / filterable overview of errors, and stopping further downloads for persistent errors (like missing USDB login).

• Baiscally everything in song_loader.py and usdb_scraper.py.

[RumovZ]

Two more downsides of the GUI log I've noticed:

• It keeps all the messages in RAM to support filtering. This can eat a lot of memory over time.
• It's really slow. Loading ~25,000 meta files on my machine takes about 30 seconds during startup, but 200 seconds after the GUI has been loaded and all the messages get rendered to the screen. When disabling logging entirely, it only takes 12 seconds.

So when the solutions above are implemented, we should not only hide the GUI log, but get rid of it entirely, or at least of repetitive messages as much as possible.

[randompersona1]

It's really slow. Loading ~25,000 meta files on my machine takes about 30 seconds during startup, but 200 seconds after the GUI has been loaded and all the messages get rendered to the screen. When disabling logging entirely, it only takes 12 seconds.

Whoa. I know logging isn't fast, but that seems extreme. I don't know how Qt signals work exactly, but I feel there must be a bottleneck we're unaware of. I'm currently unable, but I could take a look in a week or so.

How does that not show up on profiling runs? I did some tests a couple of weeks ago, but logging wasn't suspicious at all.

[RumovZ]

Hm, this time I basically got reversed results. Something else must be going on. Logging still takes considerable time (~10 secs), but it doesn't explain those stark differences I get.
I'll investigate further. Profiling doesn't work great with Qt's C code, and the current implementation only captures the main thread.

On the topic of performance, loading pdf.py, probably registering the fonts, is also really slow. It costs several seconds on every startup, even though it isn't used most of the time. @bohning, it would be best to only do the work once a PDF report is actually built.

[RumovZ]

I've now switched to py-spy. It confirms that a lot of time is spent logging. However, contrarily to what I've written above, it doesn't seem to matter whether the main window is already shown or not. No idea why it sometimes takes 30 and sometimes 200 seconds. Very weird. 😕
Still, disabling the log message consistently speeds up the _SyncMetaFolderSyncer.process() by a factor of 2 to 3, both in the 'fast' and in the 'slow' case. In the flamegraph, you can see half the time is taken up by logging, of which in return half is taken up by logging to the QPlainTextEdit.

(Download and open image in browser for interactivity.)

[bohning]

On the topic of performance, loading pdf.py, probably registering the fonts, is also really slow. It costs several seconds on every startup, even though it isn't used most of the time. @bohning, it would be best to only do the work once a PDF report is actually built.

Like this? #556