thinkpad-keys on ThinkPad X60* uses a large amount of CPU

[Chris Howells]

Binary package hint: hotkey-setup

This is on a ThinkPad X60s.

chris@thinky:~$ uptime
 13:45:30 up 3 days, 13:54, 4 users, load average: 0.94, 1.07, 1.08
chris@thinky:~$ ps aux | grep thinkpad-keys
root 4495 1.5 0.0 1412 28 ? S May14 79:12 /usr/sbin/thinkpad-keys

In three days (and numerous hibernates) thinkpad-keys has used 79 minutes of CPU time -- according to top thinkpad-keys has a constant CPU load of 2%, which unfortunately doesn't do good things for battery consumption.

[Paul Sladen (sladen)]

This only seems to show up on the X60*. Eg. on a R52 that has been up for a day, it's only used 20 seconds:

  $ uptime ; ps aux | awk '/[t]hinkpad-keys/{print$11,$10}'
  15:27:11 up 1 day, 6:20, 4 users, load average: 0.03, 0.07, 0.08
/usr/sbin/thinkpad-keys 0:20

sabdfl reported this to me and his X60 is SMP (Core Duo).

It may also, to a lesser extent, be visible on an R40e, jriddell has mentioned.

Chris: can you:

  apt-get install tpb

(this will conflict with 'hotkey-setup' so you'll temporaily have to remove the 'ubuntu-desktop' meta package).

Can you check if the CPU usage on that is any different. (It should be 25% of the amount since 'tpb' polls at 5Hz by default and 'thinkpad-keys', currently at 20Hz.

I've thought of so ways to get the current 80 /dev/nvram queries per second down to ~11 and not loose much of the responsiveness/latency.

[Chris Howells (chris-chrishowells)]

Hi Paul,

OK, I ran tbp using this command (obtained from the tpb docs):

sudo tpb --osd=on --verbose --thinkpad="/usr/bin/X11/xterm -T ntpctl -e ntpctl"

top shows that tbp sometimes uses 0%CPU, and sometimes uses 1% CPU, so about ~.5% CPU would tie in with your estimate. Still a bit excessive though, I started tpb a few minutes ago and it's already used a second of CPU.

I also recompiled thinkpad-keys and changed the poll interval from 50 to 100 milliseconds. This reduces load to ~1%.

Attaching gdb to thinkpad-keys showed a backtrace waiting in nanosleep() and usleep():

(gdb) bt
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7f1b110 in nanosleep () from /lib/tls/i686/cmov/libc.so.6
#2 0xb7f5198a in usleep () from /lib/tls/i686/cmov/libc.so.6
#3 0x08048c95 in main (argc=1, argv=0xbf8e8344) at thinkpad-keys.c:282
(gdb)

Would be interesting to know why this breaks on the X60. Mine is also the Core Duo.

[Chris Howells (chris-chrishowells)]

Well, the backtrace results aren't really surprising considering that the waiting should hopefully take a lot longer than the polling stuff. :)

[Paul Sladen (sladen)]

If you do an 'strace' you can capture what it's doing; which is a series of four nvram reads and then a what.

It maybe the result of a slow/blocking embedded controller (keyboard controller); IIRC the way that you interface with this chip is:

  1) Write to [index] register.
  2) Loop, polling whether the top bit is flipped.
  3) Read value from the [data] register.

There's two things it maybe related to as a result:

  a) We use non-blocking I/O as otherwise you get cached/previous results returned (which defeats the point...)
  b) The kernel driver using a non-yielding micro-sleep for the polling loop.

And somehow the latter (or both) maybe exacerpated by polling.

[Paul Sladen (sladen)]

...by SMP.

[noah dain (noahdain)]

getting the same behavior on an R40.

R40-2722 with pentium-m 1.7Ghz, using acpi.

I've taken to killing the thinkpad-keys process after startup. All the buttons continue working with including osd for volume control, access-ibm, brightness, thinklight, etc. (I'm using kde).

[Kristian Berge Nessa (kristian-nessa)]

I had the same behaviour on my T60p and X60t, thinkpad-keys using ~2% cpu at all times:
  $ uptime ; ps aux | awk '/[t]hinkpad-keys/{print$11,$10}'
   12:37:57 up 6 days, 19:39, 1 user, load average: 0.17, 0.14, 0.11
  /usr/sbin/thinkpad-keys 189:07

The attached patch bundles the 4 read+seek operations into one (10 byte read),
as well increasing POLL_DELAY to 100ms.
As a result thinkpad-keys drops off the top(1) charts entirely.
Additionally, the Makefile is fixed to forward CFLAGS, and call CC with default -02.

Tested on: T60p, X60t (Feisty, 2.6.20-lowlatency kernel), A30p (Edgy).
The A30p did not exhibit this behaviour, but applying the patch did not do any harm either.

Applies to latest release (0.1-17ubuntu9).
  cd hotkey-setup-0.1
  patch < hotkey-setup_0.1-17ubuntu9_optimize+CFLAGS.patch

DISCLAIMER: I have no knowledge of the inner workings of /dev/nvram, but this seems to work for me...
Also, this is my first patch here, so constructive criticism are very welcome.

[Kristian Berge Nessa (kristian-nessa)]

Sorry, please disregard the above ^ patch, this is the correct one.

Applies to latest release (0.1-17ubuntu9).
  cd hotkey-setup-0.1
  patch < hotkey-setup_0.1-17ubuntu9_optimize+CFLAGS.patch

[Kristian Berge Nessa (kristian-nessa)]

Update: After running the patched thinkpad-keys for >24 hours, CPU time is a meagre 1 sec, just a tad better than the >25 minutes it used to spend a day...

This just seemed to good to be true. So, to verify the correctness of the patch, here's some background:

The tpb source (from which thinkpad-keys is inspired) says the following:
  /* Read only the interesting bytes from nvram to reduce the CPU consupmtion of tpb */
  /* The kernel nvram driver reads byte-by-byte from nvram,
      so just reading interesting bytes reduces the amount of inb() calls */

...So I went to the kernel and checked drivers/char/nvram.c, and found:
* Each lseek() calls lock/unlock_kernel()
* Each read() calls spin_lock/unlock_irq (which is expensive)
* Each read() calls nvram_check_checksum (!).

To check the nvram checksum on a PC platform means to inb 30+2 times...
So, instead of saving 6 inb operations as intended, the current grok_nvram function does (32+1)*4=132 instead of (32+10)=42, spending 90 more than it should (in addition to any other overhead in calling lseek+read 6 times too many).

[Paul Sladen (sladen)]

Heck! At least now we know why the effect of a slow NVRAM is so amplified. Why on earth does the '/dev'/nvram' need to check the checksum *each* time.

I'm not sure we can avoid the lseek() overhead, though I guess if this is the way the 'nvram' driver is working, it *would* actually be cheaper to read the whole NVRAM block in a single read.

[Ben Collins (ben-collins)]

I don't see anything showing this was actually tested on 2.6.22. Can someone confirm this is the correct target?

[Benjamin Pineau (ben-pineau)]

Ben Collins : yes.
I'm running this on 2.6.22-rc5 on a Thinkpad X40, and:

1) This Thinkpad model is also affected, indeed.
2) The bug is still present on the original unpatched package (it's even more visible because of dynticks, see above).
3) The Kristian Berge Nessa's patch works flawlesly, and actualy fix the problem (CPU usage become marginal).

I also slightly modified the Kristian's patch to make POLL_DELAY a 200ms delay ("#define POLL_DELAY 200", in thinkpad-keys.c line 40), rather than 100ms on Kristian's, and worse, 50ms on the original.

That's because a second bug, related to this one, in hotkey-setup: not only it use a large amount of CPU by doing needly heavy operations, but it also suck lot of power, by waking up the CPU out of C3/C4 power saving c-states too often (odd for a laptop utility), and this should be avoided now we have a tickless kernel.

The original, unpatched, hotkey-setup wakes the CPU 20 times a second for no good reason. Kristian reduced this nvram poll freq to 10Hz. But I think we should go for 5Hz : that's what tpb does (tpb being the original IBM Thinkpad special keys manager, well tested), and 5Hz is enough to keep up and not loose any key event.

Arjan van de Ven pointed out tpb as an heavy power consumer on the PowerTOP hall of shame ( http://www.linuxpowertop.org/known.php#tpb ), but hotkey-setup is doing much n worse because of this to small nvram polling delay. With Kristian's patch and a 200ms POLL_DELAY, we're on par with tpb (not _that_ bad).

[Robert Bradford (robster)]

Patch works great here too. (X60s)

[Peter Meiser (meiser79)]

Hi,

the thinkpad_acpi kernel module generate an ACPI event when "echo 0xffffffff > /proc/acpi/ibm/hotkey". So, we don't need thinkpad-keys anymore which polls nvram. we could have ACPI event scripts for this. I'm attaching my proof-of-concept scripts.

Best regards,
Whoopie

[Kristian Berge Nessa (kristian-nessa)]

Whoopie: That sounds great! Just what is needed. (But does it work on any thinkpad model, older ones in particular?)
Also, I think thinkpad-keys will be with us for some time still, and as such should be patched ASAP anyway to provide a general fix that it not dependent on a recent kernel version. (I agree with Benjamin that 5Hz polling frequency should be more than enough)

If what I read on ibm-acpi-devel is correct, the reporting of keys as ACPI events was only recently added, its target kernel release being 2.6.23 which is still a little way off into the future for the ordinary ubuntu user:
http://<email address hidden>/msg00378.html

[Peter Meiser (meiser79)]

Kristian: it also works with the thinkpad_acpi version in 2.6.22-rc, although the output of /proc/acpi/ibm/hotkey doesn't show the whole 0xfffffff. But that's just a cosmetic issue.

[Roland Dreier (roland.dreier)]

Confirmed here too on my X60s... and just to amplify on what Benjamin Pineau mentioned, on my system, PowerTOP shows thinkpad-keys on my system is responsible for ~20 wakeups/second (exactly what you would expect with a 50 msec timer), which is currently about 10% of all the wakeups on my system. So it would really help save power to make thinkpad-keys able to sleep much more...

[Paul Sladen (sladen)]

I just tested here, you're right:

  echo 0xffffffff | sudo tee /proc/acpi/ibm/hotkey
  acpi_listen

now we get the rest of the events:

  0x1001 FN_F1
  ...
  0x100c FN_F12
  0x100d FN_BACKSPACE
  0x100e FN_INSERT
  0x100f FN_DELETE
  0x1010 FN_HOME (brightness)
  0x1011 FN_END (brightness) --- the one that was missing
  0x1012 FN_PAGEUP (thinklight)
  0x1013 FN_PAGEDOWN
  0x1014 FN_SPACE (zoom)
  0x1015 VolumeUp
  0x1016 VolumeDown
  0x1017 VolumeMute
  0x1018 ThinkPad/AccessIBM/ThinkVantage

The kernel proc driver needs fixing to display at least 24-bits.

We need to watch the mask handling; otherwise Fn-F7 (video switch) will break on older laptops.

[Joshua Kwan (joshk)]

Is this patch going to be applied to hotkey-setup anytime soon?

[Michael R. Head (burner)]

Seeing this on a Thinkpad T30, too. top and powertop both show that thinkpad-keys is using a lot of CPU.

[Michael R. Head (burner)]

By the way, I've only noticed this since upgrading to gutsy, but it may have been there before since I didn't go looking for it.

[Thomas Butter (tbutter)]

I did not see that problem in feisty. I am not sure if thinkpad-keys was running, but the volume keys worked. In gutsy it uses 2% cpu time on my laptop and battery is drained a lot faster.

[Medha (ubuntu-launchpad-badcode)]

Confirmed on a T43. thinkpad-keys hogs around 2-3% CPU time when running without the patch. Patched is much better.

[gagarine (gagarine)]

Confirmed on a T60p, 2% of CPU all time...

[Amit Shah (am1tshah)]

I have a T60 and run Kubuntu. I used to see 2% CPU. I changed some settings on my system and it went off mostly after I disabled arts in the kcontrol center (Enable sound system -> uncheck), though I'm not entirely sure if it was arts.

However, if I compile a newer kernel and install it, it thinkpad-keys shows up at 2%. The stock kernels from the kubuntu repo (currently 2.6.20-16-generic) doesn't have this problem for me.

[James Henstridge (jamesh)]

The new acpi-support (0.101) and hotkey-setup (0.1-17ubuntu15) packages stop thinkpad-keys from running so the 2% CPU usage dropped which is good.

However, none of the hotkeys were working. After a quick investigation, it seems that the thinkpad_acpi kernel module wasn't being loaded. A simple "sudo modprobe thinkpad_acpi" was enough to get the keys working again (I just tested the volume and brightness keys but I assume the rest were working).

For reference, I am using a Thinkpad X60s (i.e. one that reports Lenovo as the manufacturer, if that makes a difference).

[Paul Sladen (sladen)]

hotkey-setup (0.1-17ubuntu19) gutsy; urgency=low

  * Fix number of '.' in 'grep' mask string
  * Set the top 8-bits of the mask and see if the they stick
  * Add back in 'thinkpad-keys' lockfile logic
  * 'thinkpad-keys': Move open("fifo") into loop to reduce
    code duplication.
  * Roll 'thinkpad-keys-update' into "thinkpad-keys --update";
    remove second binary and duplicated FIFO location.
  * Change 'init.d' shebang from 'bash' to 'sh'
  * Add alias '--no-brightness' for 'LENOVO'; move policy
    decision from 'thinkpad-keys' to the 'init.d'

 -- Paul Sladen <email address hidden> Tue, 18 Sep 2007 19:41:36 +0300
0.1-17ubuntu18
Removed in gutsy-release on 2007-09-16

hotkey-setup (0.1-17ubuntu18) gutsy; urgency=low

  * Fix build breakage

 -- Matthew Garrett <email address hidden> Sun, 16 Sep 2007 00:52:07 +0100
0.1-17ubuntu17
Removed in gutsy-release on 2007-09-15

hotkey-setup (0.1-17ubuntu17) gutsy; urgency=low

  * Make sure that thinkpad-keys-update is actually installed

 -- Matthew Garrett <email address hidden> Sat, 15 Sep 2007 22:49:35 +0100
0.1-17ubuntu16
Removed in gutsy-release on 2007-09-15

hotkey-setup (0.1-17ubuntu16) gutsy; urgency=low

  * Add support for event-driven thinkpad-keys for machines that still need
    that. Requires kernel update for getting the notifications.
  * Reenable thinkpad-keys on hardware that doesn't have a sufficiently wide
    hotkey mask. Might still need some tuning.

 -- Matthew Garrett <email address hidden> Sat, 15 Sep 2007 22:05:20 +0100
0.1-17ubuntu15
Removed in gutsy-release on 2007-09-13

hotkey-setup (0.1-17ubuntu15) gutsy; urgency=low

  * Reduce power consumption and try to avoid circular relationships
    between key and brightness events.
  - Disable the 'thinkpad-keys' daemon
  - Enable extended ThinkPad hotkey ACPI events.
    (Combined with update to 'acpi-support' to handle new events).

 -- Paul Sladen <email address hidden> Thu, 13 Sep 2007 19:11:08 +0300