PostgreSQL Performance Puzzle

Update 7/18: y’all guessed the answer to my puzzle very fast! At the bottom of this blog post, I’ve added the expressions that I used (with credit to those who guessed it), and also other expressions guessed by readers which exhibited similar behavior. I’ll do another follow-up blog post touching on several layers of this interesting test, hopefully in the next few days.

---

This week I stumbled across a really big surprise in Open Source PostgreSQL. I thought it would make a fun puzzle to challenge the skills of all you on the internet who consider yourselves as PostgreSQL experts.

It’s very simple. I spun up a fresh copy of Centos 7 on an EC2 instance and loaded the latest Open Source PostgreSQL production version (14.4) from the official PG yum repositories. Then I created a simple table with a text column and two not-null bigint columns. I populated the table with 100 million rows of dummy data using generate_series() and then I indexed both bigint columns in the same way. I did a vacuum analyze to get stats and make sure the table is ready for a simple test. And finally, I did a quick bounce of PG and cleared the OS page cache so we could start the test cold.

Now I ran a very simple query:

select count(mydata) from test where mynumber1 < 500000;

Now here’s what shocked me. Starting with a cold cache every time, that query right there consistently completes in less than 500 milliseconds. But when I run the same query on the the other number column, it consistently takes over 100 seconds! Yes, seconds – not milliseconds. With exactly the same execution plan, processing the same number of rows! (500 thousand rows or 0.5% of the table.)

Now I’m not surprised to see specific data in a table impacting performance – that’s 101 for anyone who’s been around RDBMS performance. But the magnitude of this difference was way higher than I expected. I can repeat the two queries over and over with the same difference in executions times.

Again: it’s a simple table with two not-null bigint columns. The columns are defined identically – same data type, same index type, same execution plan, same number of rows processed. The only difference is the data in the table. There are no null values involved. And the difference in execution time is astronomical – as much as 600 X slower for some of my iterations!!

Can you guess what the data in the table is?

Included below is a complete and detailed transcript of the reproduction – I’ve just excluded the expressions that I used to populate the test table. I’m curious if anyone will be able to guess what those expressions were!!

If anyone tells me a guess on blog comments or twitter, I’ll test out their expression using the transcript below. Then I’ll credit anyone who sends a guess that exhibits the same shocking difference in performance between the two column. Fame and glory, my friends. In a week or so (maybe sooner if someone guesses it really fast), I’ll publish the two expressions that I myself redacted from my session transcript below.

Major, big-time bonus fame and glory if anyone can explain the reason. 😀

PS. Mohamed, if you’re reading this, you’re not allowed to guess! (He found it first but we worked together to figure out what was going on.)

---

instance_type: r5.large
volume_type: gp2
volume_size: 100

# CentOS Linux 7 x86_64 HVM EBS ENA 2002_01
us-west-2: ami-0bc06212a56393ee1

[root@ip-172-31-36-129 ~]# rpm -q postgresql14-server
postgresql14-server-14.4-1PGDG.rhel7.x86_64
[root@ip-172-31-36-129 ~]#

---

pg-14.4 rw root@db1=# create table test ( mydata text, mynumber1 bigint not null, mynumber2 bigint not null);
CREATE TABLE
Time: 6.617 ms

pg-14.4 rw root@db1=# insert into test
[more] - >   select 'data-XXXXXXXXXXXX'
[more] - >     , <GUESS THIS FIRST EXPRESSION>
[more] - >     , <GUESS THIS SECOND EXPRESSION>
[more] - >   from generate_series(1,100000000) as n
[more] - > ;
INSERT 0 100000000
Time: 224101.677 ms (03:44.102)

pg-14.4 rw root@db1=# create index test_mynumber1 on test(mynumber1);
CREATE INDEX
Time: 229785.314 ms (03:49.785)

pg-14.4 rw root@db1=# create index test_mynumber2 on test(mynumber2);
CREATE INDEX
Time: 108900.146 ms (01:48.900)

pg-14.4 rw root@db1=# vacuum verbose analyze test;
INFO:  00000: vacuuming "public.test"
LOCATION:  lazy_scan_heap, vacuumlazy.c:940
INFO:  00000: launched 1 parallel vacuum worker for index cleanup (planned: 1)
LOCATION:  do_parallel_vacuum_or_cleanup, vacuumlazy.c:2766
INFO:  00000: table "test": found 0 removable, 79913800 nonremovable row versions in 665949 out of 833334 pages
DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 757
Skipped 0 pages due to buffer pins, 0 frozen pages.
CPU: user: 8.44 s, system: 3.97 s, elapsed: 96.48 s.
LOCATION:  lazy_scan_heap, vacuumlazy.c:1674
INFO:  00000: vacuuming "pg_toast.pg_toast_16454"
LOCATION:  lazy_scan_heap, vacuumlazy.c:940
INFO:  00000: table "pg_toast_16454": found 0 removable, 0 nonremovable row versions in 0 out of 0 pages
DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 758
Skipped 0 pages due to buffer pins, 0 frozen pages.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
LOCATION:  lazy_scan_heap, vacuumlazy.c:1674
INFO:  00000: analyzing "public.test"
LOCATION:  do_analyze_rel, analyze.c:331
INFO:  00000: "test": scanned 30000 of 833334 pages, containing 3600000 live rows and 0 dead rows; 30000 rows in sample, 100000080 estimated total rows
LOCATION:  acquire_sample_rows, analyze.c:1357
VACUUM
Time: 100010.196 ms (01:40.010)



[root@ip-172-31-36-129 ~]# service postgresql-14 restart;
Redirecting to /bin/systemctl restart postgresql-14.service
[root@ip-172-31-36-129 ~]# sync; echo 1 > /proc/sys/vm/drop_caches
[root@ip-172-31-36-129 ~]#



pg-14.4 rw root@db1=# select count(mydata) from test where mynumber1<500000;
 count
--------
 499999
(1 row)

Time: 155.314 ms



[root@ip-172-31-36-129 ~]# service postgresql-14 restart;
Redirecting to /bin/systemctl restart postgresql-14.service
[root@ip-172-31-36-129 ~]# sync; echo 1 > /proc/sys/vm/drop_caches
[root@ip-172-31-36-129 ~]#



pg-14.4 rw root@db1=# select count(mydata) from test where mynumber2<500000;
 count
--------
 499180
(1 row)

Time: 105202.086 ms (01:45.202)



[root@ip-172-31-36-129 ~]# service postgresql-14 restart;
Redirecting to /bin/systemctl restart postgresql-14.service
[root@ip-172-31-36-129 ~]# sync; echo 1 > /proc/sys/vm/drop_caches
[root@ip-172-31-36-129 ~]#


pg-14.4 rw root@db1=# select count(mydata) from test where mynumber1<500000;
 count
--------
 499999
(1 row)

Time: 494.063 ms



[root@ip-172-31-36-129 ~]# service postgresql-14 restart;
Redirecting to /bin/systemctl restart postgresql-14.service
[root@ip-172-31-36-129 ~]# sync; echo 1 > /proc/sys/vm/drop_caches
[root@ip-172-31-36-129 ~]#



pg-14.4 rw root@db1=# select count(mydata) from test where mynumber2<500000;
 count
--------
 499180
(1 row)

Time: 104084.311 ms (01:44.084)

---

Update 7/18: Here’s the full INSERT statement from my original test:

pg-14.4 rw root@db1=# insert into test
[more] - >   select 'data-XXXXXXXXXXXX'
[more] - >     ,n
[more] - >     ,random()*100000000
[more] - >   from generate_series(1,100000000) as n
[more] - > ;
INSERT 0 100000000
Time: 224101.677 ms (03:44.102)

The very first person to correctly guess was Franck Pachot via a twitter DM at 06:05 UTC on the 17th. The first person to correctly guess with a public post was donghual@ in a blog comment at 14:33 UTC on the 17th.

At 14:48 UTC on the 17th, RustProof Labs on twitter guessed the idea behind what I did, although the explanation didn’t have an expression for me to test/measure. At 00:14 UTC on the 18th, Denish Patel made a guess on twitter that technically didn’t match but I would give credit, because his explanation suggests that it was just a typo. I didn’t run the test but I would expect similar behavior.

Two people also guessed other expressions that showed similar behavior, though less than 100 seconds per execution. At 06:38 UTC on the 17th, Andy Sayer on twitter guessed mod(n, 200 )*500000 which gave about 50 seconds per execution. At 16:26 UTC on the 18th, Joe Wildish in a blog comment guessed case n % 120 when 1 then n / 120 else 500000 + n end which gave about 30 seconds per execution. Joe was building on a blog comment from Matthis at 09:15 UTC on the 17th which also deserves credit, because his explanation suggests that his guess was correct and his expression just needed a little tweaking to avoid the integer out of range error.

Obviously I made this puzzle way too easy! 😀