In postgres, the parallel workers play an important role in query execution. The postgres planner generates multiple plans during the query planning phase and chooses the better plan. So this planner is responsible for deciding whether the query should be executed in parallel or not. Also, Postgres has minimum criteria for selecting the parallel workers for tables and indexes,
In Postgres, there are some useful parameters that are related to parallel query execution, and we can set better values for these parameters based on our use case.
So let’s understand how postgres chooses parallel workers on query execution.
Create some sample tables for testing purposes.
CREATE TABLE employee (
id BIGSERIAL PRIMARY KEY,
department INT,
salary INT,
age INT,
city TEXT,
created_at TIMESTAMP
);
Insert values.
INSERT INTO employee (department, salary, age, city, created_at)
SELECT
(random() * 50)::int,
(30000 + random() * 170000)::int,
(20 + random() * 40)::int,
md5(random()::text),
NOW() - (random() * interval '1000 days')
FROM generate_series(1, 10000000);
Execute vacuum analyze to remove the dead tuples and update the planner about the latest statistics of the table named employee.
VACUUM ANALYZE employee;
Check the current value of the parameter named max_parallel_workers.
show max_parallel_workers;
Result :
max_parallel_workers
----------------------
8
(1 row)
Check the current value of the parameter named max_parallel_workers_per_gather.
show max_parallel_workers_per_gather;
Result :
max_parallel_workers_per_gather
---------------------------------
2
(1 row)
Set this parameter value to 4 inside this session only by using the set command.
SET max_parallel_workers_per_gather = 4;
Check the current value of the parameter named min_parallel_table_scan_size.
show max_parallel_workers;
Result :
min_parallel_table_scan_size ------------------------------ 8MB(1 row)
Set this parameter value to 0 like this.
SET min_parallel_table_scan_size = 0;
Check the current value of the parameter named parallel_setup_cost.
show parallel_setup_cost;
Result:
parallel_setup_cost
---------------------
1000
(1 row)
Set this parameter value to 0 like this.
SET parallel_setup_cost = 0;
Check the current value of the parameter named parallel_tuple_cost.
show parallel_tuple_cost;
Result:
parallel_tuple_cost
---------------------
0.1
(1 row)
Set this parameter value to 0 like this.
SET parallel_tuple_cost = 0;
Now, check the size of this table like this.
SELECT
count(*),
pg_size_pretty(pg_relation_size('employee'));
Result:
count | pg_size_pretty
-------+----------------
1 | 888 MB
(1 row)
Now, execute the SELECT query with the EXPLAIN ANALYZE clause like this.
EXPLAIN (ANALYZE, VERBOSE)
SELECT count(*)
FROM employee;
The following is the query execution plan of the above query.
Result:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=144887.20..144887.21 rows=1 width=8) (actual time=6076.942..6084.573 rows=1.00 loops=1)
Output: count(*)
Buffers: shared hit=12930 read=100707
-> Gather (cost=144887.18..144887.19 rows=4 width=8) (actual time=6076.790..6084.538 rows=5.00 loops=1)
Output: (PARTIAL count(*))
Workers Planned: 4
Workers Launched: 4
Buffers: shared hit=12930 read=100707
-> Partial Aggregate (cost=144887.18..144887.19 rows=1 width=8) (actual time=6051.921..6051.927 rows=1.00 loops=5)
Output: PARTIAL count(*)
Buffers: shared hit=12930 read=100707
Worker 0: actual time=6045.763..6045.768 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.203 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.115 ms, Emission 2.919 ms, Total 3.237 ms
Buffers: shared hit=2619 read=20098
Worker 1: actual time=6045.869..6045.874 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.206 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.126 ms, Emission 2.931 ms, Total 3.262 ms
Buffers: shared hit=2560 read=20120
Worker 2: actual time=6045.807..6045.813 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.205 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.117 ms, Emission 3.033 ms, Total 3.355 ms
Buffers: shared hit=2559 read=20154
Worker 3: actual time=6045.814..6045.820 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.206 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.123 ms, Emission 2.899 ms, Total 3.228 ms
Buffers: shared hit=2591 read=20102
-> Parallel Seq Scan on public.employee (cost=0.00..138637.14 rows=2500014 width=0) (actual time=0.107..3024.938 rows=2000000.00 loops=5)
Output: id, department, salary, age, city, created_at
Buffers: shared hit=12930 read=100707
Worker 0: actual time=0.081..3017.955 rows=1999096.00 loops=1
Buffers: shared hit=2619 read=20098
Worker 1: actual time=0.090..3010.456 rows=1995784.00 loops=1
Buffers: shared hit=2560 read=20120
Worker 2: actual time=0.104..3026.269 rows=1998744.00 loops=1
Buffers: shared hit=2559 read=20154
Worker 3: actual time=0.111..3027.085 rows=1996984.00 loops=1
Buffers: shared hit=2591 read=20102
Planning:
Buffers: shared hit=47 read=11
Planning Time: 0.366 ms
JIT:
Functions: 12
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 1.007 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.588 ms, Emission 14.477 ms, Total 16.072 ms
Execution Time: 6101.257 ms
(54 rows)
From this output we can see that the workers planned and launched are the same. Nearly 4 parallel workers are included in the query execution.
In postgres, we have a parameter named client_min_messages, and we can use this parameter to see the debugging messages during the query execution in the psql terminal based on 5 different levels.
Check the current value of this parameter named client_min_messages.
show client_min_messages;
Result:
client_min_messages
---------------------
notice
(1 row)
Check this parameter’s metadata from pg_settings like this.
select * from pg_settings where name = 'client_min_messages';
Result :
-[ RECORD 1 ]---+-----------------------------------------------------------------------------------------------------
name | client_min_messages
setting | notice
unit |
category | Client Connection Defaults / Statement Behavior
short_desc | Sets the message levels that are sent to the client.
extra_desc | Each level includes all the levels that follow it. The later the level, the fewer messages are sent.
context | user
vartype | enum
source | default
min_val |
max_val |
enumvals | {debug5,debug4,debug3,debug2,debug1,log,notice,warning,error}
boot_val | notice
reset_val | notice
sourcefile |
sourceline |
pending_restart | f
Now, set the client_min_messages to debug1 like this.
set client_min_messages = 'debug1';
This is the low-level debugging option.
Now, check if the value has changed in this session.
show client_min_messages ;
Result:
client_min_messages
---------------------
debug1
(1 row)
Now, execute the same EXPLAIN ANALYZE query and check the result.
EXPLAIN (ANALYZE, VERBOSE)
SELECT count(*)
FROM employee;
Result:
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=144887.20..144887.21 rows=1 width=8) (actual time=5873.752..5881.330 rows=1.00 loops=1)
Output: count(*)
Buffers: shared hit=12832 read=100805
-> Gather (cost=144887.18..144887.19 rows=4 width=8) (actual time=5873.559..5881.289 rows=5.00 loops=1)
Output: (PARTIAL count(*))
Workers Planned: 4
Workers Launched: 4
Buffers: shared hit=12832 read=100805
-> Partial Aggregate (cost=144887.18..144887.19 rows=1 width=8) (actual time=5847.512..5847.518 rows=1.00 loops=5)
Output: PARTIAL count(*)
Buffers: shared hit=12832 read=100805
Worker 0: actual time=5841.030..5841.036 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.158 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.152 ms, Emission 2.807 ms, Total 3.118 ms
Buffers: shared hit=2531 read=20163
Worker 1: actual time=5841.076..5841.082 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.166 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.139 ms, Emission 2.817 ms, Total 3.122 ms
Buffers: shared hit=2574 read=20135
Worker 2: actual time=5841.203..5841.208 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.167 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.133 ms, Emission 2.772 ms, Total 3.071 ms
Buffers: shared hit=2628 read=20062
Worker 3: actual time=5841.013..5841.020 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.175 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.140 ms, Emission 2.807 ms, Total 3.123 ms
Buffers: shared hit=2592 read=20129
-> Parallel Seq Scan on public.employee (cost=0.00..138637.14 rows=2500014 width=0) (actual time=0.357..2921.318 rows=2000000.00 loops=5)
Output: id, department, salary, age, city, created_at
Buffers: shared hit=12832 read=100805
Worker 0: actual time=0.143..2907.809 rows=1997072.00 loops=1
Buffers: shared hit=2531 read=20163
Worker 1: actual time=0.152..2921.468 rows=1998336.00 loops=1
Buffers: shared hit=2574 read=20135
Worker 2: actual time=1.176..2926.999 rows=1996720.00 loops=1
Buffers: shared hit=2628 read=20062
Worker 3: actual time=0.185..2914.286 rows=1999448.00 loops=1
Buffers: shared hit=2592 read=20129
Planning Time: 0.084 ms
JIT:
Functions: 12
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.870 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.694 ms, Emission 13.508 ms, Total 15.072 ms
Execution Time: 5881.640 ms
(52 rows)
This query uses parallel execution to speed up the COUNT(*) operation. The planner starts four parallel worker processes, and together with the leader process, a total of five processes participate in the execution.
Each process performs a Parallel Sequential Scan on a different portion of the employee table, so no two processes scan the same blocks. Every process counts the rows in its assigned data and produces a partial count.
These partial results are then collected by the Gather node, which sends them to the Finalize Aggregate node. The Finalize Aggregate node adds all partial counts together and returns the final row count. Since the table scan is divided across multiple processes, the work is completed faster than a single-process sequential scan.
Now, set the next level of debug, named debug2, to this parameter like this.
set client_min_messages = 'debug2';
Execute the same query again.
EXPLAIN (ANALYZE, VERBOSE)
SELECT count(*)
FROM employee;
Result:
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: probing availability of JIT provider at /usr/lib/postgresql/18/lib/llvmjit.so
DEBUG: successfully loaded JIT provider in current session
DEBUG: LLVMJIT detected CPU "znver3", with features "-avx512pf,-tsxldtrk,+cx16,+sahf,-tbm,-avx512ifma,+sha,+crc32,-fma4,+vpclmulqdq,+prfchw,+bmi2,-cldemote,+fsgsbase,-avx512bf16,-amx-tile,-uintr,-gfni,+popcnt,-ptwrite,+aes,-avx512bitalg,-movdiri,-widekl,+xsaves,-avx512er,-avxvnni,-avx512fp16,-avx512vnni,-amx-bf16,-avx512vpopcntdq,-pconfig,+clwb,-avx512f,+xsavec,+clzero,+pku,+mmx,-lwp,+rdpid,-xop,+rdseed,-waitpkg,-kl,-movdir64b,+sse4a,-avx512bw,+clflushopt,+xsave,-avx512vbmi2,+64bit,-avx512vl,-serialize,-hreset,+invpcid,-avx512cd,+avx,+vaes,-amx-int8,+cx8,+fma,-rtm,+bmi,-enqcmd,+rdrnd,+mwaitx,+sse4.1,+sse4.2,+avx2,+fxsr,+wbnoinvd,+sse,+lzcnt,+pclmul,+rdpru,+f16c,+ssse3,-sgx,-prefetchwt1,+cmov,-avx512vbmi,+shstk,+movbe,-avx512vp2intersect,+xsaveopt,-avx512dq,+sse2,+adx,+sse3"
DEBUG: LLVMJIT detected CPU "znver3", with features "-avx512pf,-tsxldtrk,+cx16,+sahf,-tbm,-avx512ifma,+sha,+crc32,-fma4,+vpclmulqdq,+prfchw,+bmi2,-cldemote,+fsgsbase,-avx512bf16,-amx-tile,-uintr,-gfni,+popcnt,-ptwrite,+aes,-avx512bitalg,-movdiri,-widekl,+xsaves,-avx512er,-avxvnni,-avx512fp16,-avx512vnni,-amx-bf16,-avx512vpopcntdq,-pconfig,+clwb,-avx512f,+xsavec,+clzero,+pku,+mmx,-lwp,+rdpid,-xop,+rdseed,-waitpkg,-kl,-movdir64b,+sse4a,-avx512bw,+clflushopt,+xsave,-avx512vbmi2,+64bit,-avx512vl,-serialize,-hreset,+invpcid,-avx512cd,+avx,+vaes,-amx-int8,+cx8,+fma,-rtm,+bmi,-enqcmd,+rdrnd,+mwaitx,+sse4.1,+sse4.2,+avx2,+fxsr,+wbnoinvd,+sse,+lzcnt,+pclmul,+rdpru,+f16c,+ssse3,-sgx,-prefetchwt1,+cmov,-avx512vbmi,+shstk,+movbe,-avx512vp2intersect,+xsaveopt,-avx512dq,+sse2,+adx,+sse3"
DEBUG: LLVMJIT detected CPU "znver3", with features "-avx512pf,-tsxldtrk,+cx16,+sahf,-tbm,-avx512ifma,+sha,+crc32,-fma4,+vpclmulqdq,+prfchw,+bmi2,-cldemote,+fsgsbase,-avx512bf16,-amx-tile,-uintr,-gfni,+popcnt,-ptwrite,+aes,-avx512bitalg,-movdiri,-widekl,+xsaves,-avx512er,-avxvnni,-avx512fp16,-avx512vnni,-amx-bf16,-avx512vpopcntdq,-pconfig,+clwb,-avx512f,+xsavec,+clzero,+pku,+mmx,-lwp,+rdpid,-xop,+rdseed,-waitpkg,-kl,-movdir64b,+sse4a,-avx512bw,+clflushopt,+xsave,-avx512vbmi2,+64bit,-avx512vl,-serialize,-hreset,+invpcid,-avx512cd,+avx,+vaes,-amx-int8,+cx8,+fma,-rtm,+bmi,-enqcmd,+rdrnd,+mwaitx,+sse4.1,+sse4.2,+avx2,+fxsr,+wbnoinvd,+sse,+lzcnt,+pclmul,+rdpru,+f16c,+ssse3,-sgx,-prefetchwt1,+cmov,-avx512vbmi,+shstk,+movbe,-avx512vp2intersect,+xsaveopt,-avx512dq,+sse2,+adx,+sse3"
DEBUG: LLVMJIT detected CPU "znver3", with features "-avx512pf,-tsxldtrk,+cx16,+sahf,-tbm,-avx512ifma,+sha,+crc32,-fma4,+vpclmulqdq,+prfchw,+bmi2,-cldemote,+fsgsbase,-avx512bf16,-amx-tile,-uintr,-gfni,+popcnt,-ptwrite,+aes,-avx512bitalg,-movdiri,-widekl,+xsaves,-avx512er,-avxvnni,-avx512fp16,-avx512vnni,-amx-bf16,-avx512vpopcntdq,-pconfig,+clwb,-avx512f,+xsavec,+clzero,+pku,+mmx,-lwp,+rdpid,-xop,+rdseed,-waitpkg,-kl,-movdir64b,+sse4a,-avx512bw,+clflushopt,+xsave,-avx512vbmi2,+64bit,-avx512vl,-serialize,-hreset,+invpcid,-avx512cd,+avx,+vaes,-amx-int8,+cx8,+fma,-rtm,+bmi,-enqcmd,+rdrnd,+mwaitx,+sse4.1,+sse4.2,+avx2,+fxsr,+wbnoinvd,+sse,+lzcnt,+pclmul,+rdpru,+f16c,+ssse3,-sgx,-prefetchwt1,+cmov,-avx512vbmi,+shstk,+movbe,-avx512vp2intersect,+xsaveopt,-avx512dq,+sse2,+adx,+sse3"
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
DEBUG: time to inline: 0.000s, opt: 0.000s, emit: 0.000s
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=144887.20..144887.21 rows=1 width=8) (actual time=5884.539..5892.141 rows=1.00 loops=1)
Output: count(*)
Buffers: shared hit=12884 read=100753
-> Gather (cost=144887.18..144887.19 rows=4 width=8) (actual time=5884.291..5892.106 rows=5.00 loops=1)
Output: (PARTIAL count(*))
Workers Planned: 4
Workers Launched: 4
Buffers: shared hit=12884 read=100753
-> Partial Aggregate (cost=144887.18..144887.19 rows=1 width=8) (actual time=5859.010..5859.017 rows=1.00 loops=5)
Output: PARTIAL count(*)
Buffers: shared hit=12884 read=100753
Worker 0: actual time=5852.703..5852.712 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.236 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.240 ms, Emission 3.088 ms, Total 3.564 ms
Buffers: shared hit=2608 read=20103
Worker 1: actual time=5852.678..5852.686 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.239 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.227 ms, Emission 3.084 ms, Total 3.551 ms
Buffers: shared hit=2581 read=20137
Worker 2: actual time=5852.835..5852.841 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.241 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.212 ms, Emission 3.542 ms, Total 3.995 ms
Buffers: shared hit=2637 read=20063
Worker 3: actual time=5852.845..5852.850 rows=1.00 loops=1
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.232 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.207 ms, Emission 3.091 ms, Total 3.531 ms
Buffers: shared hit=2496 read=20190
-> Parallel Seq Scan on public.employee (cost=0.00..138637.14 rows=2500014 width=0) (actual time=0.248..2927.405 rows=2000000.00 loops=5)
Output: id, department, salary, age, city, created_at
Buffers: shared hit=12884 read=100753
Worker 0: actual time=0.228..2925.453 rows=1998568.00 loops=1
Buffers: shared hit=2608 read=20103
Worker 1: actual time=0.217..2927.423 rows=1999128.00 loops=1
Buffers: shared hit=2581 read=20137
Worker 2: actual time=0.280..2930.592 rows=1997600.00 loops=1
Buffers: shared hit=2637 read=20063
Worker 3: actual time=0.292..2913.704 rows=1996368.00 loops=1
Buffers: shared hit=2496 read=20190
Planning Time: 0.084 ms
JIT:
Functions: 12
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 1.182 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.995 ms, Emission 14.458 ms, Total 16.634 ms
Execution Time: 5892.485 ms
(52 rows)
This execution plan follows the same parallel execution model as the previous query. The planner launches four parallel worker processes, and the leader process also participates in the scan, making a total of five processes.
Each process performs a Parallel Sequential Scan on a separate portion of the employee table. After scanning its assigned rows, each process calculates a partial count using the Partial Aggregate node.
The Gather node collects the partial results from all workers and passes them to the Finalize Aggregate node, which combines them to produce the final COUNT(*) result.
Since the table is scanned simultaneously by multiple processes, the workload is distributed across the workers, reducing the overall execution time for the query.
Now, the next debugging level shows many more unwanted lines related to the aio, and now we are going to execute the query by copying the query execution into the file named pq_out_debug3.txt file like this:
postgres@cybrosys:/home/cybrosys$ psql -d postgres -X <<'EOF' > /tmp/pq_out_debug3.txt 2>&1
SELECT * FROM pg_buffercache_evict_relation('employee');
SET client_min_messages = debug3;
SET parallel_setup_cost = 0;
SET parallel_tuple_cost = 0;
SET min_parallel_table_scan_size = 0;
SET max_parallel_workers_per_gather = 2;
EXPLAIN (ANALYZE, VERBOSE) SELECT count(*) FROM employee;
EOF
Check the size of the file like this.
postgres@cybrosys:/home/cybrosys$ ls -lh /tmp/pq_out_debug3.txt
Result:
-rw-rw-r-- 1 postgres postgres 3.7M Oct 31 10:03 /tmp/pq_out_debug3.txt
Now, we can see the file size and we can ensure that the query results are properly written into the file named pq_out_debug3.txt
Now, grep the unwanted lines from this file.
postgres@cybrosys:/home/cybrosys$ for f in /tmp/pq_out.txt /tmp/pq_out_debug3.txt; do
echo "== $f"
grep '^DEBUG' "$f" | sed -E 's/^DEBUG: io [0-9]+ +/DEBUG: io N /; s/[0-9]+/N/g' \
| cut -c1-110 | sort | uniq -c | sort -rn
Done
Result :
== /tmp/pq_out.txt
6321 DEBUG: io N |op readv|target smgr|state STAGED : staged (synchronous: N, in_batch: N)
6321 DEBUG: io N |op readv|target smgr|state DEFINED : calling cb #N N/aio_shared_buffer_readv_cb->stage(N
6321 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: after local completion: result: (status OK, id N, e
6321 DEBUG: io N |op invalid|target smgr|state HANDED_OUT : adding cb #N, id N/aio_md_readv_cb
6321 DEBUG: io N |op invalid|target invalid|state HANDED_OUT : adding cb #N, id N/aio_shared_buffer_readv_cb
8 DEBUG: io N |op readv|target smgr|state COMPLETED_IO : after shared completion: distilled result: (status
3 DEBUG: time to inline: N.Ns, opt: N.Ns, emit: N.Ns
3 DEBUG: successfully loaded JIT provider in current session
3 DEBUG: probing availability of JIT provider at /usr/lib/postgresql/N/lib/llvmjit.so
3 DEBUG: LLVMJIT detected CPU "znverN", with features "-avxNpf,-tsxldtrk,+cxN,+sahf,-tbm,-avxNifma,+sha,+crcN,-
== /tmp/pq_out_debug3.txt
6241 DEBUG: io N |op readv|target smgr|state STAGED : staged (synchronous: N, in_batch: N)
6241 DEBUG: io N |op readv|target smgr|state DEFINED : calling cb #N N/aio_shared_buffer_readv_cb->stage(N
6241 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: after local completion: result: (status OK, id N, e
6241 DEBUG: io N |op invalid|target smgr|state HANDED_OUT : adding cb #N, id N/aio_md_readv_cb
6241 DEBUG: io N |op invalid|target invalid|state HANDED_OUT : adding cb #N, id N/aio_shared_buffer_readv_cb
3 DEBUG: time to inline: N.Ns, opt: N.Ns, emit: N.Ns
3 DEBUG: successfully loaded JIT provider in current session
3 DEBUG: probing availability of JIT provider at /usr/lib/postgresql/N/lib/llvmjit.so
3 DEBUG: LLVMJIT detected CPU "znverN", with features "-avxNpf,-tsxldtrk,+cxN,+sahf,-tbm,-avxNifma,+sha,+crcN,-
postgres@cybrosys:/home/cybrosys$
The output compares the debug messages generated during two executions of the same query.
In both cases, the same sequence of asynchronous I/O operations is observed, including the HANDED_OUT, DEFINED, STAGED, and COMPLETED_SHARED states. The only noticeable difference is the number of I/O operations recorded.
The first execution (pq_out.txt) contains 6,321 occurrences of each I/O state, while the second execution (pq_out_debug3.txt) contains 6,241 occurrences. The COMPLETED_IO messages appear only in the first execution, with 8 occurrences. Apart from this difference, the JIT-related debug messages remain the same in both outputs, showing that the execution path and JIT initialization are unchanged.
The comparison indicates that increasing the debug level does not alter the execution flow but only changes the amount of diagnostic information written to the log.
By the same way, execute this query in debug4 mode like this.
postgres@cybrosys:/home/cybrosys$ psql -d postgres -X <<'EOF' > /tmp/pq_out_debug4.txt 2>&1
SELECT * FROM pg_buffercache_evict_relation('employee');
SET client_min_messages = debug4;
SET parallel_setup_cost = 0;
SET parallel_tuple_cost = 0;
SET min_parallel_table_scan_size = 0;
SET max_parallel_workers_per_gather = 2;
EXPLAIN (ANALYZE, VERBOSE) SELECT count(*) FROM employee;
EOF
Check the file size.
postgres@cybrosys:/home/cybrosys$ ls -lh /tmp/pq_out_debug4.txt
Result:
-rw-rw-r-- 1 postgres postgres 6.4M Oct 31 10:04 /tmp/pq_out_debug4.txt
Now. we can see that each debugging level also increases the number of lines, and that’s why the file size becomes larger by comparing the previous ones.
Grep the unwanted lines in the file and check the result.
postgres@cybrosys:/home/cybrosys$ for f in /tmp/pq_out.txt /tmp/pq_out_debug4.txt; do
echo "== $f"
grep '^DEBUG' "$f" | sed -E 's/^DEBUG: io [0-9]+ +/DEBUG: io N /; s/[0-9]+/N/g' \
| cut -c1-110 | sort | uniq -c | sort -rn
Done
Result:
== /tmp/pq_out.txt
6321 DEBUG: io N |op readv|target smgr|state STAGED : staged (synchronous: N, in_batch: N)
6321 DEBUG: io N |op readv|target smgr|state DEFINED : calling cb #N N/aio_shared_buffer_readv_cb->stage(N
6321 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: after local completion: result: (status OK, id N, e
6321 DEBUG: io N |op invalid|target smgr|state HANDED_OUT : adding cb #N, id N/aio_md_readv_cb
6321 DEBUG: io N |op invalid|target invalid|state HANDED_OUT : adding cb #N, id N/aio_shared_buffer_readv_cb
8 DEBUG: io N |op readv|target smgr|state COMPLETED_IO : after shared completion: distilled result: (status
3 DEBUG: time to inline: N.Ns, opt: N.Ns, emit: N.Ns
3 DEBUG: successfully loaded JIT provider in current session
3 DEBUG: probing availability of JIT provider at /usr/lib/postgresql/N/lib/llvmjit.so
3 DEBUG: LLVMJIT detected CPU "znverN", with features "-avxNpf,-tsxldtrk,+cxN,+sahf,-tbm,-avxNifma,+sha,+crcN,-
== /tmp/pq_out_debug4.txt
6207 DEBUG: io N |op readv|target smgr|state STAGED : staged (synchronous: N, in_batch: N)
6207 DEBUG: io N |op readv|target smgr|state DEFINED : calling cb #N N/aio_shared_buffer_readv_cb->stage(N
6207 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: calling cb #N, id N/aio_shared_buffer_readv_cb->com
6207 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: after local completion: result: (status OK, id N, e
6207 DEBUG: io N |op readv|target smgr|state COMPLETED_LOCAL : reclaiming: distilled_result: (status OK, id N, err
6207 DEBUG: io N |op invalid|target smgr|state HANDED_OUT : adding cb #N, id N/aio_md_readv_cb
6207 DEBUG: io N |op invalid|target invalid|state HANDED_OUT : adding cb #N, id N/aio_shared_buffer_readv_cb
6188 DEBUG: aio: submitted N IOs
6187 DEBUG: io N |op readv|target smgr|state SUBMITTED : choosing worker N
3 DEBUG: time to inline: N.Ns, opt: N.Ns, emit: N.Ns
3 DEBUG: successfully loaded JIT provider in current session
3 DEBUG: probing availability of JIT provider at /usr/lib/postgresql/N/lib/llvmjit.so
3 DEBUG: LLVMJIT detected CPU "znverN", with features "-avxNpf,-tsxldtrk,+cxN,+sahf,-tbm,-avxNifma,+sha,+crcN,-
3 DEBUG: io N |op readv|target smgr|state SUBMITTED : choosing worker -N
postgres@cybrosys:/home/cybrosys$
The comparison shows that debug4 produces more detailed asynchronous I/O messages than the default debug output.
Along with the HANDED_OUT, DEFINED, and STAGED states, it also records additional states such as SUBMITTED, COMPLETED_LOCAL, and extra COMPLETED_SHARED messages. The output includes messages showing when I/O requests are submitted to workers and which worker is selected to process each request.
These additional messages provide a more complete view of the asynchronous I/O lifecycle, from request submission through completion. The JIT-related messages remain unchanged, indicating that the additional output comes from the higher debug level rather than any change in query execution.
Next, use the debug5 mode and check the result.
postgres@cybrosys:/home/cybrosys$ psql -d postgres -X <<'EOF' > /tmp/pq_out_debug5.txt 2>&1
SELECT * FROM pg_buffercache_evict_relation('employee');
SET client_min_messages = debug5;
SET parallel_setup_cost = 0;
SET parallel_tuple_cost = 0;
SET min_parallel_table_scan_size = 0;
SET max_parallel_workers_per_gather = 2;
EXPLAIN (ANALYZE, VERBOSE) SELECT count(*) FROM employee;
EOF
Check the size of this file.
postgres@cybrosys:/home/cybrosys$ ls -lh /tmp/pq_out_debug5.txt
Result:
-rw-rw-r-- 1 postgres postgres 9.7M Oct 31 10:05 /tmp/pq_out_debug5.txt
postgres@cybrosys:/home/cybrosys$
Grep the unwanted lines from the file named pq_out_debug5.
postgres@cybrosys:/home/cybrosys$ for f in /tmp/pq_out.txt /tmp/pq_out_debug5.txt; do
echo "== $f"
grep '^DEBUG' "$f" | sed -E 's/^DEBUG: io [0-9]+ +/DEBUG: io N /; s/[0-9]+/N/g' \
| cut -c1-110 | sort | uniq -c | sort -rn
Done
Result:
== /tmp/pq_out.txt
6321 DEBUG: io N |op readv|target smgr|state STAGED : staged (synchronous: N, in_batch: N)
6321 DEBUG: io N |op readv|target smgr|state DEFINED : calling cb #N N/aio_shared_buffer_readv_cb->stage(N
6321 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: after local completion: result: (status OK, id N, e
6321 DEBUG: io N |op invalid|target smgr|state HANDED_OUT : adding cb #N, id N/aio_md_readv_cb
6321 DEBUG: io N |op invalid|target invalid|state HANDED_OUT : adding cb #N, id N/aio_shared_buffer_readv_cb
8 DEBUG: io N |op readv|target smgr|state COMPLETED_IO : after shared completion: distilled result: (status
3 DEBUG: time to inline: N.Ns, opt: N.Ns, emit: N.Ns
3 DEBUG: successfully loaded JIT provider in current session
3 DEBUG: probing availability of JIT provider at /usr/lib/postgresql/N/lib/llvmjit.so
3 DEBUG: LLVMJIT detected CPU "znverN", with features "-avxNpf,-tsxldtrk,+cxN,+sahf,-tbm,-avxNifma,+sha,+crcN,-
== /tmp/pq_out_debug5.txt
6189 DEBUG: io N |op readv|target smgr|state STAGED : updating state to SUBMITTED
6189 DEBUG: io N |op readv|target smgr|state STAGED : staged (synchronous: N, in_batch: N)
6189 DEBUG: io N |op readv|target smgr|state HANDED_OUT : updating state to DEFINED
6189 DEBUG: io N |op readv|target smgr|state DEFINED : updating state to STAGED
6189 DEBUG: io N |op readv|target smgr|state DEFINED : calling cb #N N/aio_shared_buffer_readv_cb->stage(N
6189 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: updating state to COMPLETED_LOCAL
6189 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: calling cb #N, id N/aio_shared_buffer_readv_cb->com
6189 DEBUG: io N |op readv|target smgr|state COMPLETED_SHARED: after local completion: result: (status OK, id N, e
6189 DEBUG: io N |op readv|target smgr|state COMPLETED_LOCAL : updating state to IDLE
6189 DEBUG: io N |op readv|target smgr|state COMPLETED_LOCAL : reclaiming: distilled_result: (status OK, id N, err
6189 DEBUG: io N |op invalid|target smgr|state HANDED_OUT : adding cb #N, id N/aio_md_readv_cb
6189 DEBUG: io N |op invalid|target invalid|state IDLE : updating state to HANDED_OUT
6189 DEBUG: io N |op invalid|target invalid|state HANDED_OUT : adding cb #N, id N/aio_shared_buffer_readv_cb
6170 DEBUG: io N |op readv|target smgr|state SUBMITTED : choosing worker N
6170 DEBUG: aio: submitted N IOs
6 DEBUG: CommitTransaction(N) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: N/N/N
5 DEBUG: StartTransaction(N) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: N/N/N
3 DEBUG: time to inline: N.Ns, opt: N.Ns, emit: N.Ns
3 DEBUG: successfully loaded JIT provider in current session
3 DEBUG: probing availability of JIT provider at /usr/lib/postgresql/N/lib/llvmjit.so
3 DEBUG: LLVMJIT detected CPU "znverN", with features "-avxNpf,-tsxldtrk,+cxN,+sahf,-tbm,-avxNifma,+sha,+crcN,-
2 DEBUG: CommitTransaction(N) name: unnamed; blockState: PARALLEL_INPROGRESS; state: INPROGRESS, xid/subid/cid:
The debug5 output provides the most detailed view of asynchronous I/O execution. In addition to the messages available at lower debug levels, it records every major state change of an I/O request, including HANDED_OUT, DEFINED, STAGED, SUBMITTED, COMPLETED_SHARED, COMPLETED_LOCAL, and IDLE.
It also logs when I/O requests are submitted, when a worker is selected to process a request, and when completed requests are reclaimed. Unlike the previous outputs, debug5 also includes transaction-related messages such as StartTransaction and CommitTransaction, including transaction activity during parallel execution.
The JIT-related messages remain unchanged, indicating that only the amount of diagnostic information has increased. Overall, debug5 provides the most detailed view of both the asynchronous I/O lifecycle and transaction processing.
PostgreSQL uses query execution to improve the performance of large queries by distributing the work across multiple worker processes. Whether a query runs in parallel depends on planner decisions, including table size, cost estimates and the current parallel worker configuration. Parameters such as max_parallel_workers_per_gather, min_parallel_table_scan_size, parallel_setup_cost, and parallel_tuple_cost influence these decisions and can be adjusted when testing or tuning query execution.
Understanding these planner settings and debugging options helps when analysing query performance troubleshooting parallel query execution or testing planner configurations in a PostgreSQL environment.