GNU bug report logs - #43588
cuirass: Slow SQL queries.

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 43588 in the body.
You can then email your comments to 43588 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Mathieu Othacehe <othacehe <at> gnu.org>
To: bug-guix <at> gnu.org
Subject: cuirass: Slow SQL queries.
Date: Thu, 24 Sep 2020 13:49:11 +0200

Hello,

I just added SQL queries logging to Cuirass. I also adapted the Guix
shepherd service accordingly and deployed it on berlin.

The results are already interesting:

--8<---------------cut here---------------start------------->8---
SELECT E.id, E.status, E.timestamp, E.checkouttime, E.evaltime, B.total, B.succeeded, B.failed, B.scheduled FROM (SELECT id, status, timestamp, checkouttime, evaltime FROM Evaluations WHERE (id='16009' )) E LEFT JOIN (SELECT rowid, evaluation, SUM(status=0) as succeeded, SUM(status>0) as failed, SUM(status<0) as scheduled, SUM(status>-100) as total FROM Builds GROUP BY evaluation) B ON B.evaluation=E.id ORDER BY E.id ASC 95.38
SELECT E.id, E.status, E.timestamp, E.checkouttime, E.evaltime, B.total, B.succeeded, B.failed, B.scheduled FROM (SELECT id, status, timestamp, checkouttime, evaltime FROM Evaluations WHERE (id='5407' )) E LEFT JOIN (SELECT rowid, evaluation, SUM(status=0) as succeeded, SUM(status>0) as failed, SUM(status<0) as scheduled, SUM(status>-100) as total FROM Builds GROUP BY evaluation) B ON B.evaluation=E.id ORDER BY E.id ASC 65.88
SELECT E.id, E.status, E.timestamp, E.checkouttime, E.evaltime, B.total, B.succeeded, B.failed, B.scheduled FROM (SELECT id, status, timestamp, checkouttime, evaltime FROM Evaluations WHERE (id='8255' )) E LEFT JOIN (SELECT rowid, evaluation, SUM(status=0) as succeeded, SUM(status>0) as failed, SUM(status<0) as scheduled, SUM(status>-100) as total FROM Builds GROUP BY evaluation) B ON B.evaluation=E.id ORDER BY E.id ASC 86.23
--8<---------------cut here---------------end--------------->8---

Those three queries that originate from "db-get-evaluation-summary"
procedure take more than 1 minute to run (65.88, 86.23 and 95.38
seconds). Even if concurrent database reading is permitted, the number
of database workers is finite and some of the observed infamous "504"
errors are the result of database worker starvation.

If you want to help me optimize those queries, you can have a look to
"/var/log/cuirass-sql.log" and "/var/log/cuirass-web-sql.log" on berlin,
or request those files.

Thanks,

Mathieu

-- 
https://othacehe.org

Message #10 received at 43588-done <at> debbugs.gnu.org (full text, mbox):

From: Mathieu Othacehe <othacehe <at> gnu.org>
To: 43588-done <at> debbugs.gnu.org
Subject: Re: bug#43588: cuirass: Slow SQL queries.
Date: Mon, 28 Sep 2020 18:02:21 +0200

Hello,

> SELECT E.id, E.status, E.timestamp, E.checkouttime, E.evaltime, B.total, B.succeeded, B.failed, B.scheduled FROM (SELECT id, status, timestamp, checkouttime, evaltime FROM Evaluations WHERE (id='8255' )) E LEFT JOIN (SELECT rowid, evaluation, SUM(status=0) as succeeded, SUM(status>0) as failed, SUM(status<0) as scheduled, SUM(status>-100) as total FROM Builds GROUP BY evaluation) B ON B.evaluation=E.id ORDER BY E.id ASC 86.23

Turns out those queries are really slow because they are doing full
scans of the Builds table. Using "EXPLAIN QUERY PLAN" shows that this is
caused by the "GROUP BY" in the "B" sub-query.

Running the above query takes around 3 seconds right now. I think that
it took 86.23 seconds because the WAL file contained a lot of
temporary data, slowing down the whole query. I ran a "PRAGMA
wal_checkpoint(FULL)" as those queries were started to slow down and
observed an immediate improvement.

Anyway, the real problem here is just highlighted by the WAL file
usage. Those queries can really go faster.

I rewrote them and added a few indexes with
0ffcb80ebbaa2b177f03548035a2ef21ae7ac41d. They now take less than 1ms,
which should very much improve the web browsing experience as well as
decrease the database worker starvation.

Thanks,

Mathieu
-- 
https://othacehe.org

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.