Re: Degression (PG10 > 11, 12 or 13)

hI

pá 28. 5. 2021 v 16:12 odesílatel Johannes Graën <johannes(at)selfnet(dot)de>
napsal:

> Hi,
>
> When trying to upgrade an existing database from version 10 to 13 I came
> across a degression in some existing code used by clients. Further
> investigations showed that performance measures are similar in versions
> 11 to 13, while in the original database on version 10 it's around 100
> times faster. I could boil it down to perl functions used for sorting.
>
> >From the real data that I don't own, I created a test case that is
> sufficient to observe the degression: http://ix.io/3o7f
>
>
> These are the numbers on PG 10:
>
> > test=# explain (analyze, verbose, buffers)
> > select attr from tab order by func(attr);
> > QUERY PLAN
> >
> ----------------------------------------------------------------------------------------------------------------------
> > Sort (cost=3269.68..3294.36 rows=9869 width=40) (actual
> time=179.374..180.558 rows=9869 loops=1)
> > Output: attr, (func(attr))
> > Sort Key: (func(tab.attr))
> > Sort Method: quicksort Memory: 1436kB
> > Buffers: shared hit=49
> > -> Seq Scan on public.tab (cost=0.00..2614.94 rows=9869 width=40)
> (actual time=2.293..169.060 rows=9869 loops=1)
> > Output: attr, func(attr)
> > Buffers: shared hit=49
> > Planning time: 0.318 ms
> > Execution time: 182.061 ms
> > (10 rows)
> >
> > test=# explain (analyze, verbose, buffers)
> > select attr from tab;
> > QUERY PLAN
> >
> ------------------------------------------------------------------------------------------------------------
> > Seq Scan on public.tab (cost=0.00..147.69 rows=9869 width=8) (actual
> time=0.045..3.975 rows=9869 loops=1)
> > Output: attr
> > Buffers: shared hit=49
> > Planning time: 0.069 ms
> > Execution time: 6.020 ms
> > (5 rows)
>
>
> And here we have PG 11:
>
> > test=# explain (analyze, verbose, buffers)
> > select attr from tab order by func(attr);
> > QUERY PLAN
> >
> ----------------------------------------------------------------------------------------------------------------------
> > Sort (cost=3269.68..3294.36 rows=9869 width=40) (actual
> time=597.877..599.805 rows=9869 loops=1)
> > Output: attr, (func(attr))
> > Sort Key: (func(tab.attr))
> > Sort Method: quicksort Memory: 1436kB
> > Buffers: shared hit=49
> > -> Seq Scan on public.tab (cost=0.00..2614.94 rows=9869 width=40)
> (actual time=0.878..214.188 rows=9869 loops=1)
> > Output: attr, func(attr)
> > Buffers: shared hit=49
> > Planning Time: 0.151 ms
> > Execution Time: 601.767 ms
> > (10 rows)
> >
> > test=# explain (analyze, verbose, buffers)
> > select attr from tab;
> > QUERY PLAN
> >
> ------------------------------------------------------------------------------------------------------------
> > Seq Scan on public.tab (cost=0.00..147.69 rows=9869 width=8) (actual
> time=0.033..1.628 rows=9869 loops=1)
> > Output: attr
> > Buffers: shared hit=49
> > Planning Time: 0.043 ms
> > Execution Time: 2.581 ms
> > (5 rows)
>
>
> In the real scenario it's 500ms vs. 50s. The reason is obviously the
> perl function used as sort key. All different versions have been tested
> with an unmodified config and one tunes with pgtune. Creating a
> functional index does not help in the original database as the planner
> doesn't use it, while it *is* used in the test case. But the question
> what causes that noticeable difference in performance is untouched by
> the fact that it could be circumvented in some cases.
>
> The perl version used is v5.24.1.
>

I looked on profile - Postgres 14

5,67% libperl.so.5.32.1 [.] Perl_utf8_length
5,44% libc-2.33.so [.] __strcoll_l
4,73% libperl.so.5.32.1 [.] Perl_pp_subst
4,33% libperl.so.5.32.1 [.] Perl_re_intuit_start
3,25% libperl.so.5.32.1 [.] Perl_fbm_instr
1,92% libperl.so.5.32.1 [.] Perl_regexec_flags
1,79% libperl.so.5.32.1 [.] Perl_runops_standard
1,16% libperl.so.5.32.1 [.] Perl_pp_const
0,97% perf [.] 0x00000000002fcf93
0,94% libperl.so.5.32.1 [.] Perl_pp_nextstate
0,68% libperl.so.5.32.1 [.] Perl_do_trans
0,54% perf [.] 0x00000000003dd0c5

and Postgres - 10

5,45% libperl.so.5.32.1 [.] Perl_utf8_length
4,78% libc-2.33.so [.] __strcoll_l
4,15% libperl.so.5.32.1 [.] Perl_re_intuit_start
3,92% libperl.so.5.32.1 [.] Perl_pp_subst
2,99% libperl.so.5.32.1 [.] Perl_fbm_instr
1,77% libperl.so.5.32.1 [.] Perl_regexec_flags
1,59% libperl.so.5.32.1 [.] Perl_runops_standard
1,02% libperl.so.5.32.1 [.] Perl_pp_const
0,99% [kernel] [k] psi_group_change
0,85% [kernel] [k] switch_mm_irqs_off

and it doesn't look too strange.

-- postgres 14
postgres=# explain (analyze, verbose, buffers)
select attr from tab order by func(attr);
┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN
│
╞══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
│ Sort (cost=3269.68..3294.36 rows=9869 width=40) (actual
time=246.612..247.292 rows=9869 loops=1) │
│ Output: attr, (func(attr))
│
│ Sort Key: (func(tab.attr))
│
│ Sort Method: quicksort Memory: 1436kB
│
│ Buffers: shared hit=49
│
│ -> Seq Scan on public.tab (cost=0.00..2614.94 rows=9869 width=40)
(actual time=0.102..201.863 rows=9869 loops=1) │
│ Output: attr, func(attr)
│
│ Buffers: shared hit=49
│
│ Planning Time: 0.057 ms
│
│ Execution Time: 248.386 ms
│
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(10 rows)

-- postgres 10
postgres=# explain (analyze, verbose, buffers)
select attr from tab order by func(attr);
┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN
│
╞══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
│ Sort (cost=3269.68..3294.36 rows=9869 width=40) (actual
time=267.779..268.366 rows=9869 loops=1) │
│ Output: attr, (func(attr))
│
│ Sort Key: (func(tab.attr))
│
│ Sort Method: quicksort Memory: 1436kB
│
│ Buffers: shared hit=49
│
│ -> Seq Scan on public.tab (cost=0.00..2614.94 rows=9869 width=40)
(actual time=0.278..222.606 rows=9869 loops=1) │
│ Output: attr, func(attr)
│
│ Buffers: shared hit=49
│
│ Planning time: 0.132 ms
│
│ Execution time: 269.258 ms
│
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(10 rows)

This is tested on my laptop - both version uses same locale

Are you sure, so all databases use the same encoding and same locale?

Regards

Pavel

> Best
> Johannes
>
>
>
>