Subject: Re: Some kernel profiling on a 5000/133 with -current
To: port-pmax <port-pmax@netbsd.org>
From: Ken Wellsch <kwellsch@tampabay.rr.com>
List: port-pmax
Date: 08/24/2001 15:39:50
To follow up my profile data with some further details, I replaced
the assembler copy of memcpy with the C version so profiling would
be a snap.  BTW, there appear to be no references to memmove, bcopy
or ovcopy, at least in my MIPS1 custom kernel.

Anyway, here is the edited call graph data (I stopped after I had
clearly seen the major calls, but there were many more places that
memcpy is called...)

This activity represents a couple runs of "bonnie;" one with the
default 100Mb and the second with a file size of 256Mb.


  %   cumulative   self              self     total           
 time   seconds   seconds    calls  us/call  us/call  name    
-----------------------------------------------------------------------
 32.29    458.77   458.77    14411 31834.95 31834.95  mips_idle
 17.58    708.47   249.70  2023108   123.42   123.42  memcpy
  7.63    816.82   108.35                             _splset_noprof
  5.63    896.85    80.03                             _mcount
  4.96    967.27    70.41                             __mcount
  2.06    996.49    29.23  2305060    12.68    12.69  lockmgr
  1.55   1018.46    21.96   494099    44.45    44.45  mips1_FlushDCache
  1.52   1040.12    21.66  1355933    15.97    15.97  memset
  1.44   1060.59    20.47    66386   308.33   434.26  uvn_attach
  1.41   1080.68    20.10  9866645     2.04     5.78  st_scsibus_cmprss
  1.36   1100.03    19.35   471422    41.04   201.50  genfs_getpages
  1.34   1119.01    18.98  1159646    16.37    23.96  pmap_enter
	...
  0.00   1420.66     0.00        1     0.00   177.64  vn_fcntl


index % time    self  children    called     name
-----------------------------------------------------------------
[10]    19.7  249.70    0.00 2023108         memcpy [10]
-----------------------------------------------
[16]     7.8    0.36   98.55  796813         microtime <cycle 8> [16]
               98.35    0.00  796813/2023108     memcpy [10]
-----------------------------------------------
[18]     7.5   19.35   75.65  471422+70676   genfs_getpages <cycle 8> [18]
               57.45    0.00  465463/2023108     memcpy [10]
-----------------------------------------------
[33]     3.3    1.38   40.54   91130+42      softdep_setup_allocindir_meta [33]
                0.01    0.00      72/2023108     memcpy [10]
-----------------------------------------------
[37]     2.4    1.82   28.44  230418         copyin [37]
               28.44    0.00  230418/2023108     memcpy [10]
-----------------------------------------------
[44]     1.9    0.92   23.78  192636         copyout [44]
               23.78    0.00  192636/2023108     memcpy [10]
-----------------------------------------------
[48]     1.6    4.24   16.19 1447967+23      pool_get <cycle 2> [48]
               16.16    0.00  130930/2023108     memcpy [10]
-----------------------------------------------
[55]     0.9    0.00   11.08   42674         scsi_scsipi_cmd [55]
                5.27    0.00   42674/2023108     memcpy [10]
-----------------------------------------------
[70]     0.6    0.00    7.55   42897         ncr53c9x_scsipi_request [70]
                5.29    0.00   42897/2023108     memcpy [10]
-----------------------------------------------
[78]     0.4    0.00    5.28   42674         disk_unbusy [78]
                5.27    0.00   42674/2023108     memcpy [10]
-----------------------------------------------
[91]     0.3    0.00    3.66   42674         disk_busy [91]
                3.65    0.00   29553/2023108     memcpy [10]
-----------------------------------------------
[115]    0.2    0.68    1.88   12546         fill_eproc [115]
                1.55    0.00   12546/2023108     memcpy [10]
-----------------------------------------------
[136]    0.1    0.02    1.53   12377         b_to_q [136]
                1.53    0.00   12377/2023108     memcpy [10]
-----------------------------------------------
[149]    0.1    0.03    1.09    8793         amap_lookups [149]
                1.09    0.00    8793/2023108     memcpy [10]
-----------------------------------------------
[150]    0.1    0.17    0.88    2453         tcp_output [150]
                0.26    0.00    2084/2023108     memcpy [10]
-----------------------------------------------
[163]    0.1    0.01    0.73      58         sys_execve [163]
                0.01    0.00      46/2023108     memcpy [10]
-----------------------------------------------
[197]    0.0    0.07    0.28   11345         ioasic_attach_devs [197]
                0.28    0.00    2276/2023108     memcpy [10]
-----------------------------------------------
[199]    0.0    0.01    0.33    3648         q_to_b [199]
                0.33    0.00    2661/2023108     memcpy [10]
-----------------------------------------------
[207]    0.0    0.00    0.29    2030         SHA1Update [207]
                0.26    0.00    2100/2023108     memcpy [10]
-----------------------------------------------
[224]    0.0    0.00    0.18      70         fork1 [224]
                0.02    0.00     140/2023108     memcpy [10]
-----------------------------------------------

	etc.