bug#43588: cuirass: Slow SQL queries.

bug#43588: cuirass: Slow SQL queries.

[Mathieu Othacehe]

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

bug#43588: cuirass: Slow SQL queries.

[Mathieu Othacehe]

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