quodlibet / quodlibet

Music player and music library manager for Linux, Windows, and macOS
https://quodlibet.readthedocs.io
GNU General Public License v2.0
1.41k stars 223 forks source link

Responsiveness issues when disk IO is slow #2065

Closed ruuda closed 7 years ago

ruuda commented 7 years ago

I often stream music off the (slow) disk on a device in my network, or over internet even, by mounting it as an sshfs. Obviously reading from this file system is slower than reading from a local file system. I get a bandwidth of around 3 MiB/s. That’s not a lot, but for streaming music it is plenty.

Now there are a few issues:

The last two points are annoying every now and then, but I think these are an acceptable consequence of using a slow file system. Better performance (especially avoiding stutter in playback) would be nice to have. The first issue is quite annoying however. Once Quot Libet is loaded, it runs quite smoothly apart from the occasional hiccup; playback is starts quickly and browsing the library and searching are all responsive (after I have scrolled through the album list once to load the covers).

I am not familiar with the internals of Quod Libet, but my guess is that the application is doing blocking IO on the thread that is also responsible for UI operations. Ideally all IO would be async, but that would be a large and invasive change to an existing application. And to be fair, even with slow disk IO the application is still “responsive enough” most of the time. However, I hope that startup time can be improved. Is the application perhaps accessing more data than it needs to? Or could some operations be delayed until after the UI has been fully initialized?

Please let me know if there is anything I can do to further diagnose the problem. I would also be happy to try and work on a fix if somebody can point me in the right direction.


OS: Arch Linux with Gnome 3.22, kernel 4.7.6. Quod Libet: 3.7.1 installed from the Arch repositories.

lazka commented 7 years ago

I often stream music off the (slow) disk on a device in my network, or over internet even, by mounting it as an sshfs. Obviously reading from this file system is slower than reading from a local file system. I get a bandwidth of around 3 MiB/s. That’s not a lot, but for streaming music it is plenty.

Now there are a few issues:

  • The application is extremely slow to start up, and during startup no window is painted. The time between starting the application, and the moment the window appears, is ~10 minutes. This is with the “Scan library on start” option disabled in the preferences. My library contains about 10k songs and weighs around 300 GiB. I’d hope that Quod Libet doesn’t need to read much of this data just to get a window on the screen. (I am fine with cover art appearing later on demand, and library updates taking place in the background.) For reference, running du or find . in my library (mounted as sshfs) — operations that access the metadata of every file — takes about 20 seconds. Slow, but not the minutes Quod Libet is taking to start. When I look at the process in htop, I see that the application is blocked on disk IO for long streches of time (~a dozen seconds), then runs briefly, and goes back into being blocked on disk IO.

Which browser is active? Does it change when using the simple search browser

  • I occasionally experience stutter during playback, or even dozens of seconds of silence. I have already set the buffer duration to the maximum value in the playback preferences, but I am not sure whether that applies to readahead from disk, or buffering decoded output samples.

yeah, buffer duration only applies to http streaming. One thing you can do is write "queue" in the "Output pipeline" entry. That will add some additional buffering.

  • Even when loaded, the user interface occasionally locks up completely for a few seconds. Furthermore, scrolling through the album list is not smooth when album art has not been loaded yet.

We do some IO in threads, but not all of it.

The last two points are annoying every now and then, but I think these are an acceptable consequence of using a slow file system. Better performance (especially avoiding stutter in playback) would be nice to have. The first issue is quite annoying however. Once Quot Libet is loaded, it runs quite smoothly apart from the occasional hiccup; playback is starts quickly and browsing the library and searching are all responsive (after I have scrolled through the album list once to load the covers).

I am not familiar with the internals of Quod Libet, but my guess is that the application is doing blocking IO on the thread that is also responsible for UI operations. Ideally all IO would be async, but that would be a large and invasive change to an existing application. And to be fair, even with slow disk IO the application is still “responsive enough” most of the time. However, I hope that startup time can be improved. Is the application perhaps accessing more data than it needs to? Or could some operations be delayed until after the UI has been fully initialized?

Please let me know if there is anything I can do to further diagnose the problem. I would also be happy to try and work on a fix if somebody can point me in the right direction.

Please run the following command python2 -m cProfile -o prof.out $(which quodlibet). Wait until QL settles and quit the program. This should result in a file "prof.out" being generated which you can send me (reiter.christoph@gmail.com)

declension commented 7 years ago

@ruuda, also please try running with --debug as there's sometimes a fair amount of information about what's going on from a higher level.

Also, out of interest, do you have a lot of playlists?

ruuda commented 7 years ago

Apologies for the delay. Of course, right after I report this, I am no longer able to reproduce the issue. Startup times are now back to about a dozen seconds, not the minutes I reported before. I did observe this issue regularly for several months before I reported it and I don’t understand why it suddenly resolved itself. I did upgrade Quod Libet from 3.7.0 to 3.7.1 in the past month, so I downgraded it back to 3.7.0, but I can’t reproduce with that version either.

Which browser is active? Does it change when using the simple search browser?

I am using the Album List browser. At this point it is not noticeably slower than the simple search browser, but I haven’t been able to reproduce the long startup times.

@ruuda, also please try running with --debug as there's sometimes a fair amount of information about what's going on from a higher level.

When I run with debug, the operations that seem to be taking most time (judging by the delay between log messages) are:

SongFileLibrary.load: Loading contents of '/home/ruud/.quodlibet/songs
(About 240 ms.)

AlbumLibrary.__init__: Initializing Album Library to watch 'main'
(About 350 ms.)

player.gstbe.player.__message: Recalculate latency
(About 1020 ms.)

But again, this is for the "fast" (sub-minute) startup times.

Also, out of interest, do you have a lot of playlists?

No, I have two m3u files in my library, but I did not import those. They don’t show up in the playlists browser.

Feel free to close this for now. I’ll report back if I can reproduce this in the future.

lazka commented 7 years ago

Thanks for the profiles, they look pretty normal to me - most of the time is spend loading embedded album art from disk. We should probably look into caching thumbnails for those.

lazka commented 7 years ago

See #2066.

ruuda commented 7 years ago

I am experiencing slow startup times again. I was able to reproduce it with --debug this time. I can sometimes reproduce it reliably, but I haven’t figured out why I can sometimes, and sometimes not. See also more details below.

D: 0.046: util.i18n.init: LANGUAGE: None
D: 0.046: util.i18n.init: LANG: 'en_GB.UTF8'
D: 0.048: util.i18n.register_translation: Translations loaded: '/usr/share/locale/en_GB/LC_MESSAGES/quodlibet.mo'
D: 0.091: formats._misc.init: MimeType=application/x-flac;audio/aac;audio/aiff;audio/midi;audio/mp3;audio/mp4;audio/mpeg;audio/mpeg4;audio/mpg;audio/ogg;audio/vorbis;audio/wav;audio/wave;audio/x-aac;audio/x-aiff;audio/x-flac;audio/x-m4a;audio/x-midi;audio/x-mp3;audio/x-mpc;audio/x-mpeg;audio/x-ms-wma;audio/x-ms-wmv;audio/x-musepack;audio/x-oggflac;audio/x-speex;audio/x-tta;audio/x-wav;audio/x-wavpack;audio/x-wma;video/ogg;video/x-ms-asf;video/x-theora;video/x-wmv;
D: 0.091: formats._misc.init: Supported formats: aac, aiff, midi, mod, monkeysaudio, mp3, mp4, mpc, spc, trueaudio, vgm, wav, wavpack, wma, xiph
D: 0.301: qltk.add_signal_watch: Register Python signal handler: 'SIGHUP'
D: 0.301: qltk.add_signal_watch: Register Python signal handler: 'SIGINT'
D: 0.301: qltk.add_signal_watch: Register Python signal handler: 'SIGTERM'
D: 0.301: qltk.add_signal_watch: Register GLib signal handler: 'SIGHUP'
D: 0.301: qltk.add_signal_watch: Register GLib signal handler: 'SIGINT'
D: 0.301: qltk.add_signal_watch: Register GLib signal handler: 'SIGTERM'
D: 0.375: main.main: Initializing main library (~/.quodlibet/songs)
D: 0.375: SongFileLibrary.__init__: Initializing SongFileLibrary "main".
D: 0.375: SongFileLibrary.__init__: Using pickling persistence for library "main"
D: 0.375: SongFileLibrary.load: Loading contents of '/home/ruud/.quodlibet/songs'.
D: 0.702: SongFileLibrary.load(<libraries.SongFileLibrary object at 0x7f90f5489690 (quodlibet+library+libraries+SongFileLibrary at 0x564e93f21060)>): Done loading contents of '/home/ruud/.quodlibet/songs'.
D: 0.720: devices.init: Initialising device backend.
D: 0.720: devices.init: Trying 'UDisks2'
D: 0.723: devices.init: Device backend initialised.
D: 0.827: PlaylistsBrowser.load_pattern: Loading pattern from /home/ruud/.quodlibet/playlist_pattern
D: 0.828: PlaylistsBrowser.load_pattern: Couldn't load pattern for PlaylistsBrowser ([Errno 2] No such file or directory: '/home/ruud/.quodlibet/playlist_pattern'), using default.
D: 0.829: AlbumList.load_pattern: Loading pattern from /home/ruud/.quodlibet/album_pattern
D: 0.830: CoverGrid.load_pattern: Loading pattern from /home/ruud/.quodlibet/album_pattern
D: 0.830: SongFileLibrary.__init__: Initializing SongFileLibrary "filesystem".
D: 0.830: SongFileLibrary.__init__: Using pickling persistence for library "filesystem"
D: 0.834: UDisks2Manager._try_build_device: Found device: '/dev/sda1'
D: 0.870: UDisks2Manager._try_build_device: '/dev/sda1' not a media player
D: 0.870: UDisks2Manager._try_build_device: Found device: '/dev/nvme0n1p1'
D: 0.902: UDisks2Manager._try_build_device: '/dev/nvme0n1p1' not a media player
D: 0.902: _main.init_plugins: Starting plugin manager
D: 0.903: _main.init_plugins: Scanning folders: ['/usr/lib/python2.7/site-packages/quodlibet/ext/editing', '/usr/lib/python2.7/site-packages/quodlibet/ext/events', '/usr/lib/python2.7/site-packages/quodlibet/ext/playorder', '/usr/lib/python2.7/site-packages/quodlibet/ext/songsmenu', '/usr/lib/python2.7/site-packages/quodlibet/ext/playlist', '/usr/lib/python2.7/site-packages/quodlibet/ext/gstreamer', '/usr/lib/python2.7/site-packages/quodlibet/ext/covers', '/usr/lib/python2.7/site-packages/quodlibet/ext/query', '/home/ruud/.quodlibet/plugins']
D: 0.903: plugins.__restore: Restoring plugins: 5
D: 0.903: PluginManager.rescan: Rescanning..
D: 0.903: ModuleScanner.rescan: Rescanning..
D: 1.042: ModuleScanner.rescan: Rescanning done: 87 added, 0 removed, 5 error(s)
D: 1.044: PluginManager.rescan: Rescanning done.
D: 1.044: PluginManager.register_handler: Registering handler: 'EditTagsPluginHandler'
D: 1.044: PluginManager.register_handler: Registering handler: 'RenameFilesPluginHandler'
D: 1.044: PluginManager.register_handler: Registering handler: 'TagsFromPathPluginHandler'
D: 1.044: PluginManager.register_handler: Registering handler: 'GStreamerPlayer'
D: 1.045: PluginManager.register_handler: Registering handler: 'SongsMenuPluginHandler'
D: 1.045: PluginManager.enable: Enable 'Last.fm Sync'
D: 1.045: PluginManager.register_handler: Registering handler: 'CoverPluginHandler'
D: 1.045: PluginManager.register_handler: Registering handler: 'PlaylistPluginHandler'
D: 1.045: PluginManager.register_handler: Registering handler: 'QueryPluginHandler'
D: 1.074: AppMenu._export: Registering appmenu failed: X11 only
D: 1.102: PluginManager.register_handler: Registering handler: 'PluggableOrders'
D: 1.103: PluginManager.register_handler: Registering handler: 'PluggableOrders'
D: 1.104: qltk.playorder.__compose_order: Updating PlaylistModel order to <In Order>
D: 1.110: GStreamerPlayer.go_to: Going to None
D: 1.110: PlaylistMux.go_to: Told to go to None
D: 1.110: QueueModel.go_to: Told to go to None
D: 1.110: PlaylistModel.go_to: Told to go to None
D: 1.110: AlbumLibrary.__init__: Initializing Album Library to watch 'main'
D: 1.415: qltk.window.__restore_state: Restore state
D: 1.415: qltk.window.__restore_position: Restore position
D: 1.415: qltk.window.__restore_size: Restore size
D: 1.415: PluginManager.register_handler: Registering handler: 'EventPluginHandler'
D: 1.415: PluginManager.enable: Enable 'QLScrobbler'
D: 1.417: QLScrobbler.enabled: Plugin enabled - accepting new songs.
D: 1.417: PluginManager.enable: Enable 'WaveformSeekBar'
D: 1.418: PluginManager.enable: Enable 'Random Album Playback'
D: 1.418: PluginManager.enable: Enable 'Automatic Rating'
D: 1.420: mmkeys.find_active_backend: Trying to find a mmkeys backend
D: 1.421: mmkeys.find_active_backend: Found 'GnomeBackend'
D: 1.425: qltk.session.init: Connected with gnome session manager: /org/gnome/SessionManager/Client33
D: 1.426: _main.run: Entering quodlibet.main
D: 1.475: PlaylistModel.set: Filling view model with 12 songs.
D: 1.475: GStreamerPlayer.go_to: Going to '/home/ruud/music/<redacted>.flac'
D: 1.475: PlaylistMux.go_to: Told to go to '/home/ruud/music/<redacted>.flac'
D: 1.475: QueueModel.go_to: Told to go to None
D: 1.475: PlaylistModel.go_to: Told to go to '/home/ruud/music/<redacted>.flac'
D: 1.475: GStreamerPlayer._end: End song
D: 1.477: util.cover.manager.failure: Didn't get cover from FilesystemCover: This source is incapable of fetching covers
D: 1.823: util.cover.manager.run: Found local cover from EmbeddedCover: <open file '<fdopen>', mode 'w+b' at 0x7f90eaad7a50>
D: 1.824: WaveformSeekBar._create_waveform: Computing data for each 0.115 seconds
D: 1.836: GStreamerPlayer._end: Next song
D: 1.905: player.gstbe.player.__message: Recalculate latency
D: 87.951: SongFileLibrary._changed(<libraries.SongFileLibrary object at 0x7f90f5489690 (quodlibet+library+libraries+SongFileLibrary at 0x564e93f21060)>): Changing 1 items.
D: 87.952: WaveformSeekBar._create_waveform: Computing data for each 0.115 seconds
D: 87.954: library.libraries.__changed: Updating affected albums for 1 items

As you can see, there is a large delay of about 1.5 minutes before the application is fully started. During this time no window is visible.

When I start Quod Libet a second time, the delay is much shorter (prefix omitted here):

D: 1.318: util.cover.manager.failure: Didn't get cover from FilesystemCover: This source is incapable of fetching covers
D: 1.320: util.cover.manager.run: Found local cover from EmbeddedCover: <open file '<fdopen>', mode 'w+b' at 0x7f3dd17ffa50>
D: 1.320: WaveformSeekBar._create_waveform: Computing data for each 0.115 seconds
D: 1.326: GStreamerPlayer._end: Next song
D: 1.393: player.gstbe.player.__message: Recalculate latency
D: 5.601: SongFileLibrary._changed(<libraries.SongFileLibrary object at 0x7f3ddc16f690 (quodlibet+library+libraries+SongFileLibrary at 0x55a32ccd3f00)>): Changing 1 items.
D: 5.603: WaveformSeekBar._create_waveform: Computing data for each 0.115 seconds
D: 5.604: library.libraries.__changed: Updating affected albums for 1 items

I suspect that the issue is inefficient disk IO. When I drop filesystem caches using echo 3 | sudo tee /proc/sys/vm/drop_caches, then starting Quod Libet afterwards is slow again:

D: 2.270: util.cover.manager.failure: Didn't get cover from FilesystemCover: This source is incapable of fetching covers
D: 2.325: util.cover.manager.run: Found local cover from EmbeddedCover: <open file '<fdopen>', mode 'w+b' at 0x7f7753e19a50>
D: 2.327: WaveformSeekBar._create_waveform: Computing data for each 0.115 seconds
D: 2.349: GStreamerPlayer._end: Next song
D: 2.437: player.gstbe.player.__message: Recalculate latency
D: 89.049: SongFileLibrary._changed(<libraries.SongFileLibrary object at 0x7f775e7e8690 (quodlibet+library+libraries+SongFileLibrary at 0x561e4ab05b00)>): Changing 1 items.
D: 89.051: WaveformSeekBar._create_waveform: Computing data for each 0.115 seconds
D: 89.052: library.libraries.__changed: Updating affected albums for 1 items

I am currently able to reliably reproduce this. Every time I drop filesystem caches, Quod Libet is slow to start. But yesterday I was unable to reproduce the slow startup even when I dropped filesystem caches. Note that for all logs above, I closed Quod Libet after starting it, without playing a song or modifying the play queue that was still there. Yesterday I did rescan my music library and there were a few new files. Today I did not touch my filesystem; I am not sure why the logs say Changing 1 items.

I tried doing a rescan now, closing, dropping caches, and starting again. It is still slow. Since I can reproduce reliably now, I will try to do a profiling run.

Version: Quod Libet 3.9.1

ruuda commented 7 years ago

Profiling results:

p.strip_dirs().sort_stats('tottime').print_stats(10)
Sun Jul 16 17:16:17 2017    prof.out

         3913148 function calls (3889594 primitive calls) in 104.483 seconds

   Ordered by: internal time
   List reduced from 4161 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    75939   45.928    0.001   45.928    0.001 {method 'read' of 'file' objects}
     1750   31.608    0.018   31.608    0.018 {method 'seek' of 'file' objects}
        1    9.287    9.287  101.812  101.812 _main.py:273(run)
      906    7.586    0.008    7.586    0.008 {posix.listdir}
      908    1.329    0.001    1.329    0.001 {open}
        1    0.791    0.791    0.793    0.793 {cPickle.dumps}
      977    0.572    0.001    0.572    0.001 {method 'write' of 'file' objects}
      874    0.236    0.000   89.194    0.102 main.py:560(_update_row)
        2    0.188    0.094    0.188    0.094 {built-in method load}
      874    0.186    0.000    0.749    0.001 _vorbis.py:90(load)

p.strip_dirs().sort_stats('cumtime').print_stats(30)
Sun Jul 16 17:16:17 2017    prof.out

         3913148 function calls (3889594 primitive calls) in 104.483 seconds

   Ordered by: cumulative time
   List reduced from 4161 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.002    0.002  104.524  104.524 quodlibet:9(<module>)
        1    0.003    0.003  104.424  104.424 main.py:19(main)
        1    9.287    9.287  101.812  101.812 _main.py:273(run)
      877    0.034    0.000   89.304    0.102 main.py:295(__scan_paths)
      874    0.236    0.000   89.194    0.102 main.py:560(_update_row)
      874    0.017    0.000   88.923    0.102 models.py:30(scan_cover)
      874    0.007    0.000   88.823    0.102 manager.py:208(get_pixbuf_many_async)
      874    0.015    0.000   88.656    0.101 manager.py:173(get_cover_many)
     1748    0.158    0.000   88.618    0.051 manager.py:142(acquire_cover_sync_many)
       60    0.000    0.000   84.908    1.415 __init__.py:758(wrap)
       54    0.002    0.000   84.902    1.572 main.py:282(__update_visibility)
      885    0.029    0.000   81.312    0.092 built_in.py:40(cover)
      874    0.026    0.000   81.281    0.093 xiph.py:403(get_primary_image)
      874    0.006    0.000   80.404    0.092 _file.py:44(__init__)
      874    0.005    0.000   80.398    0.092 _util.py:155(wrapper)
      874    0.027    0.000   80.394    0.092 _util.py:123(wrapper)
      874    0.063    0.000   78.964    0.090 flac.py:776(load)
    83728    0.133    0.000   46.082    0.001 flac.py:66(read)
    75939   45.928    0.001   45.928    0.001 {method 'read' of 'file' objects}
     1750   31.608    0.018   31.608    0.018 {method 'seek' of 'file' objects}
      874    0.006    0.000   29.603    0.034 flac.py:897(__check_header)
     4108    0.084    0.000   17.659    0.004 flac.py:700(__read_metadata_block)
     3234    0.026    0.000   15.998    0.005 flac.py:98(__init__)
      895    0.007    0.000   15.580    0.017 flac.py:575(__init__)
      895    0.016    0.000   15.568    0.017 flac.py:601(load)
      879    0.044    0.000    7.749    0.009 built_in.py:74(cover)
      906    7.586    0.008    7.586    0.008 {posix.listdir}
       39    0.000    0.000    4.414    0.113 copool.py:24(wrap)
     1748    0.032    0.000    1.370    0.001 _util.py:175(_openfile)
      904    0.003    0.000    1.356    0.002 contextlib.py:15(__enter__)

I can also provide the output file is required.

A few more notes: