Subject: Some minor kernel profiling results
To: port-vax <port-vax@netbsd.org>
From: Ken Wellsch <kwellsch@tampabay.rr.com>
List: port-vax
Date: 11/26/2000 18:25:37
After the mention of profiling the network stack, it reminded me that I
was curious about full kernel profiling. Not long ago I noticed the '-p'
option for 'config' and commands like 'kgmon' so I thought I might give
it a go on some VAXen.
I've run it now, profiling, on a 4000/60 for the past 7 hours. Most of
that time the system have been compiling kernels for other systems, but I
did run a 'bonnie' early on as well as made several 'ttcp' runs.
Anyway, here are the top items shown via 'gprof':
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
58.70 1288.93 1288.93 Idle
11.94 1551.22 262.29 753619 0.35 0.35 copyin
8.16 1730.38 179.16 212514 0.84 0.84 lockmgr
4.52 1829.74 99.36 17044 5.83 5.83 malloc
1.83 1870.02 40.28 993046 0.04 0.07 ncr53c9x_intr
1.36 1899.88 29.86 23488 1.27 1.27 free
1.16 1925.36 25.48 156874 0.16 0.16 kcopy
1.04 1948.13 22.77 syscall
0.70 1963.44 15.31 679357 0.02 0.02 _pool_get
0.67 1978.14 14.70 71961 0.20 0.21 ltsleep
0.57 1990.56 12.42 preempt
0.55 2002.68 12.12 copystr
0.52 2014.03 11.35 1200720 0.01 0.01 _pool_put
0.47 2024.28 10.25 298142 0.03 0.13 am7990_intr
0.42 2033.53 9.25 1250334 0.01 0.01 lance_copyfrombuf_contig
0.39 2042.08 8.55 552098 0.02 0.02 ncr53c9x_msgin
0.39 2050.55 8.47 95 89.16 1169.50 uiomove
0.32 2057.56 7.01 181785 0.04 0.04 ncr53c9x_select
...
0.00 2195.95 0.00 3 0.00 0.00 pool_page_alloc
I was seeing 'Remrq' as the big time consumer but upon investigating I
noted that just below this 'global' code is the local 'idle' routine, so
I took the liberty of slamming in a JSBENTRY(Idle) item above the 'idle:'
tag so the profiling would be more 'informative.'
I built a profiling kernel in the same way for a uVAX-II but upon
booting it, I got this panic:
NetBSD 1.5 (MVAXII.PROF) #0: Sun Nov 26 13:39:51 EST 2000
kwellsch@vs4060b:/usr/src/sys/arch/vax/compile/MVAXII.PROF
MicroVAX II
total memory = 9208 KB
avail memory = 6396 KB
using 140 buffers containing 560 KB of memory
mainbus0 (root)
ibus0 at mainbus0
uba0 at ibus0: Q22
dhu0 at uba0 csr 160440 vec 300 ipl 17
dhu0: rom(1) version 2 rom(0) version 2
dhu0: DHV-11
mtc0 at uba0 csr 174500 vec 774 ipl 17
mscpbus0 at mtc0: version 4 model 3
mscpbus0: DMA burst size set to 4
mt0 at mscpbus0 drive 0: TK50
uda0 at uba0 csr 172150 vec 770 ipl 17
mscpbus1 at uda0: version 0 model 13
mscpbus1: DMA burst size set to 4
ra0 at mscpbus1 drive 0: RA80
qe0 at uba0 csr 174440 vec 764 ipl 17
qe0: deqna, hardware address 08:00:2b:04:60:8c
Trap: type 1, code 0, pc 80004600, psl 41f0008
panic: trap
syncing disks... Trap: type 2, code 0, pc 80000424, psl 4160000
panic: trap
So I'm not able to uncover anything interesting on a box that does
actually show reduced network performance versus 1.4.2 (the 4000/60
runs 1.5 just fine network-wise so isn't all that exciting I expect).
Cheers,
-- Ken