pmcstat and squid

[Adrian Chadd]

I'm trying to use pmcstat to profile userspace time used in Squid. I
just can't seem to get pmcstat to report anything useful.

The last thing I tried was something like:

# pmcstat -O file -P instructions -t <pid of squid>
# pmcstat -R file -g
# ls k7-retired-instructions
kernel.gmon

There doesn't seem to be a good example for process-based counting
stuff with PMC. Could anyone give me a hand?

Thanks!


adrian

[Joseph Koshy]

Post by Adrian Chadd
I'm trying to use pmcstat to profile userspace time used in
Squid. I just can't seem to get pmcstat to report anything
useful.
# pmcstat -O file -P instructions -t <pid of squid>
# pmcstat -R file -g
# ls k7-retired-instructions
kernel.gmon
There doesn't seem to be a good example for
process-based counting stuff with PMC. Could anyone
give me a hand?
Thanks!

I can think of one of two scenarios:

1) the squid process was in the kernel when the
samples got taken. This could happen if the
process was say in select() handling all the time.
2) There a bug in my process handling code that is
being triggered (hwpmc undercounts process-mode
samples), and samples are being missed.

Regards,
Koshy

[Adrian Chadd]

Post by Joseph Koshy
1) the squid process was in the kernel when the
samples got taken. This could happen if the
process was say in select() handling all the time.
2) There a bug in my process handling code that is
being triggered (hwpmc undercounts process-mode
samples), and samples are being missed.

I can't imagine why Squid would suddenly be in kernel mode all the time.
In fact, its in kernel space about 20% of the time under this workload
(with another 30% spent in interrupts.)

Here's the output from my latest attempt:
jacinta# pmcstat -S instructions -O samples.out
^Cjacinta# ls -l
total 89650
-rw-r--r-- 1 root wheel 576 Dec 12 03:52 1
-rw-r--r-- 1 root wheel 91719744 Dec 12 04:10 samples.out
jacinta# pmcstat -R samples.out -g
jacinta# cd k7-retired-instructions/
jacinta# ls
kernel.gmon ld-elf.so.1.gmon libc.so.6.gmon
jacinta# ls -l
total 3116
-rw-r--r-- 1 root wheel 2704268 Dec 12 04:10 kernel.gmon
-rw-r--r-- 1 root wheel 59474 Dec 12 04:10 ld-elf.so.1.gmon
-rw-r--r-- 1 root wheel 372962 Dec 12 04:10 libc.so.6.gmon

Squid is running but there's no profiling information for it still..

Scarily, on this Athlon 1800XP:

% cumulative self self total
time seconds seconds calls ms/call ms/call name
5.1 45254.00 45254.00 SHA256_Transform [1]
4.0 81184.00 35930.00 tcp_input [2]
3.8 114879.00 33695.00 tcp_output [3]
2.8 139645.00 24766.00 critical_exit [4]
2.5 162199.00 22554.00
bus_dmamap_load_mbuf_sg [5]
2.3 182415.00 20216.00 generic_bzero [6]
2.1 201156.00 18741.00 kqueue_register [7]

The kernel spends quite a bit of time in SHA256_Transform; I wonder if
it has to do with the sheer volume of TCP connections I'm making..

[Joseph Koshy]

Post by Adrian Chadd
Squid is running but there's no profiling information for it
still..

Could you run grep the output of `pmcstat -R' (no "-g")
for mention of the squid processes pids.

Also, try pmcstat -v -v (for a breakup of the buckets).

[Adrian Chadd]

There's plenty of squid process pid entries in the output of pmcstat -R.
This was gathered with pmcstat -S instructions -O samples.out.
pmcstat -R samples.out -g just generates kernel.gmon.

The top of the file:

initlog 0x1020003 "AMD_K7"
allocate 0x101 "k7-retired-instructions" 0x20000
sample 0x101 61458 0x28210f05 u
sample 0x101 61458 0x281a7a97 u
sample 0x101 61458 0xc095c5d3 s
sample 0x101 61458 0xc0701141 s

I'm running 6.2-PRERELEASE and pmcstat doesn't have '-v'.


Adrian

Post by Joseph Koshy

Post by Adrian Chadd
Squid is running but there's no profiling information for it
still..

Could you run grep the output of `pmcstat -R' (no "-g")
for mention of the squid processes pids.
Also, try pmcstat -v -v (for a breakup of the buckets).
--
FreeBSD Volunteer, http://people.freebsd.org/~jkoshy

[Stanislav Sedov]