Internet radio causes extensive disk activity

Hello All,

I have a Debian system that has a purpose as music system, currently based on musicpd.
This service also supports internet radio (an example of such station: KWTU).

What I notice and what I like to solve is excessive disk activity when I listen to internet radio. I hope to find the file that is involved and move that to a tmpfs mounted folder. With lsof I see that mpd connects to the web site, but I struggle with finding the file on disk.

How would I eliminate this disk activity (noticed by the blinking LED on the front of the system)?

 

Is there a specific process related to radio?
Can you strace it to see what gives.

strace -f -c <radio process>

This will give you a summary of all system calls.
Maybe that can be the first indicator there might be a bottleneck somewhere, like lots of open or read errors and such.

Mrk

 

There is only one process involved, the mpd daemon.

First I created a brand new setup with empty music library and only one playlist (the internet radio station)
Then I played the radio and listened to verify that it's functioning well.

The following command generates the attached log file:

Code:

strace -o /tmp/strace-count.log -f -c /usr/bin/mpd --no-daemon ./mpd-test.conf

Thank you very much.

Attachment: View attachment strace-count.log

 

OK, the interesting bits:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
47.78 0.160042 210 762 1 poll
43.68 0.146310 62 2341 52 futex
8.36 0.028001 95 294 select
0.06 0.000194 0 2793 clock_gettime
0.04 0.000119 1 109 107 access

From what I see, most of the time is spent in network connections.

The interesting part is that you have 109 access calls, with 107 errors.
This system call (man 2 access) checks real user permissions on a file. I don't know which files it's checking, but you might have problems with path or some configuration file the player needs, so it's trashing the disk looking for some data. Maybe.

Can you run now strace -f -Tt -s 512 -o <output log> <radio>?

Then, let's see what gives inside. What kind of access it's doing and why.

While you're running the radio, and let it run for a while, can you also collect:

vmstat 1 30 (poll every 1 sec 30 times)
iostat 1 30 (same as above)

Let's see if there's a correlation to disk activity or blocking.

Regards,
Mrk

 

I got a 10 MB strace log and both vmstat and iostat logs shared on dropbox:
http://dl.dropbox.com/u/466202/diagnose-01.tar.7z

 

Just got back from work, will take a look later or perhaps tomorrow.
Mrk

 

strace shows ~100 lines "access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)"
According to Google no big deal.

 

Looking at your logs:

vmstat, no blocked processes, cpu wait is ~0, so you don't seem to have much io. iostat shows several small small reads/writes every few seconds, but it looks negligible.

The only interesting thing in strace is that you have some small packet loss, it seems, but nothing major, expected for radio streaming, and that the application checks time all the time, but this is wasteful for cpu and no io.

I would assume the blinking lights are from tiny reads/writes. Could be app cache or counters or maybe slider or such. But it's not trashing the disk, just appears busy.

Cheers,
Mrk

 

This is only happening with internet radio, listening to local tracks shows minimum disk activity.

Now, if I knew the location, I could perhaps tmpfs that.

 

You have lots of opens and read for codecs.
Example: open("/usr/lib/libmms.so.0"

As to writes, you write to various file descriptors, like 9, 12, 13, 14:
1607 10:12:14 write(9, "\0", 1) = 1 <0.000035>
1607 10:12:14 write(14, "OK\n", 3) = 3 <0.000062>

Can you run again, then run lsof -p <radio>?

And then, let's see what file descriptors it's holding open for read, write or both. You may want to run with strace to correlate the system calls to fds.

One more interesting thing is:
write(13, "file: http://pubint.ic.llnwd.net/stream/pubint_kwtu\nPos: 0\nId: 0\nOK\n", 6 = 68 <0.000082>

Lots of these, looks like it's saving position, volume and such.

Can you run a local track and compare?
Try strace -c for both first, compare the summaries?
Then run a local (with all the fancy flags) and see if there's a difference?

Cheers,
Mrk

 

The daemon is controlled with commands over a telnet session by a client.

I notice when I leave the session open there is also disk activity which stops when I close the session.
The client is getting progress updates of the song being played and shows play time and a progress bar.

Logs:
http://dl.dropbox.com/u/466202/local-lsof.tar.7z
http://dl.dropbox.com/u/466202/radio-lsof.tar.7z

 

Here's the interesting part:

mpd 3927 wilbert 3u unix 0xf5516400 0t0 8142 socket
mpd 3927 wilbert 4u IPv4 8138 0t0 TCP localhost:6600 (LISTEN)
mpd 3927 wilbert 5r FIFO 0,8 0t0 8139 pipe
mpd 3927 wilbert 6w FIFO 0,8 0t0 8139 pipe
mpd 3927 wilbert 7u IPv4 8140 0t0 TCP md110.local:6600 (LISTEN)
mpd 3927 wilbert 8r FIFO 0,8 0t0 8141 pipe
mpd 3927 wilbert 9w FIFO 0,8 0t0 8141 pipe
mpd 3927 wilbert 10u REG 8,6 3072 209898 /home/wilbert/mpd/sticker.sql
mpd 3927 wilbert 11r CHR 1,9 0t0 892 /dev/urandom
mpd 3927 wilbert 12r 0000 0,9 0 885 anon_inode
mpd 3927 wilbert 13u IPv4 10416 0t0 TCP md110.local:6600-><your name>.local:61339 (ESTABLISHED)
mpd 3927 wilbert 14u IPv4 10423 0t0 TCP md110.local:37784->sc3.ord.llnw.net:www (ESTABLISHED)
mpd 3927 wilbert 16u CHR 116,6 0t0 2027 /dev/snd/pcmC1D0p

FDs 13, 14 look nice

.local names sometimes take a very long time resolving, especially if you're using multicast. This is configurable under /etc/host.conf. Try setting multi to off and see if the problem persists. But I doubt it.

FD 14 is an external address; this could cause some slowness, if there's high latency. Could it telling the radio server to keep track tags or position and suchlike. But not sure how this would cause disk activity.

FD 10 is local sql db - you may want to symlink that to ramdisk or such and mount it there. Could be worth testing.

Local lsof shows:

mpd 3897 wilbert 10u REG 8,6 3072 209898 /home/wilbert/mpd/sticker.sql
mpd 3897 wilbert 11r CHR 1,9 0t0 892 /dev/urandom
mpd 3897 wilbert 12r 0000 0,9 0 885 anon_inode
mpd 3897 wilbert 13u IPv4 10366 0t0 TCP md110.local:6600-><your name>.local:61311 (ESTABLISHED)
mpd 3897 wilbert 15r REG 8,6 2657117 33596765 /home/wilbert/mpd/music/song.flac

So you have the same local connection, which might not be the issue here.
The difference is the communication to the server, but that's expected since one is local, the other streaming. I don't immediately see how this would affect the disk spinning so much.

Looking at the summaries of two straces - and I assume they relate to similar time frames.

Local:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
73.48 0.012000 92 130 1 poll
24.85 0.004059 17 243 47 futex
1.03 0.000168 2 104 write
0.43 0.000070 0 253 mmap2
0.21 0.000034 0 105 103 access
0.00 0.000000 0 246 read
0.00 0.000000 0 118 1 open
0.00 0.000000 0 133 close

Radio:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
47.78 0.160042 210 762 1 poll
43.68 0.146310 62 2341 52 futex
8.36 0.028001 95 294 select
0.06 0.000194 0 2793 clock_gettime
0.04 0.000119 1 109 107 access
0.03 0.000097 0 329 recv
0.02 0.000083 0 269 mmap2
0.02 0.000068 0 247 ioctl
0.01 0.000029 0 139 fstat64
0.00 0.000000 0 225 read
0.00 0.000000 0 72 write
0.00 0.000000 0 130 1 open
0.00 0.000000 0 152 close

You have far more polls (wait for events on fd) for radio than local. This could translate in more disk activity, especially if you read and write from these fds. And you also have many more selects (synchronous io multiplexing). So the app is waiting to see whether io operations can be run without blocking. Don't know what internal mechanism does this, but the combination of more calls and more io related calls could explain it. Maybe worth asking in the forums/ask devs what they are doing with this.

Can you also start both apps and collect io counters under /proc/pid/io.
I hope your kernel supports io counters.

Let's see if there's a difference in reads/writes between the two.
Try about 1 minute of runtime, if you don't mind.

To sum it up, 2 possible leads:

Move sql to fast storage.
Possible extra io operations (don't know why, but they are there).


Regards,
Mrk

 

Thank you very much, Mrk

I realize that it takes some more experience to be able to read these log files, I appreciate your time and effort.
The previous tests for local and radio don't span an equal time span, that may explain the difference in polls.

For next testing I disabled avahi-daemon and connect to static IP.
I also moved the sqlite db and tag db to ram, although the time stamp of the sqlite db indicates that it was not accessed for a while.

I tuned to the radio and there is no improvement.
More testing/logging later...

 

IO activity probably comes from extra select, poll. The reason for this is most likely sync with local cache. I can't think of another reason right now. The app probably buffers very small chunks.

Do you have caching enabled on your disk?
Have you many any changes to io scheduler or any of the vm params?

Regards,
Mrk

 

No, I haven't made any 'optimizations' in this area.

 

- restart mpd
- 1 minute streaming radio
- leave client controller connected

Code:

rchar: 18421
wchar: 30724
syscr: 182
syscw: 162
read_bytes: 393216
write_bytes: 4096
cancelled_write_bytes: 0

- restart mpd
- 1 minute local song
- leave client controller connected

Code:

rchar: 6476730
wchar: 28903
syscr: 946
syscw: 148
read_bytes: 2097152
write_bytes: 4096
cancelled_write_bytes: 0

Streaming radio is 24 KB bitrate mp3 and local song is ~650 KB bitrate flac

 

Sorry to butt in. Htop can do strace system calls by selecting process and clicking 's'

eg. for gkrellm.

 

Hmm, interesting info.

It's obvious you read more locally, stands to logic.
You actually read from block storage 390K with streaming, 2MB locally.
This means that radio does cache its data somewhere on the disk.

Now, you also read fewer characters than bytes with radio, 18K versus 390K, while local song used 6MB chars versus 2MB storage read bytes. This is a weird figure. I would have expected the char read to be higher than the bytes read figure. Think about it. Chars can be read from cache, so if the apps asks for same data, and it's in the cache, then it does not really need to access the disk. But then, with radio it's the other way around, so it read a ton from disk, but asked for only a small number. Either the numbers are lying or the app is doing wicked things.

The only lead I can think of now is this: there's such a thing in kernel called dirty_writeback_centisecs and dirty_expire_centisecs under /proc/sys/vm. In a nutshell, these params define for ext filesystems the age of dirty pages before they are committed to stable storage.

It's quite likely that pages age too quickly, so your radio needs to fetch its data more often. It might be purging its cache too early, forcing re-reads from disk. Perhaps

If you increase the two parameter to something say 10 times more than their current value, do you still get the disk activity? The param can be changed on the fly echo "value" > /proc/sys ... And changed back.

Sorry for being a smartass, but this is really curious. Can you test with changing the two vm params, just for fun's sake?

Cheers,
Mrk

 

Tried that...

...no difference

 

Damn, that thing is cursed ...
I'll install mpd myself over the weekend and do some testing.
Mrk

 

I asked before in the forum of a similar application (squeezebox).
It shows similar disk activity and the response I got is that streaming data is handled in memory. and they had no idea other than memory swapping (which is not the case, the server swaps zero) Squeezebox is a solution that depends on several processes, though.

Musicpd is a single process (and supports direct writing to Audio Class USB devices, bypassing alsa. That sounds really really good!).

MPD is a simple deamon, you can test with the option mpd --no-daemon <config file>, with a regular soundcard it should function without config file and you can also define a null sound device.
Some distro's have in the /etc/mpd.conf bind_to_address "localhost" as default.
If you change that to bind_to_address "any" you can access the service over your network.
The user that runs mpd needs to be in the audio group.

I control the daemon from my ipod (MPoD is the free app), and ario is a nice gnome desktop client. MPC is a console client (or how about telnet?).

For quick internet radio setup, I attach a playlist file, which you store in the mpd playlists directory (default: /var/lib/mpd/playlists)
View attachment Radio.txt rename this to radio.m3u (attachment restrictions of this forum)

When I asked for help, I assumed that I needed to find the cache file/directory and move that to memory.
I understand that streaming data is cached, but now it starts to look like there is nothing to move around.

 

Hi wilbert,

I'm on a 64-bit Maverick at the moment, running mpd as no daemon and using ario. I see your playlist and play it like a champ, zero disk activity, maybe one little blink every minute or so ...

Checking io stats, it's reading and writing a fair deal of data, but it's all cached, and not really being written to disk. I would guess you may have a disk with low caching or no caching enabled. Is that a new/old machine? What kind of a disk do you have there?

Regards,
Mrk

 

The system is a dedicated music server based on ECS Elitegroup MD110
Here is info from http://www.ecsusa.com/. (Duocore Atom)

The harddisk is a SAMSUNG EcoGreen F2 HD103SI 1TB 5400 RPM 32MB Cache SATA 3.0Gb/s 3.5"
32 MB cache.

A recent low power / low budget system

 

Do you have another host you can test?
Mrk

 

Yes, desktops and laptops, they have Desktop environments installed. All based on Debian Wheezy (32-bit)
Anything specific in mind?