Re: patch-ikd + real profiling [first profiling result]

Michael L. Galbraith (mikeg@weiden.de)
Sat, 11 Jul 1998 08:10:57 +0200 (MET DST)


On Sat, 11 Jul 1998, Andrea Arcangeli wrote:

> On Fri, 10 Jul 1998, Andrea Arcangeli wrote:
>
> >I' ll try if it will compile tomorrow ;-). Sould work though...
>
> Ok the memleak stuff compile and run fine now, thanks.
>
> You can see the first result of the profiling after 16minutes of uptime
> on my machine here:
>
[snip]
>
> And here the most CPU eater functions:
>
> 225133 skb_copy_datagram_iovec 5628.3250
> 240400 do_normal_gettime 6010.0000
> 320103 sock_wspace 6155.8269
> 320622 sock_poll 6165.8077
> 377471 end_buffer_io_sync 6291.1833
> 714758 get_hash_table 6381.7679
> 1920554 alloc_addr 7502.1641
> 185006 __delay 7708.5833
> 662853 __brelse 7891.1071
> 1263361 __wake_up 7896.0063
> 521685 ide_get_queue 8151.3281
> 240400 get_fast_time 8585.7143
> 767084 find_buffer 8716.8636
> 225237 ip_masq_get_debug_level 9384.8750
> 712595 set_writetime 9897.1528
> 225237 icmp_discard 11261.8500
> 956774 __generic_copy_to_user 11959.6750
> 1051117 __generic_copy_from_user 13138.9625
> 1904317 free_addr 13224.4236
> 1452378 do_IRQ 17290.2143
> 2169644 system_call 27120.5500
> 574714 write_null 28735.7000
> 2251804 ret_from_sys_call 93825.1667
>
> In the first 16minutes the system was sometimes loaded with ping -f, cat
> /dev/zero | toport dragon 3000, cp /dev/hda /dev/null, cp /dev/zero file,
> cp file /dev/null and finally find / &>/dev/null.
>

YIKES! memleak looks expensive.

I usually profile using ktracer with a 1M entry buffer. A kernel build
looks like this...

CPU% USECS-TOT USECS-AVG CALLS ADDRESS FUNCTION
0.0959% 35353.00 0.88 40145 c0129692 free_addr
0.1044% 38466.81 1.84 20929 c012028d vm_enough_memory
0.1050% 38686.81 1.41 27470 c010a793 system_call
0.1057% 38958.35 1.71 22794 c0149308 ext2_permission
0.1070% 39431.27 1.65 23947 c0125d04 real_kmem_cache_alloc
0.1090% 40183.64 1.69 23840 c0125e27 real_kmem_cache_free
0.1120% 41266.62 1.37 30196 c011ff84 handle_mm_fault
0.1138% 41953.68 4.01 10457 c01202eb sys_brk
0.1177% 43396.32 1.98 21927 c0252bc4 __generic_copy_from_user
0.1284% 47322.68 2.42 19535 c0138577 d_lookup
0.1293% 47670.66 1.58 30196 c0111f27 do_page_fault
0.1338% 49323.09 3.38 14590 c0122593 filemap_nopage
0.1696% 62530.27 3.77 16607 c012792f real__get_free_pages
0.1839% 67779.29 1.65 41087 c0252b17 strlen_user
0.2074% 76461.75 1.05 72722 c014a710 ext2_check_dir_entry
0.2334% 86041.01 5061.24 17 c012014a check_pgt_cache
0.2960% 109124.56 2.64 41267 c0129597 alloc_addr
0.3664% 135059.23 77.27 1748 c0252d53 __memcpy_g
0.4371% 161118.58 4.03 39932 c0127807 real_free_pages
0.6367% 234694.60 53.18 4413 c0252e2e ___copy_user
1.0344% 381278.20 211.12 1806 c010b515 math_state_restore
1.9723% 727006.88 51.09 14229 c0252cce ___zero_chunk
3.0992% 1142386.09 848.73 1346 c0113d07 add_timer
11.3864% 4197048.40 147.76 28404 c010a7c6 ret_from_sys_call
33.2373% 12251365.11 3164.09 3872 c010bfcf do_IRQ
43.4008% 15997636.03 566.47 28241 c011f565 put_page
1048556 entries; 38049773.05 total usecs; 3.13% idle.

er.. any idea why check_pgt_cache takes so long on average?

Cheers,

-Mike

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.rutgers.edu
Please read the FAQ at http://www.altern.org/andrebalsa/doc/lkml-faq.html