Userland DTrace support on FreeBSD
FreeBSD 9.0 supports the following new providers:
- pid provider
- usdt provider
- plockstat provider
New neat features:
- dtruss
- DTrace support in MySQL (ports)
- Dtrace support in PostgreSQL (ports)
make.conf configuration
The following might help with userland DTrace (depends on what you want to do)
STRIP= CFLAGS+=-fno-omit-frame-pointer
pid provider
The pid provider allows the creation of probes that match a particular function inside your userland program.
http://wikis.sun.com/display/DTrace/pid+Provider
pid provider example
Suppose we have the following C program (test.c):
int
main()
{
for (;;)
sleep(1);
}We want to know when we enter the main function and the sleep function. The following D script accomplishes this:
pid$target:test:main:entry
{
}
pid$target:libc*:sleep:entry
{
}Call this script pid.d and execute DTrace:
# dtrace -s pid.d -c test dtrace: script 'pid.d' matched 2 probes dtrace: buffer size lowered to 2m CPU ID FUNCTION:NAME 0 22753 main:entry 0 22754 _sleep:entry 0 22754 _sleep:entry 0 22754 _sleep:entry 0 22754 _sleep:entry 0 22754 _sleep:entry 0 22754 _sleep:entry ^C 0 22754 _sleep:entry
USDT (Userland Statically Defined Traces)
If you know what SDT means, USDT is easy to understand for you (think userland).
Otherwise, please read: http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_USDT
USDT example
The following example is based on http://blogs.sun.com/ahl/entry/user_land_tracing_gets_better
First we need to create a DTrace provider. We'll use a database as an example:
% cat provider.d
provider database {
probe query__start(char *);
probe query__done(char *);
};If you run:
dtrace -h -s provider.d
You'll have a provider.h file that you can now include in your program:
% cat provider.h
/*
* Generated by dtrace(1M).
*/
#ifndef _PROVIDER_H
#define _PROVIDER_H
#include <unistd.h>
#ifdef __cplusplus
extern "C" {
#endif
#if _DTRACE_VERSION
#define DATABASE_QUERY_DONE(arg0) \
__dtrace_database___query__done(arg0)
#ifndef __sparc
#define DATABASE_QUERY_DONE_ENABLED() \
__dtraceenabled_database___query__done()
#else
#define DATABASE_QUERY_DONE_ENABLED() \
__dtraceenabled_database___query__done(0)
#endif
#define DATABASE_QUERY_START(arg0) \
__dtrace_database___query__start(arg0)
#ifndef __sparc
#define DATABASE_QUERY_START_ENABLED() \
__dtraceenabled_database___query__start()
#else
#define DATABASE_QUERY_START_ENABLED() \
__dtraceenabled_database___query__start(0)
#endif
extern void __dtrace_database___query__done(char *);
#ifndef __sparc
extern int __dtraceenabled_database___query__done(void);
#else
extern int __dtraceenabled_database___query__done(long);
#endif
extern void __dtrace_database___query__start(char *);
#ifndef __sparc
extern int __dtraceenabled_database___query__start(void);
#else
extern int __dtraceenabled_database___query__start(long);
#endif
#else
#define DATABASE_QUERY_DONE(arg0)
#define DATABASE_QUERY_DONE_ENABLED() (0)
#define DATABASE_QUERY_START(arg0)
#define DATABASE_QUERY_START_ENABLED() (0)
#endif
#ifdef __cplusplus
}
#endif
#endif /* _PROVIDER_H */We'll now use a simple C source file to trigger these probes. Edit src.c and write:
#include <stdio.h>
#include <sys/sdt.h>
#include "provider.h"
int
main(void)
{
/* Give us time to start DTrace */
sleep(5);
DATABASE_QUERY_START("SELECT * FROM apples");
/* simulate a long query */
sleep(1);
DATABASE_QUERY_DONE("TOO MANY APPLES");
return (0);
}You should also create a Makefile to make your life easier:
SRCS=src.c DTRACEOBJS=provider.o PROG=db NO_MAN= .include <bsd.dtrace.mk> .include <bsd.prog.mk>
Please note that on FreeBSD, you must link your program with libelf!. (bsd.dtrace.mk does this for you)
After typing make, you should have a executable file called db. Before running it, you should make sure that you have a DTrace script for the new provider:
% cat db.d
database$target:::query-start
{
self->ts = timestamp;
printf("Query: %s", copyinstr(arg0));
}
database$target:::query-done
{
printf("Query time: %d ms / Result: %s",
(timestamp - self->ts) / 1000000,
copyinstr(arg0));
}This will show us how much time it takes to execute that query (if you understood the above C program, we should have 1000 ms + overhead).
Now run the following command to have dtrace(1) execute db, attach to it and run the DTrace script db.d:
# dtrace -s db.d -c ./db dtrace: script 'db.d' matched 2 probes dtrace: buffer size lowered to 2m CPU ID FUNCTION:NAME 0 22766 main:query-start Query: SELECT * FROM apples 0 22765 main:query-done Query time: 1005 ms / Result: TOO MANY APPLES ^C
plockstat provider
TBD
plockstat example
TBD
dtruss
dtruss example
# dtruss date
dtrace: buffer size lowered to 2m
Tue Aug 31 23:17:36 WEST 2010
SYSCALL(args) = return
mmap(0x0, 0x8000, 0x3) = 5455872 0
issetugid(0x0, 0x0, 0x0) = 0 0
open("/etc/libmap.conf\0", 0x0, 0x1B6) = -1 Err#2
open("/var/run/ld-elf.so.hints\0", 0x0, 0x2F) = 3 0
read(0x3, "Ehnt\001\0", 0x80) = 128 0
lseek(0x3, 0x80, 0x0) = 128 0
read(0x3, "/lib:/usr/lib:/usr/lib/compat:/usr/local/lib:/usr/local/lib/compat/pkg:/usr/local/lib/compat:/usr/local/lib/zsh\0", 0x70) = 112 0
close(0x3) = 0 0
access("/lib/libc.so.7\0", 0x0, 0x0) = 0 0
open("/lib/libc.so.7\0", 0x0, 0x63E1A0) = 3 0
fstat(0x3, 0x7FFFFFFFE380, 0x0) = 0 0
pread(0x3, "\177ELF\002\001\001\t\0", 0x1000) = 4096 0
mmap(0x0, 0x245000, 0x0) = 6598656 0
mmap(0x80064B000, 0x109000, 0x5) = 6598656 0
mmap(0x800854000, 0x21000, 0x3) = 8732672 0
mprotect(0x800875000, 0x1B000, 0x3) = 0 0
close(0x3) = 0 0
sysarch(0x81, 0x7FFFFFFFE458, 0x0) = 0 0
mmap(0x0, 0x19000, 0x3) = 5488640 0
sigprocmask(0x1, 0x80063D080, 0x7FFFFFFFE420) = 0x0 0
sigprocmask(0x3, 0x80063D090, 0x0) = 0x0 0
sigprocmask(0x1, 0x80063D080, 0x7FFFFFFFE3F0) = 0x0 0
sigprocmask(0x3, 0x80063D090, 0x0) = 0x0 0
clock_gettime(0xD, 0x7FFFFFFFE580, 0x0) = 0 0
access("/etc/localtime\0", 0x4, 0x0) = 0 0
open("/etc/localtime\0", 0x0, 0x1) = 3 0
fstat(0x3, 0x7FFFFFFEF730, 0x0) = 0 0
close(0x3) = 0 0
issetugid(0x0, 0x0, 0x0) = 0 0
open("/usr/share/zoneinfo/posixrules\0", 0x0, 0x2E) = 3 0
fstat(0x3, 0x7FFFFFFE0790, 0x0) = 0 0
close(0x3) = 0 0
fstat(0x1, 0x7FFFFFFFE3E0, 0x0) = 0 0
readlink("/etc/malloc.conf\0", 0x7FFFFFFFDFB0, 0x400) = -1 Err#2
issetugid(0x0, 0x0, 0x0) = 0 0
break(0x800000, 0x0, 0x0) = 0 0
mmap(0x0, 0x400000, 0x3) = 8978432 0
mmap(0x800C90000, 0x370000, 0x3) = 13172736 0
munmap(0x800890000, 0x370000) = 0 0
ioctl(0x1, 0x402C7413, 0x7FFFFFFFE430) = 0 0
write(0x1, "Tue Aug 31 23:17:36 WEST 2010\n\0", 0x1E) = 30 0
sigprocmask(0x1, 0x80063D080, 0x7FFFFFFFE4B0) = 0x0 0
sigprocmask(0x3, 0x80063D090, 0x0) = 0x0 0
sigprocmask(0x1, 0x80063D080, 0x7FFFFFFFE460) = 0x0 0
sigprocmask(0x3, 0x80063D090, 0x0) = 0x0 0One neat feature of dtruss is that you can combine kernel system calls with userland stack traces. Here's an example:
dtrace: buffer size lowered to 2m
SYSCALL(args) = return
mmap(0x0, 0x8000, 0x3) = 5455872 0
ld-elf.so.1`__sys_mmap+0xc
ld-elf.so.1`malloc+0x15e
ld-elf.so.1`strdup+0x2a
ld-elf.so.1`xstrdup+0x9
ld-elf.so.1`_rtld+0x19c
ld-elf.so.1`0x800507849
issetugid(0x0, 0x0, 0x0) = 0 0
ld-elf.so.1`__sys_issetugid+0xc
ld-elf.so.1`0x800507849
...
write(0x1, "Tue Aug 31 23:19:20 WEST 2010\n\0", 0x1E) = 30 0
libc.so.7`__sys_write+0xc
libc.so.7`_swrite+0x50
libc.so.7`__sflush+0x56
libc.so.7`fflush+0x34
date`main+0x425
date`pututxline@@FBSD_1.2+0x2fa
ld-elf.so.1`0x800536000