These days I use macOS for my personal and work computers, but I still miss the days when I used Linux in the desktop. I won’t argue about this decision because it’s not the point of this post, but suffice to say that I really like to have an operating system that I can modify as I want, specially the kernel. Because of this, I’ve always liked to have some kind of Linux-based computer in a small form factor. Raspberry Pi (either version) is really good and I’ve had all of them, but for this I prefer something more portable. Ideally something in for form of a USB stick, exposing itself as a network interface and allowing me to connect using SSH.
Enter the USB Armory from F-Secure Foundry. This is a really neat device and I’ve loved it (and owned it) since the first version. But now in the second version it’s become even better, even more powerful. Traditionally they offered only Debian and buildroot environments, but now they also have a project for running Go programs bare-metal (i.e. without an OS) called TamaGo. I may cover TamaGo in the future, but for now let’s focus on the Linux part.
The Debian image and cpufreq issues
F-Secure Foundry provides a Debian 10 (Buster) which is fairly lightweight, stable and functional. It’s been my OS of choice on this device for some time.
When the device was launched, it used kernel 4.19.95 (and Debian 9, but that doesn’t make any difference for the purpose of this issue). While it worked fine, there were some innocent messages in the kernel log:
[ 0.892204] debugfs: Directory 'cpu0-arm' with parent '20c8000.anatop:regulator-vddcore-cpu' already present! [ 0.902242] debugfs: Directory 'cpu0-soc' with parent '20c8000.anatop:regulator-vddsoc-vddsoc' already present! [ 0.911223] cpu cpu0: _opp_is_duplicate: duplicate OPPs detected. Existing: freq: 900000000, volt: 1275000, enabled: 1. New: freq: 900000000, volt: 1275000, enabled: 1 [ 1.000010] cpu cpu0: _opp_is_duplicate: duplicate OPPs detected. Existing: freq: 900000000, volt: 1275000, enabled: 1. New: freq: 900000000, volt: 1275000, enabled: 1 [ 1.013925] cpu cpu0: _opp_is_duplicate: duplicate OPPs detected. Existing: freq: 792000000, volt: 1225000, enabled: 1. New: freq: 792000000, volt: 1225000, enabled: 1 [ 1.027809] cpu cpu0: _opp_is_duplicate: duplicate OPPs detected. Existing: freq: 528000000, volt: 1175000, enabled: 1. New: freq: 528000000, volt: 1175000, enabled: 1 [ 1.041703] cpu cpu0: _opp_is_duplicate: duplicate OPPs detected. Existing: freq: 396000000, volt: 1025000, enabled: 1. New: freq: 396000000, volt: 1025000, enabled: 1 [ 1.055574] cpu cpu0: _opp_is_duplicate: duplicate OPPs detected. Existing: freq: 198000000, volt: 950000, enabled: 1. New: freq: 198000000, volt: 950000, enabled: 1
These errors kept repeating during boot, but stopped shortly afterwards and had absolutely no effect on the device or its stability. Searching for this issue yielded many different pages with this error, but no conclusive answer, except pointing that perhaps there was an error in the DTS file.
When they updated the kernel to 5.4.31, they also changed the DTS file used. This time, it didn’t use the one for an imx6ull, but rather one for the imx6ulz (which is the correct one). This made the messages go away. Unfortunately, it also caused the cpufreq driver to not load, resulting in the device running at 396Mhz all the time (very slow!). I reported this issue with a proposed fix and they fixed it using a different approach that worked just as fine, plus was simpler to maintain. The messages were still gone and everything was working fine (more on this later; this was a mistake on my part).
Enter Linux Kernel 5.6
I was looking into porting the latest 5.6.x kernel (then 5.6.10) to the device and after messing around with the mxs-dcp driver, I had a perfectly running system. Piece of cake, or so I thought.
Even though everything was working as expected (including cpufreq), I found these horrible messages in the kernel log:
May 10 01:21:24 usbarmory kernel: ------------[ cut here ]------------ May 10 01:21:24 usbarmory kernel: WARNING: CPU: 0 PID: 84 at drivers/opp/core.c:1053 dev_pm_opp_put_opp_table+0x110/0x114 May 10 01:21:24 usbarmory kernel: Modules linked in: May 10 01:21:24 usbarmory kernel: CPU: 0 PID: 84 Comm: kworker/0:2 Tainted: G W 5.6.10-1 #1 May 10 01:21:24 usbarmory kernel: Hardware name: Freescale i.MX6 Ultralite (Device Tree) May 10 01:21:24 usbarmory kernel: Workqueue: events deferred_probe_work_func May 10 01:21:24 usbarmory kernel: [<c010d300>] (unwind_backtrace) from [<c010b15c>] (show_stack+0x10/0x14) May 10 01:21:24 usbarmory kernel: [<c010b15c>] (show_stack) from [<c0123db0>] (__warn+0xbc/0xd4) May 10 01:21:24 usbarmory kernel: [<c0123db0>] (__warn) from [<c0123e28>] (warn_slowpath_fmt+0x60/0xb8) May 10 01:21:24 usbarmory kernel: [<c0123e28>] (warn_slowpath_fmt) from [<c0472b00>] (dev_pm_opp_put_opp_table+0x110/0x114) May 10 01:21:24 usbarmory kernel: [<c0472b00>] (dev_pm_opp_put_opp_table) from [<c047ca80>] (imx6q_cpufreq_probe+0x5dc/0x874) May 10 01:21:24 usbarmory kernel: [<c047ca80>] (imx6q_cpufreq_probe) from [<c041bebc>] (platform_drv_probe+0x48/0x98) May 10 01:21:24 usbarmory kernel: [<c041bebc>] (platform_drv_probe) from [<c041a368>] (really_probe+0x1e0/0x344) May 10 01:21:24 usbarmory kernel: [<c041a368>] (really_probe) from [<c041a654>] (driver_probe_device+0x60/0x16c) May 10 01:21:24 usbarmory kernel: [<c041a654>] (driver_probe_device) from [<c04186a4>] (bus_for_each_drv+0x80/0xc4) May 10 01:21:24 usbarmory kernel: [<c04186a4>] (bus_for_each_drv) from [<c041a114>] (__device_attach+0xd0/0x13c) May 10 01:21:24 usbarmory kernel: [<c041a114>] (__device_attach) from [<c04194e4>] (bus_probe_device+0x84/0x8c) May 10 01:21:24 usbarmory kernel: [<c04194e4>] (bus_probe_device) from [<c041996c>] (deferred_probe_work_func+0x64/0x90) May 10 01:21:24 usbarmory kernel: [<c041996c>] (deferred_probe_work_func) from [<c013c984>] (process_one_work+0x1f4/0x480) May 10 01:21:24 usbarmory kernel: [<c013c984>] (process_one_work) from [<c013cecc>] (worker_thread+0x2bc/0x654) May 10 01:21:24 usbarmory kernel: [<c013cecc>] (worker_thread) from [<c01418dc>] (kthread+0x13c/0x144) May 10 01:21:24 usbarmory kernel: [<c01418dc>] (kthread) from [<c01010e8>] (ret_from_fork+0x14/0x2c) May 10 01:21:24 usbarmory kernel: Exception stack(0xdecf9fb0 to 0xdecf9ff8) May 10 01:21:24 usbarmory kernel: 9fa0: 00000000 00000000 00000000 00000000 May 10 01:21:24 usbarmory kernel: 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 May 10 01:21:24 usbarmory kernel: 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000 May 10 01:21:24 usbarmory kernel: ---[ end trace d6254352d35aeeeb ]---
Same pattern as before, it repeated several times during boot, but stopped shortly afterwards and everything worked otherwise fine.
Since the stack trace specifically seemed to be related with imx6q-cpufreq and 5.4 didn’t had this error, I started by comparing the two versions. There were only two differences, one of which I was very suspicious. This change was introduced in the mainline, but backported to 5.6.5. If I reverted this change, the message went away and everything still worked fine. Sounds like a fix, right? Well, this is where it gets more complicated.
Fixed a memory leak, but causes an error freeing memory?
The fix mentioned was pretty obvious and seemingly obnoxious: if reading the CPU grade was deferred, since the OPP list was already created, it had to be freed before returning. Just until this patch, it was simply leaked. But this change meant there was a call to dev_pm_opp_of_remove_table(), where previously there wasn’t. And it was within this call that the warning was being raised.
This just calls _dev_pm_opp_find_and_remove_table(), so I looked at it. The code is pretty straight forward: obtain the OPP table, remove all static OPPs and decrement the ref counts until zeroed, which will cause the whole table to be freed by eventually calling _opp_table_kref_release(). And this is where the warning is raised.
Looking at the code, the warning was raised when the list to be freed was not empty. Seems pretty obvious, because if it was freed the elements would be leaked. But the _dev_pm_opp_find_and_remove_table() was freeing all the OPPs by calling _opp_remove_all_static(), so there shouldn’t be anything left on the list. Or isn’t it?
This function removed OPPs from the list provided that:
- parsed_static_opps was exactly 1, or nothing would be removed.
- the OPP had to have dynamic=0, or ir wouldn’t be removed.
Since I knew that nothing was being removed, I went to check these values.
The OPP table is initialized by calling dev_pm_opp_of_add_table(), which in turn read the DT and creates the OPPs accordingly. However, there are two methods for doing this:
- If the DT node for the CPU contains a property of name “operating-points-v2”, it does “version 2” processing.
- Else, it does “version 1” processing, reading from “operating-points”. This is what it we were using.
So for V1, the DT is read in _of_add_opp_table_v1() and calls _opp_add_v1() for each OPP. Checking this last function and the parameters used to call it, it seemed pretty obvious that “dynamic” was being set to 0. That only left checking for parsed_static_opps.
But there was no such thing for V1. The values seems to be initialized at 0 when creating the table, but was never modified afterwards. I found out that the V2 equivalent for this, _of_add_opp_table_v2(), was indeed setting this variable to 1.
My first action was to add that logic to V1 and it worked fine. Problem solved, right? Well, not really. While I can see how this works with this specific board, I have no idea how this will affect other callers. I’m no specialist on this part of the kernel, so I decided to leave this out for the time being. I will still look into it in the near future (hopefully).
The obvious question was: if this only affects V1, could I use V2? This would mean no kernel code changes and only DTS changes, which is fairly easy and wouldn’t affect anyone.
Enter operating-points-v2
Since I had absolutely no idea on how this worked out, I had to read the whole documentation for it. As it turns out, while it does allow a lot more functionality (specially with big.LITTLE architectures with shared/non-shared clocks and regulators), it also allow migrating from V1 with minimal effort.
The result was simpler than expected and looked quite nice. But upon starting I got this error:
May 18 05:47:50 usbarmory kernel: imx6q-cpufreq: probe of imx6q-cpufreq failed with error -17
As it turns out, -17 is EEXIST, which didn’t make sense until I noticed that a module named cpufreq_dt was loaded. Obviously you can’t have two cpufreq drivers for the same CPU, thus the EEXIST.
This driver was loaded because it looks for “operating-points-v2” in the DT. It should work, but it doesn’t because we’re not properly declaring the clocks, regulators, etc. in the DTS file. So I disabled the module and everything has been working fine since then.
Making sense of all the previous cpufreq errors
First, we must understand that this error only happens under very specific conditions, all of which must be met:
- Device is using an imx6ulz.
- The imx6q-cpufreq driver is built into the kernel.
- The nvmem_imx_ocotp driver is built as a module.
- The DTS file has “fsl,imx6ull” in its list of compatible values.
- The DTS file uses “operating-points” (not “operating-points-v2”).
While the error was spectacular in 5.6 because of the warning message, it existed even in 4.19 but it only showed the “duplicate OPPs” messages because it was simply not removing the OPPs from the list. In fact, if I rolled back that change, 5.6 behaved exactly as 4.19 (i.e. it shows the duplicate messages).
But, why didn’t 5.4 show the same behavior?
Well, actually it did. The “duplicate OPPs” message would have appeared, except that imx6q-cpufreq was not being loaded at all, as noted above. And even after fixing, by this time I was running a 5.4 kernel that had a different patch to solving the cpufreq issue initially noted. This meant that only “fsl,imx6ulz” was in the “compatible” attribute in the DTS file. It worked because I modified arch/arm/mach-imx/mach-imx6ul.c to include “fsl,imx6ulz”, thus making sure imx6q-cpufreq would load.
But this had an interesting effect on the issue. As I mentioned above, this problem only appeared when, among other things, imx6q-cpufreq was built into the kernel and nvmem_imx_ocotp was not and the compatible attribute contained “fsl,imx6ull”. This is very important because the idea is that it will cause a deferral when reading the CPU grade until nvmem_imx_ocotp is loaded because it is needed to read the OCOTP registers needed for determining the CPU grande.
But if the “fsl,imx6ull” (or “fsl,imx6ul”) is not present, it will assume that it’s dealing with the imx6q. This means that it will look for an entry in the DT compatible with “fsl,imx6q-ocotp” and access it directly using memory-mapped I/O. Since the imx6ulz also has this device and it uses the memory directly, it will never get deferred. But the list of OPPs will be incorrect as it includes the 726MHz step that is not valid for imx6ulz. However, you probably won’t notice it unless you run “cpufreq-info” and know exactly what to look for.
On the other hand, just specifying “fsl,imx6ull” in the DTS in 5.4 will reproduce exactly the same issue as in 4.19. So this difference was not due to the kernel, but rather the DTS file. Even in 5.6, if you revert the change which fixed the leak on deferral, the “duplicate OPPs” message will still show as in all previous versions. This proves that the issue has been there for quite a while, just that last change caused some confusion, at least on me.
Final Thoughts
This was a pretty obscure bug, but thankfully it doesn’t seem to have much impact on anything else, besides the annoying messages in the kernel log. Still, it was very interesting getting to the bottom of it. Hope you enjoyed it as much as I did!