lkml.org 
[lkml]   [1998]   [Jul]   [11]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: 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

    \
     
     \ /
      Last update: 2005-03-22 13:43    [W:0.026 / U:29.636 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site