Tuesday, June 14, 2011

DTrace for Linux: Progress, but still a work in progress

A couple of months back, I blog posted on Paul Fox's port of DTrace to Linux. I've continued to play around with it since then, and so I think its about time for another blog post about it.

Certainly now there is no problem compiling DTrace for Linux on Fedora 14 with the 2.6.35 kernel, provided you install the necessary dependencies that I listed in the previous post. Since my initial report, I've exchanged many emails with Paul, and he had been able to incorporate in the code the necessary fixes to support compiling on Fedora.

Paul has spent a lot of time recently on the cross-call (aka xcall) problem, and you can read the details on Paul's blog. Certainly this is a challenging area, and although there are still some issues, it looks to me like Paul is determined to fully resolve the issues.

Ok, so let's give DTrace for Linux a bit of a work out and discover a little bit more about it.

After compiling, with 'make all' and installing with 'make install', you load
the DTrace module, with 'make load'.

# uname -a
Linux fed14-64 2.6.35.13-91.fc14.x86_64 #1 SMP Tue May 3 13:23:06 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux
# make load
tools/load.pl
21:41:23 Syncing...
21:41:24 Loading: build/driver/dtracedrv.ko
21:41:25 Preparing symbols...
21:41:25 Probes available: 319433
21:41:30 Time: 7s

So you can see there are a lot of probes available. Let's look at a break down:

# dtrace -l | awk '{ print $2 }' | sort | uniq -c | sort -n
1 PROVIDER
3 dtrace
4 io
17 profile
1270 syscall
63808 fbt
254330 instr

You can see that most of the probes come from the 'instr' provider, which I believe is unique to the Linux port of DTrace. And note that the number of providers available is less than what is available on Solaris and FreeBSD.

Let's list the probes, where there are only a small number of probes for the providers:

[root@fed14-64 ~]# dtrace -l -n dtrace:::
ID PROVIDER MODULE FUNCTION NAME
1 dtrace BEGIN
2 dtrace END
3 dtrace ERROR
[root@fed14-64 ~]# dtrace -l -n io:::
ID PROVIDER MODULE FUNCTION NAME
4 io do_sync_read start
5 io do_sync_read done
6 io do_sync_write start
7 io do_sync_write done
[root@fed14-64 ~]# dtrace -l -n profile:::
ID PROVIDER MODULE FUNCTION NAME
254912 profile profile-97
254913 profile profile-199
254914 profile profile-499
254915 profile profile-997
254916 profile profile-1999
254917 profile profile-4001
254918 profile profile-4999
254919 profile tick-1
254920 profile tick-10
254921 profile tick-100
254922 profile tick-500
254923 profile tick-1000
254924 profile tick-5000
319429 profile tick-1ms
319430 profile tick-1s
319431 profile tick-5s
319432 profile tick-10s

Now let's give a breakdown of the number of probes available for each modules for the FBT (Function Boundary Tracing) provider. This will give you an idea of what kernel modules I have loaded on my test system.

[root@fed14-64 dtrace-20110404]# dtrace -l -P fbt | awk '{print $3}' | sort | uniq -c | sort -n
1 MODULE
12 freq_table
13 output
14 speedstep_lib
15 iTCO_vendor_support
15 p4_clockmod
23 i2c_i801
29 ppdev
30 i2c_algo_bit
31 iTCO_wdt
33 snd_page_alloc
37 snd_seq_device
37 soundcore
41 dcdbas
41 snd_hwdep
61 sata_sil24
63 microcode
79 snd_hda_intel
83 parport_pc
99 snd_timer
100 drm_kms_helper
109 video
138 scsi_transport_spi
141 i2c_core
155 parport
199 snd_hda_codec_idt
337 ttm
357 snd
357 tg3
359 snd_seq
420 fuse
424 aic7xxx
490 snd_hda_codec
495 snd_pcm
744 e1000e
867 drm
1671 ipv6
1875 nouveau
52615 kernel

As you can see from the above, I have two different network interface cards in my system. One is a Broadcom, supported by the 'tg3' module, and the other is an Intel card, supported by the 'e1000e' module.

Lets list the probes available for one of the FBT modules:

# dtrace -l -n fbt:p4_clockmod::entry
ID PROVIDER MODULE FUNCTION NAME
310254 fbt p4_clockmod cpufreq_p4_get entry
310256 fbt p4_clockmod cpufreq_p4_setdc entry
310258 fbt p4_clockmod cpufreq_p4_target entry
310260 fbt p4_clockmod cpufreq_p4_verify entry
310262 fbt p4_clockmod cpufreq_p4_cpu_init entry
310264 fbt p4_clockmod cpufreq_p4_exit entry
310266 fbt p4_clockmod cpufreq_p4_cpu_exit entry
310268 fbt p4_clockmod cleanup_module entry
# dtrace -l -n fbt:p4_clockmod::return
ID PROVIDER MODULE FUNCTION NAME
310255 fbt p4_clockmod cpufreq_p4_get return
310257 fbt p4_clockmod cpufreq_p4_setdc return
310259 fbt p4_clockmod cpufreq_p4_target return
310261 fbt p4_clockmod cpufreq_p4_verify return
310263 fbt p4_clockmod cpufreq_p4_cpu_init return
310265 fbt p4_clockmod cpufreq_p4_exit return
310267 fbt p4_clockmod cpufreq_p4_cpu_exit return

Ok, enough of listing probes! Let show some simple DTrace one-liners in action on Linux:

# dtrace -n 'syscall:::entry { @num[execname] = count(); }'
dtrace: description 'syscall:::entry ' matched 635 probes
^C
audispd 1
udisks-daemon 6
rtkit-daemon 8
gnome-settings- 9
abrtd 10
console-kit-dae 10
hald-addon-acpi 12
sendmail 14
gnome-screensav 15
sshd 17
crond 18
dbus-daemon 18
gnome-panel 33
gnome-power-man 38
clock-applet 49
gvfs-afc-volume 60
metacity 68
irqbalance 120
nautilus 157
gedit 362
dtrace 1553
Xorg 10039
firefox 12083
#
# dtrace -n 'syscall:::entry { @num[probefunc] = count(); }'
dtrace: description 'syscall:::entry ' matched 635 probes
^C
rt_sigreturn 1
brk 2
getdents 2
select 6
stat 8
nanosleep 11
rt_sigaction 16
munmap 18
close 21
fstat 21
mmap 21
inotify_add_watch 26
open 32
rt_sigprocmask 32
ioctl 49
write 195
poll 525
read 736
futex 1283
#
# dtrace -n 'fbt:e1000e::entry { @num[probefunc] = count(); }'
dtrace: description 'fbt:e1000e::entry ' matched 373 probes
^C
e1000_clean 17
e1000_clean_rx_irq 17
e1000_clean_tx_irq 17
e1000_desc_unused.clone.26 17
e1000_intr_msi 17
e1000_irq_enable 17
e1000_watchdog 17
e1000_watchdog_task 17
e1000e_get_laa_state_82571 17
e1000e_has_link 17
e1000e_update_adaptive 17
e1000e_update_stats 17
napi_schedule_prep 17
test_and_set_bit 17
e1000_ioctl 34
e1000_get_stats 411

Here is the 'instr' provider in action:

# dtrace -n 'instr:e1000e:: { @num[probefunc] = count(); }'
dtrace: description 'instr:e1000e:: ' matched 3472 probes
^C

e1000_get_drvinfo-je 1
e1000_get_drvinfo-jne 1
e1000e_get_sset_count-ja 3
e1000_get_drvinfo-callr 5
e1000_clean_rx_irq-callr 27
e1000_clean_rx_irq-je 27
e1000_desc_unused.clone.26-jbe 27
e1000_irq_enable-je 27
e1000_watchdog-callr 27
e1000e_get_laa_state_82571-jne 27
e1000e_update_adaptive-jbe 27
e1000e_update_adaptive-je 27
e1000e_update_adaptive-jne 27
e1000e_update_stats-jbe 27
napi_schedule_prep-callr 27
napi_schedule_prep-jne 27
test_and_set_bit-lock 27
e1000_clean-jne 54
e1000_intr_msi-callr 54
e1000_intr_msi-je 54
e1000e_has_link-je 54
e1000e_update_stats-ja 54
e1000_clean-callr 81
e1000_clean-je 81
e1000_watchdog_task-jne 81
e1000_clean_tx_irq-je 108
e1000_watchdog_task-je 108
e1000_watchdog_task-callr 189

One of the aspects that Paul has been developing recently is a suite of test programs that can be used to stress test the system, and expose any problems with the DTrace for Linux port. To try this out, run 'make test'.

Ok, I'm out of time for tonight. Hopefully I can find time for some more post to this blog soon.

No comments: