Thursday June 30, 2005
Thursday June 30, 2005 Using DTrace for Memory Analysis
Following on from yesterday's post on using prstat to look at memory slow-downs, here is a more advanced way of investigating. The DTrace probes help us identify all sources of paging in the system, and give us the ability to drill down quickly to identify cause and affect.
With DTrace, you can probe more deeply into the sources of activity observed with higher-level memory analysis tools. For example, if you determine that a significant amount of paging activity is due to a memory shortage, you can determine which process is initiating the paging activity. In another example, if you see a significant amount of paging due to file activity, you can drill down to see which process and which file is responsible.
DTrace allows for memory analysis through a vminfo provider, and, optionally, through deeper tracing of virtual memory paging with the fbt provider.
The vminfo provider probes correspond to the fields in the "vm" named kstat: a probe provided by vminfo fires immediately before the corresponding vm value is incremented. The table below from the DTrace guide lists the probes available from the VM provider. A probe takes the following arguments:
- arg0 - The value by which the statistic is to be incremented. For most probes, this argument is always 1, but for some it may take other values.
- arg1 - A pointer to the current value of the statistic to be incremented. This value is a 64-bit quantity that is incremented by the value in arg0. Dereferencing this pointer allows consumers to determine the current count of the statistic corresponding to the probe.
For example, if you should see the following paging activity with vmstat, indicating page-in from the swap device, you could drill down to investigate.
sol8# vmstat -p 3
memory page executable anonymous filesystem
swap free re mf fr de sr epi epo epf api apo apf fpi fpo fpf
1512488 837792 160 20 12 0 0 0 0 0 8102 0 0 12 12 12
1715812 985116 7 82 0 0 0 0 0 0 7501 0 0 45 0 0
1715784 983984 0 2 0 0 0 0 0 0 1231 0 0 53 0 0
1715780 987644 0 0 0 0 0 0 0 0 2451 0 0 33 0 0
sol10$ dtrace -n anonpgin'{@[execname] = count()}'
dtrace: description 'anonpgin' matched 1 probe
svc.startd 1
sshd 2
ssh 3
dtrace 6
vmstat 28
filebench 913
| Probe Name | Description |
|---|---|
| anonfree | Fires whenever an unmodified anonymous page is freed as part of paging activity. Anonymous pages are those that are not associated with a file; memory containing such pages include heap memory, stack memory, or memory obtained by explicitly mapping zero(7D). |
| anonpgin | Fires whenever an anonymous page is paged in from a swap device. |
| anonpgout | Fires whenever a modified anonymous page is paged out to a swap device. |
| as_fault | Fires whenever a fault is taken on a page and the fault is neither a protection fault nor a copy-on-write fault. |
| cow_fault | Fires whenever a copy-on-write fault is taken on a page. arg0 contains the number of pages that are created as a result of the copy-on-write. |
| dfree | Fires whenever a page is freed as a result of paging activity. Whenever dfree fires, exactly one of anonfree, execfree, or fsfree will also subsequently fire. |
| execfree | Fires whenever an unmodified executable page is freed as a result of paging activity. |
| execpgin | Fires whenever an executable page is paged in from the backing store. |
| execpgout | Fires whenever a modified executable page is paged out to the backing store. If it occurs at all, most paging of executable pages will occur in terms of execfree; execpgout can only fire if an executable page is modified in memory -- an uncommon occurrence in most systems. |
| fsfree | Fires whenever an unmodified file system data page is freed as part of paging activity. |
| fspgin | Fires whenever a file system page is paged in from the backing store. |
| fspgout | Fires whenever a modified file system page is paged out to the backing store. |
| kernel_asflt | Fires whenever a page fault is taken by the kernel on a page in its own address space. Whenever kernel_asflt fires, it will be immediately preceded by a firing of the as_fault probe. |
| maj_fault | Fires whenever a page fault is taken that results in I/O from a backing store or swap device. Whenever maj_fault fires, it will be immediately preceded by a firing of the pgin probe. |
| pgfrec | Fires whenever a page is reclaimed off of the free page list. |
Using DTrace to Estimate Memory Slowdowns
You can use Using DTrace to, we can directly measure time elapsed time around the page-in probes when a process is waiting for page-in from the swap device, as in this example.
sched:::on-cpu
{
self->on = vtimestamp;
}
sched:::off-cpu
/self->on/
{
@oncpu[execname] = sum(vtimestamp - self->on);
self->on = 0;
}
vminfo:::anonpgin
{
self->anonpgin = 1;
}
:::pageio_setup:return
{
self->wait = timestamp;
}
:::pageio_done:entry
/self->anonpgin == 1/
{
self->anonpgin = 0;
@pageintime[execname] = sum(timestamp - self->wait);
self->wait = 0;
}
END
{
normalize(@oncpu, 1000000);
printf("Who's on cpu (milliseconds):\n");
printa(" %-50s %15@d\n", @oncpu);
normalize(@pageintime, 1000000);
printf("Who's waiting for pagein (milliseconds):\n");
printa(" %-50s %15@d\n", @pageintime);
}
With an aggregation by execname, you can we can look to see who is being held up by paging the most.
sol10$./whospaging.d ^C Who's on cpu (milliseconds): svc.startd 1 loop.sh 2 sshd 2 ssh 3 dtrace 6 vmstat 28 pageout 60 fsflush 120 filebench 913 sched 84562 Who's waiting for pagein (milliseconds): filebench 230704
The DTrace script displays the amount of time the program spends doing useful work compared to the amount of time it spends waiting for page-in.
The next script measures the elapsed time from when a program stalls on a page in from the swap device (anonymous page ins) and when it resumes for a specific pid target, specified on the command line.
sched:::on-cpu
/pid == $1/
{
self->on = vtimestamp;
}
sched:::off-cpu
/self->on/
{
@time[""] = sum(vtimestamp - self->on);
self->on = 0;
}
vminfo:::anonpgin
/pid == $1/
{
self->anon = 1;
}
:::pageio_setup:return
/pid == $1/
{
self->wait = timestamp;
}
:::pageio_done:entry
/self->anon == 1/
{
self->anon = 0;
@time[""] = sum(timestamp - self->wait);
self->wait = 0;
}
tick-5s
{
printf("\033[H\033[2J");
printf("Time breakdown (milliseconds):\n");
normalize(@time, 1000000);
printa(" %-50s %15@d\n", @time);
trunc(@time);
}
In the following example, the program spends 0.9 seconds doing useful work, and 230 seconds waiting for page-ins.
sol10$ /pagingtime.d 22599 dtrace: script './pagingtime.d' matched 10 probes ^C 1 2 :END Time breakdown (milliseconds): <on cpu> 913 <paging wait> 230704
Technorati Tag: OpenSolaris
Technorati Tag: Solaris
Technorati Tag: DTrace
( Jun 30 2005, 01:15:58 PM PDT ) Permalink Comments [1]
