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


DTrace VM Provider Probes and Descriptions
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

Comments:

<a href="http://vclosets.com">closet organizers</a>

Posted by closet organizers on November 29, 2008 at 03:53 AM PST #

Post a Comment:
  • HTML Syntax: NOT allowed
About

rmc

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today