Обсуждение: performance regression when filling in a table

Hello devs,

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?

-- 
Fabien.

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.