Jetson Nano 2GB: kernel backtrace on dunfell and kirkstone-l4t-r32.7.x branches with L4T r32.7.4

[housefm666]

Describe the bug With the L4T r32.7.4 I got a kernel backtrace, see the attachment, so I had to revert to L4T r32.7.3 version. It might be the problem with loading the GPU driver, nvargus-daemon, or after it.

Working versions: kirkstone-l4t-r32.7.x dunfell

To Reproduce Compile and flash core-image-weston with L4T r32.7.4 and run on Jetson Nano 2GB

You can reproduce with the latest commits: kirkstone-l4t-r32.7.x dunfell

Backtrace dunfell_7.4_backtrace.txt

[dwalkes]

Thanks @housefm666 Each of the warnings look like this:

Starting nvargus-daemon: [OK]
[   10.653594] ------------[ cut here ]------------
[   10.658215] WARNING: CPU: 0 PID: 2147 at mm/slab_common.c:98 kmem_cache_create+0x1cc/0x258
[   10.666459] Modules linked in: g_serial nvgpu tegra_udrm userspace_alert dione_ir
[   10.673973] 
[   10.675459] CPU: 0 PID: 2147 Comm: nvphsd_setup.sh Not tainted 4.9.337-l4t-r32.7.4+ga1cf17bc0aa0 #1
[   10.684484] Hardware name: NVIDIA Jetson Nano 2GB Developer Kit (DT)
[   10.690822] task:         (ptrval) task.stack:         (ptrval)
[   10.696727] PC is at kmem_cache_create+0x1cc/0x258
[   10.701505] LR is at kmem_cache_create+0xd4/0x258
[   10.706195] pc : [<ffffff80081f6914>] lr : [<ffffff80081f681c>] pstate: 60400045
[   10.713572] sp : ffffffc07792f830
[   10.716874] x29: ffffffc07792f830 x28: ffffffc071860000 
[   10.722189] x27: 0000000000010000 x26: ffffff800a1d78a8 
[   10.727502] x25: 0000000000000080 x24: 0000000000000000 
[   10.732814] x23: 0000000000000000 x22: 0000000000000080 
[   10.738127] x21: ffffffc0778b4010 x20: ffffff800a1d7880 
[   10.743440] x19: ffffff800a1d7840 x18: 00000000fffffffe 
[   10.748752] x17: 0000000000000000 x16: 0000000000000000 
[   10.754063] x15: 0000000000000001 x14: ffffffffffffffff 
[   10.759374] x13: ffffffc0778b4090 x12: ffffffc0778b4033 
[   10.764686] x11: ffffffc07792f9e0 x10: ffffffc07792f8a0 
[   10.769999] x9 : 00000000ffffffd8 x8 : 0000000000000080 
[   10.775312] x7 : 000000003fe00000 x6 : ffffffc07792f8a0 
[   10.780624] x5 : ffffffc07792f8a0 x4 : 0000000000000040 
[   10.785937] x3 : 0000000000000010 x2 : 0000000000000020 
[   10.791247] x1 : 0000000000000020 x0 : ffffffc0778b401e 
[   10.796559] 
[   10.798042] ---[ end trace 97efce8bb6e59d15 ]---
[   10.802646] Call trace:
[   10.805085] [<        (ptrval)>] kmem_cache_create+0x1cc/0x258
[   10.811185] [<        (ptrval)>] nvgpu_kmem_cache_create+0x88/0xd0 [nvgpu]
[   10.818326] [<        (ptrval)>] nvgpu_buddy_allocator_init+0x140/0x4b8 [nvgpu]
[   10.825883] [<        (ptrval)>] __nvgpu_vm_init+0x3d4/0x708 [nvgpu]
[   10.832482] [<        (ptrval)>] nvgpu_vm_init+0x90/0xd8 [nvgpu]
[   10.838736] [<        (ptrval)>] nvgpu_init_mm_setup_sw+0x1b4/0x4a8 [nvgpu]
[   10.845941] [<        (ptrval)>] nvgpu_init_mm_support+0x80/0xa0 [nvgpu]
[   10.852893] [<        (ptrval)>] gk20a_finalize_poweron+0x4b0/0x930 [nvgpu]
[   10.860096] [<        (ptrval)>] gk20a_pm_finalize_poweron+0xe8/0x3f8 [nvgpu]
[   10.867472] [<        (ptrval)>] gk20a_pm_runtime_resume+0x40/0x78 [nvgpu]
[   10.874333] [<        (ptrval)>] pm_generic_runtime_resume+0x40/0x60
[   10.880671] [<        (ptrval)>] __rpm_callback+0x78/0xa0
[   10.886056] [<        (ptrval)>] rpm_callback+0x38/0xa0
[   10.891267] [<        (ptrval)>] rpm_resume+0x558/0x768
[   10.896478] [<        (ptrval)>] pm_runtime_forbid+0x54/0x68
[   10.902125] [<        (ptrval)>] control_store+0xac/0x120
[   10.907509] [<        (ptrval)>] dev_attr_store+0x48/0x60
[   10.912895] [<        (ptrval)>] sysfs_kf_write+0x60/0x70
[   10.918280] [<        (ptrval)>] kernfs_fop_write+0xc4/0x1d8
[   10.923926] [<        (ptrval)>] __vfs_write+0x4c/0x128
[   10.929137] [<        (ptrval)>] vfs_write+0xb0/0x1b8
[   10.934176] [<        (ptrval)>] SyS_write+0x60/0xd0
[   10.939129] [<        (ptrval)>] el0_svc_naked+0x34/0x38
[   10.944766] ------------[ cut here ]------------

Coming from here which appears to be called from here based on call stack. Checking the return code for the snprintf there might be interesting.

Is there any problem you've noticed other than the warning print?

Have you attempted to reproduce on Stock Jetpack r32.7.x from NVIDIA yet?

[housefm666]

Thank you for the hint @dwalkes

I added debug print and config->name contains spaces: 'nvgpu-cache-0x (ptrval)-128-5', length 36

Is there any problem you've noticed other than the warning print?

• I haven't experienced it yet

Have you attempted to reproduce on Stock Jetpack r32.7.x from NVIDIA yet?

• I updated the Ubuntu 18.04 stock jetpack to r32.7.4 (sudo apt update then upgrade) without any issue and without this backtrace

[madisongh]

I suspect the problem is with the startup order of the different power management services. I haven't had a chance to try to reproduce yet, but it looks to me like the INITSCRIPT_PARAMS settings in the recipes that install the initscripts for nvpmodel and nvphsd might need some adjustment.

Even the systemd service units we install for the systemd case (which is what NVIDIA's Ubuntu uses, and what we use in our demo distro by default) look like they might need some minor tweaks to improve the ordering dependencies.

[housefm666]

I removed all symlinks from /etc/rc5.d and started to play with the services by hand.

The only solution was to wait half a minute after the kernel boots and I got a prompt:

sleep 30 && /usr/sbin/nvstartup && /usr/sbin/nvphsd_setup.sh

Less than 30sec 20-25sec was not enough, and I got the backtrace.

This is the line in the /usr/sbin/nvphsd_setup.sh, which causes the problem: echo on > /sys/devices/gpu.0/power/control

I will test it on the previous L4T r32.7.3 soon...

[housefm666]

Update: I switched to systemd and there is no issue. Since my kernel debug print message remained inside, I can see that the nvphsd_setup.sh script is called immediately after the kernel is loaded, there is no need to wait.

Shall we call any power management stuff before nvphsd?

[housefm666]

I tested a lot of things yesterday, in summary, I see that something is broken in r32.7.4 compared to r32.7.3.

1. Jetson Ubuntu 18.04: no matter what I did, I could not bring up the backtrace. I don't know what the trick might be, but I also tried your oe4t-patches-l4t-r32.7.4 branch, but the problem did not occur.

2. dunfell (or kirkstone) branch with systemd and with r32.7.4: The error didn't appear immediately at the first start, but when I issued one of the following commands, after restart the backtrace came up: $ systemctl isolate multi-user.target or $ systemctl set-default multi-user.target and I could not fix it whit his command: $ systemctl set-default graphical.target Does systemd reorder service calls maybe? I attached the results of systemd-analyze: bad.dump.txt bad.dot.txt bad.deps.txt bad.cc.txt bad.blame.txt good.deps.txt good.dump.txt good.dot.txt good.cc.txt good.blame.txt

3. dunfell (or kirkstone) branch with systemd/sysvinit and with r32.7.3: I was unable to produce the problem with the above mentioned commands. In fact, I couldn't even cause the problem with the two commands I wrote in my previous message in the case of sysvinit, it could be called without delay.

$ /usr/sbin/nvstartup && /usr/sbin/nvphsd_setup.sh

[madisongh]

Thanks for all the research on this. The problem is, sort of, with startup ordering/timing, but it's due to the kernel entropy pool not getting initialized before the nvgpu driver tries to create the labels for its kmem_cache entries. Those labels use sprintf with the %p directive, which, when the kernel can generate what it thinks are good random numbers, will be pointer-sized hex strings. Before then, though, it uses (ptrval), blank-padded. The blanks are what's triggering the WARN_ON traceback.

On the t210 platforms, we include the haveged package to help with initializing the kernel's entropy pool by starting the haveged daemon during boot. Recent versions of that package, though, have been updated for more-recent Linux kernels, which don't require a daemon for that purpose. We had updated our bbappend to fix that for systemd, but didn't when using init scripts. Also, the systemd service needed some tweaks to ensure it starts earlier in the boot sequence.

[madisongh]

Also note that or demo distro builds ensure that haveged is installed in our images on t210 platforms (for t186 and t194 platforms, we use rng-tools since the kernel on those platforms exports a /dev/hwrng device that package can use). If you're not using our demo distro setup, but instead building your own from scratch (or based on just poky), and you're targeting the TX1 or Nano platforms, you should add meta-oe to your set of layers and make sure your builds include the haveged package.

[madisongh]

For the dunfell branch, there was a slightly different set of problems, but with #1371 I've fixed things so startup is clean for both systemd and sysvinit builds. Make sure you follow the advice in my comment above about including haveged from meta-oe in your builds if you're using plain poky or your own distro.

[housefm666]

Thank you for the detailed answer!

Kernel L4T r32.7.4: You are absolutely right, I had to wait for this kernel message:

[   38.673730] random: crng init done
[   38.677200] random: 8 urandom warning(s) missed due to ratelimiting

then I could run the init commands $ /usr/sbin/nvstartup && /usr/sbin/nvphsd_setup.sh without backtrace.

If I installed the haveged, it could force to initialize the kernel's entropy pool, but the problem is that this daemon returns immediately and its effect in the kernel takes about ~1.2 seconds. So we need to ensure this delay between haveged and nvphs somehow, otherwise, we get the backtrace.

For systemds, there was no issue with haveged (I couldn't mess it up with the previously mentioned commands either), but for init scripts, I had to move it to the first place: S09haveged -> S00haveged, as S01networking takes some time, or we should add sleep 1.2 to the init script of haveged.

But the more interesting question is what happened in L4T r32.7.4? Because nvphs can be started at any time without any issues in r32.7.3 and earlier versions. However, the random: crng init done message appears in the kernel log at about the same time. Is it not possible to backport the entropy pool solution from the previous version to r32.7.4?

[madisongh]

for init scripts, I had to move it to the first place: S09haveged -> S00haveged

Interesting. The default priority of 9 worked OK for me when I tested on my Nano 2GB. A better solution might be to add some kind of check on the available entropy before starting nvphsd, so you're not having to constantly play games with startup order. There's a procfs entry you can use to check that, I'm just not sure off the top of my head what the right minimal value should be.

But the more interesting question is what happened in L4T r32.7.4?

Hard to say for sure, but it may be due to security-related patches that went into the upstream kernel between 4.9.299 (that R32.7.3 was based on) and 4.9.337, which may have made the kernel stricter about when it can use random numbers. Just looking at the git log for drivers/char/random.c, there were 180 patches between those versions.

[housefm666]

Interesting. The default priority of 9 worked OK for me when I tested on my Nano 2GB

Do you have any graphical interface? I have Weston, and its init script is S09weston right after S09haveged, and of course, this also causes a backtrace now. So I had to add something similar to the weston's init script:

while true; do
    entropy=$(cat /proc/sys/kernel/random/entropy_avail)
    if [ "$entropy" -ge 256 ]; then
        break
    fi
    sleep 0.5
done

Maybe would be better to add a new init script between S09haveged - S09weston like S09haveged-wait-entropy or similar, that can wait for the entropy. In that case, the original S09haveged remained untouched.

Hard to say for sure

I'm sad, then this will be automatically solved with the 5.10 kernel? (if there will be this for Tegra at all)

[madisongh]

I'm sad, then this will be automatically solved with the 5.10 kernel? (if there will be this for Tegra at all)

This is the last kernel we have for the t210 and t186 platforms.

I've made some adjustments to the sequencing, and added an enough-entropy check to the nvpmodel startup script, and tested this on both a Nano and a TX2-NX. The updated sequencing plus the added check work better for me when using either weston or X11 images using sysvinit. See #1374 for the changes, which I've only put into the kirkstone-l4t-r32.7.x branch.

In general, though, I'd really recommend using systemd over sysvinit. It's more aligned with NVIDIA's Ubuntu-based distro, and while we this layer has to be compatible with using initscripts, systemd is far better supported here.

[housefm666]

I tested your changes, it works, could you please apply these to the dunfell branch as well?

In general, though, I'd really recommend using systemd over sysvinit

I am of the opinion that if we support something, it should work, or if we don't support it, we should drop it and write in the readme that only systemd is supported. If someone wants to use the init scripts, they will feel endless pain (as me) if it doesn't work and they don't understand why. Of course, based on your comments, I can already hack my system locally, this is really meant for the community so that others won't mess with it.

Thanks for your efforts, really!

[housefm666]

@madisongh could you please apply these changes to dunfell branch? (as it runs on the same kernel so the issue is the same)

01f5eda6b86090fecde607d6f1f0059446226567 a89d07b860990c20c3a85c47baa959e2d15d806e 3e184a807edb27ac75dfdf28c066027c859273a8

Then I think this ticket can be closed.

Thank you!

[madisongh]

Thanks for the reminder