Using Dtrace and mdb to Understand vmstat Output [ID 1009494.1]
Modified 20-MAY-2011 Type HOWTO Migrated ID 213108 Status PUBLISHED
Applies to:
Oracle Solaris Express - Version: 2010.11 and later [Release: 11.0 and later ]
Solaris SPARC Operating System - Version: 10 3/05 and later [Release: 10.0 and later]
Solaris x64/x86 Operating System - Version: 10 3/05 and later [Release: 10.0 and later]
All Platforms
Goal
Vmstat displays virtual memory statistics.
Statistics reported are system wide with no additional information about what processes or application are contributing to unexpected resource usage. DTrace(1M) and mdb(1M) can be used to drill down into vmstat statistics to learn more.
Solution
Data reported by vmstat can be used for several purposes:
To estimate system's physical and virtual memory needs.
To learn workload characteristics: cpu, memory or io bound
To see kernel activities dominating cpu usage: interrupts, system call, pagefault, etc..
To gather percent cpu usage in kernel and user land
DTrace and mdb can help to gain an in-depth look into vmstat stats as discussed below:
r - runnable threads Number of kernel threads ready to run in the cpu dispatch queue. Each cpu has its' own dispatch queue. Thread state is set to ONPROC when it runs on the cpu. prstat -m utility reports cpu scheduling latency per process in "LAT" column.
LAT: The percentage of time the process has spent waiting for the CPU. It means there are too many runnable threads in the cpu dispatch queue competing for the cpu resources.
We can use DTrace and mdb to display threads in cpu dispatch queues:
Maximum time a kernel thread of interest is spending in the cpu dispatch queue - shows cpu scheduling latency
dtrace -n ' sched:::enqueue /execname == "oracle"/ {self->ts=timestamp;} sched:::on-cpu /self->ts/ {@[pid,cpu] = max(timestamp - self->ts);}'
Number of runnable threads in each cpu dispatch queue - shows if workload is scalable
dtrace -n ' profile-1000hz{@[cpu]= max(curthread->t_cpu->cpu_disp->disp_nrunnable);} END{printf("\n%10s %15s\n", "CPU", "Max Queue Size"); printa("%10d %@8d\n", @);}'
Print kernel threads queued during the sample period - shows type of process consuming cpu cycles
dtrace -q -n ' sched:::enqueue{@[execname, cpu] = count();} tick-5sec{printf("\n%20s %8s %25s\n", "Procss Name", "CPU", "Number of Times"); printa("%20s %8d %@12d\n", @);trunc(@);}'
Dumping kernel theads (execname) on cpu dispatch queues (via mdb)
mdb -k <
::walk cpu |::walk cpu_dispq | ::print kthread_t t_procp->p_user.u_comm
EOF
NOTE: D language does not support iterating over data structures. Therefore to dump threads in the dispq, we use mdb instead.
DTrace guide contains more examples on how to use sched provider to monitor cpu dispatch queue.
b - block threads Threads waiting for IO completion are counted as block threads - only disk IO are considered. iostat(1M) is a better tool for analyzing IO events.
DTrace can be used to dump kernel threads waiting on biowait() call:
Thread waiting on biowait() call
dtrace -q -n ' io:::wait-start{@[pid,execname,stack()] = count();} tick-5sec{printa(@); clear(@);}'
Disk IO size by process
dtrace -n 'io:::start { printf("%d %s %d",pid,execname,args[0]->b_bcount); }'
Dump the devinfo_t structure - Device for which IO is issued
dtrace -q -n ' BEGIN{printf("%10s %58s %2s %8s\n", "DEVICE", "FILE", "RW", "Size");} io:::start{ @[args[1]->dev_statname, args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W", args[0]->b_bcount] = count();} tick-5sec{ printa("%10s %58s %2s %8d\n",@); clear(@); }'
There are some useful DTrace scripts to monitor IO events are available in DTrace Toolkit. The DTrace guide contains more examples on how to use io provider to monitor IO related events.
w - runnable but swapped This shows that system memory at some point was dropped below "minfree" and that causes all pages of idle processes to page out (swap out) to the swap device. This number would decrease when the swapped out processes were set to runnable. It means either workload memory requirement is larger than the physical memory configured or memory leak in application or kernel.
For kernel memory leak and high kernel memory allocation use: * echo "kmastat"|mdb -k. It may be required to set kmem_flags to enable additional tracing for diagnosis.
For application memory corruption/leak debugging use libumem(3LIB). See article: Identifying Memory Management Bugs Within Applications Using the libumem Library
DTrace can be used to monitor any kernel thread that is in the process of being swapped out:
Print kernel threads swapped out during the sample period
dtrace -q -n ' fbt::swapout_lwp:entry{ proc = (proc *)arg[0]->t_procp; printf("Lwp: %d of \t Proc: %s being swaped out\n",arg[0]->t_id, proc->p_user.u_comm);}'
vmstat doesn't tell what processes are swapped out. Mdb(1) can be used to print swapped out processes
mdb -k <
::walk thread myvar|::print kthread_t t_schedflag|::grep .==0|::eval p_user.u_comm
EOF
NOTE: D language does not support iterating over data structure. Therefore it is not possible to dump kernel threads that are swapped out. mdb(1) should be used instead.
DTrace guide contains more examples on how to use vminfo provider to monitor solaris virtual memory events.
swap - amount of virtual swap currently available Swap space is used as a backing store for anonymous memory such as process stack, heap, COW. Each page of physical memory is associated with a vnode and offset. The vnode and offset identify the backing store for the page. When process calls malloc() virtual swap is reserved. Anon pages are allocated when the virtual page is touched. Only during free memory shortage, physical swap is allocated when anon pages are paged out to the swap device. Pagin and pageout activity on swap device, file system and application pages are reported by vmstat -p. vmstat and "swap -s" report available virtual swap - that includes both memory and physical disk swap where as "swap -l" reports only physical disk swap. For more information see Document 1010585.1 How does Solaris[TM] Operating System calculate available swap?
sample output of vmstat, swap-s and swap-l
vmstat 1
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr s0 s3 s5 -- in sy cs us sy id
0 0 47 48955912 15511744 1 8 0 0 0 0 0 0 0 0 0 290 133 51 0 0 100
Available virtual swap: 48955912KB = 46.68GB
swap -s total: 164000k bytes allocated + 9208k reserved = 173208k used, 48956144k available
Available virtual swap: 48956144KB = 46.68GB
swap -l swapfile dev swaplo blocks free
/dev/dsk/c1t0d0s1 32,25 16 1048688 1048688 /dev/dsk/c1t1d0s0 32,0 16 70078448 69997248
Available physical swap: (1048688 + 69992748) x 512 = 33.8GB
Check swap reserved by a process (via mdb)
#!/bin/ksh
echo "calculating reserve swap for process $1\n"
print ${1:?"Please enter pid as argument"}
mdb -k <
0t$1::pid2proc|::print proc_t p_as|::walk seg|::print struct seg s_data|::print -d struct segvn_data swresv $q
EOF
Check anon pages reserved by a process (mdb)
#!/bin/ksh
echo "calculating anon pages allocated for process $1\n"
mdb -k <
0t$1::pid2proc|::print proc_t p_as|::walk seg|::print struct seg s_data|::print struct segvn_data amp|::grep .>0|::walk anon|::print struct anon an_vp|::grep .>0 $q
EOF
Check physical swap allocated by a process (mdb)
#!/bin/ksh
echo "calculating physical swap allocated for process $1\n"
mdb -k <
0t$1::pid2proc|::print proc_t p_as|::walk seg|::print struct seg s_data|::print struct segvn_data amp|::grep .>0|::walk anon|::print struct anon an_pvp|::grep .>0 $q
EOF
free - size of free list Solaris 8 and beyond free column in vmstat counts pages both in freelist and cachelist when reporting free memory. Freelist contains pages that have no identity (no associated vnode,offset) and cachelist contains unmapped non-dirty pages with valid vnode,offset. For detail on how Solaris manages freelist and cachelist, see Document 1003383.1 Understanding Cyclic Caching and Page Cache on Solaris 8 and Above.
Summary of where all the physical memory allocated (mdb)
echo "::memstat"|mdb -k
Sample output
Page Summary Pages MB %Tot
------------ ---------------- ---------------- ----
Kernel 912295 712 4%
ZFS File Data 385304 1505 25%
Anon 282119 2204 20%
Exec and libs 7317 28 0%
Page cache 168445 657 11%
Free (cachelist) 27418 107 2%
Free (freelist) 284502 1111 18%
Total 1554141 6070
Physical 1554140 6070
re - pages reclaim Cachelist, as discussed above, contains list of pages that have valid vnode/offset mapping. If the page is found in the cache list, then the page is removed from the cache list and map it to the process address space. When the page is found from the cache list , it is called reclaiming a page.
File pages reclaimed
dtrace -q -n ' vminfo:::pgrec{++nrcl;} fbt::page_reclaim:entry{@[stringof(args[0]->p_vnode)->v_path]=count();} tick-5sec{ printf ("\ntotal pages reclaim: %d\n", nrcl); printf("%20s, %5s\n", "FILENAME", "PAGES"); printa("%20s %@2d\n",@); clear(@); nrcl=0; }'
mf - minor fault When the process access a virtual page in its address space with no physical page mapping, it causes a "page fault" If the page fault can be serviced by locating the physical page from the memory, it is considered a "minor fault. For e.g: a process maps in the "libc.so" library in its address space and makes a reference to a page within it. A page fault occurs, but the physical page of memory is already present (may be brought in by some other process earlier), the kernel only needs to establish a mapping of process virtual address to the existing physical page, without doing any io operation.
major fault: attempting to access a virtual memory location that is mapped by a segment but does not have a physical page of memory mapped to it, and the page does not exist in physical memory. For a major fault, the kernel has to either create a new page in the case of first access, or retrieve the page from backing store. In case, the address is not mapped by any segment, then a segmentation violation is sent.
Print application and file name that experienced a major fault
dtrace -q -n ' vminfo:::maj_fault{@a[execname] = sum(arg0);} fbt::pageio_setup:entry{ @b[stringof(args[0]->p_vnode)->v_path] = count();} tick-5sec{ printf(%10s %5s\n, "EXECNAME", "PAGES"); printa("%10s %@2d\n", @a); printf(%20s %5s\n, "FILENAME", "PAGES"); printa("%20s% %@2d\n",@b); clear(@a); clear(@b); }'
minor fault: attempting to access a virtual memory location that resides within a segment and the page is in physical memory but no MMU translation is established for it.
Print number of minor faults by application
dtrace -q -n ' vminfo:::as_fault{@[execname] = count();}'
pi - kilobytes paged in/ po - kilobytes paged out A page is brought in to the memory when application access a virtual address that cause the page fault and resulted into physical memory page mapping. Page can be brought in from the filesystem on the disk or from the swap partition. Each page of physical memory is associated with a vnode and offset that identify the backing store for the page. Backing store is the location to which the physical memory page contents will be paged out. When the process writes, data is cached in the file system buffer, called page cache. Dirty pages (modified pages) are written to backing store, in case of ufs in UFS clustersize. Partially filled UFS clusters are later written by fsflush. Process's memory pages that are part of text or data region use filesystem (where the program binary/execuatable resides) as backing store. Memory pages use for process stack (sbrk()) or heap (malloc())are allocated dynamically and thus have no reference (name) in the filesystem. Such pages are called anonymous pages, and use swap device as a backing store. One can monitor the source of page-in/page-out using "vmstat -p". If the source of page-in/page-out operation is anonymous memory(api column - swap partition) then it is a sign of memory shortage.
Monitor page-in and page-out per process
dtrace -q -n ' vminfo:::pgpgin { @pgin[execname] = sum(arg0); } vminfo:::pgpgout{ @pgout[execname] = sum(arg0);} tick-5sec{ printf("\n%20s %8s\n", "Procss Name", "page-in"); printa("%20s @8d\n", @pgin); printf("\n%20s %8s\n", "Procss Name", "page-out"); printa("%20s @8d\n", @pgout); clear(@pgin);clear(@pgout) }'
DTrace guide contains more examples on how to use vminfo provider to monitor solaris virtual memory events.
Monitoring files page-in/page-out activities resulting in physical IO
#!/usr/sbin/dtrace -qs ::bwrite_common:entry{self->name=execname;self->bwrite = 1;} ::bwrite_common:return{self->bwrite = 0;} ::bread_common:entry{self->name=execname;self->bread = 1;} ::bread_common:return{self->bread = 0;} ::fop_putpage:entry/args[0]->v_path/{ self->name=execname; self->path=stringof(args[0]->v_path); printf("put-page %10s %58s %8d\n", self->name, stringof(args[0]->v_path), args[2]); self->type = "putpage-io";self->trace = 1; } ::fop_putpage:return /self->trace == 1/{self->trace = 0;} fop_getpage:entry/args[0]->v_path/{ self->name=execname; self->path=stringof(args[0]->v_path); printf("get-page %10s %58s %8d\n", self->name, stringof(args[0]->v_path), args[2]); self->type = "getpage-io"; self->trace = 1; } ::fop_getpage:return/self->trace == 1/{self->trace = 0;} io::bdev_strategy:start/self->trace/{ printf("%s %10s %10s %51s %2s %8d %8u\n", self->type, self->name, args[1]->dev_statname, self->path, args[0]->b_flags & B_READ ? "R" : "W", args[0]->b_bcount, args[0]->b_blkno); } io::bdev_strategy:start/self->trace == 0 && (self->bwrite || self->bread)/{ printf("buffer-io %10s %10s %51s %2s %8d %8u\n", self->name, args[1]->dev_statname,args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W",args[0]->b_bcount, args[0]->b_blkno); } io::bdev_strategy:start/self->trace == 0 && (!(self->bwrite || self->bread))/{ printf("other-io %10s %51s %2s %8d %8u\n", args[1]->dev_statname, args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W", args[0]->b_bcount, args[0]->b_blkno); }
fr - kilobytes freed It is the amount of memory freed by the page daemon. When the system is short in memory (freemem < lotsfree), page daemon scans pages that can be freed. Not all pages scanned by the scanner can be freed. The time between clearing and checking of the reference bit by scanner is dependent on the distance between the front hand (set the refence bit) and back hand (check the reference bit). This distance is controlled by handspreadpages( (set to 1/2 of memory or 8,192 page or 64 MB - whichever is greater). Shorter time between the reference bit being cleared and checked, i-e smaller distance b/w hands, more pages will be freed. A longer time between checking means less pages are freed. Setting the value of handspreadpages too low would cause scanner to steel even active pages, which is not a desired. Ideal is to steel least recently used pages."vmstat -p" reports about type of pages freed in "apf", "epf" and "fpf" columns. DTrace can also be used to capture this information:
File name that has pages freed
dtrace -q -n ' fbt::checkpage:return/args[1]==1/{ page = (struct page *)args[0]; vnode = (struct vnode *)page->p_vnode; printf("file that has pages freed:%s\n", stringof(vnode->v_path)); }'
de - anticipated short-term memory shortfall (Kbytes) It is a small buffer factor, that is normally set to zero or small number, allows scanner to free few pages above lotsfree threshold in anticipation of more memory requests. When scanner starts freeing the pages, it will stops after it brings the memory above lotsfree + de range. Lotsfree is set to 1/64 of total memory.
sr - page scanned by clock algorithm It is the number of pages scanned by the scanner (page daemon). Page scanner is activated when the free memory drops below "lotsfree" threshold (lotsfree is set to 1/64 of total memory) plus a small buffer factor, called deficit. Deficit value is set to zero or small number that allows scanner to free few pages above lotsfree threshold in anticipation of more memory requests. The scanner starts scanning at a rate of slowscan (100 pages /second)pages per second when free memory drops to desfree (lotsfree/2). Scan rate increases to fastscan( 64MB or 1/2 of memory) when memory drops down further to minfree (desfree/2).By default, the scanner runs four times/second. If the amount of free memory falls below the system parameter, throttlefree (set to minfree), the scanner is awoken by the page allocator for each page create request - that gurantees "minfree" number of free pages available at all time.
Monitor number of pages scan by pagedaemon
dtrace -q -n ' int pages_scan; BEGIN{pages_scan = 0;} vminfo:::scan{pages_scan++;} tick-5sec {printf("pages:%d scan by page-daemon in 5 seconds\n", pages_scan); pages_scan=0; }'
faults:in - Interrupts Interrupts are normally initiated by hardware devices such as: disk, network card, tape etc.. to signal completion of an I/O or some activity. Intr. is a trap that causes vectored transfer of a control into the kernel, where kernel services interrupts by context-switching out the current thread running on a processor and executing an interrupt handler for the interrupting device. Interrupts below level 10 are handled as a seperate thread. level 10 and above interrupts, in contrast, barrows the LWP from the executing thread, The interrpted thread in that case is pinned, which avoids the overhead of context switch. Interrupt handler routines of level 0-9 (interrupts handler above 10 cannot block) can block if necessary, using Solaris synchronization primities. Each processor maintains a pool of partially initialized interrupt threads, one for each of the lower 9 levels plus a system wide thread for the clock interrupts. This approach allows simple, fast allocation of threads at the interrupt dispatch time, and low latency interrupt response time.
Solaris 10 command, intrstat(1M) can be used to gather runtime interrupt statistics.
How much time is spent in various device interrupts
#!/usr/sbin/dtrace -s interrupt-start{self->start = vtimestamp;} interrupt-complete{ this->devi = (struct dev_info *)arg0; @[stringof(`devnamesp[this->devi->devi_major].dn_name), this->devi->devi_instance] = quantize(vtimestamp - self->start); }
Distribution of cpu time spent in usr,sys,intr,idle
#!/usr/sbin/dtrace -Cqs long milliintr; BEGIN{ printf("Measure cpu usr:sys:intr:idle per thousand of a CPU \n\n"); usr = 0; sys = 0; intr = 0; idle = 0; ticks = 0; t0 = timestamp; t00 = t0;cpux = cpu; } profile-1ms{ usr += (arg1 != 0) ? 1 : 0; sys += (arg0 != 0) ? 1 : 0; /* usr + intr +idle */ idle += (curthread == curthread->t_cpu->cpu_idle_thread) ? 1 : 0; intr += ((curthread->t_cpu->cpu_intr_actv - 16384) > 0) ? 1 : 0; ticks += (cpu == cpux) ? 1 : 0; } tick-1s{ musr = (1000 * usr) / ticks; msys = (1000 * (sys - intr - idle)) / ticks; midle = (1000 * idle) / ticks; mintr = (1000 * intr) / ticks; mtot = musr + msys + mintr + midle; busy = musr + msys + mintr; printf("%-8s %-8s %-8s %-8s %-8s %-8s\n","BUSY","USR","SYS","INTR","IDLE","TOTAL"); printf("===================================================\n"); printf("%-8d %-8d %-8d %-8d %-8d %-8d\n\n\n", busy,musr,msys,mintr,midle,mtot); idle = 0; usr = 0; intr = 0; sys = 0; ticks = 0;t0 = timestamp; }
faults:sys - system calls System call is the way for user application to access the kernel resources. When a user program makes a system call, such as open file, the open library routine (a wrapper to open system call) pushes the system call number, used to identify the system call, onto the user stack and then invokes a special SPARC trap instruction , Tcc, called Sotware trap. The primary function of this instruction is to change the execution mode of the processor to kernel. Kernel then invokes system call handler called syscall(). Since all system calls are executed in the kernel mode and use process context, kernel thus have access to user address space and u area of the process. syscall() handler copies the arguments of the system call from the user stack to the u area. syscall() then uses system call number to index into a system call dispatch table (sysent[] array contains entries for all supported system calls and is indexed by the system call number. system call number are established from the /etc/name_to_sysnum file) to determine which kernel function to call to execute a perticuler system call. In our case it calls the "open" function. When the open function returns, syscall() handler sets the return values or error status in the appropriate registers, restores the hardware context and returns the execution to the user mode, thus transfer control back to the user process. In solaris, some system calls, known as fast system call, don't go through the overhead described above. These system calls allow fast, low-latency access to kernel resources such as: high-resolution time, cpu time etc. Fast system calls allows user process to enter kernel mode without saving all the context information - minimal processing is allowed. gethrtime(), gettimeofday()etc.. are implemented using fast system call framework.
Count syscalls per process
dtrace -n 'syscall:::entry/pid != $pid/{@[execname,probefunc] = count()}'
System wide system calls
dtrace -n 'syscall:::entry { @[probefunc] = count();}'
Count number of system calls made by application threads
dtrace -n 'syscall:::entry/execname == app_name/{@[tid,probefunc] = count();}
files opened by processes
dtrace -n 'syscall::open*:entry { printf("%s %s",execname,copyinstr(arg0)); }'
Read and Write size distribution by process
dtrace -n 'sysinfo:::readch {@dist[execname] = quantize(arg0); }' dtrace -n 'sysinfo:::writech {
Measure Syscall timing
dtrace -q -n ' syscall:::entry{self->ts = timestamp;} syscall:::return{ @a[probefunc]=avg(timestamp-self->ts); @b[probefunc]=sum(timestamp-self->ts); @c[probefunc]=count(); } END{ printf("Avg Wall Clock time"); printa(@a); printf("Total Wall Clock time"); printa(@b); printf("Counts"); printa(@c); }'
Measure syscal kernel overhead
#!/usr/sbin/dtrace -qs
/** Script collects: * 1- Syscal duration, Dump kernel cpu stack servicing the syscal * 2- All kernel functions called by the kernel thread servicing the syscal * 3- Time spent in each kernel func. * 4- Number of times each kernel function was called * 5- Average, Minimum and Maximum time spent in each function. * To run type: func.d */
#pragma D option flowindent #pragma D option quiet #pragma D option bufsize=8m #pragma D option dynvarsize=5m #pragma D option aggsize=15m
syscall::$2:entry /pid == $1/ {
printf("\nexecname:%s\tpid:%d\tsyscall:%s\n",execname,pid, probefunc);
self->init = timestamp;
stack();
}
fbt:::entry
/self->init/
{
printf("\n%s\n",probefunc);
self->start[self->depth++] = timestamp;
stack();
}
fbt:::return
/self->init/
{
this->delta = timestamp - self->start[--self->depth];
printf("\n\nProbe Func: %s\tElapsed time:%d (ns)\n\n", probefunc,this->delta);
@calls[probefunc] = count();
@avg[probefunc] = avg(this->delta);
@max[probefunc] = max(this->delta);
@min[probefunc] = max(this->delta);
self->start[self->depth] = 0;
} syscall::$2:return /self->init/ { printf("\n%s ends\n",probefunc); printf("%s time: %d\n", probefunc, timestamp - self->init); printf("Kernel overhead of %s\n", probefunc); printf("\nKernel func:\n------------\n"); printa(@calls); printf("\nAverage time(ns)\n----------------\n"); printa(@avg); printf("\nMaximum time(ns)\n----------------\n"); printa(@max); printf("\nMinimum time(ns)\n----------------\n"); printa(@min); printf("\n---END---\n\n"); } syscall::$2:return /self->init/ { trunc(@calls); trunc(@avg); trunc(@max); trunc(@min); self->init=0; } tick-30sec { exit(0);}
faults:cs - cpu context switches The process of moving a kernel thread on and off a processor is referred to as context switching or voluntary context switching. Voluntary context switching happens when the thread executing on the cpu has to block/sleep for event such as file read. In that case, the running thread is context switched off the processor and placed into a sleep queue. When the event a thread is waiting/sleeping occurs, kernel notifies (wake up) the thread and places it back into the dispatch queue of the processor. Involuntary context switch occurs when a thread is preempted (because a better priority thread has transitioned to a runnable state) or when an executing kernel thread uses up its allocated time quantum. Solaris implements both user and kernel preemption. If the preempted thread is a part of critical application, then high number of such events can hurt application performance.
Dump cpu stack when the thread is context switched
#!/usr/sbin/dtrace -qs sched:::off-cpu/execname =="vmstat"/ { @[ustack(),stack()]=count(); } tick-5sec{ printa(@); clear(@); }
Process getting involuntery context switched
dtrace -q -n 'inv_swtch{@[execname, ustack()]=count()}'
cpu:usr - cpu user time It is a cpu time spend in running user code. When application manages objects in its own memory then the cpu runs in user mode and cpu time is charged against user time. When Oracle manages it database blocks in shared memory segment, it only uses cpu user time. When application makes system call then it invokes kernel resource and cpu time is charge against system time. For example, System V semaphores used by oracle to synchronize access to shared resources and reading/writing database blocks into database file requires kernel resources.
DTrace can be used to gather more information:
Top 5 most popular user stacks
dtrace -n ' profile-1000hz/arg1/{@[ustack()] = count();} END{trunc(@,5);}'
DTrace pid provider can be used for user level tracing. You can instrument any function entry/return point or function offset in the application. pid probes are created on-the-fly as they are enabled. DTrace does not stop the process. It executes the traced instruction at other place instead of original location. Module portion in the probe tuple is actually objects loaded in the process address space. For example: a.out or libraries linked to the process are treated as module in PID provider.
The following example uses mdb(1) to display a list of objects by pid 1234:
$ mdb -p 1234 Loading modules: [ ld.so.1 libc.so.1 ] >> ::objects BASE LIMIT SIZE NAME 10000 34000 24000 /usr/bin/csh ff3c0000 ff3e8000 28000 /lib/ld.so.1 ff350000 ff37a000 2a000 /lib/libcurses.so.1
In the probe description, you name the object by the name of the file, not its full path name. You can also omit the ?.1? or ?so.1? suffix. All of the following examples name the same probe:
pid123:libc.so.1:strcpy:entry pid123:libc.so:strcpy:entry pid123:libc:strcpy:entry
For inside look into pid provider see URL: http://blogs.sun.com/ahl/resource/img0.html
Set probes at all process entry()/return() functions (High probe effect)
#!/usr/sbin/dtrace -Fs pid$1:::entry{} pid$1:::return{}
User functions called during the sample period
dtrace -n 'pid1234:::entry {@[probefunc=count()]}'
Trace a user level function(s). Trace all funcs called by this func
#!/usr/sbin/dtrace -Fs /** To run it type: ./userfunc.d . $1 is substitued with $2 is substituted with the fucntion name to trace **/ pid$1::$2:entry{self->trace = 1;} pid$1::$2:return/self->trace/{self->trace = 0;} pid$1:::entry,pid$1:::return/self->trace/{}
Trace the command using DTrace
dtrace -n 'pid$target:::entry{ @[probefunc] = count()}' -c './mytest
Watch for mutex contention in user program use plockstat(1M) for collecting user lock statistics.
plockstat -A -s20 -v -e 60 -p pid_of_oracle_process
This command will run for 60 seconds and trace all type of locking events, contention and hold; and prints the cpu stack of pid of interest.
Java programs
dtrace -q -n ' syscall:::entry /execname == "java"/{@[jstack()] = count()}'
dtrace -q -n ' profile-101 /execname == "java"/{@[jstack()] = count()}'
cpu:sy - cpu system time It is the cpu time spend in running kernel code. System time is dependent on the characterstic of the work load. If the workload depends heavily on kernel resources then cpu kernel overhead will be relatively higher. Cpu time spend in servicing pagefault, device interrupts, context switching, thread migration, locks synchronization, system calls, xcalls are all counted towards kernel time. mpstat(1M) reports frequency of these events. Use lockstat(1M) to collect profiling events lockstat -o lockstat.out -kIW -i 977 -s 40 -D 20 -n 60000 sleep 10
For more information see Document 1008930.1 How to Analyze a High System or Kernel Time in Solaris.
DTrace can be used for monitoring kernel events causing high cpu %sys usage:
Top 5 most popular stacks in kernel mode
dtrace -n ' profile-1000hz/arg0/{@[stack()] = count();} END{trunc(@,5);}'
calculate cpu time spent in each kernel function
dtrace -n ' BEGIN{self->depth = 0;} fbt:::entry{self->ts[self->depth++] = vtimestamp;} fbt:::return/self->ts[--self->depth] != 0/{ @b[probefunc] = sum(vtimestamp - self->ts[self->depth]); @a[probefunc] = avg(vtimestamp - self->ts[self->depth]); self->ts[self->depth] = 0;} END{ printf ("\tKernel Functions\t\tTotal Time (ns)") ; printf ("\n\t---------------\n"); printa ("%30s\t\t%@d\n",@b) ; printf ("\tKernel Functions\t\tAvg Time (ns)") ; printf ("\n\t---------------\n"); printa ("%30s\t\t%@d\n",@a) ; }'
Enable Kernel profiling when cpu %sys goes over the threshold (same method can be used to enable cpu %usr profiling and dumping ustack() instead of stack()
#! /usr/sbin/dtrace -qs /* Usage: profile.d $SYSPCT > profile.out */ #pragma D option bufsize=8m #pragma D option dynvarsize=8m #pragma D option aggsize=12m uint64_t kticks, uticks, iticks, aticks; fbt::new_cpu_mstate:entry{ self->cpu = `cpu[cpu]; self->mstate = self->cpu->cpu_mstate; self->mstimep = &self->cpu->cpu_acct[self->cpu->cpu_mstate]; self->oldtime = *self->mstimep; } fbt::new_cpu_mstate:return/ self->mstimep != 0 && self->mstate == 0 /{ uticks += (*self->mstimep - self->oldtime); } fbt::new_cpu_mstate:return/ self->mstimep != 0 && self->mstate == 1 /{ kticks += (*self->mstimep - self->oldtime); } fbt::new_cpu_mstate:return/ self->mstimep != 0 && self->mstate == 2 /{ iticks += (*self->mstimep - self->oldtime); } fbt::new_cpu_mstate:return/ self->mstimep != 0 /{ aticks += (*self->mstimep - self->oldtime); syspercent = (100*kticks) / aticks; self->cpu = 0;self->mstate = 0;self->mstimep = 0;self->oldtime = 0; } profile-97{@c[stack(50)] = count();} tick-3sec/ syspercent >= $1 /{trace(`time);printa(@c);} tick-3sec{ trunc(@c, 0); printf(" %Y kticks=%d uticks=%d iticks=%d aticks=%d syspercent=%d\n", walltimestamp , kticks, uticks, iticks, aticks, syspercent); syspercent = 0; kticks = 0; uticks = 0; iticks = 0; aticks = 0; }
cpu:id - cpu idle time It is a cpu idle time. When there is no other runnable thread in cpu dispatch queue, it runs idle thread. vmstat counts percent wait time (wt) reported by mpstat as idle time.
To discuss this information further with Oracle experts and industry peers, we encourage you to review, join or start a discussion in the My Oracle Support Community, Oracle Solaris Kernel Community.
Useful Links:
Dtrace Home
Cause of Defunc process with DTrace Tool kit
Dtrace introduction by Byran Cantrill
Dtrace SA Guide
Dtrace OpenSolaris Forum
DTrace - Using(placing) SDT probes in kernel and user programs
Dtrace to debug module load/unload problems
Dtrace pid provider TOI
Network Provider
Javascript Provider
System healthcheck using dexplorer
More Dtrace scripts
References
NOTE:1003383.1 - Understanding Cyclic Caching and Page Cache on Solaris 8 and Above
NOTE:1008930.1 - How to Analyze a High System or Kernel Time in Solaris
NOTE:1010585.1 - How does Solaris Operating System calculate available swap?
NOTE:1278725.1 - Using DTrace to understand mpstat output
Show Related Information Related
Products
Sun Microsystems > Operating Systems > Solaris Operating System > Oracle Solaris Express
Sun Microsystems > Operating Systems > Solaris Operating System > Solaris SPARC Operating System
Sun Microsystems > Operating Systems > Solaris Operating System > Solaris x64/x86 Operating System
Keywords
CPU; DTRACE; LOCKSTAT; MDB; SWAP; VIRTUAL MEMORY; VMSTAT