severity 573805 normal
thanks
Hi Seb,
[If you are only interested in the results, only read the last three
paragraphs.]
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: <censored>"..., 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, "<censored>"..., 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.
Helmut
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmas...@lists.debian.org
