Hey folks.
Here at Yahoo! we write a fair amount of perl code, and I've been working on a moderately sized project that is near to shipping.
The main process of the project uses OIO for a couple of its foundation working classes, and that process is showing performance issues.
So I did some profiling with Devel::Profile and found some interesting results.
The profiled test code in question creates 50,001 OIO objects by parsing 50,001 lines of text, returning an OIO object for each line.
The top 5 results reported by Devel::Profile were:
time elapsed (wall): 1524.4849
time running program: 1490.9677 (97.80%)
time profiling (est.): 33.5172 (2.20%)
number of calls: 6252142
%Time Sec. #calls sec/call F name
91.89 1370.0146 100002 0.013700 Object::InsideOut::_ID
2.44 36.4517 150003 0.000243 <anon>:.../Yggdrasil/Classifier.pm:146
1.08 16.0312 1300033 0.000012 Object::InsideOut::Util::hash_re
0.63 9.3990 300006 0.000031 Object::InsideOut::set
0.47 7.0407 50001 0.000141 Yahoo::Yggdrasil::Classifier::parse_entity
At first, I didn't believe these results, so I ran another experiment that removed OIO from the equation.
My Classifier::parse_entity() method parses the line, builds up a hash of parameters for the constructor, and returns an object as the last line by calling
(this call to new is on line Classifer.pm:146, which shows up as the second line in the profiling output).
So I removed OIO from the equation by commenting out the call to new, and ran the experiment again.
The top 5 results were:
time elapsed (wall): 36.3511
time running program: 28.6448 (78.80%)
time profiling (est.): 7.7063 (21.20%)
number of calls: 1451844
%Time Sec. #calls sec/call F name
23.96 6.8634 50001 0.000137 Yahoo::Yggdrasil::Classifier::parse_entity
14.51 4.1571 50001 0.000083 Yahoo::Yggdrasil::Classifier::_parse_rule
8.75 2.5075 50001 0.000050 Regexp::Common::_decache
8.74 2.5042 50001 0.000050 Yahoo::Yggdrasil::Classifier::_parse_line
6.79 1.9455 400004 0.000005 Yahoo::Yggdrasil::Classifier::_decode_entity_part
N.B. that the total run time went from 1,524 seconds to 36 seconds.
I still didn't believe it, so I ran the same experiment without the profiler involved, just measuring the wall clock time with and without the call to new().
The results were 5 minutes 2 seconds with OIO, and 9.8 seconds without OIO.
Additionally, I observed that a significant portion of the test time
appeared to be consumed during the DESTROY phase, deleting the 50,001
objects.
I conclude that there is a significant performance penalty using OIO when there are thousands of objects being created and destroyed.
First of all, are these surprising results to OIO gurus?
Second, what can be done to minimize the impact of id handling in OIO?
I've read the advice in the "Special Processing" section of the OIO pod; I guess I am not too anxious to go hacking around with object identity issues in the absence of some guidance from those in the know.
At this point, I am looking at ways to remove OIO from being invoked
thousands of times, and I'm considering doing an experiment with
Class::Std to see if it has this kind of performance issue with
tens of thousands of objects.
Any guidance greatly appreciated.
(2)
]
