Re: Running tests under valgrind is getting slower at an alarming pace

Hi,

On 2021-10-06 12:58:34 -0400, Tom Lane wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
> > One thing I think would really help is having the total time for each run
> > visible in an animals run history. That way we could pinpoint regressions
> > reasonably efficiently, right now that's not easily possible without writing
> > nontrivial queries to the buildfarm database...
>
> +1. I've lost count of how often I've had to drill down to an individual
> run just because I wanted to see how long it took. If we could fit that
> into the branch history pages like

I queried this in the DB for skink using

select snapshot::date, substring(git_head_ref, 1, 12) as git_rev, (SELECT SUM(stage_duration) FROM build_status_log_raw bslr WHERE bslr.sysname = bsr.sysname AND bslr.snapshot = bsr.snapshot) FROM build_status_raw bsr WHERE branch = 'HEAD' AND sysname = 'skink' and stage = 'OK' AND snapshot > '2021-01-01' order by snapshot desc;

snapshot | git_rev | sum
------------+--------------+----------
2021-10-06 | ec2133a44731 | 12:09:17
2021-10-05 | 0266e98c6b86 | 10:55:10
2021-10-03 | 2903f1404df3 | 10:24:11
2021-09-30 | 20f8671ef69b | 10:31:43
...
2021-06-14 | 2d689babe3cb | 10:29:07
2021-06-12 | f452aaf7d4a9 | 10:26:12
2021-06-11 | d08237b5b494 | 10:50:53
2021-06-09 | 845cad4d51cb | 10:58:31
2021-06-08 | eab81953682d | 09:06:35
2021-06-06 | a2dee328bbe5 | 09:02:36
2021-06-05 | e6159885b78e | 08:59:14
2021-06-03 | 187682c32173 | 09:39:07
2021-06-02 | df466d30c6ca | 09:03:05
2021-06-03 | 187682c32173 | 09:39:07
2021-06-02 | df466d30c6ca | 09:03:05
2021-05-31 | 7c544ecdad81 | 09:09:42
2021-05-30 | ba356a397de5 | 08:54:29
2021-05-28 | d69fcb9caef1 | 09:00:36
2021-05-27 | 388e75ad3348 | 09:39:14
2021-05-25 | e30e3fdea873 | 08:51:04
2021-05-24 | 99c5852e20a0 | 08:57:08
...
2021-03-23 | 1e3e8b51bda8 | 09:19:40
2021-03-21 | 96ae658e6238 | 08:29:05
2021-03-20 | 61752afb2640 | 08:15:47
2021-03-18 | da18d829c281 | 08:34:02
2021-03-17 | 6b67d72b604c | 09:11:46
2021-03-15 | 146cb3889c3c | 08:20:21
2021-03-14 | 58f57490facd | 08:06:07
2021-03-12 | d60e61de4fb4 | 08:41:12
2021-03-11 | 3f0daeb02f8d | 08:04:44
2021-03-08 | 8a812e5106c5 | 08:46:01
2021-03-07 | f9a0392e1cf3 | 08:01:47
2021-03-05 | 0ce4cd04da55 | 08:01:32
2021-03-04 | 040af779382e | 07:56:31
2021-03-02 | 5b2f2af3d9d5 | 08:20:50
2021-03-01 | f5a5773a9dc4 | 07:59:14
...
2021-01-02 | 4d3f03f42227 | 08:14:41
2021-01-01 | 32d6287d2eef | 07:31:56

It's not too surprising that 2021-10-06 is slower, I yesterday changed things
so that more valgrind runs are done in parallel (increasing individual test
times, but still allowing to get results faster than testing 1-by-1).

I don't see anything immediately suspicious for the slowdowns around
eab81953682d. Perhaps there was a system update at that time causing
changes. Unfortunately I don't have logs from back then anymore. OTOH, I don't
see a clear slowdown in 13, 12 around that time.

Greetings,

Andres Freund