Running DTrace on Linux

Following:

https://github.com/tthtlc/linuxdtrace2.git

http://nwsmith.blogspot.sg/2011/03/trying-dtrace-for-linux-on-fedora-14.html

https://blog.itu.dk/SDT1-F2012/2012/02/06/system-monitoring/

And doing this on my Ubuntu (10.04 LTS, 64-bit):

apt-file search gelf.h
apt-get install libelf-dev
apt-get install libc6-dev-i386
unzip linuxdtrace2.zip (as downloaded from github in the URL shown above)

make all (Output is at: http://pastebin.com/M2RQ1rvg, seemingly to have error at the end, but the error is not a show-stopper.)
make install
make load

And finally:

./dtrace -n syscall::open*:'{printf("%s", stringof(arg0));}'

dtrace: description 'syscall::open*:' matched 8 probes
CPU ID FUNCTION:NAME
2 530082 open:entry /proc/stat
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0x5) in action #1
2 530082 open:entry /sys/devices/system/cpu
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0x5) in action #1
2 530082 open:entry /proc/stat
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0x5) in action #1
0 530082 open:entry /dev/sr0
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0x5) in action #1
0 530082 open:entry /proc/net/if_inet6
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0xc) in action #1
0 530082 open:entry /opt/nessus/var/nessus/nessusd.restart
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0xffffffffffffffff) in action #1
1 530082 open:entry /dev/sr0
dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0xffffffffffffffff) in action #1

TO DO:

http://www.google.com.sg/search?sourceid=chrome&ie=UTF-8&q=ctfconvert+for+linux


Regards,
Peter Teoh

Advertisements

7 responses to this post.

  1. Thanks for trying it out and posting. That DTrace invocation does not look quite right; the errors it is hitting are when open:return has tried to do a stringof(arg0), which is the rval (FD) and not a string. Try changing the probe descriptor to syscall::open*:entry, to only match the entry probes. (I’m also wondering why stringof() worked instead of copyinstr()).

    In case people don’t know, there are two implementations of DTrace Linux. This is the Paul Fox port (which I’ve also used successfully for syscall tracing). The other is being developed for OEL by Oracle. The lead engineer, Kris Van Hees, was questioned about its progress by the creators of DTrace at dtrace.conf12 (http://www.youtube.com/watch?v=NElog3MvUC8), where it sounds like it is making great progress.

    Reply

  2. Thank you Brendan for the helpful advice. I tried as you said and it works:

    dtrace -n syscall::open*:entry'{printf(“%s”, stringof(arg0));}’

    dtrace: description 'syscall::open*:entry' matched 6 probes
    CPU ID FUNCTION:NAME
    1 349002 open:entry /proc/stat
    1 349002 open:entry /sys/devices/system/cpu
    1 349002 open:entry /proc/stat
    1 349002 open:entry /dev/shm/.com.google.Chrome.U1pXWj
    0 349002 open:entry /dev/sr0
    0 349002 open:entry /var/lib/upower/history-rate-LNV-L10P6Y22-43-1467.dat.4NP5GW
    0 349002 open:entry /usr/lib/charset.alias

    and replacing the “stringof” with “copyinstr” will still produce the same output – they have the same behavior apparently.

    And in my dmesg I got the output:

    [ 1629.287557] ------------[ cut here ]------------
    [ 1629.287565] WARNING: at kernel/trace/ftrace.c:1487 ftrace_bug+0x28f/0x2e0()
    [ 1629.287568] Hardware name: 1066A9U
    [ 1629.287569] Modules linked in: dtracedrv(P+) bfs usb_storage cryptd aes_x86_64 aes_generic binfmt_misc ppdev kvm_intel kvm dm_crypt snd_hda_codec_hdmi snd_hda_codec_realtek arc4 iwlwifi snd_hda_intel snd_hda_codec mac80211 snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event lp cfg80211 psmouse snd_seq parport uvcvideo snd_timer snd_seq_device snd videodev soundcore v4l2_compat_ioctl32 joydev snd_page_alloc serio_raw reiserfs fbcon tileblit font bitblit softcursor i915 drm_kms_helper usbhid hid drm i2c_algo_bit video r8169 intel_agp intel_gtt mii ahci libahci
    [ 1629.287616] Pid: 4002, comm: insmod Tainted: P O 3.2.11 #1
    [ 1629.287618] Call Trace:
    [ 1629.287624] [] warn_slowpath_common+0x7f/0xc0
    [ 1629.287629] [] ? __probe_kernel_read+0x49/0x80
    [ 1629.287647] [] ? dtrace_xcall+0x4/0x68 [dtracedrv]
    [ 1629.287658] [] ? dtrace_xcall+0x4/0x68 [dtracedrv]
    [ 1629.287660] [] warn_slowpath_null+0x1a/0x20
    [ 1629.287662] [] ftrace_bug+0x28f/0x2e0
    [ 1629.287671] [] ? dtrace_xcall+0x4/0x68 [dtracedrv]
    [ 1629.287680] [] ? dtrace_xcall+0x4/0x68 [dtracedrv]
    [ 1629.287682] [] ftrace_process_locs+0x22a/0x350
    [ 1629.287684] [] ftrace_module_notify+0x45/0x50
    [ 1629.287687] [] notifier_call_chain+0x56/0x80
    [ 1629.287691] [] __blocking_notifier_call_chain+0x5a/0x80
    [ 1629.287693] [] blocking_notifier_call_chain+0x16/0x20
    [ 1629.287696] [] sys_init_module+0x7f/0x1e0
    [ 1629.287699] [] system_call_fastpath+0x16/0x1b
    [ 1629.287701] ---[ end trace 81778f91663db7f8 ]---
    [ 1629.287702] ftrace failed to modify [] dtrace_xcall+0x4/0x68 [dtracedrv]
    [ 1629.287711] actual: e8:4f:93:ff:ff
    [ 1629.293814] Pid: 4002, comm: insmod Tainted: P W O 3.2.11 #1
    [ 1629.293818] Call Trace:
    [ 1629.293835] [] mutex_enter_common+0x37/0x150 [dtracedrv]
    [ 1629.293849] [] dmutex_enter+0x1b/0x20 [dtracedrv]
    [ 1629.293863] [] par_alloc+0x2e/0x110 [dtracedrv]
    [ 1629.293878] [] fbt_provide_module+0x3e/0x2c0 [dtracedrv]
    [ 1629.293892] [] ? dtrace_casptr+0x9/0x20 [dtracedrv]
    [ 1629.293903] [] ? mutex_enter_common+0x77/0x150 [dtracedrv]
    [ 1629.293915] [] dtrace_module_loaded+0x65/0x160 [dtracedrv]
    [ 1629.293920] [] notifier_call_chain+0x56/0x80
    [ 1629.293926] [] __blocking_notifier_call_chain+0x5a/0x80
    [ 1629.293930] [] blocking_notifier_call_chain+0x16/0x20
    [ 1629.293934] [] sys_init_module+0xd5/0x1e0
    [ 1629.293938] [] system_call_fastpath+0x16/0x1b

    Hm….have yet to figure out….

    Reply

  3. Theres a number of issues or potential issues here.

    Firstly, the

    dtrace: error on enabled probe ID 2 (ID 530083: syscall:x64:open:return): invalid address (0x5) in action #1
    2 530082 open:entry

    An error is basically where your kernel would have crashed due to an invalid pointer deref. Dtrace traps the faulting instruction and passes it back to userland – so thats good! You didnt crash your kernel. The value, 0x5, is more interesting. Your probe is incorrect. You are tracing both the entry and return from open(). The entry for open() has arg0 == filename, but not on the exit – its a file descriptor (integer). Hence the bad probe addr.

    For the stack trace you show above – thats a “known” non-issue. The kernel has its own native tracing mechanism (ftrace). ftrace is intercepting dtrace and “getting confused”. I have looked at ftrace a number of times to understand what causes this, but its basically benign (AFAICT). When the driver is loaded, ftrace parses the dtrace executable to find likely probe-points for itself. It doesnt like something, so complains. (I think ftrace may be looking for potential bugs or locking issues, and doesnt understand dtrace is its long-lost twin).

    Reply

  4. Test case 1:

    dtrace -c “ps -ef” -s ps_all.d

    aux[0]: type=33
    aux[1]: type=16
    aux[2]: type=6
    aux[3]: type=17
    aux[4]: type=3
    aux[5]: type=4
    aux[6]: type=5
    aux[7]: type=7
    aux[8]: type=8
    aux[9]: type=9
    aux[10]: type=11
    aux[11]: type=12
    aux[12]: type=13
    aux[13]: type=14
    aux[14]: type=23
    aux[15]: type=25
    aux[16]: type=31
    aux[17]: type=15
    aux[18]: type=0
    in Pupdate_maps (check for 64b maps!)
    in Pupdate_maps (check: pr_mapname is big enough PRMAPSZ=64)
    pread: pid=9904 addr=0x400000 len=64
    pread: pid=9904 addr=0x400040 len=56
    pread: pid=9904 addr=0x400078 len=56
    pread: pid=9904 addr=0x4000b0 len=56
    pread: pid=9904 addr=0x4000e8 len=56
    pread: pid=9904 addr=0x400120 len=56
    pread: pid=9904 addr=0x400158 len=56
    pread: pid=9904 addr=0x400190 len=56
    pread: pid=9904 addr=0x4001c8 len=56
    pread: pid=9904 addr=0x400200 len=56
    pread: pid=9904 addr=0x7eff7cd92000 len=64
    pread: pid=9904 addr=0x7eff7cd92040 len=56
    pread: pid=9904 addr=0x7eff7cd92078 len=56
    pread: pid=9904 addr=0x7eff7cd920b0 len=56
    pread: pid=9904 addr=0x7eff7cd920e8 len=56
    pread: pid=9904 addr=0x7eff7cd92120 len=56
    pread: pid=9904 addr=0x7eff7cd92158 len=56
    pread: pid=9904 addr=0x7eff7cd92190 len=56
    rd_new:rd_new
    rd_loadobj_iter
    proc-stub:rd_event_enable
    proc-stub:rd_errstr err=26
    Build symtab /usr/sbin/dtrace
    found section .interp
    found section .note.ABI-tag
    found section .note.gnu.build-id
    found section .hash
    found section .gnu.hash
    found section .dynsym
    found section .dynstr
    found section .gnu.version
    found section .gnu.version_r
    found section .rela.dyn
    found section .rela.plt
    found section .init
    found section .plt
    found section .text
    found section .fini
    found section .rodata
    found section .eh_frame_hdr
    found section .eh_frame
    found section .ctors
    found section .dtors
    found section .jcr
    found section .dynamic
    found section .got
    found section .got.plt
    found section .data
    found section .bss
    found section .comment
    found section .debug_aranges
    found section .debug_pubnames
    found section .debug_info
    found section .debug_abbrev
    found section .debug_line
    found section .debug_str
    found section .debug_loc
    found section .debug_ranges
    found section .shstrtab
    found section .symtab
    found section .strtab
    plt at 0x962a60
    sym_by_name_binary: NOT found _PROCEDURE_LINKAGE_TABLE_
    Pxlookup_by_name ‘main’ a.out 0x9622a0 0x960c58
    sym_by_name_binary: found main
    dtrace: failed to compile script ps_all.d: line 8: probe description pid9904:::entry does not match any probes
    dt_proc_destroy flags=37748737
    User defined signal 1

    Found the error was generated in libproc/common/Psymtab.c, and something to do with per-process binary instrumentation to insert the probes, but really don’t have the knowledge of changing it yet.

    Reply

  5. Right now, testing “dtrace -n :::” hardcrashed on me TWICE….:

    DSC_0236

    Reply

  6. Apologies that it crashed on you. Obviously that shouldnt happen, but it demonstrates that one has to be careful with dtrace/linux simply because we are exposed to so many variances of CPU/kernel version and 32/64 bitness.

    Feel free to send me details on the kernel you used to provoke this.

    The pid probes stuff is currently being worked on – what exists at the moment is ugly and broken (lots of debug outout).

    Reply

  7. Hello All,

    We installed Dtrace on RHEL 2.6.32-358.el6.x86_64. Dtrace binary was downloade from https://github.com/dtrace4linux/linux.
    Followed the steps as given in the https://github.com/dtrace4linux/linux link and dtrace was built.

    . I am running the Dtrace for “pid$target” probe but it hangs as shown below. It is not printing the trace and timestamp.
    [root@linuxvm4 build]# dtrace -n ‘pid$target:::entry { trace(timestamp); }’ -p 5295
    proc-stub:rd_event_enable
    proc-stub:rd_errstr err=26
    dtrace: description ‘pid$target:::entry ‘ matched 938 probes.

    Can someone help us to know how to execute a PID provider in dtrace linux ?

    Reply

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: