The people that make the perl community great

Today, I ventured into #dbix-class inquiring about some performance problems I was having. I wasn’t complaining about the speed of DBIC, I was looking for ways to trim out work that I was doing that I could avoid doing. The script I was running (file parser + insert into DB) was taking a little more than an hour to run. I was musing whether to drop DBIC, parallelize the job or just deal with the slowness when* ribasushi* (Peter Rabbitson) came to the rescue. After sharing with him a copy of NYTProf’s output, he quickly identified some hot-spots in SQL::Abstract that could be worked on. Soon enough, Caelum (Rafael Kitover) chipped in and we had improvements (some XS code wasn’t being used) in Class::Accessor::Grouped coming. Within an hour I was upgrading CAG, SQLA, DBIC and installing Class::XSAccessors and profiling the code again.

Total improvement: time spent inside CAG dropped by 57% and 44% in SQLA Total time elapsed: ~2 hours.

If this is not a sign of what makes the perl community great, I don’t know what is.

The code is not flying any any means, but the total runtime was reduced by 34%, which is not bad for an evening’s work.

SQL::Abstract Changes DBIx::Class Changes

(read on for comparison of the top 15 subs)


Profile of for 5246s, executing 533397042 statements and 183082682 subroutine calls in 342 source files and 80491 string evals.

Top 15 Subroutines — ordered by exclusive time
Calls P F Exclusive
11833112573s573s DBI::st::execute (xsub)
1874089351200s280s DBIx::Class::ResultSource::_columns
81193939393198s247s Class::Accessor::Grouped::get_inherited
325096011158s380s SQL::Abstract::_quote
283524042727126s126s Class::Accessor::Grouped::get_simple
535466841121s404s SQL::Abstract::_SWITCH_refkind
463784564113s318s DBIx::Class::ResultSource::column_info
11116111112s296s SQL::Abstract::_insert_values
548733911107s124s SQL::Abstract::_refkind
54873392194.7s219s SQL::Abstract::_try_refkind
32509606366.1s447s DBIx::Class::SQLAHacks::_quote
1183312157.3s287s DBIx::Class::Storage::DBI::source_bind_attributes
48272743255.4s131s DBIx::Class::ResultSource::has_column
1336411152.2s561s DBIx::Class::Row::new


Profile of for 3466s, executing 328628699 statements and 133802224 subroutine calls in 345 source files and 80406 string evals.

Top 15 Subroutines — ordered by exclusive time
Calls P F Exclusive
11833112304s304s DBI::st::execute (xsub)
81193939393198s246s Class::Accessor::Grouped::get_inherited
11116111111s270s SQL::Abstract::_insert_values
463784564103s134s DBIx::Class::ResultSource::column_info
32509606378.1s82.1s SQL::Abstract::_quote
1183312155.9s160s DBIx::Class::Storage::DBI::source_bind_attributes
48272743254.1s66.4s DBIx::Class::ResultSource::has_column
1183311151.1s846s DBIx::Class::Storage::DBI::_dbh_execute
1336411151.1s470s DBIx::Class::Row::new
21037083150.9s160s SQL::Abstract::_SWITCH_refkind
187408935243.7s43.7s DBIx::Class::ResultSource::_columns (xsub)
23749964139.3s213s DBIx::Class::Row::store_column
22363792136.2s64.0s SQL::Abstract::_try_refkind
9791840393031.7s31.7s Scalar::Util::blessed (xsub)

Pretty good!

Leave a comment

About Guillermo Roditi

user-pic I blog about Perl.