Re: some profiling info

Oskar wrote:
>I don't know how accurate this is, but I though it might be useful. It's
>not real profiling info, but anyway... you can do the same thing with
>solaris 'truss' if you are interested.
...
>% time seconds usecs/call calls errors syscall
>------ ----------- ----------- --------- --------- ----------------
> 80.39 376.869164 5144 73263 1584 stat
> 5.14 24.113076 115 209873 oldselect
> 3.66 17.141290 151 113764 21 write
> 3.60 16.864246 2062 8177 open

We've plugged in the Digital continuous profiling infrastructure on
one of our cache boxes, and it has provided some interesting stats.
The DCPI seems to perioidcally sample process images and determines
which function it is in. This means that it doesn't show the effect
of syscalls, but nevertheless I think it provides some interesting
figures on what a cache spends it's time on when its in userland.
"imiss" in this case is instruction cache miss on the processor (I
think, the documentation sucks).

Total samples for event type cycles = 27764871
Total samples for event type imiss = 4241050

The counts given below are the number of samples for each
listed event type.
==========================================================
    cycles % cum% imiss % procedure image
   2976145 10.72% 10.72% 333984 7.88% comm_select
   2819625 10.16% 20.87% 502885 11.86% _db_print
   2254499 8.12% 28.99% 4678 0.11% ipcache_compareLastRef
   1803030 6.49% 35.49% 41754 0.98% memCopy
   1120219 4.03% 39.52% 131206 3.09% free
   1098211 3.96% 43.48% 137002 3.23% malloc
    890267 3.21% 46.68% 232902 5.49% comm_select_incoming
    761431 2.74% 49.43% 30109 0.71% xstrncpy
    639858 2.30% 51.73% 5907 0.14% ipcacheExpiredEntry
    462670 1.67% 53.40% 33090 0.78% aclMatchIp
    456958 1.65% 55.04% 78110 1.84% httpReadReply
    436356 1.57% 56.62% 80009 1.89% hash4
    413331 1.49% 58.10% 54576 1.29% hash_lookup
    351445 1.27% 59.37% 86434 2.04% calloc
    319849 1.15% 60.52% 35256 0.83% mime_get_header
    317981 1.15% 61.67% 101017 2.38% commSetSelect
    244247 0.88% 62.55% 63984 1.51% fdstat_are_n_free_fd
    215699 0.78% 63.32% 1550 0.04% hash_next
    212137 0.76% 64.09% 62855 1.48% eventRun
    211850 0.76% 64.85% 40328 0.95% urlParse
    199213 0.72% 65.57% 55612 1.31% xcalloc
   ...

This is approximately 3 weeks worth of data, on a cache doing around
200k transactions / day, 8Gb cache disk.

The _db_print is of course what is behind all of those debug() calls.
We are running with debug at ALL,1. Interestingly, I turned all
debugging of for a couple of days, and it didn't effect the proportion
of _db_print at all, which suggests that my compiler (gcc 2.7.2.1)
isn't very good at handling varargs.

ipcache_compareLastRef is the comparator function for the sort of the
LRU candidate list.

I will also run up the same stats on 1.2-beta4 when I get enough
guinea pigs to trial it.

Jules
Received on Tue Jul 29 2003 - 13:15:44 MDT