Under-voltage messages in the kernel log?

[notro]

I've been reminded that inadequate power supplies continous to be a problem for Raspberry Pi users (and even seasoned ones can be bitten by it).
This is especially true for those running headless as there is no blinking under-voltage icon on the screen to get your attention.

I've had this in the back of my mind for a couple of years that it would be nice to have a message in the kernel log when under-voltage occurs. So maybe now is the time to see if I can do something about this.

The first question is ofc, would this be helpful for more people than just myself?

The next question is how to get to this info from the kernel. Is there a mailbox property for this?
Either way I guess polling is the only option here.
On the Pi2 I believe it's possible to use the pwr led gpio as an interrupt to catch events, but on the Pi3 the pwr led 'gpio chip' probably doesn't have interrupt capability that can be easily routed to the ARM.

It would also be nice to have a message in the log if the previous boot/run had an under-voltage event.
So if the watchdog rescues an under-voltage induced crash, under-voltage as one possible reason will be shown in the log after reset.

[popcornmix]

vcgencmd get_throttled has the information needed by the arm, but the gencmd/vchiq interface is quite heavyweight for a kernel driver. I could add a mailbox command to get the same information.

What sort of driver are you thinking of that could do the polling?

How are you thinking of storing the fact that previous run had an under-voltage condition?

The reset controller (RSTS) is the only state that survives a reboot, but we are already using the bits available there. sdcard is the other option, but we may not run long enough after the event to get the data safely onto the sdcard.

[notro]

What sort of driver are you thinking of that could do the polling?

I was hoping that the power_supply class could be useful for this, but it seems to be more or less dedicated to charging and maybe not a good candidate for detecting under-voltage.

Another possibility is to do a regulator driver for the 5v0 regulator. Regulators do have an event for under-voltage at least: REGULATOR_EVENT_UNDER_VOLTAGE.

We can't just write a simple module that does this since we need a DT device to get to the firmware device for querying properties.

How are you thinking of storing the fact that previous run had an under-voltage condition?

I suspected thet the RSTS was used up already so I hoped that maybe the firmware had access to some other register that survives reboot.

It is possible to preserve panic messages across reset as I found out: Using ramoops/pstore to capture kernel panics

Sooo, maybe this just as well can be written as a systemd service that polls the value and writes events to the kernel log, and then use ramoops to preserve the event across reboot.

Do you think under-voltage logging is useful and worth spending time on for the community?

[popcornmix]

Do you think under-voltage logging is useful and worth spending time on for the community?

Yes.

[FishTest]

In most cases, the raspberry pi runs as a server and does not have a screen. There is no proprietary PMIC in the raspberry pi, and the Linux power supply driver can not communicate with the PMIC. So it's very important to get some power information in other ways.

[popcornmix]

I've added a commit to firmware that supports tag GET_THROTTLED = 0x00030046

/opt/vc/bin/vcmailbox 0x00030046 4 4 0
0x0000001c 0x80000000 0x00030046 0x00000004 0x80000004 0x00060006 0x00000000

The 0x00060006 is the throttled status as described here.
Will be in next firmware build (possibly tomorrow).

[notro]

I've been thinking about the challenge of polling and reliably getting info about anything but the first under-voltage event. We would have to poll very fast to be certain that we can detect an ongoing under-voltage.

How fast would we have to poll to be certain to detect under-voltage?

One solution is to have an under-voltage bit that is reset when read.
This way the polling period doesn't matter (that much), we are able to say that an event happened some time during the last n seconds.

[popcornmix]

I believe this is already handled. We added this to vcgencmd get_throttled for bcmstat.

Basically the bottom 16 bits are the live values and top 16 bits are the sticky values.
If you pass in a parameter to get_throttled (either gencmd or mailbox) it will clear the sticky bits after returning them.

There is a slight caveat if multiple users are clearing bits, but the result isn't fatal and if a kernel driver is supporting this functionality then we can deprecate other users.

[notro]

Indeed it does, I didn't come across that functionality in my web searches.

pi@pib:~ $ vcgencmd get_throttled 0x05
throttled=0x50000
pi@pib:~ $ vcgencmd get_throttled 0x05
throttled=0x0

[popcornmix]

Latest rpi-update kernel includes the GET_THROTTLED mailbox message.

[notro]

Even if I ask to clear the sticky bit, it is stuck for ~5 seconds:

$ while true; do vcgencmd get_throttled 1; sleep 1; done
throttled=0x40000
throttled=0x40000
throttled=0x40000
<brief overload>
throttled=0x50005
throttled=0x50005
throttled=0x50005
throttled=0x50000
throttled=0x40000
throttled=0x40000
throttled=0x40000
throttled=0x40000
^C

Is it a feature or a bug?

[notro]

I can add that I'm looking at 3 use cases:

1. Logging to /var/log/get_throttled.log and /dev/kmsg, runs as root. Needs to clear the sticky bit in order to track changes.

2. Desktop notification, must run as user. Not sure how to do this since the root process is clearing the sticky bit(s). It is possible for the process running as root to send events via the dbus system bus, but I'm afraid that it will be complicated, and I want this to be as simple as possible.

3. Realtime monitoring hopefully with multiload-ng which can graph output from commands. This one polls maybe once a second so it can look at the current value.

[popcornmix]

The "live" values for get_throttled have a decay so you can catch brief events (corresponds with the length of time the warning symbol appears on display).
Under-voltage is implemented as a uint32_t history that shifts and ors each cycle (100ms). So just over 3 seconds of decay.

[popcornmix]

Can the kernel driver be the master who reads and clears sticky bits and all other users go through the kernel driver (e.g. kernel exports values to /sys or similar). That avoids other users clearing the sticky bits.

[notro]

I was actually hoping to avoid a kernel driver. Some reasons:

• There's no clear subsystem to hook into for something like this
• We need to add a device in the Device Tree to use rpi_firmware_get(), what kind of device would that be? Or we could add this directly to drivers/firmware/raspberrypi.c
• It believe it will be difficult to get this upstream
• There are no in kernel users of get_throttled and it's possible to write to the kernel log from userspace: /dev/kmsg

What I need is a way to know is when the value changes. The current value is only interesting for monitoring purposes. So for a kernel solution that would probably mean adding /dev/get_throttled for userspace to poll for changes.

Dou you have any preferences regarding userspace or kernel?

[rodizio1]

The first question is ofc, would this be helpful for more people than just myself?

I'd love to see such a feature. I am the author of a distribution made for flying FPV aircraft with the Raspberry (https://github.com/bortek/EZ-WifiBroadcast) and users not providing the Raspberrys with stable 5Volts has been a constant issue over the past 1 1/2 years.

I have already tried running vcgencmd get_throttled in a loop every 10 seconds in a background task to notifiy the user with big letters in case of under-voltage (the "lightning" symbol always gets ignored, there are plenty of youtube videos from people using my distribution with the symbol popping up in the upper right corner), however, the Pi always crashed after some time when doing that.

Would integrating it into the sys filesystem also work?

I had the same problem with vcgencmd get_temp, but since the temperature also got included in the /sys/... directory some time ago, I can read it every second and display it to the user without the Pi crashing, would be nice if I could also do that for the undervoltage.

[notro]

I have stalled with my userspace approach and since @popcornmix have put the firmware bits in place I've tried a kernel approach.

sysfs file description:

What:		/sys/devices/platform/soc/soc:firmware/get_throttled
Description:	This file returns the firmware get_throttled value which is 
		divided into 2 parts:
		- lower 16-bits are the live value
		- upper 16-bits are the history or sticky value

		Bits:
		0: under-voltage
		1: arm frequency capped
		2: currently throttled 
		16: under-voltage has occurred
		17: arm frequency capped has occurred
		18: throttling has occurred

		This file can be polled for changes.

What:		/sys/devices/platform/soc/soc:firmware/get_throttled_mask
Description:	This file does two things:
		1. Describes which bits should denote a change when polling
		2. The upper part is used when clearing the sticky bits

		Default value is 1 << 16.

What:		/sys/devices/platform/soc/soc:firmware/get_throttled_poll_ms
Description:	Specifies the get_throttled polling interval in milliseconds 
		(default 2000ms). The kernel polls this value to detect 
		under-voltage and to support polling the get_throttled file for 
		changes. Setting this to zero disables polling.

Code:

diff --git a/drivers/firmware/raspberrypi.c b/drivers/firmware/raspberrypi.c
index f261b64d1657..2e930797dd3c 100644
--- a/drivers/firmware/raspberrypi.c
+++ b/drivers/firmware/raspberrypi.c
@@ -1,3 +1,4 @@
+#define DEBUG
 /*
  * Defines interfaces for interacting wtih the Raspberry Pi firmware's
  * property channel.
@@ -14,6 +15,7 @@
 #include <linux/module.h>
 #include <linux/of_platform.h>
 #include <linux/platform_device.h>
+#include <linux/workqueue.h>
 #include <soc/bcm2835/raspberrypi-firmware.h>
 
 #define MBOX_MSG(chan, data28)		(((data28) & ~0xf) | ((chan) & 0xf))
@@ -21,11 +23,14 @@
 #define MBOX_DATA28(msg)		((msg) & ~0xf)
 #define MBOX_CHAN_PROPERTY		8
 
+#define UNDERVOLTAGE_STICKY_BIT		BIT(16)
+
 struct rpi_firmware {
 	struct mbox_client cl;
 	struct mbox_chan *chan; /* The property channel. */
 	struct completion c;
 	u32 enabled;
+	struct delayed_work get_throttled_poll_work;
 };
 
 static struct platform_device *g_pdev;
@@ -166,6 +171,162 @@ int rpi_firmware_property(struct rpi_firmware *fw,
 }
 EXPORT_SYMBOL_GPL(rpi_firmware_property);
 
+static unsigned long rpi_firmware_get_throttled_poll_ms = 2000;
+
+static ssize_t
+rpi_firmware_get_throttled_poll_ms_show(struct device *dev,
+					struct device_attribute *attr,
+					char *buf)
+{
+	return snprintf(buf, PAGE_SIZE, "%lx\n",
+			rpi_firmware_get_throttled_poll_ms);
+}
+
+static ssize_t
+rpi_firmware_get_throttled_poll_ms_store(struct device *dev,
+					 struct device_attribute *attr,
+					 const char *buf, size_t size)
+{
+	struct rpi_firmware *fw = dev_get_drvdata(dev);
+	char *end;
+	unsigned long new = simple_strtoul(buf, &end, 0);
+
+	if (end == buf)
+		return -EINVAL;
+
+	if (new && new < 150)
+		return -EINVAL;
+
+	rpi_firmware_get_throttled_poll_ms = new;
+
+	if (rpi_firmware_get_throttled_poll_ms)
+		schedule_delayed_work(&fw->get_throttled_poll_work,
+			msecs_to_jiffies(rpi_firmware_get_throttled_poll_ms));
+
+	return size;
+}
+
+static DEVICE_ATTR(get_throttled_poll_ms, S_IWUSR | S_IRUGO,
+		   rpi_firmware_get_throttled_poll_ms_show,
+		   rpi_firmware_get_throttled_poll_ms_store);
+
+static unsigned long rpi_firmware_get_throttled_mask = UNDERVOLTAGE_STICKY_BIT;
+static DEVICE_ULONG_ATTR(get_throttled_mask, S_IWUSR | S_IRUGO,
+			 rpi_firmware_get_throttled_mask);
+
+static int rpi_firmware_get_throttled(struct rpi_firmware *fw, u32 *value)
+{
+	static ktime_t old_timestamp;
+	static u32 old_value;
+	u32 new_masked, old_masked, new_uv, old_uv, new_value;
+	ktime_t new_timestamp;
+	s64 elapsed_ms;
+	int ret;
+
+	pr_debug("%s: fw=%p\n", __func__, fw);
+
+	if (!fw)
+		return -EBUSY;
+
+	if (!value)
+		value = &new_value;
+
+	/*
+	 * We can't run faster than the sticky shift (100ms) since we get
+	 * flipping in the sticky bits that are cleared.
+	 * This happens on polling, so just return the previous value.
+	 */
+	new_timestamp = ktime_get();
+	elapsed_ms = ktime_ms_delta(new_timestamp, old_timestamp);
+	pr_debug("%s: elapsed_ms=%lld\n", __func__, elapsed_ms);
+	if (elapsed_ms < 150) {
+		*value = old_value;
+		pr_debug("%s: old_value=0x%x (%s)\n", __func__,
+			 old_value, value == &new_value ? "poll" : "show");
+		return 0;
+	}
+	old_timestamp = new_timestamp;
+
+	/* Clear sticky bits */
+	*value = rpi_firmware_get_throttled_mask >> 16;
+
+	ret = rpi_firmware_property(fw, RPI_FIRMWARE_GET_THROTTLED,
+				    value, sizeof(*value));
+	if (ret)
+		return ret;
+
+	pr_debug("%s: value=0x%x, old_value=0x%x (%s)\n", __func__, *value,
+		 old_value, value == &new_value ? "poll" : "show");
+
+	new_masked = *value & rpi_firmware_get_throttled_mask;
+	old_masked = old_value & rpi_firmware_get_throttled_mask;
+	new_uv = *value & UNDERVOLTAGE_STICKY_BIT;
+	old_uv = old_value & UNDERVOLTAGE_STICKY_BIT;
+	old_value = *value;
+
+	pr_debug("%s: new_masked=0x%x, old_masked=0x%x\n", __func__,
+		 new_masked, old_masked);
+
+	if (new_masked != old_masked) {
+		sysfs_notify(&fw->cl.dev->kobj, NULL, "get_throttled");
+		kobject_uevent(&fw->cl.dev->kobj, KOBJ_CHANGE);
+	}
+
+	if (new_uv != old_uv) {
+		if (new_uv & UNDERVOLTAGE_STICKY_BIT)
+			pr_crit("Under-voltage detected!\n");
+		else
+			pr_info("Voltage normalised\n");
+	}
+
+	pr_debug("\n");
+
+	return 0;
+}
+
+static void get_throttled_poll(struct work_struct *work)
+{
+	struct rpi_firmware *fw = container_of(work, struct rpi_firmware,
+					       get_throttled_poll_work.work);
+	int ret;
+
+	ret = rpi_firmware_get_throttled(fw, NULL);
+	if (ret)
+		pr_debug("%s: Failed to read value (%d)", __func__, ret);
+
+	if (rpi_firmware_get_throttled_poll_ms)
+		schedule_delayed_work(&fw->get_throttled_poll_work,
+			msecs_to_jiffies(rpi_firmware_get_throttled_poll_ms));
+}
+
+static ssize_t
+rpi_firmware_get_throttled_show(struct device *dev,
+				struct device_attribute *attr, char *buf)
+{
+	struct rpi_firmware *fw = dev_get_drvdata(dev);
+	u32 value;
+	int ret;
+
+	ret = rpi_firmware_get_throttled(fw, &value);
+	if (ret)
+		return ret;
+
+	return sprintf(buf, "%x\n", value);
+}
+
+static DEVICE_ATTR(get_throttled, S_IRUGO, rpi_firmware_get_throttled_show, NULL);
+
+static struct attribute *rpi_firmware_attributes[] = {
+	&dev_attr_get_throttled_poll_ms.attr,
+	&dev_attr_get_throttled_mask.attr.attr,
+	&dev_attr_get_throttled.attr,
+	NULL,
+};
+
+static const struct attribute_group rpi_firmware_group = {
+	.attrs = rpi_firmware_attributes,
+};
+
 static void
 rpi_firmware_print_firmware_revision(struct rpi_firmware *fw)
 {
@@ -190,6 +351,11 @@ static int rpi_firmware_probe(struct platform_device *pdev)
 {
 	struct device *dev = &pdev->dev;
 	struct rpi_firmware *fw;
+	int ret;
+
+	ret = devm_device_add_group(dev, &rpi_firmware_group);
+	if (ret)
+		return ret;
 
 	fw = devm_kzalloc(dev, sizeof(*fw), GFP_KERNEL);
 	if (!fw)
@@ -208,12 +374,15 @@ static int rpi_firmware_probe(struct platform_device *pdev)
 	}
 
 	init_completion(&fw->c);
+	INIT_DELAYED_WORK(&fw->get_throttled_poll_work, get_throttled_poll);
 
 	platform_set_drvdata(pdev, fw);
 	g_pdev = pdev;
 
 	rpi_firmware_print_firmware_revision(fw);
 
+	schedule_delayed_work(&fw->get_throttled_poll_work, 0);
+
 	return 0;
 }
 
@@ -221,6 +390,7 @@ static int rpi_firmware_remove(struct platform_device *pdev)
 {
 	struct rpi_firmware *fw = platform_get_drvdata(pdev);
 
+	cancel_delayed_work_sync(&fw->get_throttled_poll_work);
 	mbox_free_channel(fw->chan);
 	g_pdev = NULL;
 
diff --git a/include/soc/bcm2835/raspberrypi-firmware.h b/include/soc/bcm2835/raspberrypi-firmware.h
index cbd167457043..95cb67be1d58 100644
--- a/include/soc/bcm2835/raspberrypi-firmware.h
+++ b/include/soc/bcm2835/raspberrypi-firmware.h
@@ -77,6 +77,7 @@ enum rpi_firmware_property_tag {
 	RPI_FIRMWARE_GET_EDID_BLOCK =                         0x00030020,
 	RPI_FIRMWARE_GET_CUSTOMER_OTP =                       0x00030021,
 	RPI_FIRMWARE_GET_DOMAIN_STATE =                       0x00030030,
+	RPI_FIRMWARE_GET_THROTTLED =                          0x00030046,
 	RPI_FIRMWARE_SET_CLOCK_STATE =                        0x00038001,
 	RPI_FIRMWARE_SET_CLOCK_RATE =                         0x00038002,
 	RPI_FIRMWARE_SET_VOLTAGE =                            0x00038003,

Under-voltage events goes in the kernel log:

[   41.272229] Under-voltage detected!
[   45.432263] Voltage normalised

Desktop notifier

sysfs supports polling.

Install notifier daemon (supports cancelling notifications):

sudo apt install dunst

desktop-notifier.py

import dbus
import select
import datetime
import signal

msg = """Under-voltage is blah blah not good.
See: http://some-explanation.org
"""

def quit(signo, _frame):
    exit(0)

for sig in ('TERM', 'HUP', 'INT'):
    signal.signal(getattr(signal, 'SIG'+sig), quit);

bus = dbus.SessionBus()
notifier = bus.get_object('org.freedesktop.Notifications', '/org/freedesktop/Notifications')
iface = dbus.Interface(notifier, 'org.freedesktop.Notifications')
nid = None

epoll = select.epoll()
file = open("/sys/devices/platform/soc/soc:firmware/get_throttled")
epoll.register(file.fileno(), select.EPOLLPRI | select.EPOLLERR)
status = file.read()

while(True):
    epoll.poll()
    file.seek(0)
    status = file.read()
    get_throttled = int(status, 16)

    if get_throttled & (1 << 16):
        try:
            nid = iface.Notify('get_throttled', 0, 'dialog-warning', 'Under-voltage!', msg, [], {}, 0)
        except dbus.exceptions.DBusException as e:
            sys.stderr.write("Error sending notification: %s\n" % e); sys.stderr.flush()
    elif nid:
        try: # The user might have closed it
            iface.CloseNotification(nid)
        except dbus.exceptions.DBusException:
            pass
        nid = None

epoll.unregister(file.fileno())
file.close()

Comments anyone?

I haven't got time to try and get this upstream.

[popcornmix]

Looks good to me.
I assume the idea for a regulator driver didn't work out?
@pelwell ?

[notro]

I assume the idea for a regulator driver didn't work out?

It's just that I didn't find anything in the regulator framework that helps out with this. The only thing is an under-voltage event, but this in only for in-kernel users. If we could at least have read the actual voltage, then it would make more sense to make a regulator driver.

The benefit of having it in the firmware driver is that we can deal with all the bits, not only under-voltage.

[pelwell]

The driver looks good. You could restrict the critical error message to only be generated on the rising edge of the under-voltage signal, but if you are under-voltage and over-temperature then you have bigger problems than an extra kernel message.

[notro]

You could restrict the critical error message to only be generated on the rising edge of the under-voltage signal

That's what I'm currently doing. I'm only logging voltage events. Under-voltage is critical and returning to normal is info.
Should the other bits be logged to the kernel log as well? I'm not familiar with the meaning of these bits and what they signify. Do they have anything to do with temperature?
How can I trigger throttled and capped?

Currently the get_throttled file is dependent on the device name, which depends on the DT node pathname:
/sys/devices/platform/soc/soc:firmware/get_throttled

Perhaps it would be better to put the files under the driver instead, since it less likely to change?
/sys/bus/platform/drivers/raspberrypi-firmware/get_throttled

[pelwell]

Oh I see - in that case the mask in the test is redundant and misleading, surely.

[notro]

Oh I see - in that case the mask in the test is redundant and misleading, surely.

There are 2 masks:

• rpi_firmware_get_throttled_mask is used to clear sticky bits and to tell which bits we notify sysfs/userspace about when the value changes. If userspace doesn't care about the throttled bit, it won't be told about the change when polling (select) the file.
• UNDERVOLTAGE_STICKY_BIT used to log voltage only messages

Maybe we should drop rpi_firmware_get_throttled_mask entirely and just clear all sticky bits and let userspace keep track of the bits it cares about.

I included a way to set the polling period and even stop it, but I'm not sure if it will be useful.

I could strip this down to only the get_throttled sysfs file and we can add functionality when/if it's needed. In spirit with the KISS principle. Probably best to just scratch my own itch instead of guessing where other people might itch :-)

[pelwell]

Look at the multiple uses of UNDERVOLTAGE_STICKY_BIT - I think at least one is redundant:

+	new_uv = *value & UNDERVOLTAGE_STICKY_BIT;
+	old_uv = old_value & UNDERVOLTAGE_STICKY_BIT;
...
+	if (new_uv != old_uv) {
+		if (new_uv & UNDERVOLTAGE_STICKY_BIT)
+			pr_crit("Under-voltage detected!\n");
+		else
+			pr_info("Voltage normalised\n");
+	}

[notro]

Ah, I see.

[cyr-ius]

I compiled the last kernel 4.14.27 and since then I have the following message in loop in the kern.log
raspberrypi-firmware soc:firmware: Request 0x00030046 returned status 0x80000001
and i have no problem of under voltage
Pi Zero W
vcgencmd measure_clock arm
frequency(45)=1000106000
vcgencmd measure_clock core
frequency(1)=400000000
vcgencmd measure_volts
volt=1.2000V

vcgencmd measure_temp; vcgencmd get_throttled; vcgencmd measure_temp
temp=37.9'C
throttled=0x0
temp=37.9'C

I have the problem on my Pi Zero and Pi 2

How to stop this message ?

[pelwell]

Update to a recent firmware - copy it from the raspberrypi/firmware repo or use sudo rpi-update.

[danifr]

Yesterday I upgraded my Pi2 to 4.14.29-1-ARCH. After the upgrade I noticed I started to get a bunch (dozens) of these messages:

Mar 26 20:57:50 rbpi2 kernel: Under-voltage detected! (0x00050005)
Mar 26 20:58:25 rbpi2 kernel: Voltage normalised (0x00000000)

Is there a way I can simply hide them? I'm running Kodi on that Pi and the messages are printed on top of Kodi's UI.

Thanks for your help

[pelwell]

Use a better PSU, or get KODI not to scribble over the GUI?

[ThomasKaiser]

The 0x00060006 is the throttled status as described here.

@popcornmix I think the bits for throttling and frequency capping are reversed. At least that's what testing suggests. On a NAS distribution I use the sticky bits to be logged at shutdown and to generate a motd notification when user logs in next time: https://forum.openmediavault.org/index.php/Thread/18991-New-approach-for-Raspberry-Pi-OMV-images/?postID=148934#post148934

[E3V3A]

Seem related #2512.

[lategoodbye]

I assume this under-voltage detection isn't available for all Raspberry Pis. Which one supports it?

[pelwell]

All boards since the B+ (so A+, 2B, 3B, 3B+) except Pi Zero (including Zero W) and Compute Modules.

[lategoodbye]

Thanks. So the responsible hardware part is the SMPS?

[pelwell]

No, only on the 3B+. For other devices there is a cunning analogue circuit hooked up to a regular GPIO input.

[jcea]

I am using kernel "4.19.122-1-osmc" in a Raspberry Pi 3B+ Rev 1.3. The file "/sys/devices/platform/soc/soc:firmware/get_throttled" exists, but it always returns zero:

root@osmcpi:~# vcgencmd get_throttled
throttled=0x80008
root@osmcpi:~# cat "/sys/devices/platform/soc/soc:firmware/get_throttled" 
0

More details in https://discourse.osmc.tv/t/sys-devices-platform-soc-soc-firmware-get-throttled-not-working/86639