Обсуждение: BUG #15726: parallel queries failed ERROR: invalid name syntax CONTEXT: parallel worker

Поиск
Список
Период
Сортировка

BUG #15726: parallel queries failed ERROR: invalid name syntax CONTEXT: parallel worker

От
PG Bug reporting form
Дата:
The following bug has been logged on the website:

Bug reference:      15726
Logged by:          Tiago ANASTACIO
Email address:      tiago_anastacio@yahoo.fr
PostgreSQL version: 11.2
Operating system:   Red Hat Enterprise Linux Server release 7.1 (Maipo
Description:

Hello, I'am using the reporting procedure describe on wiki.

1 - Description
--------------------
I create a sample table, insert data, analyze it, select count(*) and
finally create index
All parallel queries display immediatly an error:
ERROR:  invalid name syntax
CONTEXT:  parallel worker

appli3=# create table test1(col1 bigint);
CREATE TABLE
appli3=# insert into test1 select generate_series(1,10000000);
INSERT 0 10000000
appli3=# analyse test1;
ANALYZE
appli3=# explain select count(*) from appli3adm.test1;
                                        QUERY PLAN
------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=97331.80..97331.81 rows=1 width=8)
   ->  Gather  (cost=97331.58..97331.79 rows=2 width=8)
         Workers Planned: 2
         ->  Partial Aggregate  (cost=96331.58..96331.59 rows=1 width=8)
               ->  Parallel Seq Scan on test1  (cost=0.00..85914.87
rows=4166687 width=0)
(5 rows)

appli3=# select count(*) from appli3adm.test1;
ERROR:  invalid name syntax
CONTEXT:  parallel worker
appli3=# create index test_1_col1_idx on appli3adm.test1(col1);
ERROR:  invalid name syntax
CONTEXT:  parallel worker
appli3=#

All postgresql Logs:
--------------------------
2019-04-01 12:38:27 CEST [22962]: [3-1]
user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=00000,client=[local] LOG:
statement: create table test1(col1 bigint);
2019-04-01 12:38:47 CEST [22962]: [4-1]
user=dbaappli3,db=appli3,app=psql,xid=930,sqlstate=00000,client=[local] LOG:
 duration: 9747.640 ms  plan:
        Query Text: insert into test1 select generate_series(1,10000000);
        Insert on appli3adm.test1  (cost=0.00..17.52 rows=1000 width=8)
          ->  Subquery Scan on "*SELECT*"  (cost=0.00..17.52 rows=1000
width=8)
                Output: "*SELECT*".generate_series
                ->  ProjectSet  (cost=0.00..5.02 rows=1000 width=4)
                      Output: generate_series(1, 10000000)
                      ->  Result  (cost=0.00..0.01 rows=1 width=0)
2019-04-01 10:40:10.064 GMT [23473] ERROR:  invalid name syntax
2019-04-01 12:40:10 CEST [22962]: [5-1]
user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=42602,client=[local] ERROR:
 invalid name syntax
2019-04-01 12:40:10 CEST [22962]: [6-1]
user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=42602,client=[local]
CONTEXT:  parallel worker
2019-04-01 12:40:10 CEST [22962]: [7-1]
user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=42602,client=[local]
STATEMENT:  select count(*) from appli3adm.test1;
2019-04-01 10:40:10.065 GMT [23474] ERROR:  invalid name syntax
2019-04-01 12:40:10 CEST [22556]: [9-1]
user=,db=,app=,xid=0,sqlstate=00000,client= LOG:  background worker
"parallel worker" (PID 23473) exited with exit code 1
2019-04-01 12:40:10 CEST [22556]: [10-1]
user=,db=,app=,xid=0,sqlstate=00000,client= LOG:  background worker
"parallel worker" (PID 23474) exited with exit code 1
2019-04-01 12:40:21 CEST [22962]: [8-1]
user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=00000,client=[local] LOG:
statement: create index test_1_col1_idx on appli3adm.test1(col1);
2019-04-01 10:40:21.784 GMT [23546] ERROR:  invalid name syntax
2019-04-01 10:40:21.784 GMT [23547] ERROR:  invalid name syntax
2019-04-01 12:40:21 CEST [22962]: [9-1]
user=dbaappli3,db=appli3,app=psql,xid=933,sqlstate=42602,client=[local]
ERROR:  invalid name syntax
2019-04-01 12:40:21 CEST [22962]: [10-1]
user=dbaappli3,db=appli3,app=psql,xid=933,sqlstate=42602,client=[local]
CONTEXT:  parallel worker
2019-04-01 12:40:21 CEST [22962]: [11-1]
user=dbaappli3,db=appli3,app=psql,xid=933,sqlstate=42602,client=[local]
STATEMENT:  create index test_1_col1_idx on appli3adm.test1(col1);
2019-04-01 12:40:21 CEST [22556]: [11-1]
user=,db=,app=,xid=0,sqlstate=00000,client= LOG:  background worker
"parallel worker" (PID 23547) exited with exit code 1
2019-04-01 12:40:21 CEST [22556]: [12-1]
user=,db=,app=,xid=0,sqlstate=00000,client= LOG:  background worker
"parallel worker" (PID 23546) exited with exit code 1
2019-04-01 12:40:36 CEST [22962]: [12-1]
user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=00000,client=[local] LOG:
disconnection: session time: 0:02:18.357 user=dbaappli3 database=appli3
host=[local]


2 - postgresql version()
-------------------------------
appli3=# select version();
                                                 version
---------------------------------------------------------------------------------------------------------
 PostgreSQL 11.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5
20150623 (Red Hat 4.8.5-36), 64-bit
(1 row)

3 - Postgresql installation
-----------------------------------
community packages for red hat from
http://download.postgresql.org/pub/repos/yum/11/redhat/
lxts247a:/etc$yum list installed | grep ^postgresql11
postgresql11.x86_64                   11.2-2PGDG.rhel7
@/postgresql11-11.2-2PGDG.rhel7.x86_64
postgresql11-contrib.x86_64           11.2-2PGDG.rhel7
@/postgresql11-contrib-11.2-2PGDG.rhel7.x86_64
postgresql11-libs.x86_64              11.2-2PGDG.rhel7
@/postgresql11-libs-11.2-2PGDG.rhel7.x86_64
postgresql11-llvmjit.x86_64           11.2-2PGDG.rhel7
@/postgresql11-llvmjit-11.2-2PGDG.rhel7.x86_64
postgresql11-plpython.x86_64          11.2-2PGDG.rhel7
@/postgresql11-plpython-11.2-2PGDG.rhel7.x86_64
postgresql11-server.x86_64            11.2-2PGDG.rhel7
@/postgresql11-server-11.2-2PGDG.rhel7.x86_64

4 - Changes made to postgresql.conf from the sample file
/usr/pgsql-11/share/postgresql.conf.sample
----------------------------------------------------------------------------
listen_addresses = '*'
port = 54322
superuser_reserved_connections = 6
unix_socket_directories = '/var/run/postgresql
unix_socket_permissions = 0722
authentication_timeout = 20s
password_encryption = md5
ssl = on
ssl_ca_file = '/home/appli3/appli/connexion/dbaappli3/tls/root.crt'
ssl_cert_file = '/home/appli3/appli/connexion/dbaappli3/tls/server.crt'
ssl_key_file = '/home/appli3/appli/connexion/dbaappli3/tls/server.key'
shared_buffers =  2GB
temp_buffers = 32MB
work_mem = 128MB
maintenance_work_mem = 3GB
autovacuum_work_mem = 64MB
max_stack_depth = 6MB 
vacuum_cost_limit = 2000
effective_io_concurrency = 256
effective_io_concurrency = 256                
max_worker_processes = 8              
max_parallel_maintenance_workers = 2 
max_parallel_workers_per_gather = 2  
parallel_leader_participation = on
max_parallel_workers = 4              
wal_level = replica
fsync = on
synchronous_commit = remote_write
wal_compression = on
wal_log_hints = on
checkpoint_timeout = 30min
max_wal_size = 15GB
checkpoint_completion_target = 0.9
archive_mode = on
 archive_command = 'test ! -f /home/backupdb/appli3/archxlog/%f.gz && cp %p
/home/backupdb/appli3/archxlog/%f && gzip /home/backupdb/appli3/archxlog/%f'
              # command to use to archive a logfile segment
 archive_timeout = 60s
max_wal_senders = 18
wal_keep_segments = 0
max_replication_slots = 8
hot_standby = on
random_page_cost = 1.0
 effective_cache_size = 6GB
 jit = on
log_checkpoints = on
log_connections = on
log_disconnections = on
log_line_prefix = '%t [%p]: [%l-1]
user=%u,db=%d,app=%a,xid=%x,sqlstate=%e,client=%h ' 
log_statement = 'ddl'                 # none, ddl, mod, all
log_temp_files = 4MB                  # log temporary files equal or
larger
log_timezone = 'Europe/Paris'
 cluster_name = 'appli3' 
track_io_timing = on
track_functions = all                 # none, pl, all
track_activity_query_size = 65536     # (change requires restart)
 autovacuum = on
 log_autovacuum_min_duration = 60000
autovacuum_vacuum_scale_factor = 0.01
autovacuum_analyze_scale_factor = 0.10
search_path = 'appli3adm, common, dba, "$user"'
default_tablespace = 'data'
temp_tablespaces = 'data'
lc_messages = 'C'
lc_monetary = 'fr_FR.utf8'
lc_numeric = 'fr_FR.utf8'
lc_time = 'fr_FR.utf8' 
default_text_search_config = ''  #default 'pg_catalog.simple'
shared_preload_libraries = 'auto_explain, pg_stat_statements, auth_delay,
passwordcheck, plugin_debugger, repmgr'
 max_locks_per_transaction = 256
 include_dir = 'pg_includes'
include_if_exists =
'/home/appli3/appli/connexion/dbaappli3/custom/postgresql_custom.conf' 
 auth_delay.milliseconds = 100          
 auto_explain.log_min_duration = '5s'
 auto_explain.log_analyze = off         
 auto_explain.log_buffers = on          
 auto_explain.log_timing = on           
 auto_explain.log_triggers = on         
 auto_explain.log_verbose = on          
 auto_explain.log_format = text         
 auto_explain.log_nested_statements = on
 pg_stat_statements.max  = 10000        
 pg_stat_statements.track = all         
                                        
4 - OS details
------------------
OS
-----
Red Hat Enterprise Linux Server release 7.1 (Maipo)

Kernel
--------
lxts247a:/tmp$uname -a
Linux lxts247a 3.10.0-229.el7.x86_64 #1 SMP Thu Jan 29 18:37:38 EST 2015
x86_64 x86_64 x86_64 GNU/Linux

CPU:
-------
lxts247a:/etc$lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                12
On-line CPU(s) list:   0-11
Thread(s) per core:    1
Core(s) per socket:    12
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 63
Model name:            Intel(R) Xeon(R) CPU E5-2670 v3 @ 2.30GHz
Stepping:              2
CPU MHz:               2297.339
BogoMIPS:              4594.67
Hypervisor vendor:     VMware
Virtualization type:   full
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              30720K
NUMA node0 CPU(s):     0-11

MEMORY
-------------
lxts247a:/etc$free
              total        used        free      shared  buff/cache
available
Mem:       32782068     1139348     2799556      686408    28843164
30606124
Swap:       4194300         436     4193864

6 - full logs are describe on 1-
Full error message is:
 ERROR:  invalid name syntax
CONTEXT:  parallel worker

7- client
-----------
local psql 
lxts247a:/tmp$psql -V
psql (PostgreSQL) 11.2

8-log 
I ssee nothing special in the logs parallel_workers are new to me.


Thank you very much for your help guys

Tiago ANASTACIO
Independant DBA


Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Michael Paquier
Дата:
On Mon, Apr 01, 2019 at 11:12:16AM +0000, PG Bug reporting form wrote:
> appli3=# select count(*) from appli3adm.test1;
> ERROR:  invalid name syntax
> CONTEXT:  parallel worker

I cannot reproduce your problem at hand on HEAD or REL_11_STABLE,
though I can get the same place as you do.  The error message is very
specific to varlena.c or regproc.c, so that's a clear hint, but I am
wondering what's wrong.

> include_if_exists =
> '/home/appli3/appli/connexion/dbaappli3/custom/postgresql_custom.conf'

Do you have anything specific in that?
--
Michael

Вложения

Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
ANASTACIO Tiago
Дата:

Le lundi 1 avril 2019 à 15:29:31 UTC+2, Michael Paquier <michael@paquier.xyz> a écrit :


On Mon, Apr 01, 2019 at 11:12:16AM +0000, PG Bug reporting form wrote:
> appli3=# select count(*) from appli3adm.test1;
> ERROR:  invalid name syntax
> CONTEXT:  parallel worker

I cannot reproduce your problem at hand on HEAD or REL_11_STABLE,
though I can get the same place as you do.  The error message is very
specific to varlena.c or regproc.c, so that's a clear hint, but I am
wondering what's wrong.

> include_if_exists =
> '/home/appli3/appli/connexion/dbaappli3/custom/postgresql_custom.conf'

Do you have anything specific in that?



Thank you.

Actually I did not event create this file /home/appli3/appli/connexion/dbaappli3/custom/postgresql_custom.conf    (just set the parameter in case of).

I put the debug5 logs of potgres above (previous ones where INFO level)

Also we use systemd so I launched PostgreSQL with pg_ctl directly : same behavior (an error)

2019-04-01 15:44:51 CEST [1717]: [14-1] user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=00000,client=[local] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 15:44:51 CEST [14860]: [527-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  registering background worker "parallel worker for PID 1717"
2019-04-01 15:44:51 CEST [14860]: [528-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  registering background worker "parallel worker for PID 1717"
2019-04-01 15:44:51 CEST [14860]: [529-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  starting background worker process "parallel worker for PID 1717"
2019-04-01 15:44:51 CEST [14860]: [530-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  starting background worker process "parallel worker for PID 1717"
2019-04-01 15:44:51 CEST [1833]: [1-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  InitPostgres
2019-04-01 15:44:51 CEST [1833]: [2-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  my backend ID is 4
2019-04-01 15:44:51 CEST [1834]: [1-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  InitPostgres
2019-04-01 15:44:51 CEST [1834]: [2-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  my backend ID is 5
2019-04-01 15:44:51 CEST [1833]: [3-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 15:44:51 CEST [1834]: [3-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 15:44:51 CEST [1833]: [4-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 15:44:51 CEST [1833]: [5-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 15:44:51 CEST [1834]: [4-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 15:44:51 CEST [1834]: [5-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-04-01 13:44:51.603 GMT [1833] ERROR:  invalid name syntax
2019-04-01 15:44:51 CEST [1717]: [15-1] user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=42602,client=[local] ERROR:  invalid name syntax
2019-04-01 15:44:51 CEST [1717]: [16-1] user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=42602,client=[local] CONTEXT:  parallel worker
2019-04-01 15:44:51 CEST [1717]: [17-1] user=dbaappli3,db=appli3,app=psql,xid=0,sqlstate=42602,client=[local] STATEMENT:  select count(*) from appli3adm.test1;
2019-04-01 13:44:51.604 GMT [1834] ERROR:  invalid name syntax
2019-04-01 15:44:51 CEST [14860]: [531-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  reaping dead processes
2019-04-01 15:44:51 CEST [14860]: [532-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  unregistering background worker "parallel worker for PID 1717"
2019-04-01 15:44:51 CEST [14860]: [533-1] user=,db=,app=,xid=0,sqlstate=00000,client= LOG:  background worker "parallel worker" (PID 1833) exited with exit code 1
2019-04-01 15:44:51 CEST [14860]: [534-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  reaping dead processes
2019-04-01 15:44:51 CEST [14860]: [535-1] user=,db=,app=,xid=0,sqlstate=00000,client= DEBUG:  unregistering background worker "parallel worker for PID 1717"
2019-04-01 15:44:51 CEST [14860]: [536-1] user=,db=,app=,xid=0,sqlstate=00000,client= LOG:  background worker "parallel worker" (PID 1834) exited with exit code 1

Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Tue, Apr 2, 2019 at 12:24 AM PG Bug reporting form
<noreply@postgresql.org> wrote:
> default_text_search_config = ''  #default 'pg_catalog.simple'

That causes problems for parallel workers.  The stack looks like this:

    frame #3: 0x00000001007772d9
postgres`errfinish(dummy=<unavailable>) at elog.c:552:3 [opt]
    frame #4: 0x00000001007082ab
postgres`stringToQualifiedNameList(string=<unavailable>) at
regproc.c:0:3 [opt]
    frame #5: 0x0000000100773995
postgres`check_TSCurrentConfig(newval=0x00007ffeef918850,
extra=<unavailable>, source=PGC_S_ARGV) at ts_cache.c:603:29 [opt]
    frame #6: 0x0000000100793bc5
postgres`call_string_check_hook(conf=0x00000001009d04f8,
newval=0x00007ffeef918850, extra=<unavailable>, source=<unavailable>,
elevel=20) at guc.c:10611:7 [opt]
    frame #7: 0x00000001007933f1
postgres`parse_and_validate_value(record=0x00000001009d04f8,
name=<unavailable>, value=<unavailable>, source=PGC_S_ARGV, elevel=20,
newval=0x00007ffeef918850, newextra=0x00007ffeef918848) at
guc.c:6544:10 [opt]
    frame #8: 0x00000001007918ea
postgres`set_config_option(name="default_text_search_config",
value="\x03", context=<unavailable>, source=PGC_S_ARGV,
action=GUC_ACTION_SET, changeVal=<unavailable>, elevel=17973805,
is_reload=<unavailable>) at guc.c:7147:11 [opt]
    frame #9: 0x00000001007990ce
postgres`RestoreGUCState(gucstate=<unavailable>) at guc.c:10065:12
[opt]
    frame #10: 0x0000000100382e9b
postgres`ParallelWorkerMain(main_arg=<unavailable>) at
parallel.c:1360:2 [opt]

Why is the empty string acceptable to the master but not with
RestoreGUCState() in a parallel worker?

-- 
Thomas Munro
https://enterprisedb.com



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Tue, Apr 2, 2019 at 10:59 AM Thomas Munro <thomas.munro@gmail.com> wrote:
> On Tue, Apr 2, 2019 at 12:24 AM PG Bug reporting form
> <noreply@postgresql.org> wrote:
> > default_text_search_config = ''  #default 'pg_catalog.simple'
>
> That causes problems for parallel workers.  The stack looks like this:

> Why is the empty string acceptable to the master but not with
> RestoreGUCState() in a parallel worker?

Because check_TSCurrentConfig() only reports and error if there is an
active transaction.  So you can see this without parallelism like
this:

postgres=# begin;
BEGIN
postgres=# set default_text_search_config = '';
psql: ERROR:  invalid name syntax

I think the short term answer is that you need a better value for
default_text_search_config.  It's unfortunate that this error is
normally hidden, but then jumps out with an incomprehensible message
when you run a parallel query.  Perhaps someone who knows more about
TS than me could comment on whether this should be considered a bug?

-- 
Thomas Munro
https://enterprisedb.com



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Tue, Apr 2, 2019 at 1:24 PM Thomas Munro <thomas.munro@gmail.com> wrote:
> postgres=# begin;
> BEGIN
> postgres=# set default_text_search_config = '';
> psql: ERROR:  invalid name syntax

Erm -- obviously that BEGIN was unnecessary and you see the error
without it.  Anyway, the point I was making is that you don't get an
error if you set it in postgresql.conf, but you do if you set it in
other contexts, including the parallel worker startup sequence.  I
wondered if this might have been a consequence of the parallel startup
reordering that happened with commit 6c3c9d41, but nope --
RestoreGUCState() was always run inside a transaction.

-- 
Thomas Munro
https://enterprisedb.com



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Peter Geoghegan
Дата:
On Mon, Apr 1, 2019 at 5:33 PM Thomas Munro <thomas.munro@gmail.com> wrote:
> Erm -- obviously that BEGIN was unnecessary and you see the error
> without it.  Anyway, the point I was making is that you don't get an
> error if you set it in postgresql.conf, but you do if you set it in
> other contexts, including the parallel worker startup sequence.  I
> wondered if this might have been a consequence of the parallel startup
> reordering that happened with commit 6c3c9d41, but nope --
> RestoreGUCState() was always run inside a transaction.

I wonder if this known issue is relevant here:

https://www.postgresql.org/message-id/20153.1523471686%40sss.pgh.pa.us

-- 
Peter Geoghegan



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
ANASTACIO Tiago
Дата:
Thank you guys. I fixed the parameter and it worked.

A pity background worker are no more verbose (DEBUG5) than:

2019-04-02 09:42:38.993 GMT [17654] ERROR:  invalid name syntax

About Tracing
I used strace and grep background woker pid. But I didn't get that trace, which tool did you use ?


Le mardi 2 avril 2019 à 02:41:40 UTC+2, Peter Geoghegan <pg@bowt.ie> a écrit :


>On Mon, Apr 1, 2019 at 5:33 PM Thomas Munro <thomas.munro@gmail.com> wrote:

>> Erm -- obviously that BEGIN was unnecessary and you see the error
>> without it.  Anyway, the point I was making is that you don't get an
>> error if you set it in postgresql.conf, but you do if you set it in
>> other contexts, including the parallel worker startup sequence.  I

>> wondered if this might have been a consequence of the parallel startup
>> reordering that happened with commit 6c3c9d41, but nope --
>> RestoreGUCState() was always run inside a transaction.


>I wonder if this known issue is relevant here:

>https://www.postgresql.org/message-id/20153.1523471686%40sss.pgh.pa.us

>--
>Peter Geoghegan

Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Tue, Apr 2, 2019 at 10:59 PM ANASTACIO Tiago
<tiago_anastacio@yahoo.fr> wrote:
> A pity background worker are no more verbose (DEBUG5) than:
>
> 2019-04-02 09:42:38.993 GMT [17654] ERROR:  invalid name syntax

I agree, it would be nice to improve that.  It seems to be a general
problem with any GUC that requires a transaction to check: parallel
workers will force that, but you might not understand the error
because it comes with no context.  That gives me an idea: perhaps we
should set the elog() context while restoring GUCs, so that it is
displayed in the error output somehow.

> About Tracing
> I used strace and grep background woker pid. But I didn't get that trace, which tool did you use ?

I modified the source so that all the elog() calls that produce that
message were at PANIC level (which means abort(), which delivers
SIGABRT, which normally dumps core) instead of ERROR level, then I ran
ulimit -c unlimited to make sure my OS would dump core files before
starting the server, then I triggered the error, then I loaded the
resulting core file into my debugger and ran bt to see the backtrace
and understand how we finished up there.

-- 
Thomas Munro
https://enterprisedb.com



Re: BUG #15726: parallel queries failed ERROR: invalid name syntax CONTEXT: parallel worker

От
Tom Lane
Дата:
Thomas Munro <thomas.munro@gmail.com> writes:
> On Tue, Apr 2, 2019 at 10:59 PM ANASTACIO Tiago
> <tiago_anastacio@yahoo.fr> wrote:
>> A pity background worker are no more verbose (DEBUG5) than:
>> 2019-04-02 09:42:38.993 GMT [17654] ERROR:  invalid name syntax

> I agree, it would be nice to improve that.  It seems to be a general
> problem with any GUC that requires a transaction to check: parallel
> workers will force that, but you might not understand the error
> because it comes with no context.  That gives me an idea: perhaps we
> should set the elog() context while restoring GUCs, so that it is
> displayed in the error output somehow.

Yeah, something like

CONTEXT: while setting parameter guc_variable_name to "some value"

would likely make this a whole lot more comprehensible.  And I think
it could probably be done in a fairly centralized way using an error
callback.

            regards, tom lane



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Wed, Apr 3, 2019 at 4:19 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Thomas Munro <thomas.munro@gmail.com> writes:
> > On Tue, Apr 2, 2019 at 10:59 PM ANASTACIO Tiago
> > <tiago_anastacio@yahoo.fr> wrote:
> >> A pity background worker are no more verbose (DEBUG5) than:
> >> 2019-04-02 09:42:38.993 GMT [17654] ERROR:  invalid name syntax
>
> > I agree, it would be nice to improve that.  It seems to be a general
> > problem with any GUC that requires a transaction to check: parallel
> > workers will force that, but you might not understand the error
> > because it comes with no context.  That gives me an idea: perhaps we
> > should set the elog() context while restoring GUCs, so that it is
> > displayed in the error output somehow.
>
> Yeah, something like
>
> CONTEXT: while setting parameter guc_variable_name to "some value"
>
> would likely make this a whole lot more comprehensible.  And I think
> it could probably be done in a fairly centralized way using an error
> callback.

Would you want to do it for GUC setting in general (for example using
the SET command), or just in this GUC-restore-for-parallel-query case?
 Here's a 10 minute attempt at the latter.

postgres=# set force_parallel_mode = 'on';
SET
postgres=# select 42;
psql: ERROR:  invalid name syntax
CONTEXT:  while setting parameter "default_text_search_config" to ""
parallel worker

It gets a bit repetitive in some other cases where it was already
reporting the name and value, though:
postgres=# select 42;
psql: ERROR:  invalid value for parameter "default_text_search_config": "foo"
CONTEXT:  while setting parameter "default_text_search_config" to "foo"
parallel worker

-- 
Thomas Munro
https://enterprisedb.com

Вложения

Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Daniel Gustafsson
Дата:
> On 2 Apr 2019, at 21:54, Thomas Munro <thomas.munro@gmail.com> wrote:
>
> On Wed, Apr 3, 2019 at 4:19 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Thomas Munro <thomas.munro@gmail.com> writes:
>>> On Tue, Apr 2, 2019 at 10:59 PM ANASTACIO Tiago
>>> <tiago_anastacio@yahoo.fr> wrote:
>>>> A pity background worker are no more verbose (DEBUG5) than:
>>>> 2019-04-02 09:42:38.993 GMT [17654] ERROR:  invalid name syntax
>>
>>> I agree, it would be nice to improve that.  It seems to be a general
>>> problem with any GUC that requires a transaction to check: parallel
>>> workers will force that, but you might not understand the error
>>> because it comes with no context.  That gives me an idea: perhaps we
>>> should set the elog() context while restoring GUCs, so that it is
>>> displayed in the error output somehow.
>>
>> Yeah, something like
>>
>> CONTEXT: while setting parameter guc_variable_name to "some value"
>>
>> would likely make this a whole lot more comprehensible.  And I think
>> it could probably be done in a fairly centralized way using an error
>> callback.
>
> Would you want to do it for GUC setting in general (for example using
> the SET command), or just in this GUC-restore-for-parallel-query case?
> Here's a 10 minute attempt at the latter.

I think only doing it for the latter makes sense, when invoking the SET command
it’s more reasonable to associate the ERROR with the performed action.

> postgres=# set force_parallel_mode = 'on';
> SET
> postgres=# select 42;
> psql: ERROR:  invalid name syntax
> CONTEXT:  while setting parameter "default_text_search_config" to ""
> parallel worker

This makes it a lot better, but I wonder if it needs even more clarification to
be easily understandable by users not familiar with how parallel workers are
initiated.  I’m thinking we should add “during worker setup” or something
similar to make it even clearer, albeit more verbose.

> It gets a bit repetitive in some other cases where it was already
> reporting the name and value, though:
> postgres=# select 42;
> psql: ERROR:  invalid value for parameter "default_text_search_config": "foo"
> CONTEXT:  while setting parameter "default_text_search_config" to "foo"
> parallel worker

It is indeed repetetive, but I’m not sure it’s worth addressing that.
Consistency in error messaging seems more important in this case.

cheers ./daniel


Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Thu, Apr 11, 2019 at 8:59 PM Daniel Gustafsson
<dgustafsson@pivotal.io> wrote:
> > On 2 Apr 2019, at 21:54, Thomas Munro <thomas.munro@gmail.com> wrote:
> > psql: ERROR:  invalid name syntax
> > CONTEXT:  while setting parameter "default_text_search_config" to ""
> > parallel worker
>
> This makes it a lot better, but I wonder if it needs even more clarification to
> be easily understandable by users not familiar with how parallel workers are
> initiated.  I’m thinking we should add “during worker setup” or something
> similar to make it even clearer, albeit more verbose.

Thanks for the review.  How about this?

postgres=# set force_parallel_mode = on;
SET
postgres=# select 42;
psql: ERROR:  invalid name syntax
CONTEXT:  while setting parameter "default_text_search_config" to ""
in a parallel worker process
parallel worker

I think this is a bug and should be back-patched.  Objections?

--
Thomas Munro
https://enterprisedb.com

Вложения

Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Daniel Gustafsson
Дата:
> On 11 Apr 2019, at 12:51, Thomas Munro <thomas.munro@gmail.com> wrote:
>
> On Thu, Apr 11, 2019 at 8:59 PM Daniel Gustafsson
> <dgustafsson@pivotal.io> wrote:
>>> On 2 Apr 2019, at 21:54, Thomas Munro <thomas.munro@gmail.com> wrote:
>>> psql: ERROR:  invalid name syntax
>>> CONTEXT:  while setting parameter "default_text_search_config" to ""
>>> parallel worker
>>
>> This makes it a lot better, but I wonder if it needs even more clarification to
>> be easily understandable by users not familiar with how parallel workers are
>> initiated.  I’m thinking we should add “during worker setup” or something
>> similar to make it even clearer, albeit more verbose.
>
> Thanks for the review.  How about this?
>
> postgres=# set force_parallel_mode = on;
> SET
> postgres=# select 42;
> psql: ERROR:  invalid name syntax
> CONTEXT:  while setting parameter "default_text_search_config" to ""
> in a parallel worker process
> parallel worker

Looks good, I think the extra verbosity is worth it to help users.

> I think this is a bug and should be back-patched.  Objections?

No objections.

cheers ./daniel


Re: BUG #15726: parallel queries failed ERROR: invalid name syntax CONTEXT: parallel worker

От
Tom Lane
Дата:
Thomas Munro <thomas.munro@gmail.com> writes:
> Thanks for the review.  How about this?

> postgres=# set force_parallel_mode = on;
> SET
> postgres=# select 42;
> psql: ERROR:  invalid name syntax
> CONTEXT:  while setting parameter "default_text_search_config" to ""
> in a parallel worker process
> parallel worker

The extra appearance of "parallel worker" seems a bit redundant,
though I don't know if we can get rid of it.

Could we at least be consistent about whether the context is
"parallel worker" or "parallel worker process"?

            regards, tom lane



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Michael Paquier
Дата:
On Thu, Apr 11, 2019 at 11:04:14AM -0400, Tom Lane wrote:
> The extra appearance of "parallel worker" seems a bit redundant,
> though I don't know if we can get rid of it.
>
> Could we at least be consistent about whether the context is
> "parallel worker" or "parallel worker process"?

Indeed.  My vote would be to back-patch that stuff.
--
Michael

Вложения

Re: BUG #15726: parallel queries failed ERROR: invalid name syntax CONTEXT: parallel worker

От
Tom Lane
Дата:
Michael Paquier <michael@paquier.xyz> writes:
> On Thu, Apr 11, 2019 at 11:04:14AM -0400, Tom Lane wrote:
>> The extra appearance of "parallel worker" seems a bit redundant,
>> though I don't know if we can get rid of it.
>> 
>> Could we at least be consistent about whether the context is
>> "parallel worker" or "parallel worker process"?

> Indeed.  My vote would be to back-patch that stuff.

After thinking about it some more: can't we just make the new context
message be
    CONTEXT:  while setting parameter "x" to "y"
full stop?  The outer context line about "parallel worker" should
be enough for that.  As a bonus, if we ever decide that such a
context line would be useful for all GUC errors, we wouldn't need
a different spelling of it for that.

I took a quick look through the patch, and I think it's okay
implementation-wise, though personally I'd have used some less
generic name than "pair" for the variables.

            regards, tom lane



Re: BUG #15726: parallel queries failed ERROR: invalid name syntaxCONTEXT: parallel worker

От
Thomas Munro
Дата:
On Sat, Apr 13, 2019 at 4:47 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Michael Paquier <michael@paquier.xyz> writes:
> > On Thu, Apr 11, 2019 at 11:04:14AM -0400, Tom Lane wrote:
> >> The extra appearance of "parallel worker" seems a bit redundant,
> >> though I don't know if we can get rid of it.
> >>
> >> Could we at least be consistent about whether the context is
> >> "parallel worker" or "parallel worker process"?
>
> > Indeed.  My vote would be to back-patch that stuff.

Done.  Apologies for the delay.

> After thinking about it some more: can't we just make the new context
> message be
>         CONTEXT:  while setting parameter "x" to "y"
> full stop?  The outer context line about "parallel worker" should
> be enough for that.  As a bonus, if we ever decide that such a
> context line would be useful for all GUC errors, we wouldn't need
> a different spelling of it for that.

Agreed.  I changed that before pushing.

> I took a quick look through the patch, and I think it's okay
> implementation-wise, though personally I'd have used some less
> generic name than "pair" for the variables.

I changed it to error_context_name_and_value.