|
From: John R.
|
>> As for profiling a longer-running program, please suggest suitable >> testcases. > > > Konqueror is a good one, as it's quite big but is all a single process > (unlike OpenOffice, for example). An interesting first run would be to > start up, view a couple of websites and then close it. > > Vim or xedit or another editor would also be interesting -- again start > up, do some stuff, shut down. http://BitWagon.com/valgrind/vg-konq.tsprof.bz2 96331 bytes ==> 620595 bytes, 7463 lines http://BitWagon.com/valgrind/vg-vim.tsprof.bz2 80711 bytes ==> 513247 bytes, 6217 lines Run on 2.0GHz AMD64 using valgrind-3.0.1 minimally modified as per previously-posted patch, which identifies modules dynamically loaded by valgrind, so that other tools can "see" them. Time is measured by thread-virtual hardware TSC cycle counter provided by perfctr patches, as used by tsprof, a proprietary profiling application. The previous report on 2005-09-04 used non-virtualized wallclock time on an "otherwise-idle" machine. In the reports, "<unknown subroutine>" corresponds to VEX-generated code. For instance, the vim-under-valgrind run shows this excerpt: ----- count ticks millisec @millisec % [id] module:name 11442209 19088608055 9497.7130 0.0008 37 [10] 0:<unknown subroutine> 11442209 6634858092 3301.2348 0.0003 35 [10] 0:<unknown subroutine> (self) 6768800 3323591125 1653.6834 0.0002 17 [10]->[16] 2:amd64g_calculate_condition 1824246 2599201091 1293.2565 0.0007 14 [10]->[19] 2:vgPlain_unknown_SP_update 3402866 1620918313 806.5029 0.0002 8 [10]->[28] 2:amd64g_calculate_rflags_c 4732061 1377005011 685.1415 0.0001 7 [10]->[32] 5:vgMemCheck_helperc_LOADV1 5567188 1040584819 517.7526 0.0001 5 [10]->[38] 5:vgMemCheck_helperc_LOADV8le 4443735 698827803 347.7082 0.0001 4 [10]->[58] 5:vgMemCheck_helperc_STOREV8le 1776344 474429732 236.0569 0.0001 2 [10]->[70] 5:vgMemCheck_helperc_STOREV1 1462144 374469654 186.3208 0.0001 2 [10]->[85] 5:vgMAC_die_mem_stack_8 2044409 356894445 177.5761 0.0001 2 [10]->[88] 5:vgMemCheck_helperc_MAKE_STACK_UNINIT 1027349 233359193 116.1100 0.0001 1 [10]->[116] 5:vgMemCheck_helperc_LOADV4le 1292385 214058138 106.5066 0.0001 1 [10]->[122] 5:vgMAC_new_mem_stack_8 455598 101726912 50.6152 0.0001 1 [10]->[163] 5:vgMemCheck_helperc_STOREV4le 20989 18884921 9.3964 0.0004 0 [10]->[321] 5:mc_LOADVn_slow 34723 9040793 4.4983 0.0001 0 [10]->[378] 5:vgMemCheck_helperc_LOADV2le 14962 4322899 2.1509 0.0001 0 [10]->[430] 5:vgMemCheck_helperc_STOREV2le 2827 4156037 2.0679 0.0007 0 [10]->[433] 5:mc_STOREVn_slow 9 1466390 0.7296 0.0811 0 [10]->[517] 5:mc_record_value_error 331 225631 0.1123 0.0003 0 [10]->[680] 5:vgMAC_new_mem_stack_16 2 190098 0.0946 0.0473 0 [10]->[692] 2:sync_signalhandler 152 171809 0.0855 0.0006 0 [10]->[698] 5:vgMAC_new_mem_stack_32 170 135610 0.0675 0.0004 0 [10]->[722] 5:vgMAC_die_mem_stack_32 63 62011 0.0309 0.0005 0 [10]->[783] 5:vgMAC_die_mem_stack_16 9 11246 0.0056 0.0006 0 [10]->[936] 5:vgMemCheck_helperc_value_check0_fail 21 8910 0.0044 0.0002 0 [10]->[949] 2:amd64g_dirtyhelper_RDTSC 10 7372 0.0037 0.0004 0 [10]->[970] 2:amd64g_calculate_rflags_all ----- where execution of generated instructions accounted for 0.37 * 0.35 = 13% of all cycles, and subroutines called by generated code accounted for 0.37 * (1 - 0.35) = 24% of all cycles. Both figures include profiling overheads of a few hundred cycles per CALL+RET; YMMV. [The measurement overhead can be reduced to zero by considering the called routines as "inlined" into their callers, but then the entry counts are unavailable, too.] The profiled run of vim-under-valgrind (26 seconds) completed normally. The profiled run of konqueror-under-valgrind (55 seconds) got as far as indicated below. konqueror runs under either valgrind or the profiler separately. The blame for the Assertion during konqueror-under-valgrind-under-tsprof has not yet been investigated. ----- Detaching after fork from child process 4840. kbuildsycoca running... not in syscall (0x7005DEBA - 0x7005DF3E) valgrind: syswrap-main.c:570 (vgPlain_client_syscall): Assertion 'sci->status.what == SsIdle' failed. ==4835== at 0x7001AC21: panic (m_libcassert.c:175) ==4835== by 0x70EEEFFF: ??? ==4835== by 0x80B1412BE9: ??? sched status: running_tid=1 Thread 1: status = VgTs_Runnable ==4835== at 0x1476BF22: __write_nocancel (in /lib64/tls/libpthread-2.3.4.so) ==4835== by 0x12DBBC10: KProcessController::theSigCHLDHandler(int) (in /usr/lib64/libkdecore.so.4.2.0) ==4835== by 0x1476D31F: (within /lib64/tls/libpthread-2.3.4.so) ----- -- |