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)
BEFORE:
Profile of test.pl for 5246s, executing 533397042 statements and 183082682 subroutine calls in 342 source files and 80491 string evals.
| Calls | P | F | Exclusive Time |
Inclusive Time |
Subroutine |
|---|---|---|---|---|---|
| 118331 | 1 | 2 | 573s | 573s | DBI::st::execute (xsub) |
| 18740893 | 5 | 1 | 200s | 280s | DBIx::Class::ResultSource::_columns |
| 8119393 | 93 | 93 | 198s | 247s | Class::Accessor::Grouped::get_inherited |
| 3250960 | 1 | 1 | 158s | 380s | SQL::Abstract::_quote |
| 28352404 | 27 | 27 | 126s | 126s | Class::Accessor::Grouped::get_simple |
| 5354668 | 4 | 1 | 121s | 404s | SQL::Abstract::_SWITCH_refkind |
| 4637845 | 6 | 4 | 113s | 318s | DBIx::Class::ResultSource::column_info |
| 111161 | 1 | 1 | 112s | 296s | SQL::Abstract::_insert_values |
| 5487339 | 1 | 1 | 107s | 124s | SQL::Abstract::_refkind |
| 5487339 | 2 | 1 | 94.7s | 219s | SQL::Abstract::_try_refkind |
| 4827092 | 8 | 5 | 71.8s | 395s | DBIx::Class::ResultSourceProxy::has_column |
| 3250960 | 6 | 3 | 66.1s | 447s | DBIx::Class::SQLAHacks::_quote |
| 118331 | 2 | 1 | 57.3s | 287s | DBIx::Class::Storage::DBI::source_bind_attributes |
| 4827274 | 3 | 2 | 55.4s | 131s | DBIx::Class::ResultSource::has_column |
| 133641 | 1 | 1 | 52.2s | 561s | DBIx::Class::Row::new |
AFTER:
Profile of test.pl for 3466s, executing 328628699 statements and 133802224 subroutine calls in 345 source files and 80406 string evals.
| Calls | P | F | Exclusive Time |
Inclusive Time |
Subroutine |
|---|---|---|---|---|---|
| 118331 | 1 | 2 | 304s | 304s | DBI::st::execute (xsub) |
| 8119393 | 93 | 93 | 198s | 246s | Class::Accessor::Grouped::get_inherited |
| 111161 | 1 | 1 | 111s | 270s | SQL::Abstract::_insert_values |
| 4637845 | 6 | 4 | 103s | 134s | DBIx::Class::ResultSource::column_info |
| 3250960 | 6 | 3 | 78.1s | 82.1s | SQL::Abstract::_quote |
| 4827092 | 8 | 5 | 72.0s | 330s | DBIx::Class::ResultSourceProxy::has_column |
| 118331 | 2 | 1 | 55.9s | 160s | DBIx::Class::Storage::DBI::source_bind_attributes |
| 4827274 | 3 | 2 | 54.1s | 66.4s | DBIx::Class::ResultSource::has_column |
| 118331 | 1 | 1 | 51.1s | 846s | DBIx::Class::Storage::DBI::_dbh_execute |
| 133641 | 1 | 1 | 51.1s | 470s | DBIx::Class::Row::new |
| 2103708 | 3 | 1 | 50.9s | 160s | SQL::Abstract::_SWITCH_refkind |
| 18740893 | 5 | 2 | 43.7s | 43.7s | DBIx::Class::ResultSource::_columns (xsub) |
| 2374996 | 4 | 1 | 39.3s | 213s | DBIx::Class::Row::store_column |
| 2236379 | 2 | 1 | 36.2s | 64.0s | SQL::Abstract::_try_refkind |
| 9791840 | 39 | 30 | 31.7s | 31.7s | Scalar::Util::blessed (xsub) |
Pretty good!
I blog about Perl.
Leave a comment