p. 1

dtrace dynamic tracing in oracle® solaris mac os x and freebsd this excerpt is from the new book `dtrace dynamic tracing in oracle solaris mac os x and freebsd authored by brendan gregg and jim mauro published by pearson/prentice hall professional april 2011 isbn 0132091518 copyright 2011 oracle and/or its affiliates for more info please visit dtracebook.com or visit the publisher site www.informit.com/title/0132091518

[close]

p. 2

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 9 applications dtrace has the ability to follow the operation of applications from within the application source code through system libraries through system calls and into the kernel this visibility allows the root cause of issues including performance issues to be found and quantified even if it is internal to a kernel device driver or something else outside the boundaries of the application code using dtrace questions such as the following can be answered what transactions are occurring with what latency what disk i/o is the application performing what network i/o why is the application on-cpu as an example the following one-liner frequency counts application stack traces when the apache web server httpd performs the read system call dtrace -n syscall read:entry /execname httpd ustack count dtrace description syscall read:entry matched 1 probe libc.so.1 read+0x7 libapr-1.so.0.3.9`apr_socket_recv+0xb0 libaprutil-1.so.0.3.9`socket_bucket_read+0x5b httpd`ap_core_input_filter+0x294 mod_ssl.so`bio_filter_in_read+0xbc libcrypto.so.0.9.8`bio_read+0xaf libssl.so.0.9.8`ssl3_get_record+0xb5 libssl.so.0.9.8`ssl3_read_n+0x144 continues 783

[close]

p. 3

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 784 chapter 9 applications libssl.so.0.9.8`ssl3_read_bytes+0x161 libssl.so.0.9.8`ssl3_read_internal+0x66 libssl.so.0.9.8`ssl3_read+0x16 libssl.so.0.9.8`ssl_read+0x42 mod_ssl.so`ssl_io_input_read+0xf0 mod_ssl.so`ssl_io_filter_input+0xd0 httpd`ap_rgetline_core+0x66 httpd`ap_read_request+0x1d1 httpd`ap_process_http_connection+0xe4 httpd`ap_run_process_connection+0x28 httpd`child_main+0x3d8 httpd`make_child+0x86 httpd`ap_mpm_run+0x410 httpd`main+0x812 httpd start+0x7d 31 the output has been truncated to show only the last stack trace this stack trace was responsible for calling read 31 times and shows the application code path through libssl the secure sockets layer library because this was an https read each of the functions shown by the stack trace can be traced separately using dtrace including function arguments return value and time the previous chapter focused on the programming languages of application software particularly for developers who have access to the source code this chapter focuses on application analysis for end users regardless of language or layer in the software stack capabilities dtrace is capable of tracing every layer of the software stack including examining the interactions of the various layers see figure 9-1 strategy to get started using dtrace to examine applications follow these steps the target of each step is in bold 1 try the dtrace one-liners and scripts listed in the sections that follow and from the other chapters in the see also section which includes disk file system and network i/o 2 in addition to those dtrace tools familiarize yourself with any existing application logs and statistics that are available and also by any add-ons for example before diving into mozilla firefox performance try add-ons for performance analysis the information that these retrieve can show what is useful to investigate further with dtrace.

[close]

p. 4

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates strategy 785 figure 9-1 software stack 3 check whether any application usdt providers are available for example the mozilla provider for mozilla firefox 4 examine application behavior using the syscall provider especially if the application has a high system cpu time this is often an effective way to get a high-level picture of what the application is doing by examining what it is requesting the kernel to do system call entry arguments and return errors can be examined for troubleshooting issues and system call latency can be examined for performance analysis 5 examine application behavior in the context of system resources such as cpus disks file systems and network interfaces refer to the appropriate chapter in this book 6 write tools to generate known workloads such as performing a client transaction it can be extremely helpful to have a known workload to refer to while developing dtrace scripts 7 familiarize yourself with application internals sources may include application documentation and source code if available dtrace can also be used to learn the internals of an application such as by examining stack traces whenever the application performs i/o see the example at the start of this chapter 8 use a language provider to trace application code execution if one exists and is available for example perl see chapter 8 languages.

[close]

p. 5

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 786 chapter 9 applications 9 use the pid provider to trace the internals of the application software and libraries it uses referring to the source code if available write scripts to examine higher-level details first operation counts and drill down deeper into areas of interest checklist consider table 9-1 a checklist of application issue types that can be examined using dtrace this is similar to the checklist in chapter 8 but is in terms of applications rather than the language table 9-1 applications checklist issue on-cpu time description an application is hot on-cpu showing high %cpu in top1 or prstat1m dtrace can identify the reason by sampling user stack traces with the profile provider and by tracing application functions with vtimestamps reasons for high on-cpu time may include the following · compression · encryption · dataset iteration code path loops · spin lock contention · memory i/o the actual make-up of cpu time whether it is cycles on core for example for the arithmetic logic unit or cycles while stalled for example waiting for memory bus i/o can be investigated further using the dtrace cpc provider if available off-cpu time applications will spend time off-cpu while waiting for i/o waiting for locks not spinning and while waiting to be dispatched on a cpu after returning to the ready to run state these events can be examined and timed with dtrace such as by using the sched provider to look at thread events time off-cpu during i/o especially disk or network i/o is a common cause of performance issues for example an application performing file system reads served by slow disks or a dns lookup during client login waiting on network i/o to the dns server when interpreting off-cpu time it is important to differentiate between time spent off-cpu because of the following · waiting on i/o during an application transaction · waiting for work to do applications may spend most of their time waiting for work to do which is not typically a problem.

[close]

p. 6

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates providers 787 table 9-1 applications checklist continued issue volume description applications may be calling a particular function or code path too frequently this is the simplest type of issue to dtrace frequency count function calls examining function arguments may identify other inefficiencies such as performing i/o with small byte sizes when larger sizes should be possible waiting on locks can occur both on-cpu spin and off-cpu wait locks are used for synchronization of multithreaded applications and when poorly used can cause application latency and thread serialization use dtrace to examine lock usage using the plockstat provider if available or using pid or profile memory allocation can be examined in situations when applications consume excessive amounts of memory calls to manage memory such as malloc can be traced along with entry and return arguments applications can encounter errors in their own code and from system libraries and system calls that they execute encountering errors is normal for software which should be written to handle them correctly however it is possible that errors are being encountered but not handled correctly by the application dtrace can be used to examine whether errors are occurring and if so their origin locks memory allocation errors providers table 9-2 shows providers of most interest when tracing applications table 9-2 providers for applications provider proc syscall profile sched vminfo sysinfo plockstat cpc pid language description trace application process and thread creation and destruction and signals trace entry and return of operating system calls arguments and return values sample application cpu activity at a custom rate trace application thread scheduling events virtual memory statistic probes based on vmstat1m statistics kernel statistics probes based on mpstat1m statistics trace user-land lock events cpu performance counters provider for cpu cache hit/miss by function trace internals of the application including calls to system libraries specific language provider see chapter 8.

[close]

p. 7

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 788 chapter 9 applications you can find complete lists of provider probes and arguments in the dtrace guide.1 pid provider the process id pid provider instruments user-land function execution providing probes for function entry and return points and for every instruction in the function it also provides access to function arguments return codes return instruction offsets and register values by tracing function entry and return the elapsed time and on-cpu time during function execution can also be measured it is available on solaris and mac os x and is currently being developed for freebsd.2 the pid provider is associated with a particular process id which is part of the provider name pid

[close]

p. 8

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates providers 789 15708 15709 19019 19020 19021 19022 19023 19024 pid1122 pid1122 pid1122 pid1122 pid1122 pid1122 pid1122 pid1122 libsocket.so.1 libsocket.so.1 libc.so.1 libc.so.1 libc.so.1 libc.so.1 libc.so.1 libc.so.1 getprotobynumber entry getprotoent entry fopen _freopen_null freopen fgetpos fsetpos fputc entry entry entry entry entry entry there were 8,003 entry probes listed the previous truncated output shows a sample of the available probes from the bash code segment and three libraries libcurses libsocket and libc the probe module name is the segment name listing all pid provider probes for the libc function fputc yields the following dtrace -ln pid$target fputc -p 1122 id provider module 19024 pid1122 libc.so.1 20542 pid1122 libc.so.1 20543 pid1122 libc.so.1 20544 pid1122 libc.so.1 20545 pid1122 libc.so.1 20546 pid1122 libc.so.1 20547 pid1122 libc.so.1 20548 pid1122 libc.so.1 20549 pid1122 libc.so.1 20550 pid1122 libc.so.1 20551 pid1122 libc.so.1 20552 pid1122 libc.so.1 20553 pid1122 libc.so.1 20554 pid1122 libc.so.1 20555 pid1122 libc.so.1 20556 pid1122 libc.so.1 20557 pid1122 libc.so.1 function fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc fputc name entry return 0 1 3 4 7 c d 13 16 19 1c 21 24 25 26 the probes listed are the entry and return probes for the fputc function as well as probes for each instruction offset in hexadecimal 0 1 3 4 7 c d and so on be careful when using the pid provider especially in production environments application processes vary greatly in size and many production applications have large text segments with a large number of instrumentable functions each with tens to hundreds of instructions and with each instruction another potential probe target for the pid provider the invocation dtrace -n pid1234 will instruct dtrace to instrument every function entry and return and to instrument every instruction in process pid 1234 here s an example solaris dtrace -n pid1471 dtrace invalid probe specifier pid1471 failed to create offset probes in 1cfstatem_sub_op_coni6mpknenode v not enough space solaris dtrace -n pid1471 entry dtrace description pid1471 entry matched 26847 probes

[close]

p. 9

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 790 chapter 9 applications process pid 1471 was a java jvm process the first dtrace command attempted to insert a probe at every instruction location in the jvm but was unable to complete the not enough space error means the default number of 250,000 pid provider probes was not enough to complete the instrumentation the second invocation in the example instruments the same process but this time with the entry string in the name component of the probe instructing dtrace to insert a probe at the entry point of every function in the process in this case dtrace found 26,847 instrumentation points once a process is instrumented with the pid provider depending on the number of probes and how busy the process is using the pid provider will induce some probe effect meaning it can slow the execution speed of the target process in some cases dramatically stability the pid provider is considered an unstable interface meaning that the provider interface which consists of the probe names and arguments may be subject to change between application software versions this is because the interface is dynamically constructed based on the thousands of compiled functions that make up a software application it is these functions that are subject to change and when they do so does the pid provider this means that any dtrace scripts or oneliners based on the pid provider may be dependent on the application software version they were written for although application software can and is likely to change between versions many library interfaces are likely to remain unchanged such as libc libsocket libpthread and many others especially those exporting standard interfaces such as posix these can make good targets for tracing with the pid provider because one-liners and scripts will have a higher degree of stability than when tracing application-specific software if a pid-based script has stopped working because of minor software changes then ideally the script can be repaired with equivalent minor changes to match the newer software if the software has changed significantly then the pid-based script may need to be rewritten entirely because of this instability it is recommended to use pid only when needed if there are stable providers available that can serve a similar role they should be used instead and the scripts that use them will not need to be rewritten as the software changes since pid is an unstable interface the pid provider one-liners and scripts in this book are not guaranteed to work or be supported by software vendors the pid provider scripts in this book serve not just as examples of using the pid provider in d programs but also as example data that dtrace can make available and why that can be useful if these scripts stop working you can try fixing them or check for updated versions on the web try this book s web site www.dtracebook.com

[close]

p. 10

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates providers 791 arguments and return value the arguments and return value for functions can be inspected on the pid entry and return probes pid

[close]

p. 11

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 792 chapter 9 applications event[0-3 papi_br_ins papi_br_msp papi_br_tkn papi_fp_ops papi_fad_ins papi_fml_ins papi_fpu_idl papi_tot_cyc papi_tot_ins papi_l1_dca papi_l1_dcm papi_l1_ldm papi_l1_stm papi_l1_ica papi_l1_icm papi_l1_icr papi_l2_dch papi_l2_dcm papi_l2_dcr papi_l2_dcw papi_l2_ich papi_l2_icm papi_l2_ldm papi_l2_stm papi_res_stl papi_stl_icy papi_hw_int papi_tlb_dm papi_tlb_im papi_l3_dcr papi_l3_icr papi_l3_tcr papi_l3_stm papi_l3_ldm papi_l3_tcm see generic_events3cpc for descriptions of these events platform specific events event[0-3 fp_dispatched_fpu_ops fp_cycles_no_fpu_ops_retired fp_dispatched_fpu_ops_ff ls_seg_reg_load ls_uarch_resync_self_modify ls_uarch_resync_snoop ls_buffer_2_full ls_locked_operation ls_retired_cflush ls_retired_cpuid dc_access dc_miss dc_refill_from_l2 dc_refill_from_system dc_copyback dc_dtlb_l1_miss_l2_hit dc_dtlb_l1_miss_l2_miss dc_misaligned_data_ref see bios and kernel developer s guide bkdg for amd family 10h processors amd publication 31116 the first group generic events is the papi events and is documented on solaris in the generic_events3cpc man page the second group platform specific events is from the cpu manufacturer and is typically documented in the cpu user guide referenced in the cpustat1m output the mode component of the probe name can be user for profiling user-mode kernel for kernel-mode or all for both the optional mask component is sometimes used by platform-specific events as directed by the cpu user guide the final component of the probe name is the overflow count once this many of the specified event has occurred on the cpu the probe fires on that cpu for frequent events such as cycle and instruction counts this can be set to a high number to reduce the rate that the probe fires and therefore reduce the impact on target application performance cpc provider probes have two arguments arg0 is the kernel program counter or 0 if not executing in the kernel and arg1 is the user-level program counter or 0 if not executing in user-mode depending on the cpu type it may not be possible to enable more than one cpc probe simultaneously subsequent enablings will encounter a failed to enable probe error this behavior is similar to and for the same reason as the operating system allowing only one invocation of cpustat1m at a time there is a finite number of performance counter registers available for each cpu type the sections that follow have example cpc provider one-liners and output.

[close]

p. 12

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates providers 793 see also there are many topics relevant to application analysis most of which are covered fully in separate chapters of this book chapter 3 system view chapter 4 disk i/o chapter 5 file systems chapter 6 network lower-level protocols chapter 7 application-level protocols chapter 8 languages all of these can be considered part of this chapter the one-liners and scripts that follow summarize application analysis with dtrace and introduce some remaining topics such as signals thread scaling and the cpc provider one-liners for many of these a web server with processes named httpd is used as the target application modify httpd to be the name of the application process of interest proc provider trace new processes dtrace -n proc exec-success traceexecname trace new processes current freebsd5 dtrace -n proc exec_success traceexecname new processes with arguments dtrace -n proc exec-success tracecurpsinfo pr_psargs 5 freebsd 8.0 this will change to become exec-success consistent with solaris and mac os x now that support for hyphens in freebsd probe names is being developed.

[close]

p. 13

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 794 chapter 9 applications new threads created by process dtrace -n proc lwp-create pid execname count successful signal details dtrace -n proc signal-send printf s d %d execname args[2 args[1 pr_pid syscall provider system call counts for processes named httpd dtrace -n syscall entry /execname httpd probefunc count system calls with non-zero errno errors dtrace -n syscall return /errno probefunc errno count profile provider user stack trace profile at 101 hertz showing process name and stack dtrace -n profile-101 execname ustack count user stack trace profile at 101 hertz showing process name and top five stack frames dtrace -n profile-101 execname ustack5 count user stack trace profile at 101 hertz showing process name and stack top ten only dtrace -n profile-101 execname ustack count end trunc 10

[close]

p. 14

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates providers 795 user stack trace profile at 101 hertz for processes named httpd dtrace -n profile-101 /execname httpd ustack count user function name profile at 101 hertz for processes named httpd dtrace -n profile-101 /execname httpd ufuncarg1 count user module name profile at 101 hertz for processes named httpd dtrace -n profile-101 /execname httpd umodarg1 count sched provider count user stack traces when processes named httpd leave cpu dtrace -n sched off-cpu /execname httpd ustack count pid provider the pid provider instruments functions from a particular software version these example one-liners may therefore require modifications to match the software version you are running they can be executed on an existing process by using -p pid or by running a new process using -c command count process segment function calls dtrace -n pid$target:a.out entry probefunc count -p pid count libc function calls dtrace -n pid$target:libc entry probefunc count -p pid count libc string function calls dtrace -n pid$target:libc:str entry probefunc count -p pid

[close]

p. 15

dtrace gregg/mauro published by prentice hall copyright 2011 oracle and/or its affiliates 796 chapter 9 applications trace libc fsync calls showing file descriptor dtrace -n pid$target:libc:fsync:entry tracearg0 -p pid trace libc fsync calls showing file path name dtrace -n pid$target:libc:fsync:entry tracefds[arg0 fi_pathname -p pid count requested malloc bytes by user stack trace dtrace -n pid$target malloc:entry ustack sumarg0 -p pid trace failed malloc requests dtrace -n pid$target malloc:return /arg1 null ustack -p pid see the c section of chapter 8 for more pid provider one-liners plockstat provider as with the pid provider these can also be run using the -c command mutex blocks by user-level stack trace dtrace -n plockstat$target mutex-block ustack count -p pid mutex spin counts by user-level stack trace dtrace -n plockstat$target mutex-acquire /arg2 ustack sumarg2 -p pid reader/writer blocks by user-level stack trace dtrace -n plockstat$target rw-block ustack count -p pid

[close]