SystemTap
SystemTap is a profiling and debugging infrastructure based on kprobes. Essentially, it’s a scripting facility for kprobes. It allows you to dynamically instrument the kernel and user application to track down complex and obscure problems in system behavior.
With SystemTap you write a tapscript in a special language inspired by C, awk and dtrace. SystemTap language asks you to write handlers for probes defined in kernel or userspace that will be invoked when execution hits these probes. You can define your own functions and use extensive tapsets library. Language provides you integers, strings, associative arrays and statistics, without requiring types and memory allocation. Comprehensive information about SystemTap language can be found in language reference.
Scripts that you wrote are “elaborated” (resolving references to tapsets, kernel and userspace symbols), translated to C, wrapped with kprobes API invocation and compiled into kernel module that, finally, is loaded into kernel.
Script output and other data collected is transferred from kernel to userspace via high-performance transport like relayfs or netlink.
Setup
Installation part is boring and depends on your distro, on Fedora it’s as simple as:
$ dnf install systemtap
You will need SystemTap runtime and client tools along with tapsets and other development files for building your modules.
Also, you will need kernel debug info:
$ dnf debuginfo-install kernel
After installation, you may check if it’s working:
$ stap -v -e 'probe begin { println("Started") }'
Pass 1: parsed user script and 592 library scripts using 922624virt/723440res/7456shr/715972data kb, in 3250usr/220sys/3577real ms.
Pass 2: analyzed script: 1 probe, 0 functions, 0 embeds, 0 globals using 963940virt/765008res/7588shr/757288data kb, in 320usr/10sys/338real ms.
Pass 3: translated to C into "/tmp/stapMS0u1v/stap_804234031353467eccd1a028c78ff3e3_819_src.c" using 963940virt/765008res/7588shr/757288data kb, in 0usr/0sys/0real ms.
Pass 4: compiled C into "stap_804234031353467eccd1a028c78ff3e3_819.ko" in 9530usr/1380sys/11135real ms.
Pass 5: starting run.
Started
^CPass 5: run completed in 20usr/20sys/45874real ms.
Playground
Various examples of what SystemTap can do can be found here.
You can see call graphs with para-callgraph.stp:
$ stap para-callgraph.stp 'process("/home/avd/dev/block_hasher/block_hasher").function("*")' \
-c '/home/avd/dev/block_hasher/block_hasher -d /dev/md0 -b 1048576 -t 10 -n 10000'
0 block_hasher(10792):->_start
11 block_hasher(10792): ->__libc_csu_init
14 block_hasher(10792): ->_init
17 block_hasher(10792): <-_init
18 block_hasher(10792): ->frame_dummy
21 block_hasher(10792): ->register_tm_clones
23 block_hasher(10792): <-register_tm_clones
25 block_hasher(10792): <-frame_dummy
26 block_hasher(10792): <-__libc_csu_init
31 block_hasher(10792): ->main argc=0x9 argv=0x7ffc78849278
44 block_hasher(10792): ->bdev_open dev_path=0x7ffc78849130
88 block_hasher(10792): <-bdev_open return=0x163b010
0 block_hasher(10796):->thread_func arg=0x163b2c8
0 block_hasher(10797):->thread_func arg=0x163b330
0 block_hasher(10795):->thread_func arg=0x163b260
0 block_hasher(10798):->thread_func arg=0x163b398
0 block_hasher(10799):->thread_func arg=0x163b400
0 block_hasher(10800):->thread_func arg=0x163b468
0 block_hasher(10801):->thread_func arg=0x163b4d0
0 block_hasher(10802):->thread_func arg=0x163b538
0 block_hasher(10803):->thread_func arg=0x163b5a0
0 block_hasher(10804):->thread_func arg=0x163b608
407360 block_hasher(10799): ->time_diff start={...} end={...}
407371 block_hasher(10799): <-time_diff
407559 block_hasher(10799):<-thread_func return=0x0
436757 block_hasher(10795): ->time_diff start={...} end={...}
436765 block_hasher(10795): <-time_diff
436872 block_hasher(10795):<-thread_func return=0x0
489156 block_hasher(10797): ->time_diff start={...} end={...}
489163 block_hasher(10797): <-time_diff
489277 block_hasher(10797):<-thread_func return=0x0
506616 block_hasher(10803): ->time_diff start={...} end={...}
506628 block_hasher(10803): <-time_diff
506754 block_hasher(10803):<-thread_func return=0x0
526005 block_hasher(10801): ->time_diff start={...} end={...}
526010 block_hasher(10801): <-time_diff
526075 block_hasher(10801):<-thread_func return=0x0
9840716 block_hasher(10804): ->time_diff start={...} end={...}
9840723 block_hasher(10804): <-time_diff
9840818 block_hasher(10804):<-thread_func return=0x0
9857787 block_hasher(10802): ->time_diff start={...} end={...}
9857792 block_hasher(10802): <-time_diff
9857895 block_hasher(10802):<-thread_func return=0x0
9872655 block_hasher(10796): ->time_diff start={...} end={...}
9872664 block_hasher(10796): <-time_diff
9872816 block_hasher(10796):<-thread_func return=0x0
9875681 block_hasher(10798): ->time_diff start={...} end={...}
9875686 block_hasher(10798): <-time_diff
9874408 block_hasher(10800): ->time_diff start={...} end={...}
9874413 block_hasher(10800): <-time_diff
9875767 block_hasher(10798):<-thread_func return=0x0
9874482 block_hasher(10800):<-thread_func return=0x0
9876305 block_hasher(10792): ->bdev_close dev=0x163b010
10180742 block_hasher(10792): <-bdev_close
10180801 block_hasher(10792): <-main return=0x0
10180808 block_hasher(10792): ->__do_global_dtors_aux
10180814 block_hasher(10792): ->deregister_tm_clones
10180817 block_hasher(10792): <-deregister_tm_clones
10180819 block_hasher(10792): <-__do_global_dtors_aux
10180821 block_hasher(10792): ->_fini
10180823 block_hasher(10792): <-_fini
Pass 5: run completed in 20usr/3200sys/10716real ms.
You can find generic source of latency with latencytap.stp:
$ stap -v latencytap.stp -c \
'/home/avd/dev/block_hasher/block_hasher -d /dev/md0 -b 1048576 -t 10 -n 1000000'
Reason Count Average(us) Maximum(us) Percent%
Reading from file 490 49311 53833 96%
Userspace lock contention 8 118734 929420 3%
Page fault 17 27 65 0%
unmapping memory 4 37 55 0%
mprotect() system call 6 25 45 0%
4 19 37 0%
3 23 49 0%
Page fault 2 24 46 0%
Page fault 2 20 36 0%
Note: you may need to change timer interval in latencytap.stp:
-probe timer.s(30) {
+probe timer.s(5) {
There is even 2048 written in SystemTap!
All in all, it’s simple and convenient. You can wrap your head around it in a single day! And it works as you expect and this is a big deal because it gives you certainty and confidence in the infirm ground of profiling kernel problems.
Profiling I/O latency for block_hasher
So, how can we use it for profiling kernel, module or userspace application? The thing is that we have almost unlimited power in our hands. We can do whatever we want and howsoever we want, but we must know what we want and express it in SystemTap language.
You have a tapsets – standard library for SystemTap – that contains a massive variety of probes and functions that are available for your tapscripts.
But, let’s be honest, nobody wants to write scripts, everybody wants to use scripts written by someone who has the expertise and who already spent a lot of time, debugged and tweaked the script.
Let’s look at what we can find in SystemTap I/O examples.
There is one that seems legit: “ioblktime”. Let’s launch it:
stap -v ioblktime.stp -o ioblktime -c \
'/home/avd/dev/block_hasher/block_hasher -d /dev/md0 -b 1048576 -t 10 -n 10000'
Here’s what we’ve got:
device rw total (us) count avg (us)
ram4 R 101628 981 103
ram5 R 99328 981 101
ram6 R 64973 974 66
ram2 R 57002 974 58
ram3 R 66635 974 68
ram0 R 101806 974 104
ram1 R 98470 974 101
ram7 R 64250 974 65
dm-0 R 48337401 974 49627
sda W 3871495 376 10296
sda R 125794 14 8985
device rw total (us) count avg (us)
sda W 278560 18 15475
We see a strange device dm-0. Quick check:
$ dmsetup info /dev/dm-0
Name: delayed
State: ACTIVE
Read Ahead: 256
Tables present: LIVE
Open count: 1
Event number: 0
Major, minor: 253, 0
Number of targets: 1
DeviceMapper’s “delayed” target that we saw previously. This target creates a block device that identically maps to disk but delays each request by given amount of milliseconds. This is a cause of our RAID problems: performance of a striped RAID is a performance of the slowest disk.
I’ve looked for other examples, but they mostly show which process generates the most I/O.
Let’s try to write our own script!
There is a tapset dedicated for I/O scheduler and block I/O. Let’s useprobe::ioblock.end matching our RAID device and print backtrace.
probe ioblock.end
{
if (devname == "md0") {
printf("%s: %d\n", devname, sector);
print_backtrace()
}
}
Unfortunately, this won’t work because RAID device request ends up in the concrete disk, so we have to hook into raid0 module.
Dive into drivers/md/raid0.cand look to raid0_make_request. Core of the RAID 0 is encoded in these lines:
530 if (sectors < bio_sectors(bio)) {
531 split = bio_split(bio, sectors, GFP_NOIO, fs_bio_set);
532 bio_chain(split, bio);
533 } else {
534 split = bio;
535 }
536
537 zone = find_zone(mddev->private, &(sector));
538 tmp_dev = map_sector(mddev, zone, sector, &(sector));
539 split->bi_bdev = tmp_dev->bdev;
540 split->bi_iter.bi_sector = sector + zone->dev_start +
541 tmp_dev->data_offset;
...
548 generic_make_request(split);
that tell us: “split bio requests to raid md device, map it to particular disk and issue generic_make_request”.
Closer look to generic_make_request
1966 do {
1967 struct request_queue *q = bdev_get_queue(bio->bi_bdev);
1968
1969 q->make_request_fn(q, bio);
1970
1971 bio = bio_list_pop(current->bio_list);
1972 } while (bio);
will show us that it gets request queue from a block device, in our case a particular disk, and issue make_request_fn.
This will lead us to see which block devices our RAID consists of:
$ mdadm --misc -D /dev/md0
/dev/md0:
Version : 1.2
Creation Time : Mon Nov 30 11:15:51 2015
Raid Level : raid0
Array Size : 3989504 (3.80 GiB 4.09 GB)
Raid Devices : 8
Total Devices : 8
Persistence : Superblock is persistent
Update Time : Mon Nov 30 11:15:51 2015
State : clean
Active Devices : 8
Working Devices : 8
Failed Devices : 0
Spare Devices : 0
Chunk Size : 512K
Name : alien:0 (local to host alien)
UUID : d2960b14:bc29a1c5:040efdc6:39daf5cf
Events : 0
Number Major Minor RaidDevice State
0 1 0 0 active sync /dev/ram0
1 1 1 1 active sync /dev/ram1
2 1 2 2 active sync /dev/ram2
3 1 3 3 active sync /dev/ram3
4 1 4 4 active sync /dev/ram4
5 1 5 5 active sync /dev/ram5
6 1 6 6 active sync /dev/ram6
7 253 0 7 active sync /dev/dm-0
and here we go – the last device is our strange /dev/dm-0.
And again, I knew it from the beginning and tried to come into the root of the problem with SystemTap. But SystemTap was just a motivation to look into kernel code and think deeper, which is nice, though. This again proofs that the best tool to investigate any problem, be that performance issue or bug, is your brain and experience.
Top comments (0)