Re: Very slow SQLite driver

On a non-ancient machine I would have expected the overhead from perl to be less than half a second, more likely even less than 0.1s.

There are many possible reasons I can think of. For example the Perl installation (or one of the modules) could be on a slow NFS mount, or an otherwise very slow file system. Or Perl's module search path contains such a slow file system, so the mere search of a module makes the Perl thing slow.

My first attempt at diagnosing would be to run

strace perl testdb.pl
[download]

Maybe you can already see which system call takes so much time.

If not, install Devel::NYTProf, and follow the instructions for profiling a script, and tell us which routines have the highest exclusive run times.

Perl 6 - second systems done right

Comment on Re: Very slow SQLite driver Download Code

Replies are listed 'Best First'.
Re^2: Very slow SQLite driver by raschu (Initiate) on Aug 13, 2011 at 06:04 UTC
Thank you! Here is a output of Devel::NYTProf: Profile of testdb.pl for 6.46s (of 6.47s), executing 1879 statements a +nd 610 subroutine calls in 21 source files and 3 string evals. Top 15 Subroutines Calls P F Exclusive Time Inclusive Time Subroutine 2 2 2 6.39s 6.39s DBI::st::execute (xsub) 2 1 1 19.1ms 19.1ms DynaLoader::CORE:ftsize (op +code) 1 1 1 16.0ms 53.1ms main::BEGIN@1 6 1 1 8.95ms 8.95ms DBI::st::fetchrow_array +(xsub) 1 1 1 4.61ms 9.37ms DBI::install_driver 1 1 1 2.79ms 7.47ms DBI::BEGIN@157 1 1 1 2.61ms 2.82ms Config::AUTOLOAD 1 1 1 2.32ms 2.39ms Exporter::Heavy::BEGIN@186 1 1 1 1.86ms 4.34ms Exporter::as_heavy 1 1 1 1.33ms 1.33ms DBI::BEGIN@156 1 1 1 1.05ms 1.65ms DBD::SQLite::BEGIN@30 1 1 1 801盜 25.2ms DBI::BEGIN@160 1 1 1 726盜 1.40ms DynaLoader::BEGIN@24 3 3 3 617盜 682盜 warnings::register::import 104 2 1 596盜 596盜 DBI::_install_method + (xsub) [download] and `# spent 6.39s within DBI::st::execute which was called 2 times, avg 3. +19s/call: # once (6.39s+0s) by main::RUNTIME at line 8 # once (18盜+0s) by DBD::SQLite::db::do at line 206 of DBD/SQLite.p +m sub DBI::st::execute; # xsub` [download] Only "DBI::st::execute" is slow, the rest is o.k. You can download the whole report on http://dl.dropbox.com/u/61444/temp/nytprof.zip	[reply] [d/l] [select]

Replies are listed 'Best First'.

Re^2: Very slow SQLite driver
by raschu (Initiate) on Aug 13, 2011 at 06:04 UTC


Profile of testdb.pl for 6.46s (of 6.47s), executing 1879 statements a
+nd 610 subroutine calls in 21 source files and 3 string evals.
Top 15 Subroutines
Calls    P    F    Exclusive
Time    Inclusive
Time    Subroutine
2    2    2    6.39s    6.39s               DBI::st::execute (xsub)
2    1    1    19.1ms    19.1ms            DynaLoader::CORE:ftsize (op
+code)
1    1    1    16.0ms    53.1ms                  main::BEGIN@1
6    1    1    8.95ms    8.95ms               DBI::st::fetchrow_array 
+(xsub)
1    1    1    4.61ms    9.37ms                   DBI::install_driver
1    1    1    2.79ms    7.47ms                   DBI::BEGIN@157
1    1    1    2.61ms    2.82ms                Config::AUTOLOAD
1    1    1    2.32ms    2.39ms       Exporter::Heavy::BEGIN@186
1    1    1    1.86ms    4.34ms              Exporter::as_heavy
1    1    1    1.33ms    1.33ms                   DBI::BEGIN@156
1    1    1    1.05ms    1.65ms           DBD::SQLite::BEGIN@30
1    1    1    801盜    25.2ms                   DBI::BEGIN@160
1    1    1    726盜    1.40ms            DynaLoader::BEGIN@24
3    3    3    617盜    682盜    warnings::register::import
104    2    1    596盜    596盜                   DBI::_install_method
+ (xsub)
[download]

# spent 6.39s within DBI::st::execute which was called 2 times, avg 3.
+19s/call:
#    once (6.39s+0s) by main::RUNTIME at line 8
#    once (18盜+0s) by DBD::SQLite::db::do at line 206 of DBD/SQLite.p
+m
sub DBI::st::execute; # xsub
[download]

[reply]
[d/l]
[select]