Slow startup

[bodqhrohro]

mpv version and platform

0.29.1, Debian GNU/Linux 10

Reproduction steps

Playing a single file, already opened before, so both the file and mpv should be cached in RAM.

Expected behavior

There is nothing to lag much.

Actual behavior

mpv still takes several seconds to start playback.

Log file

https://0x0.st/zrg7.log

Sample files

strace -c:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 76.15    0.352872         589       599        11 futex
  6.81    0.031563          28      1140           mmap
  5.60    0.025956          73       354        44 openat
  3.58    0.016610          53       312         1 read
  1.92    0.008905          20       445           mprotect
  1.71    0.007905          34       231       230 access
  1.49    0.006925          21       325           close
  1.25    0.005803          19       309           fstat
  0.34    0.001553          97        16           getdents64
  0.25    0.001175          98        12           clone
  0.24    0.001128           9       130           write
  0.15    0.000698          16        45        30 stat
  0.13    0.000597           3       210           getpid
  0.12    0.000552          46        12           munmap
  0.04    0.000199           5        37           ioctl
  0.04    0.000174          11        16           rt_sigaction
  0.04    0.000173           4        49           fcntl
  0.03    0.000157         157         1           execve
  0.01    0.000062           4        16           getpgrp
  0.01    0.000060           4        17           poll
  0.01    0.000055           6         9           writev
  0.01    0.000045           6         8           lseek
  0.01    0.000036           5         8           recvmsg
  0.01    0.000035           4         8           brk
  0.01    0.000026           7         4           lstat
  0.01    0.000024          12         2           socket
  0.00    0.000021          11         2           connect
  0.00    0.000015           4         4           pipe
  0.00    0.000015           8         2           recvfrom
  0.00    0.000009           9         1           memfd_create
  0.00    0.000006           6         1           ftruncate
  0.00    0.000005           5         1           shutdown
  0.00    0.000005           5         1           getpeername
  0.00    0.000005           1         5         5 mkdir
  0.00    0.000005           2         3           getuid
  0.00    0.000004           4         1           setsockopt
  0.00    0.000004           2         2           umask
  0.00    0.000004           4         1           fstatfs
  0.00    0.000004           4         1           getrandom
  0.00    0.000003           3         1         1 sendto
  0.00    0.000003           3         1           getsockname
  0.00    0.000003           3         1           uname
  0.00    0.000003           3         1           getgid
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         1           readlink
  0.00    0.000000           0         1           geteuid
  0.00    0.000000           0         2         2 statfs
  0.00    0.000000           0         1           mlock
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         2           sched_getaffinity
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           pipe2
  0.00    0.000000           0         1           prlimit64
------ ----------- ----------- --------- --------- ----------------
100.00    0.463402                  4357       324 total

strace -cw:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 93.38    5.664546        8661       654         6 futex
  1.22    0.073905         166       445           mprotect
  1.13    0.068446          60      1140           mmap
  0.95    0.057919         185       313         1 read
  0.66    0.039783         112       355        44 openat
  0.43    0.026143          80       326           close
  0.37    0.022690         175       130           write
  0.34    0.020869        1159        18           poll
  0.34    0.020511          89       231       230 access
  0.33    0.019806         104       190           getpid
  0.16    0.009478          31       309           fstat
  0.12    0.007106         444        16           rt_sigaction
  0.09    0.005494         122        45        30 stat
  0.07    0.004412         368        12           munmap
  0.07    0.003977         442         9           writev
  0.05    0.003302        3302         1           execve
  0.05    0.003211          92        35           ioctl
  0.04    0.002378         297         8           lseek
  0.03    0.002095          43        49           fcntl
  0.03    0.001846        1846         1           readlink
  0.03    0.001674         140        12           clone
  0.01    0.000880         110         8           recvmsg
  0.01    0.000868          54        16           getdents64
  0.01    0.000723         723         1           setsockopt
  0.01    0.000538         269         2           connect
  0.01    0.000401          27        15           getpgrp
  0.01    0.000377         377         1           shutdown
  0.01    0.000331          41         8           brk
  0.00    0.000251         126         2           socket
  0.00    0.000235          59         4           pipe
  0.00    0.000226          57         4           lstat
  0.00    0.000210          42         5         5 mkdir
  0.00    0.000157          52         3           getuid
  0.00    0.000141         141         1           fstatfs
  0.00    0.000124         124         1           getgid
  0.00    0.000123         123         1           ftruncate
  0.00    0.000096          32         3         1 recvfrom
  0.00    0.000086          86         1           uname
  0.00    0.000073          37         2         2 statfs
  0.00    0.000060          60         1           pipe2
  0.00    0.000051          51         1           arch_prctl
  0.00    0.000050          50         1           mlock
  0.00    0.000045          45         1           memfd_create
  0.00    0.000036          18         2           sched_getaffinity
  0.00    0.000035          18         2           umask
  0.00    0.000031          31         1         1 sendto
  0.00    0.000030          30         1           set_tid_address
  0.00    0.000028          28         1           getrandom
  0.00    0.000023          23         1           set_robust_list
  0.00    0.000021          21         1           getpeername
  0.00    0.000019          19         1           getsockname
  0.00    0.000018          18         1           prlimit64
  0.00    0.000016          16         1           rt_sigprocmask
  0.00    0.000015          15         1           geteuid
------ ----------- ----------- --------- --------- ----------------
100.00    6.065909                  4394       320 total

I also tried running -v -v -v -v, as you suggested for some similar issues, but without timestamps it's barely informative anyway. How do I enable timestamps? Grepping futexes in plain strace output is not much informative too, as only by descriptors I have no idea what are they for and what do they wait for.

[mia-0]

Please post a log made with --log-file, as that includes timing information which may be helpful in narrowing it down.

Other than that, your mpv executable was built against different versions of the FFmpeg libraries than those installed on your system, so make sure to fix that in order to avoid potential issues with undefined behavior.

[bodqhrohro]

Okay, the slowest things turned out to be ytdl hook (why is it even called for local files?!) and window initialization. Got rid of it: with --no-ytdl --no-video. Still too much.

[CounterPillow]

Can't reproduce here, ytdl isn't executed for me for local files, and playback starts after 0.039 seconds.

[mia-0]

All of this looks really slow. I would have expected something like OpenGL context creation taking up most of the time, but that doesn’t seem to be the case. Even the libarchive demuxer check seems to be taking over 100 milliseconds where it should take no more than maybe 2 or 5 on very slow systems.

[CounterPillow]

Also, the ytdl messages you see in the log are from literally just this piece of lua, which should not even remotely take this long to run: https://github.com/mpv-player/mpv/blob/master/player/lua/ytdl_hook.lua#L655-L665

Is your disk dying?

[mia-0]

So yeah, first fix the FFmpeg library issue. Who knows. We actually have code to detect this and exit with an error, but Debian chose to patch it out without fixing their broken packaging/infra.

Other than that, you might have to upgrade from your AMD C-50 (which I assume this is since you’ve never mentioned what you’re trying to run mpv on) or start using a distro that is better suited for your hardware.

[bodqhrohro]

Is your disk dying?

Unlikely.

ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   100   100   062    Pre-fail  Always       -       0
  2 Throughput_Performance  0x0005   100   100   040    Pre-fail  Offline      -       0
  3 Spin_Up_Time            0x0007   174   174   033    Pre-fail  Always       -       1
  4 Start_Stop_Count        0x0012   096   096   000    Old_age   Always       -       7109
  5 Reallocated_Sector_Ct   0x0033   100   100   005    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000b   100   100   067    Pre-fail  Always       -       0
  8 Seek_Time_Performance   0x0005   100   100   040    Pre-fail  Offline      -       0
  9 Power_On_Hours          0x0012   042   042   000    Old_age   Always       -       25449
 10 Spin_Retry_Count        0x0013   100   100   060    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   098   098   000    Old_age   Always       -       4007
191 G-Sense_Error_Rate      0x000a   097   097   000    Old_age   Always       -       262146
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       153
193 Load_Cycle_Count        0x0012   092   092   000    Old_age   Always       -       87680
194 Temperature_Celsius     0x0002   139   139   000    Old_age   Always       -       43 (Min/Max 11/59)
196 Reallocated_Event_Count 0x0032   100   100   000    Old_age   Always       -       21
197 Current_Pending_Sector  0x0022   100   100   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0008   100   100   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always       -       0
223 Load_Retry_Count        0x000a   100   100   000    Old_age   Always       -       0

[CounterPillow]

If this really is an AMD C-50 (lowest-end CPU from January 2011, and phased out by the end of 2011), then your best hope is to compile mpv yourself with some of the non-essentials stripped out, namely:

• disable libarchive
• disable dvdnav/dvdread
• disable libbluray

[mia-0]

Even if it is, it should still be faster than my eeePC 900, which is the only comparable piece of hardware I have around. And mpv is not that slow on it (running openSUSE). So yeah, probably either a Debian issue, or a hardware defect.

[bodqhrohro]

without fixing their broken packaging/infra

So should they rebuild all of dependent packages on every minor update? This would probably delay updates a lot. Broken compatibility is the fault of those who make breaking changes without incrementing the major version.

or start using a distro that is better suited for your hardware.

What exactly? Do they ship some tools for improving performance on HDD which Debian doesn't? Like cachers, or maybe kernel patches? I've heard of BFQ/UKSM, which could improve performance here, but haven't heard of distros shipping them out of box. And building a custom kernel does not require to abandon the polished-for-years system.

your best hope is to compile mpv

Sounds good, but the same could be said about almost all software. Compilation is much more painful on such CPU, and requires a lot of disk space for sources. Moreover, I play archives sometimes too (I could mount it with fuse-zip too, but this is less convenient for occasional use), and even use a DVD drive :D So if they're the bottleneck, they deserve the performance drawdown.

[mia-0]

On Thursday, January 31, 2019 1:55:48 PM CET bodqhrohro wrote: >without fixing their broken packaging/infra So should they rebuild all of dependent packages on every minor update? This would probably delay updates a lot. Broken compatibility is the fault of those who make breaking changes without incrementing the major version.

That is actually what openSUSE does, and they manage to build and automatically test several snapshots of the entire distro every week.

>or start using a distro that is better suited for your hardware. What exactly? Do they ship some tools for improving performance on HDD which Debian doesn't? Like cachers, or maybe kernel patches? I've heard of BFQ/UKSM, which could improve performance here, but haven't heard of distros shipping them out of box. And building a custom kernel does not require to abandon the polished-for-years system.

No, just a distro that is built and configured for systems with slow CPUs, slow storage and not a lot of RAM, with packages disabling less frequently used features by default. This is a niche, so mainstream distros don’t cater to it. But like I mentioned after that post, it shouldn’t actually be necessary with your hardware, as even my eeePC 900 still somehow copes with a modern distro running a full KDE desktop. It isn’t fast at all, but mpv runs much faster than on your system. Something is fishy.

>your best hope is to compile mpv Sounds good, but the same could be said about almost all software. Compilation is much more painful on such CPU, and requires a lot of disk space for sources. Moreover, I play archives sometimes too (I could mount it with `fuse-zip` too, but this is less convenient for occasional use), and even use a DVD drive :D So if they're the bottleneck, they deserve the performance drawdown.

Well, it is how it is. At least building mpv yourself would allow us to eliminate the FFmpeg version mismatch as a potential cause for this behavior.

[haasn]

Did you somehow manage to disable your hard drive cache? It seems like disk I/O is taking forever in your log. I mean 3s to initialize fonts?!

[bodqhrohro]

Did you somehow manage to disable your hard drive cache?

Unlikely. Free RAM compensates slow HDD well when there is a lot of it. That's why I have zram instead of disk swap, and high vm.swappiness.

And if the main bottleneck is disk I/O, shouldn't related calls like mmap, read, fstat and so prevail in strace? But there are stably an overwhelming majority of futex, which probably just means that some threads are waiting for others to do some CPU-heavy tasks? Or maybe it communicates with some external processes which is not shown there?

[mia-0]

On Thursday, January 31, 2019 5:58:20 PM CET bodqhrohro wrote: >Did you somehow manage to disable your hard drive cache? Unlikely. Free RAM compensates slow HDD well when there is a lot of it. That's why I have `zram` instead of disk swap, and high `vm.swappiness`.

More things coming to light about your setup. This will likely cause Linux to (perhaps unnecessarily) swap out a lot of program code in compressed RAM, which has considerable performance overhead especially on a system with slow CPU/RAM such as yours.

[mia-0]

Also, swap on zram is probably less efficient than zswap. You are effectively reducing the amount of RAM that is immediately available for both program code and I/O caching, thereby just slowing down your system.

[haasn]

So does disabling all swap (including zram, zswap, etc.) help?

[mia-0]

Do try that, yes. But disabling swap will pretty much always make things worse compared to having swapspace available. We’re just blindly guessing here anyway, but if it does turn out to fix this performance issue, I suggest trying to enable on-disk swap as well as zswap (which pretty much acts as a compressed swap cache, as it evicts the least recently used pages to disk if necessary).

[bodqhrohro]

zram does compression great. I have compressed/uncompressed amount of zram printed to the panel, usually the compression level is about 20%–35%. Desktop software tend to "leak" (past chatlogs, terminal scrollbacks, forsaken browser tabs and so on), and even though restarting it from time to time is a good practice, having some kind of swap to toss barely useful pages out is a musthave too, if not abused too much, of course.. High vm.swappiness makes a good balance between zram and disk cache: even with several gigabytes of pages in zram, I still have about 0.5G of free RAM for cache.

The HDD is usually more loaded than CPU, so additionally loading it with pages swapping, even compressed ones, would make things even worse. When I had disk swap, in critical thrashing conditions I had to wait about 10 minutes for each command to complete when rescuing the system in TTY; now it's way better even with LA >50.

[mia-0]

Would you please try the things we’ve told you to try? We’re not getting any closer to tracking down the cause for this slowness without some cooperation, as apparently none of us can reproduce your performance issues even on much slower hardware.

[mia-0]

Actually, you don’t have to. I’m absolutely certain that this is not mpv’s fault, as many of the points where it stalls according to your log make absolutely no sense. Even code that effectively just prints a message and immediately returns sometimes takes dozens of milliseconds to execute on your system. There’s just absolutely nothing we can do about that.