High CPU usage when idle

[silentbicycle]

After updating mpd and ncmpc, I noticed that ncmpc is using >80% CPU -- it seems to be endlessly looping when idle.

Since I update fairly often, this was probably introduced in the 0.33 release. (It could have been in 0.32, but anything older would be unlikely.)

Versions:

• ncmpc: 0.33
• mpd: 0.20.23
• libmpdclient: 2.16.0
• boost: 1.68.0

Running Void Linux:

$ uname -a
Linux pranaferox 4.17.9_1 #1 SMP PREEMPT Mon Jul 23 20:12:05 UTC 2018 x86_64 GNU/Linux

The strace log has sending an "idle\n" to a dup'd IPv6 socket to ::1:

sendto(9, "idle\n", 5, MSG_DONTWAIT, NULL, 0) = 5

and then it goes into a loop of running this over and over, as fast as it can:

rt_sigaction(SIGTSTP, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f40f7969370}, {sa_handler=0x7f40f83d36f0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f40f7969370}, 8) = 0
poll([{fd=0, events=POLLIN}], 1, 0)     = 0 (Timeout)
poll([{fd=0, events=POLLIN}], 1, 0)     = 0 (Timeout)
rt_sigaction(SIGTSTP, {sa_handler=0x7f40f83d36f0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f40f7969370}, NULL, 8) = 0
rt_sigaction(SIGTSTP, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f40f7969370}, {sa_handler=0x7f40f83d36f0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f40f7969370}, 8) = 0
poll([{fd=0, events=POLLIN}], 1, 0)     = 0 (Timeout)
poll([{fd=0, events=POLLIN}], 1, 0)     = 0 (Timeout)
rt_sigaction(SIGTSTP, {sa_handler=0x7f40f83d36f0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f40f7969370}, NULL, 8) = 0
timerfd_settime(5, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=1}}, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=2, tv_nsec=985596675}}) = 0
epoll_wait(4, [{EPOLLIN, {u32=2444182820, u64=94100882670884}}], 128, 0) = 1
timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=2, tv_nsec=985560000}}, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}) = 0

aside from the high CPU usage, ncmpc remains responsive.

I used perf to make a flamegraph, and it suggests that Instance:OnCheckKeyBindings, KeyBindings::Check, KeyBindings::FindKey ... is the sequence of calls where it's spending nearly all its time. Also, I noticed that the high CPU usage does not appear when run as root, but I don't see an EACCESS or other permission failures in the strace log suggesting why that makes a difference.

Please let me know if there's any other specific information I could add -- I can reproduce this pretty easily, but I'm not very familiar with modern C++ or the boost APIs. Hopefully these details are enough to point you in the right direction.

[silentbicycle]

Here's the flamegraph SVG, renamed to .svg.txt because github doesn't recognize the file type.

high_cpu_idle.svg.txt

[MaxKellermann]

Thanks for excellent data, and sorry for letting you wait. This bug was triggered by a problem with your key bindings file; watch out for ncmpc's error messages.

[silentbicycle]

Thanks!

When I start it, it just prints a couple lines like "Key Ctrl-N assigned to scroll-down-line and down", but those didn't register as error messages to me. They're quickly replaced by the UI.

My keybinding file has been basically unchanged since 2008 (if not earlier: that's when I imported my homedir into git...), so it's not surprising that there's something missing / with slightly different meaning.

I confirmed that if I rename my keybindings file so it starts without any configuration, the high CPU usage goes away. 👍 I guess this didn't happen when run as root because root doesn't have an ncmpc config at all.

[silentbicycle]

It looks like just having multiple bindings associated with the same key was the problem, specifically.

Working great now, thanks again.

[MaxKellermann]

That was not the problem; the problem was a bug, but it was only triggered by your configuration error. The bug is solved (no high CPU usage anymore even if your config is bad).

[silentbicycle]

Oh, I meant the problem with my config file -- I was curious what it was about my config file that had been triggering the underlying bug.

[hiqua]

I have a similar problem with the search functionality: starting a search (by pressing 5 5) results in high cpu usage, and a similar output from strace.

I have this bug with both the current GitHub version and 0.33-2+b10 from Debian. Let me know if I should open a new issue, but it seems related.

[MaxKellermann]

@hiqua new issue (with perf report).