Subject: Re: 1.6 woes
To: Jukka Marin <jmarin@pyy.jmp.fi>
From: Manuel Bouyer <bouyer@antioche.lip6.fr>
List: port-sparc
Date: 07/29/2002 18:10:20
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
--