On Mon, Jul 29, 2002 at 05:56:34PM +0200, Manuel Bouyer wrote:
> Well, I set up kernel profiling. With an almost idle machine the kernel
> time is already high: just 12% for running top though an ssh session
> load averages:  0.23,  0.64,  0.66                                     17:47:38
> 23 processes:  22 sleeping, 1 on processor
> CPU states:  0.9% user,  0.0% nice, 12.8% system,  0.5% interrupt, 85.8% idle
> Memory: 16M Act, 1936K Wired, 2336K Exec, 9956K File, 37M Free
> Swap: 31M Total, 31M Free
> 
>   PID USERNAME PRI NICE   SIZE   RES STATE      TIME   WCPU    CPU COMMAND
>   217 bouyer    31    0   200K  952K CPU        0:30  5.66%  5.66% top
>   209 bouyer     2    0   464K 1792K select     0:20  3.76%  3.76% sshd
>   160 root      18  -12   776K 1788K pause      0:33  3.22%  3.22% ntpd
> [all other below at at 0% CPU]
> profiling results show:
> Flat profile:
> 
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total           
>  time   seconds   seconds    calls  us/call  us/call  name    
>  85.11     27.67    27.67                             idle
>   9.38     30.72     3.05    26880   113.47   113.47  sun4_vcache_flush_page
>   2.18     31.43     0.71                             Lgot_result
>   0.34     31.54     0.11      331   332.33   332.33  pmap_count_ptes
>   0.31     31.64     0.10    16509     6.06     6.06  pvhead
>   0.25     31.72     0.08      426   187.79  7523.74  me_alloc
>   0.22     31.79     0.07                             sparc_interrupt44c
>   0.18     31.85     0.06     3874    15.49    15.49  callout_reset
>   0.15     31.90     0.05     1806    27.69    27.69  memcpy
>   0.15     31.95     0.05      508    98.43  6407.70  mmu_pagein
>   0.12     31.99     0.04     3308    12.09    27.58  nfs_timer
>   0.09     32.02     0.03     3323     9.03    44.74  softclock
>   0.09     32.05     0.03     3308     9.07    48.75  hardclock
>   0.09     32.08     0.03      331    90.63   504.72  fill_kproc2
>   0.09     32.11     0.03       12  2500.00  2500.00  sun4_vcache_flush_segment
>   0.09     32.14     0.03                             Lbcopy_doubles
>   0.06     32.16     0.02     2442     8.19     8.19  pv_syncflags4_4c
>   0.06     32.18     0.02     1775    11.27    11.27  lockmgr
> 
> If I read things properly, the killer is sun4_vcache_flush_page(), and
> it seems to be called from me_alloc() most of the time.
> 
> More clearly: it looks like my patch is causing this overuse of system time.
> 
> I'm doing another run of profiling with a kernel compile running.

With gcc running:
Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  us/call  us/call  name    
 82.10    188.18   188.18  1628958   115.52   115.52  sun4_vcache_flush_page
  8.22    207.03    18.85                             Lgot_result
  2.19    212.04     5.01    25604   195.67  7724.64  me_alloc
  2.10    216.86     4.82   947255     5.09     5.09  pvhead
  0.98    219.10     2.24    27309    82.02  7296.10  mmu_pagein
  0.44    220.10     1.00     2958   338.07   338.07  pmap_count_ptes
  0.24    220.64     0.54                             normal_mem_fault
  0.17    221.03     0.39    26415    14.76  7592.50  mem_access_fault
  0.17    221.42     0.39    23822    16.37    54.74  softclock
  0.17    221.80     0.38     2542   149.49   306.80  genfs_putpages
  0.15    222.15     0.35    23813    14.70    19.57  hardclock
  0.15    222.49     0.34                             Lsw_load
  0.15    222.83     0.34                             sparc_interrupt44c
  0.13    223.12     0.29    23798    12.19    21.85  nfs_timer
  0.13    223.41     0.29                             softintr_common
  0.12    223.68     0.27    27949     9.66     9.66  callout_reset
  0.11    223.94     0.26     7017    37.05    37.05  memset
  0.10    224.18     0.24     2958    81.14   483.73  fill_kproc2

Again most of the time is sun4_vcache_flush_page() called from me_alloc().

--
Manuel Bouyer, LIP6, Universite Paris VI.           Manuel.Bouyer@lip6.fr
--