Dumping kernel page tables

Sometimes when debugging kernel issues, you might come across kernel addresses that you would find very difficult to map to a particular section in the kernel, ie, vmalloc, vmemmap, low/high kernel mapping, kernel text, etc. On x86, Arjan van de Ven has written an interface that provides a dump of the kernel page tables which gives information on the various memory areas in the kernel.

# cat /debug/kernel_page_tables
---[ User Space ]---
0x0000000000000000-0xffff800000000000 16777088T pgd
---[ Kernel Space ]---
0xffff800000000000-0xffff880000000000 8T pgd
---[ Low Kernel Mapping ]---
0xffff880000000000-0xffff880000200000 2M RW GLB x pte
0xffff880000200000-0xffff880040000000 1022M RW PSE GLB x pmd
0xffff880040000000-0xffff8800cfe00000 2302M RW PSE GLB NX pmd
...
---[ vmalloc() Area ]---
0xffffc20000000000-0xffffc20000001000 4K RW PCD GLB NX pte
0xffffc20000001000-0xffffc20000004000 12K pte
0xffffc20000004000-0xffffc20000005000 4K RW PCD GLB NX pte
0xffffc20000005000-0xffffc20000008000 12K pte
0xffffc20000008000-0xffffc2000000d000 20K RW PCD GLB NX pte
0xffffc2000000d000-0xffffc20000010000 12K pte
0xffffc20000010000-0xffffc20000011000 4K RW PCD GLB NX pte
....
---[ Vmemmap ]---
0xffffe20000000000-0xffffe20007c00000 124M RW PSE GLB NX pmd
0xffffe20007c00000-0xffffe20040000000 900M pmd
0xffffe20040000000-0xffffe28000000000 511G pud
0xffffe28000000000-0xffffff8000000000 29T pgd
0xffffff8000000000-0xffffffff80000000 510G pud
---[ High Kernel Mapping ]---
0xffffffff80000000-0xffffffff80200000 2M pmd
0xffffffff80200000-0xffffffff80a00000 8M RW PSE GLB x pmd
0xffffffff80a00000-0xffffffffa0000000 502M pmd
---[ Modules ]---
0xffffffffa0000000-0xffffffffa000a000 40K RW GLB x pte
0xffffffffa000a000-0xffffffffa000f000 20K pte
0xffffffffa000f000-0xffffffffa0016000 28K RW GLB x pte
0xffffffffa0016000-0xffffffffa001b000 20K pte
....
...

Understanding the above output:

o First field indicates the address range of a particular type of area (for example, user space, vmalloc area, kernel space, etc)
o The second field indicates the size of the address range in K,M,G,T units
o The fields following the size of the range have the following meaning:
USR - whether the page being mapped is a user page or not
RW - whether the page is read/write. If not RW, the output would be 'ro' to indicate a read-only page
PCD - Page Cache Disabled - maps a page with caching disabled
PWT - page with Page Write-Through set
PSE - Extended paging enabled - allows large linear contiguous address ranges to be mapped
GLB - Page Global flag - The global flag is set for a page that is frequently used and prevents it from being flushed from the TLB
NX - Page is non-executable, else marked as 'x'
o The last entry indicates the particular level of the page table - pgd, pud, pmd or pte that the region corresponds to

Enable the CONFIG_X86_PTDUMP configuration option, along with enabling debugfs. The corresponding kernel code for the interface can be found under arch/x86/mm/dump_pagetables.c

Using gdb for debugging kernel modules

This is a very simple and maybe trivial post.. and nothing novel ! But something that has helped me a lot in debugging issues with my kernel modules and kernel panics in general. So, when you get a panic originating in a kernel module, you normally get it in the following format:

BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
IP: [<ffffffff8023262c>] mmput+0x11/0xb0
PGD 22bcf6067 PUD 211839067 PMD 0
Oops: 0002 [#1] SMP
last sysfs file: /sys/block/sdb/size
CPU 6
Modules linked in: <a routine in my module> ehci_hcd uhci_hcd [last unloaded: <my module>]
Pid: 26830, comm: <my kernel thread> Not tainted 2.6.28-anki #13
RIP: 0010:[<ffffffff8023262c>] [<ffffffff8023262c>] mmput+0x11/0xb0
RSP: 0000:ffff8802279fbed0 EFLAGS: 00010246
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000045
RDX: ffff88022e150300 RSI: 0000000000000282 RDI: 0000000000000000
RBP: ffff8802279fbee0 R08: 0000000000000018 R09: ffff88022e150300
R10: ffff88022e150300 R11: 00007fffe6dfefff R12: ffff88022e52f860
R13: ffff88022e150300 R14: ffff88022d99aed0 R15: ffff88022d99b110
FS: 0000000000000000(0000) GS:ffff88022f818280(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000050 CR3: 0000000211829000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process memref (pid: 26830, threadinfo ffff8802279fa000, task
ffff88022d4ef1b0)
Stack:
ffff88022e150300 0000000000000000 ffff8802279fbf20 ffffffffa003314b
ffff8802279fbf20 ffff88022d99aed0 ffffffffa00330f2 ffff880210cf1c68
ffff88022f855ee0 ffff88022f855f00 ffff8802279fbf40 ffffffff802468e3
Call Trace:
[<ffffffffa003314b>] <routine in my module>+0x59/0xb2 [<my kernel thread>]
[<ffffffffa00330f2>] ? <my modulee>+0x0/0xb2 [<my kernel thread>]
[<ffffffff802468e3>] kthread+0x49/0x76
[<ffffffff8020cce9>] child_rip+0xa/0x11
[<ffffffff802277a5>] ? dequeue_task+0xbf/0xca
[<ffffffff8024689a>] ? kthread+0x0/0x76
[<ffffffff8020ccdf>] ? child_rip+0x0/0x11
Code: df e8 88 c7 fd ff 48 8b 3d ba 28 6b 00 48 89 de e8 b1 af 05 00 41 59 5b
c9 c3 55 48 89 e5 53 48 89 fb 48 83 ec 08 e8 6a fa 39 00 <f0> ff 4b 50 0f 94
c0 84 c0 0f 84 8b 00 00 00 48 89 df e8 8b 76
RIP [<ffffffff8023262c>] mmput+0x11/0xb0
RSP <ffff8802279fbed0>
CR2: 0000000000000050

Now, to find out from where exactly in my module the panic happened, I simply use gdb, as below:

#gdb <path to my module.o file from the kernel source root dir> [for example, #gdb drivers/misc/ankita.o]
....
(gdb) list *(the routine)+0x59

The above gives a source listing, pointing to the lines which correspond to 0x59 address. This serves as a good starting point to debug the issue. Hope this helps some folks atleast :-)

Fake NUMA nodes in Linux

While NUMA systems are becoming commonplace, many a times we do not have access to such systems when either writng new code, understanding NUMA architecture, conducting experiments or debugging existing code. For such cases, the Linux kernel provides a very neat feature called 'fake numa nodes'. One can create fake numa nodes on a non-NUMA machine by simply passing a commandline parameter to the kernel. Below are the steps for x86 systems:

1. Following config options need to be turned on: CONFIG_NUMA=y, CONFIG_NUMA_EMULATION=y
2. Build the kernel with the above config options set
3. The kernel commandline could be any one of the following, depending on your requirement:

• numa=fake=4 : Split the entire memory into 4 equal nodes
• numa=fake=8*1024 : Split the memory into 8 equal chunks of 1024MB (ie 1G) (note, the number is considered to be in MB) [If system has more memory, the last node will be assigned remaining memory]
  
• numa=fake=2*512,2*1024 : Split the memory into 2 nodes of 512MB each and 2 more nodes of 1GB each (and so on)

Note: On ppc, the nodes required are specified using cumulative comma separated list. For example, to create 4 nodes of 2GB each the parameter would be: "numa=fake=2G,4G,6G,8G"

You can play around with more options :) The userspace numa utilities like numactl and numastat would then show the numa environment that has been setup. Details of the cpumap and per-node meminfo can be obtained from the sysfs file /sys/devices/system/node/node<0|1|2..>.

Fake NUMA has one flaw however and that is the CPU mapping to nodes. There would exist nodes that do not show up as having any CPUs (unde the cpumap file in the node dir of the above mentioned sysfs file). As per the semantics, a CPU must unquely belong to a NUMA node. However, inside the kernel, the CPU is mapped to all the fake nodes.

Fake NUMA nodes can be created even on a real NUMA system. In this case, the fake nodes are aligned within a real node. The distances between two fake nodes across two real nodes is maintained. Could cover internal implementation details in a separate post. Have fun playing around with NUMA !

Collecting trace data from Linux kernel using klog

Many mechanisms exist to trace through the linux kernel code, both dynamically and statically. For example, for static tracing, one could use the markers or ftrace, and for dynamic tracing, there is kprobe, systemtap (which is built on top of kprobes). However, I was looking for a way to just dump some data from the kernel into a buffer and dump that data to the user at a later point in time. An example scenario being, while I am in the timer interrupt or in some other non-preemptible code section, I only wish to capture some timestamps, I cannot afford to do a printk from there. Also for instance, I want to instrument the scheduler code to capture timestamp information, I will be into trouble.. as, scheduler code being executed so very often, I will be bombarded with data and the depending on how much data I am collecting, the system could also become unusable.

I came across the klog kernel patch very recently. It was written by Tom Zanussi in 2005. Recently, Vaidyanathan Srinivasan made a few changes to klog, by adding the function ktrace, which makes it even more simpler to use it. Below, I describe how one could make use of this mechanism. Before we begin, note that klog is a static tracer. So, everytime you want to trace new code, the kernel will need to be recompiled.

Apply the klog patch to your kernel. This includes the changes made by Vaidy for ktrace. To trace through any code (ie, kernel routine), ktrace provides the following infrastructure:

1) Trace events (defined in include/linux/ktrace.h):

enum KTRACE_EVENT_ID {
KT_EVENT_FUNC_ENTER,
KT_EVENT_FUNC_EXIT,
KT_EVENT_INFO1,
KT_EVENT_INFO2,
KT_EVENT_INFO3,
KT_EVENT_INFO4,
KT_EVENT_ERROR,
};

2) Enumerator for the functions to be traced (include/linux/ktrace.h):

enum KTRACE_FUNC_ID {
KT_FUNC_tick_nohz_stop_sched_tick, /* 0 */
KT_FUNC_tick_nohz_restart_sched_tick, /* 1 */
};


3) Logging routines (lib/ktrace.c):

void ktrace_log2(unsigned char func, unsigned char event, uint64_t u1, uint64_t u2);
void ktrace_log4(unsigned char func, unsigned char event, uint32_t u1, uint32_t u2,
uint32_t u3, uint32_t u4);

So now, if you want to capture timestamps between the entry and exit of a routine x (assuming the routine executes in preempt disable mode), the following changes would be needed:

a) Add that function into the KTRACE_FUNC_ID,

enum KTRACE_FUNC_ID {
KT_FUNC_tick_nohz_stop_sched_tick, /* 0 */
KT_FUNC_tick_nohz_restart_sched_tick, /* 1 */
+ KT_FUNC_my_func_to_trace,
};

b) At the entry of the routine, capture the timestamp:

ktime_to_ns(start);

At the exit of the routine, make a call to ktrace_log2,

ktrace_log2(KT_FUNC_my_func_to_trace, KT_FUNC_EXIT,ktime_to_ns(now)-start, 0);

Now, whenever the routine is executed, the ktrace_log2 call will dump the information into the klog buffer. Compile and reboot into the modified kernel. Mount debugfs:

# mkdir /debug
# mount -t debugfs nodev /debug

Now run the klog.c program

# ./klog [-b subbuf-size -n n_subbufs]


The resultant trace data will be stored in ./cpu0..cpu[x] files. Remember that this data is in binary format and needs to be processed to convert into ascii. For that, a simple python program can be used. A sample python script could be as follows: (adopted from this script)

import os
import sys
import struct

# Globals
nr_cpus = 4

tracedata = []

cookedtrace = open("trace.txt", 'w')
for cpu in range(nr_cpus):
tracefile = open("cpu%d" % cpu)
while(1):
tracerecord = tracefile.read(24)
if not len(tracerecord):
break
tracerecordfields = struct.unpack("IBBBxQQ", tracerecord)
tracedata.append(tracerecordfields)
cookedtrace.write("U%-10d C%d F%X E%x %10d %10d\n" % tracerecordfields)
cookedtrace.close()

The above will generate trace.txt file, with the data in the different columsn. Further processing could be done based on the particular event type and function id, to capture more information. From the information captured, one could easily plot graphs usig gnuplot.

Division Between Users And Kernel Hackers On Git Bisect

The source code management tool git has come under scanner again. This time for a different reason. Flame war's are pretty common in linux community. Everytime there is a divided opinion on certain things, it unlocks a fury of mails from the community guru's. What happened this time is no different. It all started when Mark Lord reported a regression in the network stack. Even after a few mail exchanges it was not clear what the cause of problem was. So the netdev guru's asked Mark to "bisect" and arrive at the culprit patch. Mark responded furiously saying that he didnt have time or inclination to do such a thing. He argued that he was only a bug reporter and is not his job to do the bisection. This triggered the whole issue of who does what. It was exchange of heated arguments over mail and few humorous stories to support the claims. No one can forget the "Doctor Patient" story. To sum up the argument, main focus of this whole episode was who is responsible for such regressions. Lets know a little bit of git bisect. Git bisect is used to find a possible cause of the problem. It works on a simple principle, the bug hunter has to know which kernel is working well and which has bug. For example, 2.6.24 is not having any problem but 2.6.25 does, in this case one can use bisect to choose a version somewhere in the middle of these two release. Once done, the bug is to be verified and if found, git bisect has to be run again with the first half release. To make things easy take the same example as above. Bisecting this showed that 2.6.25-rc4 had the issue. So its now clear that the bug was introduced somewhere between 2.6.24 and 2.6.25-rc4. So running git bisect will narrow down even further and this will continue till we narrow down on a particular commit. This will help identify the bug. But the process is time consuming. To lay fact down plain and simple, git bisect need not necessarily narrow down on the correct patch which causes the problem. There is a possibility that problem was created else where and came into light on introducing this "culprit" patch. So this is not a sure shot way to identify the problem. In our issue Mark states that a user identifying a problem must only report it and that where his/her duty ends. It is upto the individual user to do some more homework and help the developers fix the bug. The developers argue that user will be asked to bisect as a last resort. By forcing users to do more work than just reporting bug can cause them to stop reporting bugs which is not a good thing for the community. On the other hand well known kernel hackers like David Miller claims that it is unavoidable sometimes due to unavailability of hardware the user had used in his environment. This requires the user to cooperate in this effort. As one can see, both side do have a strong point to argue. Its difficult to take sides here. This can become a major issue if not resolved quickly. Some suggestions made by Al Viro and James Morris suggest that the subsystem maintainers need to be more careful in committing patches. This can avoid most regression. Another question that was discussed was, how does a user decide which are "real" bugs? What happens in a complex code like the kernel is, bugs can arise due to some faulty hardware which nobody else faces. When that happens it is virtually impossible to fix it. In such cases the bug remains unfixed. It only come to light if multiple users complain of the same problem. The community urged its users to properly test before posting bugs on the mailing list. The story has not concluded yet as there is no clear solution to this problem. It is left to be seen as to how the community will tackle this issue.