[Dbix-class] Re: Horrendous Performance Problem

[Robert Inder]

Hi,

Thanks for replying, and sorry to have been slow to respond.

The good news is that the latest version of the DBIx::Class::Schema::Loader
performs OK.

I was reluctant to switch to the latest version, because we're trying to
keep the system working
with a stable set of packages, and I was worried that the newer version
(including
DBIx::Class::Schema::Loader 07033) was (so much) worse than the old one
(using 07015).

But some investigation revealed that the latest version (07036) did not
mention
INFORMATION_SCHEMA.  So since it was obviously working in a different way
to the problem version, I decided to just try the latest version (even
though I didn't
understand what was wrong, or why it might help) and see what happened.
And I found that performance is now reasonable.

So it looks, from my perspective, like it was 07033 that had very, very
serious performance
problems, but 07036 is OK.

On 14 September 2013 19:25, Dagfinn Ilmari Manns=E5ker <ilmari at ilmari.org>w=
rote:

>
> I'm surprised these queries take _that_ long, even with dozens of tables
> and relationships.


Indeed!  Hence the "Horrendous" in the subject line!


> Could you try running the query from _table_fk_info
> manually (both with and without the WHERE clause) in psql and see how
> long it takes? Type \timing at the psql prompt to turn on timing
> information.
>

It took about 8 seconds (for one of the larger tables)

It does this for each of the tables, with times that I think vary depending
on the
number of rows in the table, and they add up to "a good few minutes"...

There are also many other things that happen between the first
INFORMATION_SCHEMA query from _table_fk_info and the first "drop tables",
some of which take hundreds of milliseconds.

I have a verbose postgres log if it would be of  interest...


> On the schema created by the DBIx::Class::Schema::Loader test suite,
> which has 54 tables and 39 constraints, it takes about 25ms for a
> specific table, and 150ms without the where clause. This is on
> PostgreSQL 9.2.4 on my laptop. Which verson of are you running?
>
> > The version of /DBIx/Class/Schema/Loader/DBI/Pg.pm on the "fast"
> > system is 0.07015: it does not have a "_table_fk_info" function, and
> > makes no mention of INFORMATION_SCHEMA.
>
> > Can anyone shed any light on what is going on?  Why the two installatio=
ns
> > are going about things in completely different ways?
> >
> > Is the system with the newer modules trying to use a new feature that
> > is horrendously slow?  And if so, is there something I can do (e.g to
> > the database) to make it faster?
>
> The newer version of DBIx::Class::Schema::Loader extracts more
> information about foreign key constraints (specifically ON UPDATE/DELETE
> and DEFERRABLE clauses), so it runs different queries. On closer
> inspection (and by running the test suite), it seems like the
> Pg-specific _table_fk_info function is redundant, and the generic one in
> DBI.pm suffices. Can you try disabling the former (just change the name
> of the sub in DBIx/Class/Schema/Loader/DBI/Pg.pm, so the generic one is
> inherited) and see if that affects the performance?
>

I've just reverted to 0.07033 and tried that.
With 07033 as shipped, I get...
13:03] ttscore-src{master} $$ time prove t/00-deploy-test-db.t
t/00-deploy-test-db.t .. ok
All tests successful.
Files=3D1, Tests=3D82, 541 wallclock secs ( 0.03 usr  0.00 sys + 16.40 cusr
0.47 csys =3D 16.90 CPU)
Result: PASS

real    9m0.827s
user    0m16.503s
sys     0m0.485s

If I then modify DBIx/Class/Schema/Loader/DBI/Pg.pm and modify line 43 to
sub renamed_table_fk_info {
I then get
13:15] ttscore-src{master} $$ time prove t/00-deploy-test-db.t
t/00-deploy-test-db.t .. ok
All tests successful.
Files=3D1, Tests=3D82, 21 wallclock secs ( 0.03 usr  0.00 sys + 16.36 cusr
0.44 csys =3D 16.83 CPU)
Result: PASS

real    0m20.620s
user    0m16.458s
sys     0m0.453s

Finally, reinstating the latest version (0.07036) I get

13:19] ttscore-src{master} $$ time prove t/00-deploy-test-db.t
t/00-deploy-test-db.t .. ok
All tests successful.
Files=3D1, Tests=3D82, 27 wallclock secs ( 0.03 usr  0.00 sys + 16.34 cusr
0.44 csys =3D 16.81 CPU)
Result: PASS

real    0m27.608s
user    0m16.448s
sys     0m0.461s
13:20] ttscore-src{master} $$ time prove t/00-deploy-test-db.t
t/00-deploy-test-db.t .. ok
All tests successful.
Files=3D1, Tests=3D82, 20 wallclock secs ( 0.03 usr  0.01 sys + 16.34 cusr
0.40 csys =3D 16.78 CPU)
Result: PASS

real    0m20.477s
user    0m16.436s
sys     0m0.424s

So, possibly slower than the modified 0.07033, but far, far better than the
unmodified version.

Hope that helps.

Oh, and keep up the good work on this and your other CPAN packages.
It's appreciated....

Robert.


-- =

Robert Inder,                                    0131 229 1052 / 07808 492
213
Interactive Information Ltd,   3, Lauriston Gardens, Edinburgh EH3 9HH
Registered in Scotland, Company no. SC 150689
                                           Interactions speak louder than
words
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.scsys.co.uk/pipermail/dbix-class/attachments/20130917/6dc=
7096d/attachment.htm