thermald spamming kernel log when updating powercap RAPL powerlimit

[Colin Ian King]

[SRU Justification][Trusty][Wily]

thermald is triggering the kernel to SPAM the kernel log with frequent "package locked by BIOS, monitoring only" messages.

[Fix]
This issue is fixed with the following upstream commits:

f1a77c5f3b936ba8a7a63d587a803641974f8e62 ("thd_cdev_rapl: stop writing to sysfs if the write fails (LP: #1543046)")

833245725494eb26a1c61ca6f1a9db90599ae71b ("Initialize bios_locked to false")

These two fixes have been shown to work on Xenial and apply cleanly to Trusty and Wily versions of thermald. The risk of regression is low since these fixes add extra sanity checking to the code rather than completely new functionality plus they are upstream commits that have been available Xenial for some time now.

[Testcase]
Run on a system that reads /sys/devices/virtual/powercap/intel-rapl/intel-rapl:0/constraint_0_power_limit_uw where the BIOS has this feature locked and the kernel emits this message every time thermald accesses this /sys file.

With the fix, this message only appears once, and no more spamming occurs thereafter.

[Regression Potential]
Minimal. The fixes are upstream and have been tested in Xenial for quite a while. The fixes patch cleanly to Trusty and Wily and result in the same upstream code, so the code paths are identical to that of Xenial's thermald.

----------------------------------------

When thermald updates /sys/devices/virtual/powercap/intel-rapl/intel-rapl:0/constraint_0_power_limit_uw the kernel is emitting the following message:

[38458.753468] powercap intel-rapl:0: package locked by BIOS, monitoring only
[38637.993447] powercap intel-rapl:0: package locked by BIOS, monitoring only
[38674.154336] powercap intel-rapl:0: package locked by BIOS, monitoring only
[38691.500619] powercap intel-rapl:0: package locked by BIOS, monitoring only

This message comes from set_power_limit() in drivers/powercap/intel_rapl.c because the domain is locked by the BIOS. Writing to this interface fails with an error:

open("/sys/devices/virtual/powercap/intel-rapl/intel-rapl:0/constraint_0_power_limit_uw", O_WRONLY) = 3
write(3, "35000000", 8) = -1 ENODATA (No data available)

so in theory thermald should be seeing this failed write and handling it appropriately rather.

cthd_sysfs_cdev_rapl::set_curr_state() and cthd_sysfs_cdev_rapl::set_curr_state_raw() in src/thd_cdev_rapl.cpp perform the update and they do check that the sysfs write fails:

         if (cdev_sysfs.write(tc_state_dev.str(), state_str.str()) < 0)
                curr_state = (state == 0) ? 0 : max_state;

however, I believe they should check errno for the failed write and disable the rapl interface if we get -ENODATA on this interface to avoid repeated failures and hence repeated spamming of kernel messages

[dino99 (9d9)]

This not not the only existing issue, and flooding journalctl.
Looks like thermald does not check for valid cpu model to avoid that spamming: mine is an old intel q9550, and journalctl has logged:

***********
thermald[791]: NO RAPL sysfs present
Feb 08 07:16:23 u64 thermald[791]: 10 CPUID levels; family:model:stepping 0x6:17:7 (6:23:7)
Feb 08 07:16:23 u64 thermald[791]: Need Linux PowerCap sysfs
Feb 08 07:16:23 u64 thermald[791]: failed to open /dev/acpi_thermal_rel
Feb 08 07:16:23 u64 thermald[791]: failed to open /dev/acpi_thermal_rel
Feb 08 07:16:23 u64 thermald[791]: TRT/ART read failed
...
...
Unsupported cpu model, use thermal-conf.xml file or run with --ignore-cpuid-check
THD engine start failed
*************
So thermal-conf.xml might be completed to blacklist some incompatible hardware i suppose.

[Colin Ian King (colin-king)]

@dino99, please file a new bug for that particular issue, I am trying to get these issues fixed one by one rather than trying to address all the different issues in one fix.

[Colin Ian King (colin-king)]

Workaround pull request: https://github.com/01org/thermal_daemon/pull/79

I'll see what Intel says about this.

[dino99 (9d9)]

sorry for the noise, reported as Bug #1543109

[Jamie Strandboge (jdstrand)]

FYI, I applied the pull request locally and it seems to fix the issue.

[Colin Ian King (colin-king)]

Fix committed: https://github.com/01org/thermal_daemon/commit/f1a77c5f3b936ba8a7a63d587a803641974f8e62, currently waiting in -proposed

[Tuomas Jormola (tjormola)]

Unfortunately the 1.4.3-5ubuntu1 does not fix this bug for me. I'm using Ubuntu 16.10 on a Dell XPS 13 9343 machine with Haswell i7-5500U CPU and still getting this same error spammed in syslog every 4 seconds even after updating the thermald package from wily-proposed.

[Colin Ian King (colin-king)]

Please try thermald from the following ppa:

sudo add-apt-repository ppa:colin-king/thermald-1564443
sudo apt-get update
sudo apt-get install --reinstall thermald

and let me know if it fixes the issue.

[Dr4K4n (stefan-dr4k4n)]

Just did a fresh install on my XPS 13 9343 with Ubuntu 16.04 Beta 2 and thermald 1.5-2. No more error messages appear. Before I was running 15.10 and dmesg was spammed.

[JuanJo Ciarlante (jjo)]

FYI I'm running trusty with linux-generic-lts-xenial 4.4.0.18.10,
was getting same thermald spamming until I manually upgraded
to the package as per comment#8 above:
- upgrade thermald:amd64 1.4.3-5~14.04.2 1.4.3-5~14.04.3
, then no more kern.log spamming, thanks!.

[Colin Ian King (colin-king)]

Fixes currently waiting in -proposed for Trusty and Wily

[Brian Murray (brian-murray)]

Hello Colin, or anyone else affected,

Accepted thermald into wily-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.4.3-5ubuntu2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Brian Murray (brian-murray)]

Hello Colin, or anyone else affected,

Accepted thermald into trusty-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.4.3-5~14.04.3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Martin Ekendahl (hardlined)]

thermald 1.4.3-5~14.04.3 does not fix this issue for me.

[Colin Ian King (colin-king)]

@Martin can you double check:

dpkg -l | grep thermald

and also what messages are you seeing?

[Colin Ian King (colin-king)]

Just to re-iterate, this fix stops the spamming messages:

[38458.753468] powercap intel-rapl:0: package locked by BIOS, monitoring only
[38637.993447] powercap intel-rapl:0: package locked by BIOS, monitoring only
[38674.154336] powercap intel-rapl:0: package locked by BIOS, monitoring only
[38691.500619] powercap intel-rapl:0: package locked by BIOS, monitoring only

[Martin Ekendahl (hardlined)]

Colin:

# dpkg -l | grep thermald
ii thermald 1.4.3-5~14.04.3 amd64 Thermal monitoring and controlling daemon

Yes still getting those messages, a new line every 5-10 seconds.

[178055.276188] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178059.281879] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178063.287516] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178067.296361] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178071.306240] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178075.319197] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178079.325172] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178083.328756] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178087.339126] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178091.343039] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178095.356923] powercap intel-rapl:0: package locked by BIOS, monitoring only
[178099.362327] powercap intel-rapl:0: package locked by BIOS, monitoring only

etc..

[Colin Ian King (colin-king)]

OK, I've spent the last 3 hours verifying this manually on 3 different machines that trigger this issue.

Without 1.4.3-5~14.04.3, I see:

[72761.740827] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73066.277771] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73070.281923] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73074.285950] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73078.290045] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73082.294180] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73086.278074] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73090.282163] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73090.302293] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73098.310360] powercap intel-rapl:0: package locked by BIOS, monitoring only

That is, every 4-8 seconds and update.

I then installed thermald from -proposed, (1.4.3-5~14.04.3) and it restarted, and one only gets the initial message once and after that it does not occur. This is the expected behaviour, so on my 3 machines it's working fine.

I also verified this by running it not as a service but in non-daemon mode:

sudo dmesg -c
sudo thermald --no-daemon --loglevel=info

then I loaded the machine with stress-ng --cpu 0 and waiting for it to heat up a while. The kernel logs the following messages:

[73484.272942] powercap intel-rapl:0: package locked by BIOS, monitoring only
[73516.305392] intel_powerclamp: Start idle injection to reduce power
[73520.325616] intel_powerclamp: Stop forced idle injection
[73524.449552] intel_powerclamp: Start idle injection to reduce power
[73528.465760] intel_powerclamp: Stop forced idle injection
[73532.590030] intel_powerclamp: Start idle injection to reduce power

And the thermald is logging:

sysfs write failed constraint_0_power_limit_uw
Set : threshold:87000, temperature:89000, cdev:6(rapl_controller), curr_state:26250000, max_state:26250000
Set : threshold:87000, temperature:92000, cdev:7(intel_pstate), curr_state:1, max_state:10
cdev index:7 consecutive call, increment exponentially state 3
turbo disabled
Set : threshold:87000, temperature:87000, cdev:7(intel_pstate), curr_state:3, max_state:10
turbo enabled
Set : threshold:87000, temperature:86000, cdev:7(intel_pstate), curr_state:2, max_state:10
turbo disabled
Set : threshold:87000, temperature:89000, cdev:7(intel_pstate), curr_state:3, max_state:10
cdev index:7 consecutive call, increment exponentially state 5
Set : threshold:87000, temperature:89000, cdev:7(intel_pstate), curr_state:5, max_state:10
cdev index:7 consecutive call, increment exponentially state 7
Set : threshold:87000, temperature:93000, cdev:7(intel_pstate), curr_state:7, max_state:10
update_pid 1461351021 1461351021 500 250 92250
Read set point 93500
cdev index:7 consecutive call, increment exponentially state 11
Set : threshold:87000, temperature:92000, cdev:7(intel_pstate), curr_state:10, max_state:10
Set : threshold:87000, temperature:92000, cdev:5(intel_powerclamp), curr_state:5, max_state:50
Set : threshold:87000, temperature:85000, cdev:5(intel...

[Martin Ekendahl (hardlined)]

Colin could I implore you to include --enable-dbus in one more test, that appears to be the triggering factor for my machine. Without it the problem does appear to be fixed.

[Colin Ian King (colin-king)]

Thanks Martin, the --enable-dbus does trigger it for some reason. I appreciate you finding this and letting me know. I will get around to fixing this next week

[Colin Ian King (colin-king)]

OK, seems like commit c2e17ee973c59ca2b0898a147fa059c0c32369f4 may be required too:

    csys_fs::write: return -errno on write failure

    sysfs writes can fail for various reasons, and returning -errno is
    useful for indicating an error so that the caller can determine
    the best strategy to take if a sysfs write fails. This change
    is compatible with the current semantics, e.g. -ve is an error, but
    also propagates the errno back to the caller.

I'll get this resolved next week.

[Colin Ian King (colin-king)]

I've uploaded thermald 1.4.3-5~14.04.4 for testing in my PPA ppa:colin-king/thermald-sru

sudo add-apt-repository ppa:colin-king/thermald-sru
sudo apt-get update && sudo apt-get upgrade

I have also tested this out with the --enable-dbus on a few machines and the latest .4 version seems to fix this problem. However, I'd appreciate it if this version is tested before I upload it to -proposed for more testing.

[Martin Ekendahl (hardlined)]

1.4.3-5~14.04.4 fixes it for me, been running now for 2 hours with no messages.

[Colin Ian King (colin-king)]

1.4.3-5~14.04.4 in trusty -upload queue, waiting for 1.4.3-5~14.04.3 in updates to be rejected and for 1.4.3-5~14.04.4 to be promoted to -updates for testing again

[Martin Pitt (pitti)]

Hello Colin, or anyone else affected,

Accepted thermald into trusty-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.4.3-5~14.04.4 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Colin Ian King (colin-king)]

I've soak tested thermald with 1.4.3-5~14.04.4 and the bug does not occur, we don't see any spamming of the log with the "package locked by BIOS, monitoring only" message. Just one occurrence of the message occurs, and no more, as one expects with this fix.

[Launchpad Janitor (janitor)]

This bug was fixed in the package thermald - 1.4.3-5~14.04.4

---------------
thermald (1.4.3-5~14.04.4) trusty; urgency=medium

  * csys_fs::write: return -errno on write failure (LP: #1543046)
    - this detection helps previous fixes to stop BIOS message spamming

thermald (1.4.3-5~14.04.3) trusty; urgency=medium

  * Initialise bios_locked; may lead to random behaviour (LP: #1547594)
    - bios_locked should be initialised to false so that RAPL is
      enabled by default.
  * thd_cdev_rapl: stop writing to sysfs if the write fails (LP: #1543046)

 -- Colin King <email address hidden> Mon, 25 Apr 2016 09:02:11 +0100

[Chris J Arges (arges)]

The verification of the Stable Release Update for thermald has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Launchpad Janitor (janitor)]

This bug was fixed in the package thermald - 1.4.3-5ubuntu2

---------------
thermald (1.4.3-5ubuntu2) wily; urgency=medium

  * Initialise bios_locked; may lead to random behaviour (LP: #1547594)
    - bios_locked should be initialised to false so that RAPL is
      enabled by default.
  * thd_cdev_rapl: stop writing to sysfs if the write fails (LP: #1543046)

 -- Colin King <email address hidden> Thu, 7 Apr 2016 14:23:23 +0100

[Gabor Kulcsar (gkulcsar)]

Is this supposed to be fixed in 15.10 by now?

$ uname -a
Linux gabor-xps 4.2.0-36-generic #42-Ubuntu SMP Thu May 12 22:05:35 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

$ dpkg -l | grep thermald
ii thermald 1.4.3-5ubuntu2 amd64 Thermal monitoring and controlling daemon

$ grep "powercap intel-rapl:0: package locked by BIOS" /var/log/kern.log | wc -l
11470

$ head kern.log
Jun 5 08:44:57 gabor-xps kernel: [73322.633738] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jun 5 08:45:01 gabor-xps kernel: [73326.643339] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jun 5 08:45:05 gabor-xps kernel: [73330.654640] powercap intel-rapl:0: package locked by BIOS, monitoring only
...

[teo1978 (teo8976)]

This is NOT fixed on wily.

Thanks btw @30 for providing a quick test command which nobody else did before.

$ grep "powercap intel-rapl:0: package locked by BIOS" /var/log/kern.log

[......]
Jul 7 22:15:11 xxx1 kernel: [ 3027.312178] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:15 xxx1 kernel: [ 3031.317984] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:19 xxx1 kernel: [ 3035.326558] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:23 xxx1 kernel: [ 3039.335042] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:27 xxx1 kernel: [ 3043.343561] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:31 xxx1 kernel: [ 3047.350491] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:35 xxx1 kernel: [ 3051.358630] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:15:43 xxx1 kernel: [ 3059.374773] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:27:29 xxx1 kernel: [ 3766.104801] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:27:37 xxx1 kernel: [ 3774.116272] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:46:58 xxx1 kernel: [ 4935.901501] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:02 xxx1 kernel: [ 4939.910053] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:06 xxx1 kernel: [ 4943.917496] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:10 xxx1 kernel: [ 4947.926111] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:14 xxx1 kernel: [ 4951.934742] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:18 xxx1 kernel: [ 4955.943334] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:22 xxx1 kernel: [ 4959.951989] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:26 xxx1 kernel: [ 4963.960600] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:30 xxx1 kernel: [ 4967.969191] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:37 xxx1 kernel: [ 4974.605072] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:42 xxx1 kernel: [ 4979.793172] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:47 xxx1 kernel: [ 4985.030657] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:52 xxx1 kernel: [ 4990.159024] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:57 xxx1 kernel: [ 4995.257313] powercap intel-rapl:0: package locked by BIOS, monitoring only
Jul 7 22:47:57 xxx1 kernel: [ 4995.257887] powercap intel-rapl:0: package locked by BIOS, monitoring only

[Colin Ian King (colin-king)]

OK, not sure how that didn't get fixed properly in Wily, I'll look at it first thing on Monday.

[Colin Ian King (colin-king)]

Mind you, Wily is EOL on the 28th July, so upgrading to Xenial is recommended.

[Colin Ian King (colin-king)]

OK, apologies for that bug, I overlooked my original upstream commit c2e17ee973c59ca2b0898a147fa059c0c32369f4 ("csys_fs::write: return -errno on write failure") from the Wily backport hence it was not propagating the sysfs error status up to the RAPL interface. I've prepared a fix (1.4.3-5ubuntu3) and it can be accessed from my PPA: ppa:colin-king/thermald-wily-sru-1543046

I've uploaded the package for building, it should be published and ready in an hour or so.

sudo add-apt-repository ppa:colin-king/thermald-wily-sru-1543046
sudo apt-get update
sudo apt-get dist-upgrade

please can you test this and let me know if it fixes the issue. I can then upload it before the wily EOL.

[teo1978 (teo8976)]

> upgrading to Xenial is recommended.

Upgrading to Xenial may leave you with a broken, unbootable, unrecoverable system.

https://bugs.launchpad.net/ubuntu/+source/gconf/+bug/1551623

[teo1978 (teo8976)]

> sudo apt-get dist-upgrade

Forgive my ignorance: I always thought that "sudo apt-get dist-upgrade" was the command-line way of upgrading to the latest release (e.g. from Wily to Xenial).

I was way off, right?

[Colin Ian King (colin-king)]

Try this instead:

sudo add-apt-repository ppa:colin-king/thermald-wily-sru-1543046
sudo apt-get update
sudo apt-get upgrade

[Andy Whitcroft (apw)]

Hello Colin, or anyone else affected,

Accepted thermald into wily-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.4.3-5ubuntu3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Colin Ian King (colin-king)]

Verified this on an x220 which has been heavily loaded with the stress-ng matrix test - this kicks in the thermal controls and one sees just the one BIOS locked message and thereafter no more spamming.

[Launchpad Janitor (janitor)]

This bug was fixed in the package thermald - 1.4.3-5ubuntu3

---------------
thermald (1.4.3-5ubuntu3) wily; urgency=medium

  * Fix spamming kermel log (re-do) (LP: #1543046)
    - we need upstream commit c2e17ee973c59ca2b0898a147fa059c0c32369f4
      ("csys_fs::write: return -errno on write failure") so that we can
      pass the errno status back to thd_cdev_rapl to detect the RAPL sysfs
      write failure. This was missing from the previous attempt at the fix.

 -- Colin King <email address hidden> Fri, 8 Jul 2016 16:59:11 +0100