dtrace and web server

[Boris Samorodov]

Hello List,

I try to locate (potential) bottlenecks at a web server:
-----
% uname -a
FreeBSD bbserver.ipt.ru 8.0-STABLE FreeBSD 8.0-STABLE #3 r203959: Sun Feb 21 11:53:57 MSK 2010     root at bbserver.ipt.ru:/z/obj/z/src/sys/BBSERVER  amd64

% top -jd1 | head -20
last pid: 47907;  load averages:  2.30,  1.88,  1.90  up 1+17:44:36    11:31:05
177 processes: 4 running, 172 sleeping, 1 zombie

Mem: 916M Active, 558M Inact, 2899M Wired, 2656K Cache, 31M Buf, 3502M Free
Swap: 4096M Total, 4096M Free

  PID JID USERNAME  THR PRI NICE   SIZE    RES STATE   C   TIME   WCPU COMMAND
22148   4     88     25  44    0   735M   530M ucond   3  23:05  7.81% mysqld
47705   4 www         1  54    0   223M 58476K select  2   0:07  7.76% httpd
47845   4 www         1  51    0   225M 48800K accept  1   0:02  7.47% httpd
47857   4 www         1  53    0   221M 44308K select  3   0:01  7.47% httpd
47797   4 www         1  51    0   225M 56276K accept  1   0:03  6.59% httpd
47843   4 www         1  50    0   221M 43580K select  3   0:01  6.30% httpd
47873   4 www         1  51    0   233M 52424K CPU2    2   0:01  5.96% httpd
47633   4 www         1  49    0   221M 56476K select  3   0:08  5.76% httpd
47878   4 www         1  47    0   221M 43480K accept  2   0:01  4.30% httpd
47708   4 www         1  52    0   221M 56756K accept  2   0:06  4.20% httpd
47880   4 www         1  52    0   223M 39516K accept  2   0:01  4.05% httpd
47875   4 www         1  49    0   235M 45080K CPU3    3   0:00  4.05% httpd
-----

Let's use dtrace to understand what's going on within 10 seconds
interval and normalize to 1 second:
-----
% cat top-10-count-periodic.d
#pragma D option quiet
BEGIN
{
last = timestamp;
}
syscall:::entry
{
@func[execname] = count();
}
tick-10sec
{
trunc(@func, 10);
normalize(@func, (timestamp - last) / 1000000000);
printa(@func);
clear(@func);
last = timestamp;
}
-----

The result is here:
ftp://ftp.bsam.ru/pub/tmp/top-10-count-periodic.1.log.txt

OK, seems that we are mostly interested at mysqld and httpd processes
(well, not a surprise).

The following script is intended to test and quantize mysqld process:
-----
% cat quant.d
syscall:::entry
/ execname == "mysqld" /
{
self->ts = timestamp;
}
syscall:::return
/ self->ts && execname == "mysqld" /
{
@time[probefunc] = quantize(timestamp - self->ts);
self->ts = 0;
}
-----

The result: ftp://ftp.bsam.ru/pub/tmp/quant.mysqld.1.log.txt

The same D script but for httpd process:
ftp://ftp.bsam.ru/pub/tmp/quant.httpd.1.log.txt

And now can you advise me what to do next? What should I pay
attention to? Thanks!


-- 
WBR, Boris Samorodov (bsam)
Research Engineer, http://www.ipt.ru Telephone & Internet SP
FreeBSD Committer, http://www.FreeBSD.org The Power To Serve