100% cpu load after wake-up from suspend

[Helmut Rohs]

Useing PowerNap very successfully for some time.

Unequal to its intention to save power I remarked that it tends to keep one core busy at 100% load.
Now I trapped it to be connected to a wake-up by keyboard or mouse from suspend mode. Unfortunately I have not found any hint to it, wich might be just a config error. Neither I was able to attach with a python debugger yet.

Appreciate any hint.

[Helmut Rohs (helmut-rohs)]

powernap version: 2.18-0ubuntu

[Helmut Rohs (helmut-rohs)]

Had the powernapd now debugged for a while and for this reason I disabled the daemonizing of the service and started it directly from the python debugger. Otherwise I would be urged to debug through python with gdb ...

It kind of circumvent the behavior. My guess is that the daemonized childs get to poll from /dev/null as a stdin and read \cr in a poll loop. That gives nearly 100% CPU load without affecting the system seriously, what is kind of the observation.

[Helmut Rohs (helmut-rohs)]

OK, continued to run powernapd in the debugger. My last comment does not turn out to by valuable, no polling on /dev/null. But some kind of polling is going on.

Line 92 in InputMonitor.py returns always directly after calling it (res = self._poll.poll(1000)). And always returns code 24. The InputMonitor is hooked to my USB keyboard. The keyboard is working properly while this. Killing the thread gets powernap into a sane state again.
Because I am seeing this from ubuntu 12.04 up to ubuntu 13.10 on two different i386 (32bit) boxes with different keyboards attached, I would scratch out some bad hardware behavior because of power save modes.

Let's see if I can bring some more info.

[Helmut Rohs (helmut-rohs)]

Hm, poll() returning 24 means (select.POLLERR|select.POLLHUP), so the handle to the keyboard got broken for what ever reason. Adding an error handling into the InputMonitor would solve this and would be good in any case, whereas it would not get us the root cause.

Anybody knows about the lifetime of handles in terms of power save modes?

[Till Rosenband (trosenband)]

Hello Helmut,
The same problem of 100 % occurred on my PC. I agree that it would be nice to know the root cause of why POLLHUP occurs. Nevertheless, error handling is needed, if for example the keyboard is temporarily unplugged and then replugged. The attached patch attempts to implement this. It runs ok on my PC, but I haven't verified that it fixes the 100 % CPU problem, which has only occurred once in a while for me. Disclaimer: I am not so familiar with Python event polling. But considering the amount of energy that is likely wasted due to this bug, it would be nice to submit a patch to the maintainers.
Best,
-Till

[Till Rosenband (trosenband)]

Steps to reproduce bug:

1. Make sure powernapd is running.
2. Unplug USB keyboard.
3. Observe 100 % CPU usage for powernapd process.

My config file is attached.

[Till Rosenband (trosenband)]

Here is a better version of the patch.
-Till

[Helmut Rohs (helmut-rohs)]

Here is my fix.
I assumed that a evaporating handle allows the monitor thread to resign. The consequence should be that it gets recreated with a reopened device handle, but I am not sure about this.
The patch solves the 100% cpu load polling, but as already said I am not sure if you loose the Monitor this way further on.

Reading your patch suggestion I'd say that not checking poll on it's return value is to consider a bug.

Best

Helmut

[Till Rosenband (trosenband)]

You are right that my previous patch was not so good.

I did not see any provision in the code to restart the thread if it simply returns false on error, as in your patch. Did I miss this?

Here is a new patch that re-registers the input events when unplugging and replugging a USB keyboard (this could also be needed when using a KVM switch).

Regarding a separate issue, the patch now registers all input devices of the requested type, not just the first. This was causing trouble, because the if01 device (see below) was being registered, but generated no events. Only the non-if01 keyboard device generates events while typing.

2014-02-13_13:08:16 INFO keyboard unregister inputs
2014-02-13_13:08:16 INFO keyboard update inputs
2014-02-13_13:08:16 INFO For path: /dev/input/by-id found event: usb-Microsoft_Comfort_Curve_Keyboard_2000-if01-event-kbd
2014-02-13_13:08:16 INFO Registered event: /dev/input/by-id/usb-Microsoft_Comfort_Curve_Keyboard_2000-if01-event-kbd
2014-02-13_13:08:16 INFO For path: /dev/input/by-id found event: usb-Microsoft_Comfort_Curve_Keyboard_2000-event-kbd
2014-02-13_13:08:16 INFO Registered event: /dev/input/by-id/usb-Microsoft_Comfort_Curve_Keyboard_2000-event-kbd
2014-02-13_13:08:16 INFO mouse unregister inputs
2014-02-13_13:08:16 INFO mouse update inputs
2014-02-13_13:08:16 INFO For path: /dev/input found event: mice
2014-02-13_13:08:16 INFO Registered event: /dev/input/mice
2014-02-13_13:08:16 INFO Starting powernap
2014-02-13_13:11:07 INFO keyboard poll error: 24
2014-02-13_13:11:08 INFO keyboard unregister inputs
2014-02-13_13:11:08 INFO keyboard update inputs
2014-02-13_13:11:09 INFO keyboard update inputs
2014-02-13_13:11:10 INFO keyboard update inputs
2014-02-13_13:11:11 INFO keyboard update inputs
2014-02-13_13:11:12 INFO keyboard update inputs
2014-02-13_13:11:12 INFO For path: /dev/input/by-id found event: usb-Microsoft_Comfort_Curve_Keyboard_2000-if01-event-kbd
2014-02-13_13:11:12 INFO Registered event: /dev/input/by-id/usb-Microsoft_Comfort_Curve_Keyboard_2000-if01-event-kbd
2014-02-13_13:11:12 INFO For path: /dev/input/by-id found event: usb-Microsoft_Comfort_Curve_Keyboard_2000-event-kbd
2014-02-13_13:11:12 INFO Registered event: /dev/input/by-id/usb-Microsoft_Comfort_Curve_Keyboard_2000-event-kbd

Best,
-Till

[Tim Passingham (tim-8aw3u04umo)]

I've tried to comment on this and failed twice. I'm not sure what the problem is. I'll try again:

I've had the exact same problem with powernap. Do I just need to apply patch p3 (the last one) or any of the others as well, and just to the python source and then restart? I'm not that familiar with patching others' code.

[Helmut Rohs (helmut-rohs)]

Hi Tim,

Yes you are right. Try the last patch and apply it to the python script.
Kind of unfortunate that the nice project does not seem to get much
attention and thus is not well maintained.
I would like to see an arch Linux package ...

Thx

Helmut

Am Thursday, den 15.01.2015, 13:33 +0000 schrieb Tim Passingham:
> I've tried to comment on this and failed twice. I'm not sure what the
> problem is. I'll try again:
>
> I've had the exact same problem with powernap. Do I just need to apply
> patch p3 (the last one) or any of the others as well, and just to the
> python source and then restart? I'm not that familiar with patching
> others' code.
>

[Tim Passingham (tim-8aw3u04umo)]

I applied the last patch (p3) and the problem is fixed. Thanks very much. In my case I'm occasionally switching my USB keyboard and mouse to a (normally) headless music server.

I agree it's a shame that small fixes like this aren't getting into the main distribution. I got my original via the ubuntu software centre. I realise this isn't a critical fix, but using 100% of a CPU isn't good either.

[Amit Kucheria (amitk)]

Saw the same thing today on my headless server after connecting and disconnecting a usb keyboard for some debugging.

[zeke2135 (dlbrewe-2)]

I have seen this problem recently with one particular Logitech Universal receiver. I believe it is the newest receiver I own. It is paired with an M310 mouse.

I have not seen the problem with an older receiver paired with two different M310 mice. I have not seen the problem on an almost identical machine with a receiver (also older than the problem receiver) paired with an Anywhere MX mouse.

I couldn't pair both M310 mice to find out if the problem occurs with both mice. I don't know why, I think solaar got confused with the swapping.

This is trusty 14.04.3 with the latest vivid kernel. I believe this started up after a recent kernel update (within the last month at the most).