RE: Pg10 : Client Configuration for Parallelism ?

Auto explain shows that in both cases there are workers planned, but with DBeaver they are not launched.

Here's what I get with auto_explain :

<DBEAVER>
2019-04-17 14:46:09 CEST;54882;thedbuser;thedb;00000;LOG: 00000: duration: 0.095 ms
2019-04-17 14:46:09 CEST;54882;thedbuser;thedb;00000;LOCATION: exec_parse_message, postgres.c:1433
2019-04-17 14:46:09 CEST;54882;thedbuser;thedb;00000;LOG: 00000: duration: 0.191 ms
2019-04-17 14:46:09 CEST;54882;thedbuser;thedb;00000;LOCATION: exec_bind_message, postgres.c:1813
2019-04-17 14:46:09 CEST;54882;thedbuser;thedb;00000;LOG: 00000: execute <unnamed>: SELECT COUNT(1) FROM big_table
2019-04-17 14:46:09 CEST;54882;thedbuser;thedb;00000;LOCATION: exec_execute_message, postgres.c:1959
2019-04-17 14:46:45 CEST;54882;thedbuser;thedb;00000;LOG: 00000: duration: 35842.146 ms
2019-04-17 14:46:45 CEST;54882;thedbuser;thedb;00000;LOCATION: exec_execute_message, postgres.c:2031
2019-04-17 14:46:45 CEST;54882;thedbuser;thedb;00000;LOG: 00000: duration: 35842.110 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Finalize Aggregate (cost=3081157.61..3081157.62 rows=1 width=8) (actual time=35842.072..35842.072 rows=1 loops=1)
Output: count(1)
-> Gather (cost=3081156.68..3081157.59 rows=9 width=8) (actual time=35842.062..35842.062 rows=1 loops=1)
Output: (PARTIAL count(1))
Workers Planned: 9
Workers Launched: 0
-> Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=35842.060..35842.060 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.036..24038.340 rows=183778867 loops=1)
Heap Fetches: 57043846
2019-04-17 14:46:45 CEST;54882;thedbuser;thedb;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359

<BASIC JDBC>
2019-04-17 14:47:39 CEST;55222;thedbuser;thedb;00000;LOCATION: exec_parse_message, postgres.c:1433
2019-04-17 14:47:39 CEST;55222;thedbuser;thedb;00000;LOG: 00000: duration: 2.077 ms
2019-04-17 14:47:39 CEST;55222;thedbuser;thedb;00000;LOCATION: exec_bind_message, postgres.c:1813
2019-04-17 14:47:39 CEST;55222;thedbuser;thedb;00000;LOG: 00000: execute <unnamed>: SELECT COUNT(1) FROM big_table
2019-04-17 14:47:39 CEST;55222;thedbuser;thedb;00000;LOCATION: exec_execute_message, postgres.c:1959
2019-04-17 14:47:50 CEST;55235;;;00000;LOG: 00000: duration: 11317.118 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11317.095..11317.095 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.135..10036.104 rows=18161056 loops=1)
Heap Fetches: 5569541
2019-04-17 14:47:50 CEST;55235;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55236;;;00000;LOG: 00000: duration: 11316.071 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11316.043..11316.043 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.171..10000.782 rows=18377525 loops=1)
Heap Fetches: 5735254
2019-04-17 14:47:50 CEST;55236;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55237;;;00000;LOG: 00000: duration: 11315.871 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11315.851..11315.852 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.140..10042.102 rows=18082389 loops=1)
Heap Fetches: 5579176
2019-04-17 14:47:50 CEST;55237;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55232;;;00000;LOG: 00000: duration: 11317.573 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11317.553..11317.553 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.115..10047.908 rows=18732838 loops=1)
Heap Fetches: 5849965
2019-04-17 14:47:50 CEST;55232;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55234;;;00000;LOG: 00000: duration: 11317.221 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11317.202..11317.202 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.116..10027.937 rows=18517339 loops=1)
Heap Fetches: 5849910
2019-04-17 14:47:50 CEST;55234;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55238;;;00000;LOG: 00000: duration: 11316.571 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11316.553..11316.554 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.111..10047.353 rows=18722306 loops=1)
Heap Fetches: 5829235
2019-04-17 14:47:50 CEST;55238;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55230;;;00000;LOG: 00000: duration: 11320.223 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11320.198..11320.198 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.132..10040.186 rows=18164384 loops=1)
Heap Fetches: 5585309
2019-04-17 14:47:50 CEST;55230;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55231;;;00000;LOG: 00000: duration: 11319.001 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11318.981..11318.981 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.157..10035.136 rows=18189018 loops=1)
Heap Fetches: 5638358
2019-04-17 14:47:50 CEST;55231;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:50 CEST;55233;;;00000;LOG: 00000: duration: 11317.772 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11317.750..11317.751 rows=1 loops=1)
Output: PARTIAL count(1)
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.113..10036.766 rows=18198240 loops=1)
Heap Fetches: 5627716
2019-04-17 14:47:50 CEST;55233;;;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359
2019-04-17 14:47:51 CEST;55222;thedbuser;thedb;00000;LOG: 00000: duration: 11735.201 ms
2019-04-17 14:47:51 CEST;55222;thedbuser;thedb;00000;LOCATION: exec_execute_message, postgres.c:2031
2019-04-17 14:47:51 CEST;55222;thedbuser;thedb;00000;LOG: 00000: duration: 11735.174 ms plan:
Query Text: SELECT COUNT(1) FROM big_table
Finalize Aggregate (cost=3081157.61..3081157.62 rows=1 width=8) (actual time=11326.891..11326.891 rows=1 loops=1)
Output: count(1)
-> Gather (cost=3081156.68..3081157.59 rows=9 width=8) (actual time=11325.571..11735.108 rows=10 loops=1)
Output: (PARTIAL count(1))
Workers Planned: 9
Workers Launched: 9
-> Partial Aggregate (cost=3080156.68..3080156.69 rows=1 width=8) (actual time=11318.223..11318.223 rows=1 loops=10)
Output: PARTIAL count(1)
Worker 0: actual time=11316.553..11316.554 rows=1 loops=1
Worker 1: actual time=11315.851..11315.852 rows=1 loops=1
Worker 2: actual time=11316.043..11316.043 rows=1 loops=1
Worker 3: actual time=11317.095..11317.095 rows=1 loops=1
Worker 4: actual time=11317.202..11317.202 rows=1 loops=1
Worker 5: actual time=11317.750..11317.751 rows=1 loops=1
Worker 6: actual time=11317.553..11317.553 rows=1 loops=1
Worker 7: actual time=11318.981..11318.981 rows=1 loops=1
Worker 8: actual time=11320.198..11320.198 rows=1 loops=1
-> Parallel Index Only Scan using idx_big_table__inact on big_table (cost=0.57..3029148.07 rows=20403444 width=0) (actual time=0.131..10036.680 rows=18377887 loops=10)
Heap Fetches: 5779382
Worker 0: actual time=0.111..10047.353 rows=18722306 loops=1
Worker 1: actual time=0.140..10042.102 rows=18082389 loops=1
Worker 2: actual time=0.171..10000.782 rows=18377525 loops=1
Worker 3: actual time=0.135..10036.104 rows=18161056 loops=1
Worker 4: actual time=0.116..10027.937 rows=18517339 loops=1
Worker 5: actual time=0.113..10036.766 rows=18198240 loops=1
Worker 6: actual time=0.115..10047.908 rows=18732838 loops=1
Worker 7: actual time=0.157..10035.136 rows=18189018 loops=1
Worker 8: actual time=0.132..10040.186 rows=18164384 loops=1
2019-04-17 14:47:51 CEST;55222;thedbuser;thedb;00000;LOCATION: explain_ExecutorEnd, auto_explain.c:359

-----Message d'origine-----
De : DECHAMBE Laurent DTSI/DSI
Envoyé : mercredi 17 avril 2019 13:26
À : 'Andreas Kretschmer'; pgsql-performance(at)lists(dot)postgresql(dot)org
Objet : RE: Pg10 : Client Configuration for Parallelism ?

I can see whether there is parallelism with pg_top or barely top on the server.

<DBEAVER>
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
38584 postgres 20 0 8863828 8.153g 8.151g R 100.0 3.2 1:23.01 postgres
10 root 20 0 0 0 0 S 0.3 0.0 88:07.26 rcu_sched

<BASIC JDBC>
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
46687 postgres 20 0 8864620 0.978g 0.977g S 38.5 0.4 0:01.16 postgres
46689 postgres 20 0 8864348 996.4m 995.1m R 38.5 0.4 0:01.16 postgres
46690 postgres 20 0 8864348 987.2m 985.8m S 38.5 0.4 0:01.16 postgres
46691 postgres 20 0 8864348 998436 997084 R 38.5 0.4 0:01.16 postgres
46692 postgres 20 0 8864348 982612 981260 S 38.5 0.4 0:01.16 postgres
46693 postgres 20 0 8864348 979.9m 978.6m R 38.5 0.4 0:01.16 postgres
46694 postgres 20 0 8864348 987.9m 986.6m S 38.5 0.4 0:01.16 postgres
46696 postgres 20 0 8864348 996864 995512 S 38.5 0.4 0:01.16 postgres
46688 postgres 20 0 8864348 982.3m 981.0m R 38.2 0.4 0:01.15 postgres
46695 postgres 20 0 8864348 986.9m 985.6m S 38.2 0.4 0:01.15 postgres
21323 postgres 20 0 8862788 8.096g 8.095g S 0.7 3.2 2:24.75 postgres
46682 postgres 20 0 157996 2596 1548 R 0.7 0.0 0:00.05 top

This is not a matter of cache. If I execute the queries in a different order the result will be the same : DBeaver query is longer.

There is something in documentation that says that there won't be parallelism if " The client sends an Execute message with a non-zero fetch count."
I am not sure what this sentence means.

-----Message d'origine-----
De : Andreas Kretschmer [mailto:andreas(at)a-kretschmer(dot)de]
Envoyé : mercredi 17 avril 2019 12:39
À : pgsql-performance(at)lists(dot)postgresql(dot)org
Objet : Re: Pg10 : Client Configuration for Parallelism ?

Am 17.04.19 um 11:51 schrieb laurent(dot)dechambe(at)orange(dot)com:
>
> Here are the logs (with log_error_verbosity = verbose) :
>
> <DBEAVER>
>
> 2019-04-17 11:30:42 CEST;35895;thedbuser;thedb;00000;LOG:  00000:
> execute <unnamed>: SELECT COUNT(1) FROM big_table
>
> 2019-04-17 11:30:42 CEST;35895;thedbuser;thedb;00000;LOCATION:
> exec_execute_message, postgres.c:1959
>
> 2019-04-17 11:31:08 CEST;35895;thedbuser;thedb;00000;LOG:  00000:
> duration: 25950.908 ms
>
> <BASIC JDBC>
>
> 2019-04-17 11:31:20 CEST;37257;thedbuser;thedb;00000;LOG:  00000:
> execute <unnamed>: SELECT COUNT(1) FROM big_table
>
> 2019-04-17 11:31:20 CEST;37257;thedbuser;thedb;00000;LOCATION:
> exec_execute_message, postgres.c:1959
>
> 2019-04-17 11:31:32 CEST;37257;thedbuser;thedb;00000;LOG:  00000:
> duration: 11459.943 ms
>
>
> <PGADMIN4>
>
> 2019-04-17 11:32:56 CEST;37324;thedbuser;thedb;00000;LOG:  00000:
> statement: SELECT COUNT(1) FROM big_table;
>
> 2019-04-17 11:32:56 CEST;37324;thedbuser;thedb;00000;LOCATION: 
> exec_simple_query, postgres.c:940
>
> 2019-04-17 11:33:08 CEST;37324;thedbuser;thedb;00000;LOG:  00000:
> duration: 11334.677 ms
>
>

That's compareable. The first one took more time, cold cache. The 2nd
and 3rd are faster, warm cache.

But: we can't see if the execution is paralell or not. If you want to
know that, install and use auto_explain.

Regards, Andreas

--
2ndQuadrant - The PostgreSQL Support Company.
www.2ndQuadrant.com

_________________________________________________________________________________________________________________________

Ce message et ses pieces jointes peuvent contenir des informations confidentielles ou privilegiees et ne doivent donc
pas etre diffuses, exploites ou copies sans autorisation. Si vous avez recu ce message par erreur, veuillez le signaler
a l'expediteur et le detruire ainsi que les pieces jointes. Les messages electroniques etant susceptibles d'alteration,
Orange decline toute responsabilite si ce message a ete altere, deforme ou falsifie. Merci.

This message and its attachments may contain confidential or privileged information that may be protected by law;
they should not be distributed, used or copied without authorisation.
If you have received this email in error, please notify the sender and delete this message and its attachments.
As emails may be altered, Orange is not liable for messages that have been modified, changed or falsified.
Thank you.