Note: This post is meant to help you debug a memory corruption if you are building your own kernel from source.
The symptoms:
If you see one of the following errors in your in your dmesg log:
* BUG: unable to handle kernel paging request at 7f45402d
* invalid opcode: 0000 [#1] SMP
* general protection fault: 0000 [#1] SMP
* BUG: unable to handle kernel NULL pointer dereference at 0000000000000258
Then you probably have a memory corruption somewhere.
In my case, I didn't get these errors at first. I was adding objects to a list by calling list_add_tail(my_list, my_obj) and verifying that list_empty(my_list) was returning false as expected (and it was). But latter in the code when I called list_empty(my_list) again, it was returning true, and in nowhere in my code I was removing objects from the list.
Weird behaviors that doesn't make sense probably are due to memory corruption. When I started simplifying the code to isolate the problem, I start getting the errors above in the dmesg log.
Where it is happening:
When you have an error, you get a log message in dmesg like:
We will be looking at 2 infos there:
1) The IP (instruction pointer) address in the 2nd line
2) The call trace at line 23rd
The IP
In the 2nd line of this log, we have the instruction pointer address, it is the address the computer was executing that generated the error.
In this example, the IP is ffffffff817c69f0, then we can find where in the code this address corresponds to using the
addr2line tool:
Where the path_to_your_kernel_tree is the path to the kernel code where you downloaded it (where you do make && make install)
The vmlinux file is the uncompressed version of the Linux image (it is created when you do make)
Note: if it doesn't work, check if your make menuconfig if your kernel is compiled with DEBUG flag
But this technique won't work if the corresponding address is not part of the kernel core code (if it was an error caused by some module, as we will see in the call trace section).
The call trace
In the log above, line 23rd, it means that the function devres_remove was called by devres_destroy, which was called by devm_kfree, which was called by vmc_cap_destroy and so on.
Now suppose that the vmc_cap_destroy function call devm_kfree in many places and you want to know exactly which one has triggered the bug. Lets do this in 2 steps:
1) Get the offset in the code section of the function using
nm:
nm is a tool to get the offset of a symbol in a section:
In this example, the offset of the vmc_cap_destroy function is
0x680
2) Get the file and the line using addr2line:
In line 27th we have:
vmc_cap_destroy+0x40, where the 0x40 is the offset inside the vmc_cap_destroy function where the code execution would return if the call to devm_kfree hadn't triggered the bug.
So lets add the function offset we found in the previous step with the offset inside the function: 0x680 + 0x40 =
0x6c0
And now we use the addr2line with the compile module.ko to find out where is it:
Then the buggy devm_kfree call is the first one just
before the line 396 in file vmc-capture.c
Enable debug prints:
Besides the techniques above, you can enable the debug level prints in the dmesg log:
sudo sh -c "echo 8 > /proc/sys/kernel/printk"
If this doesn't work, check if the DYNAMIC_DEBUG flag is enabled in your menuconfig, if so, then check the next section about Dynamic debug.
In the case of a module that I was testing (the vivid module), I needed to change the vivid_debug parameter:
We can do this when we start the module:
sudo modprobe vivid vivid_debug=8
Or changing the parameter while its already running:
sudo sh -c "echo -n 0 > sys/module/vivid/parameters/vivid_debug"
Dynamic debug:
If your kernel is compiled with DYNAMIC_DEBUG flag, then changing the printk level probably won't enable the debug prints in the dmesg log.
Lets say the module we are working is called media, lets add it into the kernel:
sudo modprobe media
And now we will enable all the debug prints in the media module by sending
'module media +p' to the dynamic_debug/control file:
If you look at the dynamic_debug/control file content (as we did above) you can see the "
=p" which means that the prints in those lines are enabled.
To disable the prints, we send
'module media -p' to the dynamic_debug/control file:
If you look at the dynamic_debug/control file content again you can see the "
=_" which means that the prints in those lines are disabled.
Enabling a specific print
Instead of enabling all the debug prints of the entire module, we can enable all the prints on a specific file, or we can specify a file and a line:
$ sudo sh -c "echo -n 'file media-entity.c +p' > /sys/kernel/debug/dynamic_debug/control"
$ sudo sh -c "echo -n 'file media-entity.c line 301 +p' > /sys/kernel/debug/dynamic_debug/control"
Read dmesg log continuously
Instead of calling dmesg every time to check the log, you can do:
$ tail -f /var/log/kern.log
and the log will be printed continuously.
