Moonbase59 / ices0

Enhanced source client for broadcasting to an Icecast/Shoutcast server in MP3 format.
GNU General Public License v2.0
25 stars 9 forks source link

Ices0 at some point starts using more and more RAM #3

Closed AlphaJack closed 3 years ago

AlphaJack commented 4 years ago

I'm running on my Raspberry Pi 2 eight ices0 streams of 320kbps mp3 without reecoding the files on the fly (they have all been reencoded in this format . With this setup all the streams together use only 43MB of RAM and 2% of CPU.

As soon as I realized that the set of ices0 streams sometimes increases its RAM usage until the machine becomes unresponsive, I wrote a script that periodically checks how much memory it is using, and if it exceeds a threshold, it kills and restarts all the streams, which consume again 43MB together.

I obtain the value in MB from this command ps axo rss,comm | awk -v CONVFMT='%.0f' '/ices0/ {$1/=1024;sum+=$1} END {print sum""}'.
I've also tried to see what changes in memory usage when there is a normal and an excessive RAM usage by comparing the smaps, but they only differ in 4 lines for few kB. I read per-stream smaps with sudo cat /proc/$pid/smaps.

Do you know some other places where I can look the composition of the memory usage when it is excessive? Can this behaviour be a consequence of a memory leak? Why does it only start after some hour the stream have been restarted and not immediatly after?

Could you add a timestamp to each line of the ices0 log, both verbose and not?

EDIT I was able to find out that only a stream is guily of today fail. It disappeared from the list of Icecast streams in status-json.xsl and its mountpoint returned 404, but according to the logs and the time it took, the stream waited for the song to finish before serving the following track.

Screenshot from htop: htop

With sudo pmap $pid I found a difference between the normal and the excessive usage at the beginning of the file: normal

00429000     72K r-x-- ices0
0044a000      4K r---- ices0
0044b000      4K rw--- ices0
0044c000    728K rw---   [ anon ]
00f81000    132K rw---   [ anon ]
00fa2000    452K rw---   [ anon ]
74381000     36K r-x-- libnss_files-2.30.so
[...]

excessive

00429000     72K r-x-- ices0
0044a000      4K r---- ices0
0044b000      4K rw--- ices0
0044c000    728K rw---   [ anon ]
00f81000    132K rw---   [ anon ]
00fa2000 171432K rw---   [ anon ]
74381000     36K r-x-- libnss_files-2.30.so
[...]

This is the output of sudo cat /proc/$pid/maps:

00429000-0043b000 r-xp 00000000 b3:02 78340      /usr/bin/ices0
0044a000-0044b000 r--p 00011000 b3:02 78340      /usr/bin/ices0
0044b000-0044c000 rw-p 00012000 b3:02 78340      /usr/bin/ices0
0044c000-00502000 rw-p 00000000 00:00 0 
00f81000-00fa2000 rw-p 00000000 00:00 0          [heap]
00fa2000-084ee000 rw-p 00000000 00:00 0          [heap]
74381000-7438a000 r-xp 00000000 b3:02 29087      /usr/lib/libnss_files-2.30.so
[...]

Hexdumping the last line outputs hundreds of MB of junk.

The stream log file looks like this:

[...]

# Start of the strange behaviour
DEBUG: Builtin playlist handler serving: /path/to/Artist - Title.mp3
DEBUG: Filename cleaned up from [/path/to/Artist - Title.mp3] to [Artist - Title]
DEBUG: Trimmed short frame (301 bytes missing) at offset 109247768
DEBUG: MPEG-1 layer III, 320 kbps, 44100 Hz, j-stereo
DEBUG: Ext: 0   Mode_Ext: 0 Copyright: 0    Original: 1
DEBUG: Error Protection: 0  Emphasis: 0 Padding: 0
Playing /path/to/Artist - Title.mp3
Updating metadata on /mountpoint failed.
DEBUG: Done sending

# Other tracks show a log like this until the script kills the source
DEBUG: Builtin playlist handler serving: /path/to/Artist2 - Title2.mp3
DEBUG: Filename cleaned up from [/path/to/Artist2 - Title2.mp3] to [Artist2 - Title2]
DEBUG: ID3v2: version 4.0. Tag size is 332806 bytes.
DEBUG: ID3v2: Title found: Title2
DEBUG: ID3v2: Artist found: Artist2
DEBUG: MPEG-1 layer III, 320 kbps, 44100 Hz, j-stereo
DEBUG: Ext: 0   Mode_Ext: 2 Copyright: 0    Original: 1
DEBUG: Error Protection: 0  Emphasis: 0 Padding: 0
Playing /path/to/Artist2 - Title2.mp3
Updating metadata on /mountpoint failed.
DEBUG: Done sending

[...]

* Stream is automatically stopped and manually restared with a new playlists that begins with the new "faulty" track*

# Begin of streaming
DEBUG: Builtin playlist handler serving: /path/to/Artist - Title.mp3
DEBUG: Filename cleaned up from [/path/to/Artist - Title.mp3] to [Artist - Title]
DEBUG: Trimmed short frame (301 bytes missing) at offset 109247768
DEBUG: MPEG-1 layer III, 320 kbps, 44100 Hz, j-stereo
DEBUG: Ext: 0   Mode_Ext: 0 Copyright: 0    Original: 1
DEBUG: Error Protection: 0  Emphasis: 0 Padding: 0
Playing /path/to/Artist - Title.mp3
Mounted on http://127.0.0.1:4040/mountpoint
DEBUG: Delaying metadata update...
DEBUG: Updated metadata on /mountpoint to: Artist - Title
DEBUG: Updated metadata on /mountpoint to: Artist - Title

[...]

The .mp3 files are fine, I can't understand why it can now mount and update the metadata if it failed some minutes ago. The timestamps would confirm if this strange behaviour started with the "Artist - Title" track, or if it had already begun.

AlphaJack commented 3 years ago

It has been some weeks since the last time I encountered this problem, without me changing program files or playlists.