On 24 Aug 2001, Owen Taylor wrote: > > > Oh for decent profiling tools.... this sort of information is useful, > > > but without call graphs not that useful. I'd really like to be able > > > to see _where_ all the lock/unlock action was coming from. > > > > well, grepping for static_rw on the profile i posted an excerpt from earlier, > > (before merging): > > Hmmm... > > > Percentage | Total | Average | # Calls | Function | Caller > > 5.457186910 | 7.891597889 | 0.000055861 | 141272 | g_static_rw_lock_reader_lock | g_type_is_a > > 0.107371600 | 0.155269281 | 0.000001099 | 141272 | g_static_rw_lock_reader_unlock | g_type_is_a > > > > 0.241135842 | 0.348704769 | 0.000000760 | 458668 | g_static_rw_lock_reader_lock | g_type_check_instance_cast > > 0.315551063 | 0.456316073 | 0.000000995 | 458668 | g_static_rw_lock_reader_unlock | g_type_check_instance_cast > > '# calls' numbers look right, the time/percentage parts look just a bit funny.... hmmmmm. upon further detailed investigation, and after consulting additional input from hackers around this area, we came to the conclusion, that, basically, i'm a moron. for one, i used rdtsc for time stamping on an SMP system, and stefan westerfeld also found a sign bug in the time calculations. so, here's the profile again (again fgrepping for static_rw), first on that very same SMP system, but this time using gettimeofday() and then with rdtsc on an uni-processor system. i tried to perform roughly the same task as before. one pretty impressive thing to note is the number of calls to g_static_rw_lock_signal() from check_derivation_U(). 2.03 million calls in 71 seconds is a bit huge. i'm not claiming responsibility for further mistakes though, i'll simply attach the profiling code used, so you can take results up against the source ;) SMP system, dual pentium 550MHz: Total time accounted: 72.180096 Profiler timing device: Glibc gettimeofday(2) Percentage | Total | Average | # Calls | Function | Caller 2.507120523 | 1.809642000 | 0.000000948 | 1908932 | g_static_rw_lock_signal | check_derivation_U 1.844933817 | 1.331675000 | 0.000002256 | 590181 | g_static_rw_lock_reader_unlock | g_type_value_table_peek 1.341231245 | 0.968102000 | 0.000002290 | 422725 | g_static_rw_lock_reader_unlock | g_type_check_instance_cast 1.281645566 | 0.925093000 | 0.000002295 | 403165 | g_static_rw_lock_reader_unlock | g_type_instance_is_a 1.088694867 | 0.785821000 | 0.000001331 | 590181 | g_static_rw_lock_reader_lock | g_type_value_table_peek 0.831903853 | 0.600469000 | 0.000001420 | 422725 | g_static_rw_lock_reader_lock | g_type_check_instance_cast 0.799299297 | 0.576935000 | 0.000001431 | 403165 | g_static_rw_lock_reader_lock | g_type_instance_is_a 0.568865965 | 0.410608000 | 0.000002252 | 182368 | g_static_rw_lock_reader_unlock | g_type_check_value 0.434576867 | 0.313678000 | 0.000002288 | 137081 | g_static_rw_lock_reader_unlock | g_type_is_a 0.360276606 | 0.260048000 | 0.000001426 | 182368 | g_static_rw_lock_reader_lock | g_type_check_value 0.257906279 | 0.186157000 | 0.000001358 | 137081 | g_static_rw_lock_reader_lock | g_type_is_a 0.204678309 | 0.147737000 | 0.000002266 | 65192 | g_static_rw_lock_reader_unlock | g_type_check_instance 0.144995651 | 0.104658000 | 0.000002295 | 45599 | g_static_rw_lock_reader_unlock | g_type_parent 0.122277477 | 0.088260000 | 0.000001354 | 65192 | g_static_rw_lock_reader_lock | g_type_check_instance 0.087122356 | 0.062885000 | 0.000001379 | 45599 | g_static_rw_lock_reader_lock | g_type_parent 0.050347675 | 0.036341000 | 0.000002297 | 15821 | g_static_rw_lock_reader_unlock | g_type_check_class_cast 0.044384812 | 0.032037000 | 0.000002245 | 14271 | g_static_rw_lock_reader_unlock | g_type_create_instance 0.035220236 | 0.025422000 | 0.000002278 | 11161 | g_static_rw_lock_reader_unlock | g_type_check_flags 0.031939553 | 0.023054000 | 0.000002590 | 8901 | g_static_rw_lock_writer_unlock | g_type_class_ref 0.030906027 | 0.022308000 | 0.000001410 | 15821 | g_static_rw_lock_reader_lock | g_type_check_class_cast 0.027824845 | 0.020084000 | 0.000001407 | 14271 | g_static_rw_lock_reader_lock | g_type_create_instance 0.026916007 | 0.019428000 | 0.000000975 | 19918 | g_static_rw_lock_signal | g_type_init_with_debug_flags 0.026537787 | 0.019155000 | 0.000002269 | 8443 | g_static_rw_lock_reader_unlock | g_type_name 0.024738122 | 0.017856000 | 0.000002374 | 7521 | g_static_rw_lock_writer_unlock | g_type_class_unref 0.020750873 | 0.014978000 | 0.000001342 | 11161 | g_static_rw_lock_reader_lock | g_type_check_flags 0.019551096 | 0.014112000 | 0.000001585 | 8901 | g_static_rw_lock_writer_lock | g_type_class_ref 0.017262377 | 0.012460000 | 0.000001657 | 7521 | g_static_rw_lock_writer_lock | g_type_class_unref 0.015570775 | 0.011239000 | 0.000001331 | 8443 | g_static_rw_lock_reader_lock | g_type_name 0.012313644 | 0.008888000 | 0.000002325 | 3823 | g_static_rw_lock_reader_unlock | g_type_free_instance 0.008840387 | 0.006381000 | 0.000002209 | 2889 | g_static_rw_lock_reader_unlock | g_type_class_peek 0.007549173 | 0.005449000 | 0.000001425 | 3823 | g_static_rw_lock_reader_lock | g_type_free_instance 0.005520913 | 0.003985000 | 0.000001379 | 2889 | g_static_rw_lock_reader_lock | g_type_class_peek 0.004599606 | 0.003320000 | 0.000002276 | 1459 | g_static_rw_lock_reader_unlock | g_type_from_name 0.004407032 | 0.003181000 | 0.000002240 | 1420 | g_static_rw_lock_reader_unlock | g_type_class_is_a 0.003505121 | 0.002530000 | 0.000002249 | 1125 | g_static_rw_lock_reader_unlock | g_type_interface_peek 0.003456632 | 0.002495000 | 0.000002283 | 1093 | g_static_rw_lock_writer_unlock | g_type_create_instance 0.002920473 | 0.002108000 | 0.000001485 | 1420 | g_static_rw_lock_reader_lock | g_type_class_is_a 0.002741753 | 0.001979000 | 0.000001356 | 1459 | g_static_rw_lock_reader_lock | g_type_from_name 0.002206980 | 0.001593000 | 0.000002417 | 659 | g_static_rw_lock_writer_unlock | g_type_free_instance 0.002122469 | 0.001532000 | 0.000001362 | 1125 | g_static_rw_lock_reader_lock | g_type_interface_peek 0.002017177 | 0.001456000 | 0.000001332 | 1093 | g_static_rw_lock_writer_lock | g_type_create_instance 0.001507341 | 0.001088000 | 0.000002276 | 478 | g_static_rw_lock_reader_unlock | g_type_get_qdata 0.001348017 | 0.000973000 | 0.000001476 | 659 | g_static_rw_lock_writer_lock | g_type_free_instance 0.001266277 | 0.000914000 | 0.000002274 | 402 | g_static_rw_lock_reader_unlock | check_derivation_U 0.001224714 | 0.000884000 | 0.000002272 | 389 | g_static_rw_lock_writer_unlock | type_class_init_Wm 0.001206704 | 0.000871000 | 0.000002292 | 380 | g_static_rw_lock_reader_unlock | type_data_finalize_class_U 0.001206704 | 0.000871000 | 0.000002239 | 389 | g_static_rw_lock_reader_unlock | type_class_init_Wm 0.001195620 | 0.000863000 | 0.000002538 | 340 | g_static_rw_lock_writer_unlock | g_type_register_static 0.001183152 | 0.000854000 | 0.000002247 | 380 | g_static_rw_lock_writer_unlock | type_data_last_unref_Wm 0.000972567 | 0.000702000 | 0.000001469 | 478 | g_static_rw_lock_reader_lock | g_type_get_qdata 0.000846494 | 0.000611000 | 0.000001571 | 389 | g_static_rw_lock_writer_lock | type_class_init_Wm 0.000829869 | 0.000599000 | 0.000001490 | 402 | g_static_rw_lock_reader_lock | check_derivation_U 0.000795233 | 0.000574000 | 0.000001511 | 380 | g_static_rw_lock_writer_lock | type_data_last_unref_Wm 0.000738431 | 0.000533000 | 0.000001370 | 389 | g_static_rw_lock_reader_lock | type_class_init_Wm 0.000724576 | 0.000523000 | 0.000001538 | 340 | g_static_rw_lock_writer_lock | g_type_register_static 0.000709337 | 0.000512000 | 0.000002216 | 231 | g_static_rw_lock_reader_unlock | g_type_interfaces 0.000703795 | 0.000508000 | 0.000001337 | 380 | g_static_rw_lock_reader_lock | type_data_finalize_class_U 0.000699639 | 0.000505000 | 0.000002371 | 213 | g_static_rw_lock_writer_unlock | g_type_init_with_debug_flags 0.000678858 | 0.000490000 | 0.000002322 | 211 | g_static_rw_lock_reader_unlock | g_type_class_peek_parent 0.000649764 | 0.000469000 | 0.000002430 | 193 | g_static_rw_lock_writer_unlock | g_type_class_ref 0.000497367 | 0.000359000 | 0.000001701 | 211 | g_static_rw_lock_reader_lock | g_type_class_peek_parent 0.000480742 | 0.000347000 | 0.000001629 | 213 | g_static_rw_lock_writer_lock | g_type_init_with_debug_flags 0.000425325 | 0.000307000 | 0.000001329 | 231 | g_static_rw_lock_reader_lock | g_type_interfaces 0.000404544 | 0.000292000 | 0.000002264 | 129 | g_static_rw_lock_writer_unlock | g_type_set_qdata 0.000401773 | 0.000290000 | 0.000001503 | 193 | g_static_rw_lock_writer_lock | g_type_class_ref 0.000343585 | 0.000248000 | 0.000002138 | 116 | g_static_rw_lock_reader_unlock | g_type_depth 0.000270158 | 0.000195000 | 0.000001512 | 129 | g_static_rw_lock_writer_lock | g_type_set_qdata 0.000210584 | 0.000152000 | 0.000002452 | 62 | g_static_rw_lock_writer_unlock | g_type_register_dynamic 0.000209199 | 0.000151000 | 0.000001302 | 116 | g_static_rw_lock_reader_lock | g_type_depth 0.000134386 | 0.000097000 | 0.000001565 | 62 | g_static_rw_lock_writer_lock | g_type_register_dynamic 0.000063729 | 0.000046000 | 0.000002300 | 20 | g_static_rw_lock_writer_unlock | g_type_register_fundamental 0.000041563 | 0.000030000 | 0.000001500 | 20 | g_static_rw_lock_writer_lock | g_type_register_fundamental 0.000027708 | 0.000020000 | 0.000002500 | 8 | g_static_rw_lock_writer_unlock | type_iface_vtable_init_Wm 0.000026323 | 0.000019000 | 0.000002375 | 8 | g_static_rw_lock_writer_lock | type_iface_vtable_init_Wm 0.000026323 | 0.000019000 | 0.000002375 | 8 | g_static_rw_lock_writer_unlock | g_type_add_interface_static 0.000016625 | 0.000012000 | 0.000001500 | 8 | g_static_rw_lock_writer_lock | g_type_add_interface_static 0.000008313 | 0.000006000 | 0.000003000 | 2 | g_static_rw_lock_writer_unlock | g_type_interface_add_prerequisite 0.000006927 | 0.000005000 | 0.000002500 | 2 | g_static_rw_lock_reader_unlock | g_type_children 0.000005542 | 0.000004000 | 0.000002000 | 2 | g_static_rw_lock_reader_lock | g_type_children 0.000002771 | 0.000002000 | 0.000001000 | 2 | g_static_rw_lock_writer_lock | g_type_interface_add_prerequisite Uni processor system, Athlon, 800MHz: Total time accounted: 77.126328 Profiler timing device: Pentium(R) RDTSC - CPU clock cycle counter Percentage | Total | Average | # Calls | Function | Caller 0.519038064 | 0.400314998 | 0.000000781 | 512445 | g_static_rw_lock_reader_unlock | g_type_check_instance_cast 0.455079024 | 0.350985739 | 0.000000751 | 467163 | g_static_rw_lock_reader_unlock | g_type_instance_is_a 0.425961181 | 0.328528217 | 0.000000641 | 512445 | g_static_rw_lock_reader_lock | g_type_check_instance_cast 0.420043196 | 0.323963892 | 0.000000575 | 563199 | g_static_rw_lock_reader_unlock | g_type_value_table_peek 0.405751850 | 0.312941501 | 0.000000556 | 563199 | g_static_rw_lock_reader_lock | g_type_value_table_peek 0.400426792 | 0.308834479 | 0.000000152 | 2028379 | g_static_rw_lock_signal | check_derivation_U 0.339956015 | 0.262195590 | 0.000000561 | 467163 | g_static_rw_lock_reader_lock | g_type_instance_is_a 0.140960502 | 0.108717659 | 0.000000628 | 173177 | g_static_rw_lock_reader_lock | g_type_check_value 0.132415824 | 0.102127462 | 0.000000590 | 173177 | g_static_rw_lock_reader_unlock | g_type_check_value 0.119822862 | 0.092414973 | 0.000000703 | 131503 | g_static_rw_lock_reader_unlock | g_type_is_a 0.086537325 | 0.066743061 | 0.000000508 | 131503 | g_static_rw_lock_reader_lock | g_type_is_a 0.072067776 | 0.055583229 | 0.000000862 | 64458 | g_static_rw_lock_reader_lock | g_type_check_instance 0.051596296 | 0.039794328 | 0.000000617 | 64458 | g_static_rw_lock_reader_unlock | g_type_check_instance 0.033845828 | 0.026104044 | 0.000000561 | 46571 | g_static_rw_lock_reader_unlock | g_type_parent 0.026979792 | 0.020808523 | 0.000000447 | 46571 | g_static_rw_lock_reader_lock | g_type_parent 0.015541072 | 0.011986258 | 0.000000687 | 17445 | g_static_rw_lock_reader_lock | g_type_create_instance 0.013246697 | 0.010216691 | 0.000000586 | 17445 | g_static_rw_lock_reader_unlock | g_type_create_instance 0.012243646 | 0.009443074 | 0.000000559 | 16905 | g_static_rw_lock_reader_unlock | g_type_check_class_cast 0.010926277 | 0.008427037 | 0.000000498 | 16905 | g_static_rw_lock_reader_lock | g_type_check_class_cast 0.009658661 | 0.007449370 | 0.000000568 | 13108 | g_static_rw_lock_reader_lock | g_type_check_flags 0.009359810 | 0.007218878 | 0.000000551 | 13108 | g_static_rw_lock_reader_unlock | g_type_check_flags 0.008737618 | 0.006739004 | 0.000000621 | 10852 | g_static_rw_lock_writer_unlock | g_type_class_ref 0.008407058 | 0.006484055 | 0.000000597 | 10852 | g_static_rw_lock_writer_lock | g_type_class_ref 0.008067914 | 0.006222486 | 0.000000659 | 9448 | g_static_rw_lock_writer_lock | g_type_class_unref 0.007458380 | 0.005752374 | 0.000000609 | 9448 | g_static_rw_lock_writer_unlock | g_type_class_unref 0.005925985 | 0.004570494 | 0.000000549 | 8323 | g_static_rw_lock_reader_unlock | g_type_name 0.004733235 | 0.003650571 | 0.000000439 | 8323 | g_static_rw_lock_reader_lock | g_type_name 0.004678568 | 0.003608408 | 0.000000152 | 23797 | g_static_rw_lock_signal | g_type_init_with_debug_flags 0.003647046 | 0.002812832 | 0.000000587 | 4792 | g_static_rw_lock_reader_unlock | g_type_free_instance 0.002797098 | 0.002157299 | 0.000000450 | 4792 | g_static_rw_lock_reader_lock | g_type_free_instance 0.002370964 | 0.001828638 | 0.000004549 | 402 | g_static_rw_lock_reader_lock | check_derivation_U 0.002208993 | 0.001703715 | 0.000000566 | 3010 | g_static_rw_lock_reader_unlock | g_type_class_peek 0.001898361 | 0.001464136 | 0.000000486 | 3010 | g_static_rw_lock_reader_lock | g_type_class_peek 0.001085968 | 0.000837567 | 0.000000574 | 1459 | g_static_rw_lock_reader_unlock | g_type_from_name 0.001023943 | 0.000789730 | 0.000000556 | 1420 | g_static_rw_lock_reader_unlock | g_type_class_is_a 0.000935919 | 0.000721840 | 0.000000508 | 1420 | g_static_rw_lock_reader_lock | g_type_class_is_a 0.000890826 | 0.000687061 | 0.000000576 | 1192 | g_static_rw_lock_reader_unlock | g_type_interface_peek 0.000820004 | 0.000632439 | 0.000000433 | 1459 | g_static_rw_lock_reader_lock | g_type_from_name 0.000797523 | 0.000615100 | 0.000000563 | 1093 | g_static_rw_lock_writer_unlock | g_type_create_instance 0.000701877 | 0.000541332 | 0.000000454 | 1192 | g_static_rw_lock_reader_lock | g_type_interface_peek 0.000602075 | 0.000464359 | 0.000000425 | 1093 | g_static_rw_lock_writer_lock | g_type_create_instance 0.000506390 | 0.000390560 | 0.000000593 | 659 | g_static_rw_lock_writer_unlock | g_type_free_instance 0.000411779 | 0.000317590 | 0.000000482 | 659 | g_static_rw_lock_writer_lock | g_type_free_instance 0.000389884 | 0.000300703 | 0.000000629 | 478 | g_static_rw_lock_reader_lock | g_type_get_qdata 0.000340988 | 0.000262991 | 0.000000550 | 478 | g_static_rw_lock_reader_unlock | g_type_get_qdata 0.000308633 | 0.000238037 | 0.000000700 | 340 | g_static_rw_lock_writer_unlock | g_type_register_static 0.000300548 | 0.000231802 | 0.000000577 | 402 | g_static_rw_lock_reader_unlock | check_derivation_U 0.000297536 | 0.000229479 | 0.000001088 | 211 | g_static_rw_lock_reader_lock | g_type_class_peek_parent 0.000296845 | 0.000228945 | 0.000000589 | 389 | g_static_rw_lock_reader_unlock | type_class_init_Wm 0.000281638 | 0.000217217 | 0.000000572 | 380 | g_static_rw_lock_reader_unlock | type_data_finalize_class_U 0.000279387 | 0.000215481 | 0.000000554 | 389 | g_static_rw_lock_writer_unlock | type_class_init_Wm 0.000276736 | 0.000213436 | 0.000000562 | 380 | g_static_rw_lock_writer_unlock | type_data_last_unref_Wm 0.000253345 | 0.000195396 | 0.000000575 | 340 | g_static_rw_lock_writer_lock | g_type_register_static 0.000245931 | 0.000189678 | 0.000000488 | 389 | g_static_rw_lock_writer_lock | type_class_init_Wm 0.000245289 | 0.000189182 | 0.000000486 | 389 | g_static_rw_lock_reader_lock | type_class_init_Wm 0.000214406 | 0.000165363 | 0.000000435 | 380 | g_static_rw_lock_writer_lock | type_data_last_unref_Wm 0.000212198 | 0.000163660 | 0.000000431 | 380 | g_static_rw_lock_reader_lock | type_data_finalize_class_U 0.000176926 | 0.000136456 | 0.000000707 | 193 | g_static_rw_lock_writer_unlock | g_type_class_ref 0.000165593 | 0.000127716 | 0.000000597 | 214 | g_static_rw_lock_writer_unlock | g_type_init_with_debug_flags 0.000161650 | 0.000124675 | 0.000000540 | 231 | g_static_rw_lock_reader_unlock | g_type_interfaces 0.000151888 | 0.000117146 | 0.000000555 | 211 | g_static_rw_lock_reader_unlock | g_type_class_peek_parent 0.000147421 | 0.000113700 | 0.000000531 | 214 | g_static_rw_lock_writer_lock | g_type_init_with_debug_flags 0.000141134 | 0.000108851 | 0.000000564 | 193 | g_static_rw_lock_writer_lock | g_type_class_ref 0.000127862 | 0.000098616 | 0.000000427 | 231 | g_static_rw_lock_reader_lock | g_type_interfaces 0.000114253 | 0.000088119 | 0.000001421 | 62 | g_static_rw_lock_writer_lock | g_type_register_dynamic 0.000092390 | 0.000071257 | 0.000000552 | 129 | g_static_rw_lock_writer_unlock | g_type_set_qdata 0.000081166 | 0.000062600 | 0.000000540 | 116 | g_static_rw_lock_reader_unlock | g_type_depth 0.000070950 | 0.000054721 | 0.000000424 | 129 | g_static_rw_lock_writer_lock | g_type_set_qdata 0.000064066 | 0.000049412 | 0.000000426 | 116 | g_static_rw_lock_reader_lock | g_type_depth 0.000048415 | 0.000037341 | 0.000000602 | 62 | g_static_rw_lock_writer_unlock | g_type_register_dynamic 0.000042168 | 0.000032522 | 0.000001626 | 20 | g_static_rw_lock_writer_unlock | g_type_register_fundamental 0.000012823 | 0.000009890 | 0.000000495 | 20 | g_static_rw_lock_writer_lock | g_type_register_fundamental 0.000007342 | 0.000005662 | 0.000000708 | 8 | g_static_rw_lock_writer_unlock | g_type_add_interface_static 0.000006664 | 0.000005140 | 0.000000643 | 8 | g_static_rw_lock_writer_unlock | type_iface_vtable_init_Wm 0.000006555 | 0.000005056 | 0.000000632 | 8 | g_static_rw_lock_writer_lock | type_iface_vtable_init_Wm 0.000004328 | 0.000003338 | 0.000000417 | 8 | g_static_rw_lock_writer_lock | g_type_add_interface_static 0.000004267 | 0.000003291 | 0.000001645 | 2 | g_static_rw_lock_reader_unlock | g_type_children 0.000003168 | 0.000002443 | 0.000001222 | 2 | g_static_rw_lock_writer_unlock | g_type_interface_add_prerequisite 0.000002974 | 0.000002293 | 0.000001147 | 2 | g_static_rw_lock_reader_lock | g_type_children 0.000001083 | 0.000000835 | 0.000000418 | 2 | g_static_rw_lock_writer_lock | g_type_interface_add_prerequisite > > Regards, > Owen > --- ciaoTJ
Attachment:
toyprof-0.1.tar.gz
Description: Profiler Toy