dtrace discuss - Nov 2006 - Tracking user time of libc functions

I want to track how much time the CPU spends executing each libc function in the
user context (user time).  My goal is to look for optimization targets. 
I''m using dtrace(1), rather than gprof(1), because dtrace allows me to
collate data from thousands of invocations and many different processes.

The approach I''m currently working on involves tracking the system call
time with vtimestamp on syscall entry/return and subtracting that from the
corresponding libc entry/return.  I''ve also found I can access the
process accounting fields with curthread->t_lwp->lwp_mstate.ms_acct[0],
and curthread->t_lwp->lwp_mstate.ms_acct[1], but (unsurprisingly) dtrace
doesn''t update these fields on pid provider traps.  I''d be
interested in any better ideas.
 
 
This message posted from opensolaris.org

Diomidis Spinellis wrote:
> I want to track how much time the CPU spends executing each libc function
in the user context (user time).  My goal is to look for optimization targets. 
I''m using dtrace(1), rather than gprof(1), because dtrace allows me to
collate data from thousands of invocations and many different processes.
> 
> The approach I''m currently working on involves tracking the system
call time with vtimestamp on syscall entry/return and subtracting that from the
corresponding libc entry/return.  I''ve also found I can access the
process accounting fields with curthread->t_lwp->lwp_mstate.ms_acct[0],
and curthread->t_lwp->lwp_mstate.ms_acct[1], but (unsurprisingly) dtrace
doesn''t update these fields on pid provider traps.  I''d be
interested in any better ideas.
>  

While dtrace will work nicely for this, you can also use
the LD_PROFILE feature in the run time linker.  It provides
simple gprof results from multiple processes....


bash-3.00$ export LD_PROFILE=libc.so.1
bash-3.00$ date
Wed Nov 22 08:20:17 PST 2006
bash-3.00$ ls > /dev/null
bash-3.00$ time

real    0m0.000s
user    0m0.000s
sys     0m0.000s
bash-3.00$ export LD_PROFILEbash-3.00$ gprof -b /usr/lib/libc.so.1
/var/tmp/libc.so.1.profile

granularity: each sample hit covers 2 byte(s) no time propagated

                                   called/total       parents
index  %time    self descendents  called+self    name           index
                                   called/total       children

                 0.00        0.00       1/1576        getsystemTZ [349]
                 0.00        0.00       1/1576        ltzset_u [484]

...
granularity: each sample hit covers 2 byte(s) no time accumulated

    %  cumulative    self              self    total
  time   seconds   seconds    calls  ms/call  ms/call name
   0.0       0.00     0.00     1576     0.00     0.00  strcmp [1]
   0.0       0.00     0.00     1572     0.00     0.00  _strcoll [968]
   0.0       0.00     0.00      557     0.00     0.00  _private___errno 
[969]
   0.0       0.00     0.00      545     0.00     0.00  _readdir64 [970]
   0.0       0.00     0.00      423     0.00     0.00  strlen [2]
   0.0       0.00     0.00      420     0.00     0.00  ferror [3]
   0.0       0.00     0.00      213     0.00     0.00  _realbufend [971]
   0.0       0.00     0.00      210     0.00     0.00  printf [4]
...

You''ll need to run a lot of commands, obviously, to see the clock file
even once...

- Bart



-- 
Bart Smaalders			Solaris Kernel Performance
barts at cyber.eng.sun.com		http://blogs.sun.com/barts

Thanks!  For the past  five hours I''ve been running a Perl build under
dtrace to get some library performance numbers.  I estimate the build will take
another four hours to finish. Once, I''m done I''ll repeat the
build with the LD_PROFILE method; it appears to be a lot easier and more
trustworthy (my dtrace scripts are now over 100 lines long, so there could be
some mistakes in them).  I''ll post the results here.

- Diomidis
 
 
This message posted from opensolaris.org

On Wed, Nov 22, 2006 at 01:43:29AM -0800, Diomidis Spinellis
wrote:
> I want to track how much time the CPU spends executing each libc function
in the user context (user time).  My goal is to look for optimization targets. 
I''m using dtrace(1), rather than gprof(1), because dtrace allows me to
collate data from thousands of invocations and many different processes.
> 
> The approach I''m currently working on involves tracking the system
call time with vtimestamp on syscall entry/return and subtracting that from the
corresponding libc entry/return.  I''ve also found I can access the
process accounting fields with curthread->t_lwp->lwp_mstate.ms_acct[0],
and curthread->t_lwp->lwp_mstate.ms_acct[1], but (unsurprisingly) dtrace
doesn''t update these fields on pid provider traps.  I''d be
interested in any better ideas.
This is a very, very invasive approach -- too invasive for the question
you want to ask.  I would recommend using a profile probe, and then
using ufunc()/umod() to determine hot functions or libraries.

As an example of the output here, take this:

---8<--- hotmod.d ---8<---

#pragma D option quiet

profile-1234hz
/arg1 != NULL/
{
	@[umod(arg1)] = count();
}

tick-1sec
{
	trunc(@, 10);
	printa(@);
	trunc(@);
}

---8<--- hotmod.d ---8<---

And here''s two seconds of this output when I go to
http://opensolaris.org:

  Xorg                                                             11
  libxpconnect.so                                                  14
  libxpcom_core.so                                                 18
  libmozjs.so                                                      20
  libflashplayer.so                                                31
  nvidia_drv.so                                                    37
  libfb.so                                                         49
  libgklayout.so                                                   54
  libc.so.1                                                        81
  libfontconfig.so.1                                              303

  libjsd.so                                                         5
  libnspr4.so                                                       6
  nvidia_drv.so                                                     8
  libfb.so                                                          9
  libc.so.1                                                        24
  libfontconfig.so.1                                               38
  libxpcom_core.so                                                 46
  libxpconnect.so                                                  62
  libgklayout.so                                                  423
  libmozjs.so                                                     452

In terms of your question, here''s a one-liner using ufunc():

  # dtrace -n profile-1234hz''/arg1 != NULL/{@[ufunc(arg1)] =
count()}''

On the one hand, this will not be exactly what you want, because different
processes will have different entries, even if the function name is the
same.  On the other hand, this has (1) virtually no performance impact
(2) is highly accurate for CPU utilization and (3) has output that is a
snap to re-aggregate in Perl or whatever.  (Also, note that you can''t
use predicates here -- the conversion from address to user-level function
name happens in user-land as a postprocessing step, and can therefore
not be used in a predicate.)

	- Bryan

--------------------------------------------------------------------------
Bryan Cantrill, Solaris Kernel Development.       http://blogs.sun.com/bmc

This is great news!  When I started looking at the problem, I first considered
using a profile provider, but couldn''t find a function to map an
address to a function name.  I still can''t find ufunc() in the
documentation I use (the January 2005 Guide
http://docs.sun.com/app/docs/doc/817-6223, and
http://developers.sun.com/solaris/articles/dtrace_quickref/dtrace_functions.html),
but it''s clear that ufunc() is exactly what I was looking for.  The
dtrace in our Solaris installation (Sun D 1.1), doesn''t support
ufunc(), but I''ll look for a way to upgrade.

Let me note here how great dtrace is.  I think I haven''t felt so
excited about a tool, since 1987, when I first met yacc, lex, sed, and awk. This
is my third day using it, and I''m hooked for good.  I now regret
leaving it in my TODO list for more than a year.
 
 
This message posted from opensolaris.org