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    [from the cache]
©2003-2011 Jasper Spaans. Advertise on this site