This task was made more difficult by my inability to get Devel::DProf working in Mac OS X (see my posts to the mod_perl and [EMAIL PROTECTED] lists), so I had to resort to the use of Time::HiRes and a smattering of calls to my own simple timer routines. I eventually narrowed the time-suck down to a loop that looked something like this:
# bind columns to %row here
while($sth->fetch)
{
push(@widgets, Widget->new(%row));
}Now I suspected some sort of DBI issue, so I replaced the loop body with a no-op. Suddenly, the request completed in one second or less. Now I suspected my Widget class, and benchmarked its constructor offline. (The constructor just calls $self->$key($value) for each k/v pair in %row.) This eventually led me to find that setting the date fields in the Widget object was the culprit.
I use DateTime objects for my internal date representation, but I have a set of wrapper functions that hide this fact. Now I suspected that my date parsing wrapper code was the problem, so I replaced my parse function's body with a simple call to DateTime->now. The request became slow again, taking several seconds to complete.
There was no avoiding it: the bottleneck for my web app was not the database, not HTML::Mason, not my object classes, not even my date parsing code, but DateTime object creation! (Perl 5.8, latest DateTime from CPAN.)
My quick fix was to make sure that %row only contains a single date field, rather than the four that each object has when "completely filled out." This produced a noticeable (~2x) speed increase for the whole request.
Sorry to provide so many gory details, but I wanted to try to establish exactly how I'm using DateTime, and how its performance came to my attention in the first place. I benchmarked DateTime's object creation speed against a few random classes, just to get a feel for where it stands:
CGI->new(''): 5 wallclock secs @ 1869.16/s
(5.25 usr + 0.10 sys = 5.35 CPU)Date::Manip::ParseDate('now'): 49 wallclock secs @ 223.81/s
(44.44 usr 0.24 sys + 0.01 cusr 0.01 csys = 44.70 CPU)Date::Simple->new('2003-01-01'): 2 wallclock secs @ 4273.50/s
(2.31 usr + 0.03 sys = 2.34 CPU)# "..." includes args: year, month, day, hour, minute, second DateTime->new(...): 16 wallclock secs @ 687.29/s (14.48 usr + 0.07 sys = 14.55 CPU)
DateTime->now(): 21 wallclock secs @ 547.95/s (18.13 usr + 0.12 sys = 18.25 CPU)
DateTime does well against Date::Manip, but not so well against even a "big" module like CGI. But for object creation alone, should it really be ~5x as slow as Date::Simple?
My final step was to profile 10,000 calls to DateTime->new(...) using Devel::DProf (which works from the command line in OS X). dprofpp had this to say:
Total Elapsed Time = 19.91729 Seconds
User+System Time = 14.60729 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
27.6 4.035 4.685 20274 0.0002 0.0002 Params::Validate::_validate
24.0 3.510 17.549 10000 0.0004 0.0018 DateTime::new
18.9 2.770 3.809 10001 0.0003 0.0004 DateTime::Locale::_load_class_from
_id
8.96 1.309 2.647 10020 0.0001 0.0003 DateTime::TimeZone::BEGIN
6.44 0.940 1.030 10001 0.0001 0.0001 DateTime::Locale::Base::new
6.23 0.910 1.190 10002 0.0001 0.0001 DateTime::_calc_local_components
4.45 0.650 0.650 50000 0.0000 0.0000 DateTime::__ANON__
3.90 0.570 1.009 10002 0.0001 0.0001 DateTime::_calc_utc_rd
2.88 0.420 0.490 10000 0.0000 0.0000 DateTime::_last_day_of_month
2.67 0.390 0.399 10006 0.0000 0.0000 DateTime::TimeZone::Floating::BEGI
N
2.40 0.350 1.619 10002 0.0000 0.0002 DateTime::_calc_local_rd
1.92 0.280 0.299 10001 0.0000 0.0000 DateTime::DefaultLocale
1.64 0.240 0.240 30006 0.0000 0.0000 DateTime::TimeZone::Floating::is_f
loating
1.51 0.220 0.220 10000 0.0000 0.0000 DateTime::_rd2ymd
1.37 0.200 4.009 10001 0.0000 0.0004 DateTime::Locale::load
These numbers confuse me a bit, because I'm only creating about 30 Widget objects in my mod_perl request, not 10,000. But I see a very significant speed hit, even if I replace my entire Widget->new() call with a simple call to DateTime->new(). Maybe it's some sort of mod_perl/DateTime interaction?
Anyway, I don't want to get sidetracked into mod_perl stuff. I'm not sure what (else) to make of the results above, other than a possible wish that I could "turn off" Params::Validate's validation in certain performance-critical situations.
So, what does everyone else think of the object creation performance situation? Is it simply "good enough" to be "3x faster that Date::Manip::ParseDate()"? Are there any obvious areas that I should consider before I start mucking around with DateTime::new()?
-John
