performance: `tuplehash_iterate` and `group by` question, very slow

From: Mingjun Yang <yangxiaoming2019(at)gmail(dot)com>
To: pgsql-bugs(at)lists(dot)postgresql(dot)org
Subject: performance: `tuplehash_iterate` and `group by` question, very slow
Date: 2024-03-20 09:55:05
Message-ID: CA+KW-rofmein99=KvdLA8t0vm13q=hJrhCqdY9jrj2JRfWuN2g@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

VERSION: PostgreSQL 16.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC)
11.4.1 20230605 (Red Hat 11.4.1-2), 64-bit
SYSTEAM KERNEL: Linux localhost.localdomain 5.14.0-362.13.1.el9_3.x86_64 #1
SMP PREEMPT_DYNAMIC Wed Dec 13 14:07:45 UTC 2023 x86_64 x86_64 x86_64
GNU/Linux
SYSTEAM INFO: Rocky Linux 9.3 (Blue Onyx)
CPU: Intel(R) Xeon(R) w5-2445
MOMROY: 256GB

I have a 460 GB table.
+------------------+--------------------------+-----------+
| Column | Type | Modifiers |
|------------------+--------------------------+-----------|
| sha_256 | bytea | not null |
| aaaaa_id | bigint | not null |
| bbbbb_timestamp | timestamp with time zone | not null |
| cccccc_id | integer | not null |
| ddddddddddddddd | cert_purpose_type | not null |
+------------------+--------------------------+-----------+

I run the query:

```sql
SELECT
l1.cccccc_id,
l1.count
FROM (
SELECT
cccccc_id,
count(aaaaa_id) count
FROM (
SELECT
cccccc_id,
aaaaa_id
FROM
some_table cle
GROUP BY
cccccc_id,
aaaaa_id) cle_data
GROUP BY
cccccc_id) l1;
```

It's long time run, more than 25 hours, CPU keep 95.6%.
My table were create by timescaledb, the query first stage run about 2
hours , and 243.17G temp file created.
I d'not know what's happened, And how I debug or performance this question.
And who had the same question?

```text
PostgreSQL 16.2 - localhost.localdomain - xxxx(at)localhost:5432/xxxx - Ref.:
2s - Duration mode: query
* Global: 1 day, 22 hours and 13 minutes uptime, 5.38T dbs size - 0B/s
growth, - cache hit ratio, 0.00% rollback ratio
Sessions: 6/800 total, 2 active, 4 idle, 0 idle in txn, 0 idle in txn
abrt, 0 waiting
Activity: 3 tps, 0 insert/s, 0 update/s, 0 delete/s, 0 tuples
returned/s, 244 temp files, 243.17G temp size
* Worker processes: 0/16 total, 0/4 logical workers, 0/16 parallel workers
Other processes & info: 0/8 autovacuum workers, 0/0 wal senders, 0 wal
receivers, 0/10 repl. slots
* Mem.: 250.85G total, 20.69G (8.25%) free, 18.60G (7.42%) used, 211.55G
(84.34%) buff+cached
Swap: 0B total, 0B (-) free, 0B (-) used
IO: 1/s max iops, 0B/s - 0/s read, 7.93K/s - 1/s write
Load average: 1.11 1.11 1.15

PID DATABASE APP USER CLIENT
CPU% MEM% READ/s WRITE/s TIME+ Waiting IOW
state Query
522417 some_db psql some_user 127.0.0.1 95.6
21.1 0B 7.93K 25 h N active
xxxx
```

I run the `perf top -p 522417` monitor the thread, the `tuplehash_iterate`
use 98.79% CPU cycles:

```text
Samples: 327K of event 'cycles', 4000 Hz, Event count (approx.):
64246693339 lost: 0/0 drop: 0/0
Overhead Shared Object Symbol
98.79% postgres [.] tuplehash_iterate
0.94% libc.so.6 [.] __memset_avx512_unaligned_erms
0.03% [kernel] [k] sync_regs
0.02% [kernel] [k] perf_adjust_freq_unthr_context
0.01% [kernel] [k] nohz_balancer_kick
0.01% [kernel] [k] timekeeping_advance
0.01% [kernel] [k] arch_asym_cpu_priority
0.01% [kernel] [k] arch_scale_freq_tick
0.01% [kernel] [k] _raw_spin_lock_irqsave
0.01% [kernel] [k] _raw_spin_lock
0.01% [kernel] [k] __intel_pmu_enable_all.constprop.0
0.01% [kernel] [k] cpuacct_account_field
0.01% [kernel] [k] update_cfs_group
0.01% [kernel] [k] cpuacct_charge
0.01% [kernel] [k] native_sched_clock
0.00% [kernel] [k] lapic_next_deadline
0.00% [kernel] [k] __run_timers.part.0
0.00% [kernel] [k] ktime_get_update_offsets_now
......
```

```text
+-----------------------------------------------------------------------------------------------------------------------+
| QUERY PLAN
|
|-----------------------------------------------------------------------------------------------------------------------|
| Subquery Scan on l1 (cost=167901456.53..167901758.53 rows=200 width=20)
|
| InitPlan 1 (returns $0)
|
| -> Result (cost=0.00..0.01 rows=1 width=8)
|
| -> GroupAggregate (cost=167901456.52..167901758.52 rows=200 width=12)
|
| Group Key: cle_1.cccccc_id
|
| -> Sort (cost=167901456.52..167901556.52 rows=40000 width=12)
|
| Sort Key: cle_1.cccccc_id
|
| -> HashAggregate (cost=167897998.98..167898398.98
rows=40000 width=12) |
| Group Key: cle_1.cccccc_id, cle_1.aaaaa_id
|
| -> Append (cost=0.00..141132044.98 rows=5353190799
width=12) |
| -> Seq Scan on _hyper_10_71_chunk cle_1
(cost=0.00..35615836.68 rows=1667104768 width=12) |
| -> Seq Scan on _hyper_10_72_chunk cle_2
(cost=0.00..22931461.24 rows=1073370624 width=12) |
| -> Seq Scan on _hyper_10_73_chunk cle_3
(cost=0.00..12029957.12 rows=563086912 width=12) |
| -> Seq Scan on _hyper_10_74_chunk cle_4
(cost=0.00..10949797.28 rows=512535328 width=12) |
| -> Seq Scan on _hyper_10_75_chunk cle_5
(cost=0.00..13747554.76 rows=643480576 width=12) |
| -> Seq Scan on _hyper_10_76_chunk cle_6
(cost=0.00..7800797.52 rows=365127552 width=12) |
| -> Seq Scan on _hyper_10_77_chunk cle_7
(cost=0.00..3433002.24 rows=160687824 width=12) |
| -> Seq Scan on _hyper_10_78_chunk cle_8
(cost=0.00..3689582.96 rows=172702896 width=12) |
| -> Seq Scan on _hyper_10_79_chunk cle_9
(cost=0.00..3913904.52 rows=183197152 width=12) |
| -> Seq Scan on _hyper_10_102_chunk cle_10
(cost=0.00..103.32 rows=4732 width=12) |
| -> Seq Scan on _hyper_10_103_chunk cle_11
(cost=0.00..96.84 rows=4484 width=12) |
| -> Seq Scan on _hyper_10_104_chunk cle_12
(cost=0.00..688.01 rows=32201 width=12) |
| -> Seq Scan on _hyper_10_105_chunk cle_13
(cost=0.00..713.61 rows=33361 width=12) |
| -> Seq Scan on _hyper_10_106_chunk cle_14
(cost=0.00..899.98 rows=42098 width=12) |
| -> Seq Scan on _hyper_10_107_chunk cle_15
(cost=0.00..1264.84 rows=59184 width=12) |
| -> Seq Scan on _hyper_10_108_chunk cle_16
(cost=0.00..2671.00 rows=125000 width=12) |
| -> Seq Scan on _hyper_10_109_chunk cle_17
(cost=0.00..3344.34 rows=156534 width=12) |
| -> Seq Scan on _hyper_10_110_chunk cle_18
(cost=0.00..243609.02 rows=11402202 width=12) |
| -> Seq Scan on _hyper_10_148_chunk cle_19
(cost=0.00..375.74 rows=17574 width=12) |
| -> Seq Scan on _hyper_10_155_chunk cle_20
(cost=0.00..42.39 rows=1939 width=12) |
| -> Seq Scan on _hyper_10_157_chunk cle_21
(cost=0.00..1.46 rows=46 width=12) |
| -> Seq Scan on _hyper_10_158_chunk cle_22
(cost=0.00..46.81 rows=2181 width=12) |
| -> Seq Scan on _hyper_10_159_chunk cle_23
(cost=0.00..5.63 rows=263 width=12) |
| -> Seq Scan on _hyper_10_161_chunk cle_24
(cost=0.00..100.79 rows=4679 width=12) |
| -> Seq Scan on _hyper_10_172_chunk cle_25
(cost=0.00..232.89 rows=10689 width=12) |
| JIT:
|
| Functions: 59
|
| Options: Inlining true, Optimization true, Expressions true, Deforming
true |
+-----------------------------------------------------------------------------------------------------------------------+
EXPLAIN 38
```

```text
+-------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------->
| name | setting

>
|-------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------->
| BINDIR | /usr/local/pg16/bin

>
| DOCDIR | /usr/local/pg16/share/doc/postgresql

>
| HTMLDIR | /usr/local/pg16/share/doc/postgresql

>
| INCLUDEDIR | /usr/local/pg16/include

>
| PKGINCLUDEDIR | /usr/local/pg16/include/postgresql

>
| INCLUDEDIR-SERVER | /usr/local/pg16/include/postgresql/server

>
| LIBDIR | /usr/local/pg16/lib

>
| PKGLIBDIR | /usr/local/pg16/lib/postgresql

>
| LOCALEDIR | /usr/local/pg16/share/locale

>
| MANDIR | /usr/local/pg16/share/man

>
| SHAREDIR | /usr/local/pg16/share/postgresql

>
| SYSCONFDIR | /usr/local/pg16/etc/postgresql

>
| PGXS | /usr/local/pg16/lib/postgresql/pgxs/src/makefiles/
pgxs.mk

>
| CONFIGURE | '--prefix=/usr/local/pg16' '--with-openssl'
'-with-lz4' '--with-systemd' '--with-python' '--with-llvm'

>
| CC | gcc

>
| CPPFLAGS | -D_GNU_SOURCE

>
| CFLAGS | -Wall -Wmissing-prototypes -Wpointer-arith
-Wdeclaration-after-statement -Werror=vla -Wendif-labels
-Wmissing-format-attribute -Wimplicit-fallthrough=3 -Wcast-function-type
-Wshadow=compatible-local -Wfor>
| CFLAGS_SL | -fPIC

>
| LDFLAGS | -L/usr/lib64 -Wl,--as-needed
-Wl,-rpath,'/usr/local/pg16/lib',--enable-new-dtags

>
| LDFLAGS_EX |

>
| LDFLAGS_SL |

>
| LIBS | -lpgcommon -lpgport -llz4 -lssl -lcrypto -lz -ledit
-lm

>
| VERSION | PostgreSQL 16.2

>
+-------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------->
```

Browse pgsql-bugs by date

  From Date Subject
Next Message Alexander Korotkov 2024-03-20 10:24:55 Re: [BUG] false positive in bt_index_check in case of short 4B varlena datum
Previous Message Wolfgang Walther 2024-03-20 09:39:20 Re: Regression tests fail with musl libc because libpq.so can't be loaded