performance regression when filling in a table

Hi,

On 2019-04-30 07:12:03 +0200, Fabien COELHO wrote:

On my SSD Ubuntu laptop, with postgres-distributed binaries and unmodified
default settings using local connections:

## pg 11.2

time pgbench -i -s 100

...
done in 31.51 s
# (drop tables 0.00 s, create tables 0.01 s, generate 21.30 s, vacuum 3.32 s, primary keys 6.88 s).
# real 0m31.524s

## pg 12devel (cd3e2746)

time pgbench -i -s 100

# done in 38.68 s
# (drop tables 0.00 s, create tables 0.02 s, generate 29.70 s, vacuum 2.92 s, primary keys 6.04 s).
real 0m38.695s

That is an overall +20% regression, and about 40% on the generate phase
alone. This is not a fluke, repeating the procedure shows similar results.

Is it the same for other people out there, or is it only something related
to my setup?

What change could explain such a significant performance regression?

I think the pre-release packages have had assertions enabled at some
point. I suggest checking that. If it's not that, profiles would be
helpful.

Greetings,

Andres Freund

Hello Andres,

## pg 11.2 done in 31.51 s
## pg 12devel (cd3e2746) real 0m38.695s

What change could explain such a significant performance regression?

I think the pre-release packages have had assertions enabled at some
point. I suggest checking that. If it's not that, profiles would be
helpful.

Thanks for the pointer.

After some more tests based on versions compiled from sources, the
situation is different, and I was (maybe) mostly identifying another
effect not related to postgres version.

The effect is that the first generation seems to take more time, but
dropping the table and regenerating again much less, with a typical 40%
performance improvement between first and second run, independently of the
version. The reported figures above where comparisons between first for
pg12 and second or later for pg11.

So I was wrong, there is no significant performance regression per se,
the two versions behave mostly the same.

I'm interested if someone has an explanation about why the first run is so
bad or others are so good. My wide guess is that there is some space reuse
under the hood, although I do not know enough about the details to
confirm.

A few relatively bad news nevertheless:

Performances are quite unstable, with index generation on the same scale
100 data taking anything from 6 to 15 seconds over runs.

Doing a VACUUM and checksums interact badly: vacuum time jumps from 3
seconds to 30 seconds:-(

--
Fabien.

Hi,

On 2019-04-30 12:32:13 +0200, Fabien COELHO wrote:

The effect is that the first generation seems to take more time, but
dropping the table and regenerating again much less, with a typical 40%
performance improvement between first and second run, independently of the
version. The reported figures above where comparisons between first for pg12
and second or later for pg11.

Yea, that's pretty normal. The likely difference is that in the repeated
case you'll have WAL files ready to be recycled. I'd assume that the
difference between the runs would be much smaller if used unlogged
tables (or WAL on a ramdisk or somesuch).

Performances are quite unstable, with index generation on the same scale 100
data taking anything from 6 to 15 seconds over runs.

How comparable are the runs? Are you restarting postgres inbetween?
Perform checkpoints?

Doing a VACUUM and checksums interact badly: vacuum time jumps from 3
seconds to 30 seconds:-(

Hm, that's more than I normally see. What exactly did you do there?

Greetings,

Andres Freund

Hello Andres,

The effect is that the first generation seems to take more time, but
dropping the table and regenerating again much less, with a typical 40%
performance improvement between first and second run, independently of the
version. The reported figures above where comparisons between first for pg12
and second or later for pg11.

Yea, that's pretty normal. The likely difference is that in the repeated
case you'll have WAL files ready to be recycled. I'd assume that the
difference between the runs would be much smaller if used unlogged
tables (or WAL on a ramdisk or somesuch).

I tried unlogged, and indeed the first run is no different from subsequent
ones.

Performances are quite unstable, with index generation on the same scale 100
data taking anything from 6 to 15 seconds over runs.

How comparable are the runs?

See below for a taste.

Are you restarting postgres inbetween?

Nope. Trying once did not change the measures.

Perform checkpoints?

Nope, but with the default settings there is one avery five minutes. I'm
not sure a checkpoint should have a significant impact on a COPY
initialization.

Doing a VACUUM and checksums interact badly: vacuum time jumps from 3
seconds to 30 seconds:-(

Hm, that's more than I normally see. What exactly did you do there?

I simply ran "pgbench -i -s 100" on master, with
https://commitfest.postgresql.org/23/2085/ thrown in for detailed stats.

Without checksums:

# init
37.68 s (drop tables 0.00 s, create tables 0.02 s, generate 27.12 s, vacuum 2.97 s, primary keys 7.56 s)
30.53 s (drop tables 0.25 s, create tables 0.01 s, generate 16.64 s, vacuum 3.47 s, primary keys 10.16 s)
36.31 s (drop tables 0.25 s, create tables 0.01 s, generate 18.94 s, vacuum 3.40 s, primary keys 13.71 s)
31.34 s (drop tables 0.23 s, create tables 0.01 s, generate 19.07 s, vacuum 3.00 s, primary keys 9.03 s)
# reinit
38.25 s (drop tables 0.00 s, create tables 0.03 s, generate 29.33 s, vacuum 3.10 s, primary keys 5.80 s)
35.16 s (drop tables 0.25 s, create tables 0.01 s, generate 17.62 s, vacuum 2.62 s, primary keys 14.67 s)
29.15 s (drop tables 0.25 s, create tables 0.01 s, generate 17.35 s, vacuum 2.98 s, primary keys 8.55 s)
32.70 s (drop tables 0.25 s, create tables 0.01 s, generate 21.49 s, vacuum 2.65 s, primary keys 8.29 s)
# reinit
42.39 s (drop tables 0.00 s, create tables 0.03 s, generate 33.98 s, vacuum 2.16 s, primary keys 6.23 s)
31.24 s (drop tables 0.24 s, create tables 0.01 s, generate 17.34 s, vacuum 4.74 s, primary keys 8.91 s)
26.91 s (drop tables 0.24 s, create tables 0.01 s, generate 16.83 s, vacuum 2.89 s, primary keys 6.94 s)
29.00 s (drop tables 0.25 s, create tables 0.01 s, generate 17.78 s, vacuum 2.97 s, primary keys 7.98 s)
# init
37.68 s (drop tables 0.00 s, create tables 0.02 s, generate 27.12 s, vacuum 2.97 s, primary keys 7.56 s)
30.53 s (drop tables 0.25 s, create tables 0.01 s, generate 16.64 s, vacuum 3.47 s, primary keys 10.16 s)
36.31 s (drop tables 0.25 s, create tables 0.01 s, generate 18.94 s, vacuum 3.40 s, primary keys 13.71 s)
31.34 s (drop tables 0.23 s, create tables 0.01 s, generate 19.07 s, vacuum 3.00 s, primary keys 9.03 s)
# reinit
38.25 s (drop tables 0.00 s, create tables 0.03 s, generate 29.33 s, vacuum 3.10 s, primary keys 5.80 s)
35.16 s (drop tables 0.25 s, create tables 0.01 s, generate 17.62 s, vacuum 2.62 s, primary keys 14.67 s)
29.15 s (drop tables 0.25 s, create tables 0.01 s, generate 17.35 s, vacuum 2.98 s, primary keys 8.55 s)
32.70 s (drop tables 0.25 s, create tables 0.01 s, generate 21.49 s, vacuum 2.65 s, primary keys 8.29 s)
# reinit
42.39 s (drop tables 0.00 s, create tables 0.03 s, generate 33.98 s, vacuum 2.16 s, primary keys 6.23 s)
31.24 s (drop tables 0.24 s, create tables 0.01 s, generate 17.34 s, vacuum 4.74 s, primary keys 8.91 s)
26.91 s (drop tables 0.24 s, create tables 0.01 s, generate 16.83 s, vacuum 2.89 s, primary keys 6.94 s)
29.00 s (drop tables 0.25 s, create tables 0.01 s, generate 17.78 s, vacuum 2.97 s, primary keys 7.98 s)

With checksum enabled:

# init
73.84 s (drop tables 0.00 s, create tables 0.03 s, generate 32.81 s, vacuum 34.95 s, primary keys 6.06 s)
61.49 s (drop tables 0.24 s, create tables 0.01 s, generate 18.55 s, vacuum 33.26 s, primary keys 9.42 s)
62.79 s (drop tables 0.24 s, create tables 0.01 s, generate 21.08 s, vacuum 33.50 s, primary keys 7.96 s)
58.77 s (drop tables 0.23 s, create tables 0.06 s, generate 21.98 s, vacuum 31.21 s, primary keys 5.30 s)
# restart
63.77 s (drop tables 0.04 s, create tables 0.02 s, generate 17.37 s, vacuum 40.84 s, primary keys 5.51 s)
64.48 s (drop tables 0.22 s, create tables 0.01 s, generate 19.84 s, vacuum 33.43 s, primary keys 10.98 s)
64.10 s (drop tables 0.23 s, create tables 0.01 s, generate 22.11 s, vacuum 33.17 s, primary keys 8.57 s)
# reinit
71.65 s (drop tables 0.00 s, create tables 0.03 s, generate 34.23 s, vacuum 31.67 s, primary keys 5.72 s)
64.33 s (drop tables 0.23 s, create tables 0.01 s, generate 21.31 s, vacuum 36.58 s, primary keys 6.20 s)
62.06 s (drop tables 0.23 s, create tables 0.02 s, generate 19.15 s, vacuum 37.34 s, primary keys 5.32 s)

Detailed figure are not visibly different (other reported figures about
checksum vs no checksum suggested a few percent impact), but for VACUUM
where it is closer to a thousand percent. Cassert is off, this is not the
issue. Hmmm.

--
Fabien.