Messages in this thread | | | Date | Sat, 11 Jul 1998 08:10:57 +0200 (MET DST) | From | "Michael L. Galbraith" <> | Subject | Re: patch-ikd + real profiling [first profiling result] |
| |
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
| |