Out of memory when playing from url large file (~100MB)

[ondonadas]

Out of memory when playing large file (~100MB) from url

Running these commands

echo add 'http://192.168.1.1/90.mp3' | nc localhost 6600 echo lsinfo 'http://192.168.1.1/90.mp3' | nc localhost 6600 echo playlistinfo | nc localhost 6600 echo play | nc localhost 6600

crashes CPU with out of memory. Please note that 90.mp3 file size = 90MB

Expected Behavior

Tested with old mpd versions 0.19.19 works flawlessly. Only uses few MB when playing same files. It shouldn't use such amount of ram (IMHO)

Actual Behavior

With MPD 0.21.25 and 0.23.5 after run the "play" command mpd gets ~100MB of memory and this crashes the whole CPU (I'm using a router with openWRT with 128MB of ram). Trying same process with local file (playing from USB) works fine.

Version

Music Player Daemon 0.23.5 (0.23.5) Copyright 2003-2007 Warren Dukes warren.dukes@gmail.com Copyright 2008-2021 Max Kellermann max.kellermann@gmail.com This is free software; see the source for copying conditions. There is NO warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Database plugins: simple proxy

Storage plugins: local curl

Decoders plugins: [mad] mp3 mp2 [vorbis] ogg oga [oggflac] ogg oga [flac] flac [opus] opus ogg oga [faad] aac [pcm]

Filters:

Tag plugins: id3tag

Output plugins: null alsa httpd

Encoder plugins: null opus wave flac

Input plugins: file alsa curl

Playlist plugins: extm3u m3u pls xspf asx rss flac cue embcue

Protocols: file:// alsa:// ftp:// ftps:// http:// https://

Other features: epoll iconv inotify tcp un

Log

config_file: loading file /root/mpd.conf opus: libopus 1.3.1-fixed curl: version 7.66.0 curl: with mbedTLS/2.16.8 client: [0] opened from 127.0.0.1:33232 client: [0] process command "add http://192.168.1.1/90.mp3" client: [0] command returned 0 client: [0] closed client: [1] opened from 127.0.0.1:33234 client: [1] process command "lsinfo http://192.168.1.1/90.mp3" client: [1] command returned 0 client: [1] closed client: [2] opened from 127.0.0.1:33238 client: [2] process command "playlistinfo" client: [2] command returned 0 client: [2] closed client: [3] opened from 127.0.0.1:33240 client: [3] process command "play" playlist: play 0:"http://192.168.1.1/90.mp3" client: [3] command returned 0 client: [3] closed decoder_thread: probing plugin mad decoder: audio_format=44100:24:2, seekable=true decoder: converting to 44100:16:2 output: opened "null_audio_test" (null) audio_format=44100:16:2

[MaxKellermann]

Please run MPD with valgrind --tool=massif mpd --no-daemon .... and convert the resulting file with "ms_print massif.out..." to a report, upload it here.

[MaxKellermann]

I tried with a 97 MB mp3 file, and MPD peaks at 7.8 MB RAM usage. Can't reproduce, I need more data from you.

[ondonadas]

Hi @MaxKellermann running valgrind inside the "router box" crash with --18086-- WARNING: unhandled mips32-linux syscall: 4326 --18086-- You may be able to write your own handler. --18086-- Read the file README_MISSING_SYSCALL_OR_IOCTL. --18086-- Nevertheless we consider this a bug. Please report --18086-- it at http://valgrind.org/support/bug_reports.html. exception: epoll_create1() failed: Function not implemented Unexpected error occurs. So no way to test it on the small machine (router box MIPS based)

In order to go ahead, I'll try same test in a x86 machine with same mpd compilation flags that the ones in the openwrt builder image. BTW @MaxKellermann, when you say "7.8MB RAM ussage" which tools do you use to get such info?

[ondonadas]

Hi @MaxKellermann

Running in x86

Regular mpd Ubuntu version

mpd-0.21.25 $ valgrind --tool=massif --pages-as-heap=yes --massif-out-file=massif.out mpd mpd.conf --no-daemon ==1301471== Massif, a heap profiler ==1301471== Copyright (C) 2003-2017, and GNU GPL'd, by Nicholas Nethercote ==1301471== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info ==1301471== Command: mpd mpd.conf --no-daemon ==1301471== exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg exception: Input plugin 'tidal' is unavailable: No Tidal application token configured exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured ^C==1301471==

My custom openwrt mpd version

mpd-0.21.25 $ valgrind --tool=massif --pages-as-heap=yes --massif-out-file=massif.out output/release/mpd mpd.conf --no-daemon ==1301525== Massif, a heap profiler ==1301525== Copyright (C) 2003-2017, and GNU GPL'd, by Nicholas Nethercote ==1301525== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info ==1301525== Command: output/release/mpd mpd.conf --no-daemon ==1301525== exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg exception: Input plugin 'tidal' is not configured: No Tidal application token configured exception: Input plugin 'qobuz' is not configured: No Qobuz app_id configured ^C==1301471==

As far as I understand 1301471 and 1301471 are the peak memory, isn't? So, in x86 case only 1,3MB of ram are used If this is correct, I'll try the same in the MIPS machine and come back with the results.

Please, let me know if my suppositions are correct.

[ondonadas]

I've done quick testing before to start my daily routine. As I can't run mpd with valgrind in MIPS machine, I've tested /usr/bin/time .. sorry I don't use these tools very often.. hope it helps!

root@PLAYER:/# /usr/bin/time -v mpd mpd.conf --verbose --stderr --no-daemon &
root@PLAYER:/# echo add 'http://192.168.33.217:8088/90.mp3' | nc localhost 6600
root@PLAYER:/# echo play | nc localhost 6600
root@PLAYER:/# top

Then I wait until the "end of memory" .. and here you have the results

CPU:   8% usr  16% sys   0% nic  58% idle   0% io   0% irq  16% sirq
Load average: 1.02 0.41 0.15 1/46 2954
  PID  PPID USER     STAT   VSZ %VSZ %CPU COMMAND
 2116  2115 root     S     103m  84%  35% mpd mpd.conf --verbose --stderr --no-d
 2954   491 root     R     1208   1%   7% top
  899     1 root     S     2036   2%   0% /sbin/rpcd -s /var/run/ubus.sock -t 30
 1135     1 nobody   S     1960   2%   0% avahi-daemon: running [PLAYER.local]
  993     1 root     S     1744   1%   0% /sbin/netifd
    1     0 root     S     1560   1%   0% /sbin/procd
 1110     1 root     S     1516   1%   0% /usr/bin/dbus-daemon --system
 1509     1 dnsmasq  S     1344   1%   0% /usr/sbin/dnsmasq -C /var/etc/dnsmasq.
 1095     1 root     SN    1316   1%   0% /usr/sbin/uhttpd -f -h /tmp/ramfs/www
 1367     1 root     SN    1220   1%   0% /bin/sh /sbin/switch_ports_status star
  490     1 root     S     1216   1%   0% /sbin/ubusd
  491     1 root     S     1216   1%   0% /bin/ash --login
 1393     1 root     S<    1212   1%   0% /usr/sbin/ntpd -n -N -S /usr/sbin/ntpd
 1030     1 root     SN    1208   1%   0% /bin/sh /sbin/uSDaemon
 1237   993 root     S     1208   1%   0% udhcpc -p /var/run/udhcpc-eth0.2.pid -
 2946  1030 root     SN    1208   1%   0% sleep 2
 2953  1367 root     SN    1208   1%   0% sleep 2
 2115   491 root     S     1208   1%   0% usr/bin/time -v mpd mpd.conf --verbose
  508     1 root     S     1028   1%   0% /sbin/urngd
^C142     2 root     IW       0   0%   0% [kworker/0:1]
## press ctl+c to stop top 
## observe mpd memory 103m
root@PLAYER:/# ^C
root@PLAYER:/# [  146.122965] avahi-daemon invoked oom-killer: gfp_mask=0x14201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=(null),  order=0, oom_score_adj=0
[  146.147996] CPU: 0 PID: 1135 Comm: avahi-daemon Not tainted 4.14.209 #0
[  146.161104] Stack : 00000000 80054098 80440000 803ef510 00000000 00000000 00000000 00000000
[  146.177675]         00000000 00000000 00000000 00000000 00000000 00000001 87239b28 bad86abe
[  146.194243]         87239bc0 00000000 00000000 00003a08 00000038 803900f8 00000007 00000000
[  146.210819]         00000000 80420000 0002421c 00000000 87239b08 80000000 87239d18 803c9f64
[  146.227389]         000002b3 00200000 ffffffff 0000549a 00000002 8020e994 00000000 80570000
[  146.243957]         ...
[  146.248809] Call Trace:
[  146.248822] [<80054098>] 0x80054098
[  146.260559] [<80440000>] 0x80440000
[  146.267533] [<803900f8>] 0x803900f8
[  146.274451] [<8020e994>] 0x8020e994
[  146.281389] [<8000aa10>] 0x8000aa10
[  146.288309] [<8000aa18>] 0x8000aa18
[  146.295241] [<80097bcc>] 0x80097bcc
[  146.302204] [<80096ea4>] 0x80096ea4
[  146.309140] [<80097a6c>] 0x80097a6c
[  146.316057] [<8009c198>] 0x8009c198
[  146.322989] [<8009272c>] 0x8009272c
[  146.329954] [<8009471c>] 0x8009471c
[  146.336883] [<800bf518>] 0x800bf518
[  146.343870] [<800bb820>] 0x800bb820
[  146.350826] [<800bfd20>] 0x800bfd20
[  146.357743] [<8004df7c>] 0x8004df7c
[  146.364702] [<8001219c>] 0x8001219c
[  146.371616] [<800e00d4>] 0x800e00d4
[  146.378532] [<8029ce34>] 0x8029ce34
[  146.385488] [<80049fac>] 0x80049fac
[  146.392426] [<80391980>] 0x80391980
[  146.399371] [<8001839c>] 0x8001839c
[  146.406296]
[  146.409232] Mem-Info:
[  146.413744] active_anon:22576 inactive_anon:416 isolated_anon:0
[  146.413744]  active_file:158 inactive_file:227 isolated_file:0
[  146.413744]  unevictable:0 dirty:0 writeback:0 unstable:0
[  146.413744]  slab_reclaimable:198 slab_unreclaimable:1051
[  146.413744]  mapped:11 shmem:426 pagetables:84 bounce:0
[  146.413744]  free:4094 free_pcp:14 free_cma:0
[  146.477300] Node 0 active_anon:90304kB inactive_anon:1664kB active_file:632kB inactive_file:908kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:44kB dirty:0kB writeback:0kB shmem:1704kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[  146.521919] Normal free:16376kB min:16384kB low:20480kB high:24576kB active_anon:90304kB inactive_anon:1664kB active_file:632kB inactive_file:908kB unevictable:0kB writepending:0kB present:131072kB managed:125268kB mlocked:0kB kernel_stack:328kB pagetables:336kB bounce:0kB free_pcp:56kB local_pcp:56kB free_cma:0kB
[  146.576995] lowmem_reserve[]: 0 0
[  146.583554] Normal: 102*4kB (UME) 90*8kB (UME) 61*16kB (UME) 32*32kB (UME) 5*64kB (ME) 5*128kB (ME) 2*256kB (ME) 3*512kB (UME) 2*1024kB (UE) 0*2048kB 2*4096kB (M) = 16376kB
[  146.614104] 811 total pagecache pages
[  146.621361] 0 pages in swap cache
[  146.627931] Swap cache stats: add 0, delete 0, find 0/0
[  146.638283] Free swap  = 0kB
[  146.643970] Total swap = 0kB
[  146.649676] 32768 pages RAM
[  146.655192] 0 pages HighMem/MovableOnly
[  146.662808] 1451 pages reserved
[  146.669031] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
[  146.685940] [  490]     0   490      304       17       4       0        0             0 ubusd
[  146.703009] [  491]     0   491      304       12       5       0        0             0 ash
[  146.719735] [  508]     0   508      257       12       4       0        0             0 urngd
[  146.736806] [  899]     0   899      509       41       4       0        0             0 rpcd
[  146.753704] [  993]     0   993      436       44       4       0        0             0 netifd
[  146.770951] [ 1095]     0  1095      329       19       4       0        0             0 uhttpd
[  146.788194] [ 1110]     0  1110      379       23       4       0        0             0 dbus-daemon
[  146.806297] [ 1135] 65534  1135      490       33       5       0        0             0 avahi-daemon
[  146.824572] [ 1237]     0  1237      302       10       4       0        0             0 udhcpc
[  146.841815] [ 1393]     0  1393      303       17       3       0        0             0 ntpd
[  146.858714] [ 1509]   453  1509      336       23       5       0        0             0 dnsmasq
[  146.876128] [ 2115]     0  2115      302       10       4       0        0             0 time
[  146.893026] [ 2116]     0  2116    26451    22298      29       0        0             0 mpd
[  146.909748] Out of memory: Kill process 2116 (mpd) score 691 or sacrifice child
[  146.924274] Killed process 2116 (mpd) total-vm:105804kB, anon-rss:89188kB, file-rss:4kB, shmem-rss:0kB
[  147.821636] oom_reaper: reaped process 2116 (mpd), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Command terminated by signal 9
        Command being timed: "mpd mpd.conf --verbose --stderr --no-daemon"
        User time (seconds): 8.86
        System time (seconds): 19.47
        Percent of CPU this job got: 34%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1m 22.32s
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 361584
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 132
        Minor (reclaiming a frame) page faults: 22521
        Voluntary context switches: 39993
        Involuntary context switches: 20180
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

top is showing that mpd is using 103MB time shows Maximum resident set size (kbytes): 361584

Does it helps?

[MaxKellermann]

when you say "7.8MB RAM ussage" which tools do you use to get such info?

From valgrind/massif.

As far as I understand 1301471 and 1301471 are the peak memory, isn't?

No, that's the process id. After running massif, you need to use ms_print to convert massif's output to an analysis, as I already wrote in my first reply.

top is showing that mpd is using 103MB

No, that's virtual memory size, which has little to do with actual memory use.

[ondonadas]

Thank you for the clarification

Then is it possible to debug further such issue without valgrind? My router/openwrt box total memory is 128MB (no swap in such devices) so virtual memory is, more or less, physical memory.

The weird thing is that, reproducing same file locally stored (USB) top virtual memory shows ~11MB, while playing from url drain all the memory available and crahses

[MaxKellermann]

My router/openwrt box total memory is 128MB (no swap in such devices) so virtual memory is, more or less, physical memory.

That's not quite correct. "Virtual memory" includes address space which is not backed by any memory - neither RAM nor swap.

[ondonadas]

Yes! absolutely agree with you.. Any indication how to debug further the out of memory due to mpd process?

[MaxKellermann]

For the third time: After running massif, you need to use ms_print to convert massif's output to an analysis!

[ondonadas]

Thank you for the answer, I see. The question was more related to an alternative way to valgrind massif, because as said before when run valgrind --tool=massif mpd myconfig.conf in the router, it throws an exception as soon as starts

--18086-- WARNING: unhandled mips32-linux syscall: 4326 --18086-- You may be able to write your own handler. --18086-- Read the file README_MISSING_SYSCALL_OR_IOCTL. --18086-- Nevertheless we consider this a bug. Please report --18086-- it at http://valgrind.org/support/bug_reports.html. exception: epoll_create1() failed: Function not implemented Unexpected error occurs. So no way to test it on the small machine (router box MIPS based)

[MaxKellermann]

But it works on your Ubuntu box. It would be interesting to see MPD's memory usage on your Ubuntu box. Note that I'm unable to help with MPD version 0.21.25 - do not even bother to post any data or bug report about it. Only 0.23.5 is supported. If this can be reproduced on Ubuntu (but doesn't crash, because your Ubuntu box has enough memory), can we see what's wrong. If this cannot be reproduced with Ubuntu, then this bug must be specific to your OpenWRT build, and this is not a MPD bug, and thus cannot be fixed by MPD. Maybe it's a bug in a library shipped with OpenWRT. (So far, I could not reproduce it on Debian.)

Other than Valgrind, I know no tools to reveal what really uses memory inside a process. There may be other tools, but I don't know them. Valgrind is the standard tool. If Valgrind is broken on OpenWRT, complain to the OpenWRT project so they fix it, or ask them to name a different tool, but I can't help you.

Of course, I care very much about MPD's resource usage, and I think MPD is the lightest music player. But if your tools are broken, we can't fix or even analyze anything.

[ondonadas]

Understood. I'll try the x86 test with mpd 0.23.5 next week-end

[ondonadas]

HI @MaxKellermann

Sorry for the late answer. You can download massif test using massif.out.143514.txt. This test is done with mpd v0.21.26+ and my desktop PC because I can't run massif in the final hardware (I'll try to make it work).

Just to make some memory. I was using mpd inside a openwrt small CPU (a router with 128MB of ram). When streaming from http://192.168.0.100/file.mp3 (file.mp3 size ~200MB) I've got out of memory. When playing same file from USB all works fine. Hope it helps, but AFAIK running this test is ok with the memory consumption.

[ondonadas]

Hi @MaxKellermann

The issue seems related to the use of MUSL instead glibc in openwrt. I've compile again whole openwrt with glibc and works fine. The problem is that I can't test valgrind with MUSL. Are there any mpd flag to debug further memory problems?

[MaxKellermann]

No, there are not. That's what tools like valgrind are supposed to do. I can't help with Musl specific problems because I don't use Musl. I don't know how to debug allocation problems with Musl. Ask somebody who knows Musl better than I.

But right now, this doesn't look like a MPD problem at all.

Your massif file shows that MPD never consumes more than 9 MB.

[ondonadas]

Understood, thank you Max