Hi all, so i done some profiling and here are the results: 1. DBIx profiling:
E:\Documents\ProgramovanieProgramyAskripty\Symphaty0.4>perl -MDBIx::Pr +ofile symphaty.pl Gtk-CRITICAL **: gtk_tree_view_column_cell_layout_pack_start: assertio +n `! gtk_t ree_view_column_get_cell_info (column, cell)' failed at symphaty.pl li +ne 250. ================================================================= 2444 "SELECT me.eng_id, me.engword FROM englishword me WHERE ( engword + = ? )" Total wall clock time: 1.197475s execute --------------------------------------- Total Count : 2 Wall Clock : 1.1974750 s 0.5987375 s Cpu Time : 0.2020000 s 0.1010000 s returned 0E0 Count : 2 Wall Clock : 1.1974750 s 0.5987375 s Cpu Time : 0.2020000 s 0.1010000 s ================================================================= 2444 "SELECT me.eng_id, me.engphrase, me.skphrase, me.phrase_id FROM p +hrase me W HERE ( me.eng_id = ? )" Total wall clock time: 0.790816s execute --------------------------------------- Total Count : 1 Wall Clock : 0.7908160 s 0.7908160 s Cpu Time : 0.0160000 s 0.0160000 s returned 0E0 Count : 1 Wall Clock : 0.7908160 s 0.7908160 s Cpu Time : 0.0160000 s 0.0160000 s ================================================================= 2444 "SELECT skword.sk_id, skword.skword FROM en_to_sk me JOIN skword +meaning sk word ON skword.sk_id = me.sk_id WHERE ( me.eng_id = ? )" Total wall +clock time : 0.369762s execute --------------------------------------- Total Count : 1 Wall Clock : 0.3697620 s 0.3697620 s Cpu Time : 0.1250000 s 0.1250000 s returned 0E0 Count : 1 Wall Clock : 0.3697620 s 0.3697620 s Cpu Time : 0.1250000 s 0.1250000 s ================================================================= 2444 "SELECT me.eng_id, me.infinitive, me.past, me.participle, me.irre +gular_id F ROM irregular me WHERE ( ( infinitive = ? OR past = ? OR participle = +? ) )" T otal wall clock time: 0.102356s execute --------------------------------------- Total Count : 1 Wall Clock : 0.1023560 s 0.1023560 s Cpu Time : 0.0000000 s 0.0000000 s returned 0E0 Count : 1 Wall Clock : 0.1023560 s 0.1023560 s Cpu Time : 0.0000000 s 0.0000000 s ================================================================= 2444 "SELECT me.sk_id, me.skword FROM skwordmeaning me WHERE ( skword += ? )" T otal wall clock time: 0.071004s execute --------------------------------------- Total Count : 1 Wall Clock : 0.0710040 s 0.0710040 s Cpu Time : 0.0160000 s 0.0160000 s returned 0E0 Count : 1 Wall Clock : 0.0710040 s 0.0710040 s Cpu Time : 0.0160000 s 0.0160000 s ================================================================= 2444 "SELECT engword.eng_id, engword.engword FROM en_to_sk me JOIN en +glishword engword ON engword.eng_id = me.eng_id WHERE ( me.sk_id = ? )" Total +wall clock time: 0.004899s execute --------------------------------------- Total Count : 1 Wall Clock : 0.0048990 s 0.0048990 s Cpu Time : 0.0160000 s 0.0160000 s returned 0E0 Count : 1 Wall Clock : 0.0048990 s 0.0048990 s Cpu Time : 0.0160000 s 0.0160000 s
2. whole script profiling, most important restults:
# spent 28.7s (0ns+28.7) within Searcher::searchWord which was called +2 times, avg 14.4s/call: # 2 times (0ns+28.7s) by Searcher::search at + line 62, avg 14.4s/call sub searchWord($) { my $self = shift; my $searchedString = shift; my @word = (); my @engwords = (); my $engword; my @skwordsSet = (); my $skwordSet; my @engwordsSet = (); my $engwordSet; my @skwords = (); my $skword; if($self->{direction} eq "eng") { my @engwords = $schema->resultset('Engword')->search({engword =>search +edString}); # spent 12.8s making 1 call to DBIx::Class::ResultSet::search # spent +1.00ms making 1 call to DBIx::Class::Schema::resultset foreach $engword(@engwords){ my @skwordsSet = $engword->skwords; foreach $skwordSet(@skwordsSet){ push(@word,$skwordSet->skword); } # foreach } # foreach } # if if($self->{direction} eq "svk") { my @skwords = $schema->resultset('Skword')->search({skword => $searche +dString}); # spent 9.87s making 1 call to DBIx::Class::ResultSet::search # spent +1.00ms making 1 call to DBIx::Class::Schema::resultset foreach $skword(@skwords){ my @engwordsSet = $skword->engwords; # spent 6.07s making 1 call to MyDictionary::Schema::Skword::engwords foreach $engwordSet(@engwordsSet){ push(@word,$engwordSet->engword); # spent 0s making 4 calls to MyDictionary::Schema::Engword::engword, a +vg 0s/call } # foreach } # foreach } # if return @word; } # method searchWord
So my opinion is that queries are fast, but there is something with fetching the results. Also look at this:
# spent 21.3s (0ns+21.3) within DBIx::Class::Storage::DBI::Cursor::_db +h_all which was called 5 times, avg 4.26s/call: # 5 times (0ns+21.3s) + by DBIx::Class::Storage::DBI::dbh_do at line 547 of C:/Perl/site/lib +/DBIx/Class/Storage/DBI.pm, avg 4.26s/call sub _dbh_all { 120 30 18.8s 628ms my ($storage, $dbh, $self) = @_; 121 122 $self->_check_dbh_gen; # spent 0s making 5 calls to DBIx::Class::Storage::DBI::Cursor::_check +_dbh_gen, avg 0s/call 123 $self->{sth}->finish if $self->{sth}->{Active}; 124 delete $self->{sth}; 125 my ($rv, $sth) = $storage->_select(@{$self->{args}} +); # spent 2.46s making 5 calls to DBIx::Class::Storage::DBI::_select, av +g 492ms/call 126 return @{$sth->fetchall_arrayref}; # spent 18.8s making 5 calls to DBI::st::fetchall_arrayref, avg 3.77s/ +call 127 }
In reply to Re^1: DBIx startup slow
by anjalis
in thread DBIx startup slow
by anjalis
| For: | Use: | ||
| & | & | ||
| < | < | ||
| > | > | ||
| [ | [ | ||
| ] | ] |