lkml.org 
[lkml]   [1998]   [Apr]   [4]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    Subjectmuch overhead profiling 2.1.92
    Hello MM hackers,

    I was doing some profiling of 2.1.92 when I noticed that my results
    seemed a bit screwy. I'm keeping the text short as to spare you the
    gory details my floundering searching :^)

    I upped the tracebuffer for ktracer to 1M entries so that I can capture
    an entire (small) Bonnie run like so..
    echo >/proc/trace;Bonnie -s #>repx 2>&1;dotrace >xx;profit>>repx
    As long as the trace length is less than the full buflen, I've captured
    everything from the time echo resets the buffer to when the buffer is
    beginning to be read out. (AFIKT)

    Hope this helps. If anything important is missing, holler.

    -Mike

    The script for processing counts schedule and hard_idle as idle time.
    The percentages on the left are from what's left after removing this.

    ==> report1 <==
    File './Bonnie.1226', size: 1048576
    Writing with putc()...done
    Rewriting...done
    Writing intelligently...done
    Reading with getc()...done
    Reading intelligently...done
    Seeker 1...Seeker 2...Seeker 3...start 'em...done...done...done...
    -------Sequential Output-------- ---Sequential Input-- --Random--
    -Per Char- --Block--- -Rewrite-- -Per Char- --Block--- --Seeks---
    Machine MB K/sec %CPU K/sec %CPU K/sec %CPU K/sec %CPU K/sec %CPU /sec %CPU
    1 6189 96.7 12971 101.3 6894 101.0 6454 100.9 38691 113.4 4304.2 99.0

    ==> report2 <==
    File './Bonnie.1238', size: 2097152
    Writing with putc()...done
    Rewriting...done
    Writing intelligently...done
    Reading with getc()...done
    Reading intelligently...done
    Seeker 1...Seeker 2...Seeker 3...start 'em...done...done...done...
    -------Sequential Output-------- ---Sequential Input-- --Random--
    -Per Char- --Block--- -Rewrite-- -Per Char- --Block--- --Seeks---
    Machine MB K/sec %CPU K/sec %CPU K/sec %CPU K/sec %CPU K/sec %CPU /sec %CPU
    2 6231 97.4 13184 103.0 6814 99.8 6397 100.0 38469 93.9 4173.5 99.1

    ==> report3 <==
    File './Bonnie.1250', size: 3145728
    Writing with putc()...done
    Rewriting...done
    Writing intelligently...done
    Reading with getc()...done
    Reading intelligently...done
    Seeker 1...Seeker 2...Seeker 3...start 'em...done...done...done...
    -------Sequential Output-------- ---Sequential Input-- --Random--
    -Per Char- --Block--- -Rewrite-- -Per Char- --Block--- --Seeks---
    Machine MB K/sec %CPU K/sec %CPU K/sec %CPU K/sec %CPU K/sec %CPU /sec %CPU
    3 6241 101.6 13151 98.5 6771 99.2 6381 99.7 38092 99.2 4149.8 99.6
    ==> report1 <==
    0.7554% 12528.71 0.44 28755 c0128400 get_hash_table
    0.8400% 13930.66 0.52 26879 c0128f09 set_writetime
    1.0056% 16678.31 1.18 14187 c0123fd3 __free_page
    1.7261% 28627.34 2862.73 10 c0112f8b add_timer
    1.7980% 29819.39 0.91 32906 c0128f57 refile_buffer
    2.3547% 39052.17 1.36 28787 c01283a7 find_buffer
    2.6911% 44631.83 19.03 2345 c020904b ___zero_chunk
    8.4356% 139904.87 224.57 623 c01116d5 do_page_fault
    9.1108% 151101.84 23.62 6398 c02090cf __memcpy_g
    13.7406% 227886.98 15.51 14697 c010a556 ret_from_sys_call
    46.1657% 765656.65 50.67 15110 c02091aa ___copy_user
    383399 entries; 6630996.77 total usecs; 74.99% idle.

    ==> report2 <==
    0.9158% 20832.88 744.03 28 c0112f8b add_timer
    1.0687% 24309.87 0.52 46944 c0128f09 set_writetime
    1.1611% 26411.18 0.43 61753 c0128400 get_hash_table
    1.2724% 28942.55 1.40 20638 c0123fd3 __free_page
    2.7980% 63646.58 0.91 70119 c0128f57 refile_buffer
    3.2546% 74033.76 16.81 4403 c020904b ___zero_chunk
    4.0894% 93023.56 1.50 61817 c01283a7 find_buffer
    6.1553% 140015.32 225.11 622 c01116d5 do_page_fault
    9.6896% 220411.92 23.28 9469 c02090cf __memcpy_g
    17.6039% 400441.81 25.24 15866 c010a556 ret_from_sys_call
    40.0113% 910148.11 48.03 18950 c02091aa ___copy_user
    626714 entries; 7264058.89 total usecs; 68.69% idle.

    ==> report3 <==
    1.0055% 28692.35 610.48 47 c0112f8b add_timer
    1.2078% 34463.35 0.52 66533 c0128f09 set_writetime
    1.3077% 37315.83 1.45 25746 c0123fd3 __free_page
    1.3550% 38665.87 0.43 90548 c0128400 get_hash_table
    3.0083% 85841.06 0.89 96845 c0128f57 refile_buffer
    3.6169% 103205.94 15.98 6457 c020904b ___zero_chunk
    4.5553% 129982.83 1.43 90645 c01283a7 find_buffer
    4.9187% 140352.68 226.01 621 c01116d5 do_page_fault
    10.1274% 288980.48 23.06 12533 c02090cf __memcpy_g
    20.0596% 572393.36 33.63 17021 c010a556 ret_from_sys_call
    36.3875% 1038305.93 45.58 22782 c02091aa ___copy_user
    840444 entries; 7985157.00 total usecs; 64.27% idle.

    Noticing the variations in add_timer, I rummaged in the (XXX large)
    traces and found sequences like this. Idle time isn't thrown out from
    the individual percentages here.

    0.0001% 0.47 0.47 1 c010a523 system_call
    0.0001% 0.50 0.50 1 c0130fa7 do_select
    0.0001% 0.54 0.54 1 c01882ca tcp_find_established
    0.0001% 0.60 0.60 1 c019733d inet_poll
    0.0001% 0.77 0.77 1 c018846e tcp_listen_poll
    0.0001% 0.83 0.83 1 c010f8b7 old_select
    0.0001% 0.92 0.92 1 c013119b sys_select
    0.0002% 1.11 1.11 1 c017222d sock_wspace
    0.0002% 1.13 0.56 2 c017014e sock_poll
    0.0002% 1.34 1.34 1 c0173568 datagram_poll
    0.0002% 1.35 1.35 1 c01723dc __release_sock
    0.0002% 1.57 1.57 1 c01884c3 tcp_poll
    0.0003% 1.78 1.78 1 c01138dd second_overflow
    0.0003% 1.95 1.95 1 c0112f15 process_timeout
    0.0005% 3.18 3.18 1 c0130ef0 max_select_fd
    0.0005% 3.73 3.73 1 c011327e del_timer
    0.0016% 11.19 5.59 2 c01241e3 __get_free_pages
    0.0018% 12.50 12.50 1 c010a556 ret_from_sys_call
    0.0036% 24.85 0.36 69 c0113c0e update_wall_time
    0.0038% 25.93 0.38 69 c0123a88 swap_tick
    0.0041% 28.59 0.41 69 c0113d5f update_process_times
    0.0044% 30.20 0.44 69 c010babc handle_IRQ_event
    0.0044% 30.49 0.44 69 c010bd25 do_IRQ
    0.0045% 31.22 0.45 69 c010bcfd do_IRQ
    0.0056% 38.65 0.56 69 c011aca7 do_bottom_half
    0.0057% 39.72 0.58 69 c0113b35 update_wall_time_one_tick
    0.0059% 41.07 0.60 69 c010f2ee pentium_timer_interrupt
    0.0070% 48.06 0.70 69 c010bd3f do_IRQ
    0.0088% 60.55 0.88 69 c0113dd7 timer_bh
    0.0099% 68.55 0.99 69 c0114151 do_timer
    0.0110% 75.94 1.10 69 c0113c63 update_one_process
    0.0121% 83.42 1.21 69 c010bb05 handle_IRQ_event
    0.0141% 97.76 1.42 69 c0123f6b free_memory_available
    0.0198% 136.61 1.98 69 c010bc37 do_8259A_IRQ
    1.4223% 9828.21 9828.21 1 c0112f8b add_timer
    1.4476% 10002.90 10002.90 1 c0108d35 hard_idle
    96.9989% 670272.20 9575.32 70 c01132c7 schedule
    1196 entries; 691010.38 total usecs.
    \
     
     \ /
      Last update: 2005-03-22 13:42    [W:0.043 / U:4.888 seconds]
    ©2003-2017 Jasper Spaans. hosted at Digital OceanAdvertise on this site