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