When set to act on the 'playlist' event, hangs (using 100% CPU) on large playlists

[sdelafond]

This is Debian bug #573805 (http://bugs.debian.org/573805).

More info available at the URL above, but basically:

On Sun, Mar 14, 2010 at 06:59:14PM +0100, Sebastien Delafond wrote:

[stats] Resolved `localhost' to 127.0.0.1
[stats] Successful bind to 127.0.0.1:6601
[1]
Sending list_queue_meta command to Mpd server
[2]
=== it goes into an infinite loop here ===
^C[stats] Exiting

Sorry for having overlooked this detail. [1] is the point where I issue
mpc del 0. As it seems hard to reproduce I ran it again with strace, to
give you some pointers of what happens.

[pid 26309] poll([{fd=4, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 3, -1) = 1 ([{fd=4, revents=POLLIN}])
[pid 26309] select(5, [4], [], [4], {30, 0}) = 1 (in [4], left {29, 999993})
[pid 26309] recvfrom(4, "changed: playlist\nchanged: playe"..., 4096, MSG_DONTWAIT, NULL, NULL) = 37
[pid 26309] write(2, "Sending list_queue_meta command "..., 45Sending list_queue_meta command to Mpd server) = 45
[pid 26309] write(2, "\n", 1
) = 1
[pid 26309] sendto(4, "playlistinfo\n", 13, MSG_DONTWAIT, NULL, 0) = 13
[pid 26309] select(5, [4], [], [4], {30, 0}) = 1 (in [4], left {29, 991003})
[pid 26309] recvfrom(4, "file: "..., 4096, MSG_DONTWAIT, NULL, NULL) = 4096
[pid 26309] open("/etc/localtime", O_RDONLY) = 8
[pid 26309] fstat(8, {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] fstat(8, {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7feb77595000
[pid 26309] read(8, "TZif\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0\10\0\0\0\0"..., 4096) = 837
[pid 26309] close(8) = 0
[pid 26309] munmap(0x7feb77595000, 4096) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] select(5, [4], [], [4], {30, 0}) = 1 (in [4], left {29, 999994})
[pid 26309] recvfrom(4, ""..., 4074, MSG_DONTWAIT, NULL, NULL) = 4074
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0
[pid 26309] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=837, ...}) = 0

From this up a repeating pattern starting with the last select can be
seen.

Occasionally some lines like:
[pid 26832] mremap(0x7f201096e000, 458752, 462848, MREMAP_MAYMOVE) = 0x7f201096e000
or
[pid 26832] brk(0x2bd7000) = 0x2bd7000
come along. They show that mpdcron grows in memory size.

Since mpdcron continues to read data from mpd (very slowly), it is
probably not an infinite loop, but a slow algorithm. The loop seems to
be getting slower over time which suggests an O(n^2) algorithm. I should
probably mention that my playlist currently has around 10000 entries.
You can easily create such a playlist by concatenating a playlist to
itself often enough. After eleven minutes of watching mpdcron read a
playlist I gave up and killed it, because two songs already passed by.

Furthermore I verified that disabling the stats module does not solve
the problem.

A quick check of the source shows that it probably blows up in
env_list_all_meta, because it uses strftime (and thus doing all those
stat calls) and using g_setenv in a loop and thus being an O(n^2)
algorithm.

The bad thing about this is that there is no easy way to solve this
problem, because the real problem didn't even show up: Let us assume
10500 playlist entries with each of them having a filename of 60
characters. For each entry two variables are added, which should take
another 40 characters only counting the lengths of their names. So a
lower bound for the size of the environment would be 1MB. This size may
not be supported by the operating system, so the whole approach of
feeding the playlist via the environment is flawed. Using g_setenv in a
loop only makes things break at an earlier point.

Given that it requires a large playlist I downgraded the severity to
normal. I hope this helps for solving the issue.

Cheers,

--Seb

[alip]

We really need a better way to pass data to the hooks. Using the environment was
the easiest way so I went with that initially. But as you said this approach is
flawed and it shows itself clearly with the playlist event case.

Maybe using standard input to pass data is a better way. What do you think?

[sdelafond]

stdin is a much better way, yes :)

[alip]

As of 387f423 mpdcron is more conservative when exporting variables to the environment.
I'll update the documentation on webpage soonish.
I did this because I don't have time to properly solve this problem (with stdin method or some other one)... That can wait for later.
Please test and report back!

[alip]

Documentation fixed by 0a25333
Closing this, reopen if the problem persists.