Back from a fabulous Christmas holidays and I'm busy profiling some tests to find out why they're slow. Here are our top ten offenders:
time elapsed (wall): 1338.6896 time running program: 1063.1014 (79.41%) time profiling (est.): 275.5731 (20.59%) number of calls: 62524605 number of exceptions: 620 %Time Sec. #calls sec/call F name 4.89 52.0217 49746 0.001046 ? DBI::st::execute 4.78 50.8507 2166072 0.000023 Class::Accessor::Grouped::get_inherited 2.86 30.4032 6066183 0.000005 Class::Accessor::Grouped::get_simple 2.58 27.4112 290321 0.000094 DBIx::Class::ResultSet::_collapse_result 2.00 21.2111 1137080 0.000019:...5//XML/XPath/XMLParser.pm:63 1.73 18.3833 975751 0.000019 :.../perl5//Test/XML/XPath.pm:45 1.58 16.8466 761923 0.000022 DBIx::Class::ResultSourceHandle::resolve 1.57 16.6434 1049788 0.000016 :...DBIx/Class/ResultSet.pm:2106 1.42 15.0791 328238 0.000046 XML::XPath::Node::ElementImpl::DESTROY 1.40 14.9275 565934 0.000026 XML::XPath::XMLParser::parse_char
Those may be tough to work around, but we've also found this:
grep UNIVERSAL::isa prof.out 0.99 10.5302 620280 0.000017 UNIVERSAL::isa::object_or_class 0.94 10.0405 631328 0.000016 UNIVERSAL::isa 0.63 6.6978 622348 0.000011 UNIVERSAL::isa::invocant_type 0.00 0.0133 2068 0.000006 UNIVERSAL::isa::reference 0.00 0.0000 1 0.000007 UNIVERSAL::isa::import
Killing off UNIVERSAL::isa is a quick win for a bit of gain. We've enough tests that we're confident this won't hurt us.
CURRENT VERSION:
Benchmark: running get_foo, get_inherited_class, get_inherited_object, get_simple, set_foo, set_inherited_class, set_inherited_object, set_simple for at least 3 CPU seconds...
get_foo: 3 wallclock secs ( 3.01 usr + 0.02 sys = 3.03 CPU) @ 612308.25/s (n=1855294)
get_inherited_class: 3 wallclock secs ( 3.15 usr + 0.02 sys = 3.17 CPU) @ 207205.36/s (n=656841)
get_inherited_object: 3 wallclock secs ( 3.14 usr + 0.02 sys = 3.16 CPU) @ 160767.72/s (n=508026)
get_simple: 2 wallclock secs ( 3.32 usr + 0.01 sys = 3.33 CPU) @ 1446515.02/s (n=4816895)
set_foo: 2 wallclock secs ( 3.00 usr + 0.01 sys = 3.01 CPU) @ 540478.41/s (n=1626840)
set_inherited_class: 3 wallclock secs ( 3.00 usr + 0.02 sys = 3.02 CPU) @ 615212.58/s (n=1857942)
set_inherited_object: 3 wallclock secs ( 2.98 usr + 0.02 sys = 3.00 CPU) @ 597675.67/s (n=1793027)
set_simple: 4 wallclock secs ( 3.17 usr + 0.02 sys = 3.19 CPU) @ 1158235.74/s (n=3694772)
DEV VERSION:
Benchmark: running get_foo, get_inherited_class, get_inherited_object, get_simple, set_foo, set_inherited_class, set_inherited_object, set_simple for at least 3 CPU seconds...
get_foo: 4 wallclock secs ( 3.29 usr + 0.02 sys = 3.31 CPU) @ 944515.11/s (n=3126345)
get_inherited_class: 3 wallclock secs ( 3.14 usr + 0.00 sys = 3.14 CPU) @ 224126.43/s (n=703757)
get_inherited_object: 3 wallclock secs ( 3.14 usr + 0.01 sys = 3.15 CPU) @ 172029.84/s (n=541894)
get_simple: 2 wallclock secs ( 3.14 usr + 0.01 sys = 3.15 CPU) @ 2345890.48/s (n=7389555)
set_foo: 3 wallclock secs ( 3.07 usr + 0.02 sys = 3.09 CPU) @ 939491.91/s (n=2903030)
set_inherited_class: 4 wallclock secs ( 3.04 usr + 0.02 sys = 3.06 CPU) @ 779833.33/s (n=2386290)
set_inherited_object: 2 wallclock secs ( 3.02 usr + 0.01 sys = 3.03 CPU) @ 691498.35/s (n=2095240)
set_simple: 3 wallclock secs ( 3.05 usr + 0.01 sys = 3.06 CPU) @ 1785796.08/s (n=5464536)