Thread: error messages (autovaccum canceled and syntax errors) while loadinga DUMP

error messages (autovaccum canceled and syntax errors) while loadinga DUMP

From

Matthias Apitz

Date:

25 June 2020, 14:11:37

Hello

A PG dump file was produced on a 11.4. server the usual ways.
When it is loaded with

$ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis sisis

it gives lots of error messages in the server log as:

2020-06-25 12:00:50.333 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:50.333 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_targetlog"
2020-06-25 12:00:53.658 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:53.658 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_targettab"
2020-06-25 12:00:55.375 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:55.375 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_tasktab"

and also syntax errors like:

2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order" at character 652
2020-06-25 12:02:15.509 CEST [32719] STATEMENT:  select id, brgroup, ins_time, upd_time, task_1, task_2, task_3,
int_sel_1,int_sel_2, int_sel_3, int_sel_4, int_sel_5, str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, sel_seq_1,
sel_seq_2,int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, str_val_1, str_val_2, str_val_3, str_val_4, str_val_5,
valtype_1,valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, valmode_1, valmode_2, valmode_3, valmode_4,
valmode_5,valmode_6, valmode_7, valname_1, valname_2, valname_3, valname_4, valname_5, valname_6, valname_7, valcont_1,
valcont_2,valcont_3, valcont_4, valcont_5, valcont_6, valcont_7, sel_seq_3 from acq_vardata where id= order by
sel_seq_3
2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or near "q" at character 1
2020-06-25 12:06:42.098 CEST [306] STATEMENT:  q
        select count(*) from ig_bigstrings ;

What could be the reason for this?

    matthias

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Matthias Apitz

Date:

25 June 2020, 15:54:02


El día jueves, junio 25, 2020 a las 01:11:37p. m. +0200, Matthias Apitz escribió:

>
> Hello
>
> A PG dump file was produced on a 11.4. server the usual ways.
> When it is loaded with
>
> $ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis sisis
>
> it gives lots of error messages in the server log as:
>
> ...
>
> and also syntax errors like:

>
> 2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order" at character 652
> 2020-06-25 12:02:15.509 CEST [32719] STATEMENT:  select id, brgroup, ins_time, upd_time, task_1, task_2, task_3,
int_sel_1,int_sel_2, int_sel_3, int_sel_4, int_sel_5, str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, sel_seq_1,
sel_seq_2,int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, str_val_1, str_val_2, str_val_3, str_val_4, str_val_5,
valtype_1,valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, valmode_1, valmode_2, valmode_3, valmode_4,
valmode_5,valmode_6, valmode_7, valname_1, valname_2, valname_3, valname_4, valname_5, valname_6, valname_7, valcont_1,
valcont_2,valcont_3, valcont_4, valcont_5, valcont_6, valcont_7, sel_seq_3 from acq_vardata where id= order by
sel_seq_3
> 2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or near "q" at character 1
> 2020-06-25 12:06:42.098 CEST [306] STATEMENT:  q
>         select count(*) from ig_bigstrings ;
>
> What could be the reason for this?

I looked in the dump file after uncompressing it. The 'syntax error'
comes from: one large table contains in a bytea column Perl code wich
our software reads from the table and executes it with Perl. But, why
the psql tryes to understand this code when it should INSERT it into the
table? This is a bit part of the content of the table:

# function: readAcqVarData\n#\n# parameter: where condition (string)\n# returns: array of records\n#
$recordList->[0]->{'int_val_1'}= "20";\n#          $recordList->[0]->{'str_val_1'} = "string";\n#
$recordList->[1]->{'int_val_1'}= "99";\n#          $recordList->[1]->{'str_val_1'} = "Dummy";\n#\nsub readAcqVarData
{\n\tmy($where) = @_;\n\tmy $recordList = undef;\n\tmy $ipos_valcont_7 = 56; # position valcont_7-Spalte in
select-statement- 1\n\n\t$debug .= "<h3>readAcqVarData() </h3>\\n" if $debugOn;\n\n\t$erg = selectData(\n\t\t
"selectid, brgroup, ins_time, upd_time, task_1, task_2, task_3, "\n\t\t  . "int_sel_1, int_sel_2, int_sel_3, int_sel_4,
int_sel_5,"\n\t\t  . "str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, "\n\t\t  . "sel_seq_1, sel_seq_2, "\n\t\t
."int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, "\n\t\t  . "str_val_1, str_val_2, str_val_3, str_val_4,
str_val_5,"\n\t\t  . "valtype_1, valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, "\n\t\t  .
"valmode_1,valmode_2, valmode_3, valmode_4, valmode_5, valmode_6, valmode_7, "\n\t\t  . 

        matthias

--
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Adrian Klaver

Date:

25 June 2020, 18:59:49

On 6/25/20 5:54 AM, Matthias Apitz wrote:
> 
> 
> El día jueves, junio 25, 2020 a las 01:11:37p. m. +0200, Matthias Apitz escribió:
> 
>>
>> Hello
>>
>> A PG dump file was produced on a 11.4. server the usual ways.
>> When it is loaded with
>>
>> $ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis sisis

What was the command to produce the dump?

>>
>> it gives lots of error messages in the server log as:
>>
>> ...
>>
>> and also syntax errors like:
> 
>>
>> 2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order" at character 652
>> 2020-06-25 12:02:15.509 CEST [32719] STATEMENT:  select id, brgroup, ins_time, upd_time, task_1, task_2, task_3,
int_sel_1,int_sel_2, int_sel_3, int_sel_4, int_sel_5, str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, sel_seq_1,
sel_seq_2,int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, str_val_1, str_val_2, str_val_3, str_val_4, str_val_5,
valtype_1,valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, valmode_1, valmode_2, valmode_3, valmode_4,
valmode_5,valmode_6, valmode_7, valname_1, valname_2, valname_3, valname_4, valname_5, valname_6, valname_7, valcont_1,
valcont_2,valcont_3, valcont_4, valcont_5, valcont_6, valcont_7, sel_seq_3 from acq_vardata where id= order by
sel_seq_3
>> 2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or near "q" at character 1
>> 2020-06-25 12:06:42.098 CEST [306] STATEMENT:  q
>>          select count(*) from ig_bigstrings ;
>>
>> What could be the reason for this?


What was logged before?:

2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near 
"order" at character 652

What happens if you do as a test something like?:

CREATE TABLE test_table AS SELECT * FROM large_table WHERE row_id = 
row_below;

> 
> I looked in the dump file after uncompressing it. The 'syntax error'
> comes from: one large table contains in a bytea column Perl code wich
> our software reads from the table and executes it with Perl. But, why
> the psql tryes to understand this code when it should INSERT it into the
> table? This is a bit part of the content of the table:
> 
> # function: readAcqVarData\n#\n# parameter: where condition (string)\n# returns: array of records\n#
$recordList->[0]->{'int_val_1'}= "20";\n#          $recordList->[0]->{'str_val_1'} = "string";\n#
$recordList->[1]->{'int_val_1'}= "99";\n#          $recordList->[1]->{'str_val_1'} = "Dummy";\n#\nsub readAcqVarData
{\n\tmy($where) = @_;\n\tmy $recordList = undef;\n\tmy $ipos_valcont_7 = 56; # position valcont_7-Spalte in
select-statement- 1\n\n\t$debug .= "<h3>readAcqVarData() </h3>\\n" if $debugOn;\n\n\t$erg = selectData(\n\t\t
"selectid, brgroup, ins_time, upd_time, task_1, task_2, task_3, "\n\t\t  . "int_sel_1, int_sel_2, int_sel_3, int_sel_4,
int_sel_5,"\n\t\t  . "str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, "\n\t\t  . "sel_seq_1, sel_seq_2, "\n\t\t
."int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, "\n\t\t  . "str_val_1, str_val_2, str_val_3, str_val_4,
str_val_5,"\n\t\t  . "valtype_1, valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, "\n\t\t  .
"valmode_1,valmode_2, valmode_3, valmode_4, valmode_5, valmode_6, valmode_7, "\n\t\t  .
 
> 
>          matthias
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Matthias Apitz

Date:

25 June 2020, 21:03:29

El día Donnerstag, Juni 25, 2020 a las 08:59:49 -0700, Adrian Klaver escribió:

> On 6/25/20 5:54 AM, Matthias Apitz wrote:
> >
> >
> > El día jueves, junio 25, 2020 a las 01:11:37p. m. +0200, Matthias Apitz escribió:
> >
> > >
> > > Hello
> > >
> > > A PG dump file was produced on a 11.4. server the usual ways.
> > > When it is loaded with
> > >
> > > $ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis sisis
>
> What was the command to produce the dump?

$ /usr/local/sisis-pap/pgsql/bin/pg_dump --file=newanna_export.dmp --compress=9 --user=sisis newanna

>
> > >
> > > it gives lots of error messages in the server log as:
> > >
> > > ...
> > >
> > > and also syntax errors like:
> >
> > >
> > > 2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order" at character 652
> > > 2020-06-25 12:02:15.509 CEST [32719] STATEMENT:  select id, brgroup, ins_time, upd_time, task_1, task_2, task_3,
int_sel_1,int_sel_2, int_sel_3, int_sel_4, int_sel_5, str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, sel_seq_1,
sel_seq_2,int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, str_val_1, str_val_2, str_val_3, str_val_4, str_val_5,
valtype_1,valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, valmode_1, valmode_2, valmode_3, valmode_4,
valmode_5,valmode_6, valmode_7, valname_1, valname_2, valname_3, valname_4, valname_5, valname_6, valname_7, valcont_1,
valcont_2,valcont_3, valcont_4, valcont_5, valcont_6, valcont_7, sel_seq_3 from acq_vardata where id= order by
sel_seq_3
> > > 2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or near "q" at character 1
> > > 2020-06-25 12:06:42.098 CEST [306] STATEMENT:  q
> > >          select count(*) from ig_bigstrings ;
> > >
> > > What could be the reason for this?
>
>
> What was logged before?:
>
> 2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order"
> at character 652

2020-06-25 11:58:42.909 CEST [11004] LOG:  checkpoints are occurring too frequently (24 seconds apart)
2020-06-25 11:58:42.909 CEST [11004] HINT:  Consider increasing the configuration parameter "max_wal_size".
2020-06-25 11:59:30.776 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 11:59:30.776 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.d01buch"
2020-06-25 11:59:41.289 CEST [31282] ERROR:  canceling autovacuum task
2020-06-25 11:59:41.289 CEST [31282] CONTEXT:  automatic analyze of table "sisis.public.d03geb"
2020-06-25 11:59:43.515 CEST [31282] ERROR:  canceling autovacuum task
2020-06-25 11:59:43.515 CEST [31282] CONTEXT:  automatic analyze of table "sisis.public.d11loesch"
2020-06-25 11:59:45.838 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 11:59:45.838 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.d11rueck"
2020-06-25 12:00:17.007 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:17.007 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_statistic"
2020-06-25 12:00:50.333 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:50.333 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_targetlog"
2020-06-25 12:00:53.658 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:53.658 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_targettab"
2020-06-25 12:00:55.375 CEST [31295] ERROR:  canceling autovacuum task
2020-06-25 12:00:55.375 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_tasktab"
2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order" at character 652
2020-06-25 12:02:15.509 CEST [32719] STATEMENT:  select id, brgroup, ins_time, upd_time, task_1, task_2, task_3,
int_sel_1,int_sel_2, int_sel_3, int_sel_4, int_sel_5, str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, sel_seq_1,
sel_seq_2,int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, str_val_1, str_val_2, str_val_3, str_val_4, str_val_5,
valtype_1,valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, valmode_1, valmode_2, valmode_3, valmode_4,
valmode_5,valmode_6, valmode_7, valname_1, valname_2, valname_3, valname_4, valname_5, valname_6, valname_7, valcont_1,
valcont_2,valcont_3, valcont_4, valcont_5, valcont_6, valcont_7, sel_seq_3 from acq_vardata where id= order by
sel_seq_3
2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or near "q" at character 1
...

>
> What happens if you do as a test something like?:
>
> CREATE TABLE test_table AS SELECT * FROM large_table WHERE row_id =
> row_below;
>

I do not understand this request, what is 'large_table' and what is
'row_below'?

Thanks

    matthias

> >
> > I looked in the dump file after uncompressing it. The 'syntax error'
> > comes from: one large table contains in a bytea column Perl code wich
> > our software reads from the table and executes it with Perl. But, why
> > the psql tryes to understand this code when it should INSERT it into the
> > table? This is a bit part of the content of the table:
> >
> > # function: readAcqVarData\n#\n# parameter: where condition (string)\n# returns: array of records\n#
$recordList->[0]->{'int_val_1'}= "20";\n#          $recordList->[0]->{'str_val_1'} = "string";\n#
$recordList->[1]->{'int_val_1'}= "99";\n#          $recordList->[1]->{'str_val_1'} = "Dummy";\n#\nsub readAcqVarData
{\n\tmy($where) = @_;\n\tmy $recordList = undef;\n\tmy $ipos_valcont_7 = 56; # position valcont_7-Spalte in
select-statement- 1\n\n\t$debug .= "<h3>readAcqVarData() </h3>\\n" if $debugOn;\n\n\t$erg = selectData(\n\t\t
"selectid, brgroup, ins_time, upd_time, task_1, task_2, task_3, "\n\t\t  . "int_sel_1, int_sel_2, int_sel_3, int_sel_4,
int_sel_5,"\n\t\t  . "str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, "\n\t\t  . "sel_seq_1, sel_seq_2, "\n\t\t
."int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, "\n\t\t  . "str_val_1, str_val_2, str_val_3, str_val_4,
str_val_5,"\n\t\t  . "valtype_1, valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, "\n\t\t  .
"valmode_1,valmode_2, valmode_3, valmode_4, valmode_5, valmode_6, valmode_7, "\n\t\t  . 
> >
> >          matthias
> >
>
>
> --
> Adrian Klaver
> adrian.klaver@aklaver.com

--
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Adrian Klaver

Date:

25 June 2020, 22:12:50

On 6/25/20 11:03 AM, Matthias Apitz wrote:
> El día Donnerstag, Juni 25, 2020 a las 08:59:49 -0700, Adrian Klaver escribió:
> 
>> On 6/25/20 5:54 AM, Matthias Apitz wrote:
>>>
>>>
>>> El día jueves, junio 25, 2020 a las 01:11:37p. m. +0200, Matthias Apitz escribió:
>>>
>>>>
>>>> Hello
>>>>
>>>> A PG dump file was produced on a 11.4. server the usual ways.
>>>> When it is loaded with
>>>>
>>>> $ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis sisis
>>
>> What was the command to produce the dump?
> 
> 
> $ /usr/local/sisis-pap/pgsql/bin/pg_dump --file=newanna_export.dmp --compress=9 --user=sisis newanna
> 
> 

>>
>> What was logged before?:
>>
>> 2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order"
>> at character 652
> 
> 

> 2020-06-25 12:00:55.375 CEST [31295] ERROR:  canceling autovacuum task
> 2020-06-25 12:00:55.375 CEST [31295] CONTEXT:  automatic analyze of table "sisis.public.idm_tasktab"
> 2020-06-25 12:02:15.509 CEST [32719] ERROR:  syntax error at or near "order" at character 652
> 2020-06-25 12:02:15.509 CEST [32719] STATEMENT:  select id, brgroup, ins_time, upd_time, task_1, task_2, task_3,
int_sel_1,int_sel_2, int_sel_3, int_sel_4, int_sel_5, str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, sel_seq_1,
sel_seq_2,int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, str_val_1, str_val_2, str_val_3, str_val_4, str_val_5,
valtype_1,valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, valmode_1, valmode_2, valmode_3, valmode_4,
valmode_5,valmode_6, valmode_7, valname_1, valname_2, valname_3, valname_4, valname_5, valname_6, valname_7, valcont_1,
valcont_2,valcont_3, valcont_4, valcont_5, valcont_6, valcont_7, sel_seq_3 from acq_vardata where id= order by
sel_seq_3
> 2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or near "q" at character 1
> ...


If this was coming from the restore of the dump file I would expect to 
see a COPY line just prior to the error. To me it looks like something 
other then the restore is running that query and that the query itself 
is flawed.

> 
> 
>>
>> What happens if you do as a test something like?:
>>
>> CREATE TABLE test_table AS SELECT * FROM large_table WHERE row_id =
>> row_below;
>>
> 
> I do not understand this request, what is 'large_table' and what is
> 'row_below'?

The "large_table" is whatever table the Perl scripts are stored in. 
'row_below' is whatever row identifier there is for the row that stores 
this particular script. Just trying to confirm that the script will run 
when the row it is part of is INSERTed into a table. I'm guessing not.

You could also just manually run the script to see if the query is 
valid. I'm guessing it is not.

> 
> Thanks
> 
>     matthias
> 
>>>
>>> I looked in the dump file after uncompressing it. The 'syntax error'
>>> comes from: one large table contains in a bytea column Perl code wich
>>> our software reads from the table and executes it with Perl. But, why
>>> the psql tryes to understand this code when it should INSERT it into the
>>> table? This is a bit part of the content of the table:
>>>
>>> # function: readAcqVarData\n#\n# parameter: where condition (string)\n# returns: array of records\n#
$recordList->[0]->{'int_val_1'}= "20";\n#          $recordList->[0]->{'str_val_1'} = "string";\n#
$recordList->[1]->{'int_val_1'}= "99";\n#          $recordList->[1]->{'str_val_1'} = "Dummy";\n#\nsub readAcqVarData
{\n\tmy($where) = @_;\n\tmy $recordList = undef;\n\tmy $ipos_valcont_7 = 56; # position valcont_7-Spalte in
select-statement- 1\n\n\t$debug .= "<h3>readAcqVarData() </h3>\\n" if $debugOn;\n\n\t$erg = selectData(\n\t\t
"selectid, brgroup, ins_time, upd_time, task_1, task_2, task_3, "\n\t\t  . "int_sel_1, int_sel_2, int_sel_3, int_sel_4,
int_sel_5,"\n\t\t  . "str_sel_1, str_sel_2, str_sel_3, dat_sel_1, dat_sel_2, "\n\t\t  . "sel_seq_1, sel_seq_2, "\n\t\t
."int_val_1, int_val_2, int_val_3, int_val_4, int_val_5, "\n\t\t  . "str_val_1, str_val_2, str_val_3, str_val_4,
str_val_5,"\n\t\t  . "valtype_1, valtype_2, valtype_3, valtype_4, valtype_5, valtype_6, valtype_7, "\n\t\t  .
"valmode_1,valmode_2, valmode_3, valmode_4, valmode_5, valmode_6, valmode_7, "\n\t\t  .
 
>>>
>>>           matthias
>>>
>>
>>
>> -- 
>> Adrian Klaver
>> adrian.klaver@aklaver.com
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Re: error messages (autovaccum canceled and syntax errors) while loading a DUMP

From

Matthias Apitz

Date:

25 June 2020, 22:24:33

On Thursday, 25 June 2020 21:12:50 CEST, Adrian Klaver
<adrian.klaver@aklaver.com> wrote:


>> acq_vardata where id= order by sel_seq_3
>> 2020-06-25 12:06:42.098 CEST [306] ERROR:  syntax error at or
>> near "q" at character 1
>> ...
>
>
> If this was coming from the restore of the dump file I would expect to
> see a COPY line just prior to the error. To me it looks like something
> other then the restore is running that query and that the query itself
> is flawed.

I will rerun it on a clean empty database and with no other proc on the
server accessing the PG server.


>>> What happens if you do as a test something like?:
>>>
>>> CREATE TABLE test_table AS SELECT * FROM large_table WHERE row_id =
>>> row_below;
>>>
>>
>> I do not understand this request, what is 'large_table' and what is
>> 'row_below'?
>
> The "large_table" is whatever table the Perl scripts are stored in.
> 'row_below' is whatever row identifier there is for the row that stores
> this particular script. Just trying to confirm that the script will run
> when the row it is part of is INSERTed into a table. I'm guessing not.
>
> You could also just manually run the script to see if the query is
> valid. I'm guessing it is not.

Ok, I will figure it out. Thanks for the clarification.

matthias




--
Sent from my Ubuntu phone
http://www.unixarea.de/
NO to the EU! NEIN zur EU!

Re: error messages (autovaccum canceled and syntax errors) while loading a DUMP

From

Tom Lane

Date:

25 June 2020, 22:41:54

Adrian Klaver <adrian.klaver@aklaver.com> writes:
> On 6/25/20 11:03 AM, Matthias Apitz wrote:
>> I looked in the dump file after uncompressing it. The 'syntax error'
>> comes from: one large table contains in a bytea column Perl code wich
>> our software reads from the table and executes it with Perl. But, why
>> the psql tryes to understand this code when it should INSERT it into the
>> table?

The perl fragment you show is similar to what's reported in the error
message, but it doesn't quite match, so I'm not 100% sold on the
theory that that's somehow not been quoted correctly.  However,
regardless of the exact details, it seems like the most likely theory
about what is happening is that the dump file is corrupt and the
corruption is causing the de-gzipped output to be missing or
duplicating chunks of text.  (Given the way gzip compression works,
that wouldn't be a very surprising symptom.)  So that leads me to
wonder what was done to the dump file in between creation and use.
One idea, seeing that the dump file was not given a ".gz" extension
that would reflect its compressed state, is that something thought it
was plain text and tried to do a newline conversion on it.  If it was
passed through email that would be a really plausible mechanism...

            regards, tom lane

Re: error messages (autovaccum canceled and syntax errors) while loading a DUMP

From

Matthias Apitz

Date:

25 June 2020, 23:04:57

On Thursday, 25 June 2020 21:41:54 CEST, Tom Lane <tgl@sss.pgh.pa.us>
wrote:
> Adrian Klaver <adrian.klaver@aklaver.com> writes:
>> On 6/25/20 11:03 AM, Matthias Apitz wrote:
>>> I looked in the dump file after uncompressing it. The 'syntax error'
>>> comes from: one large table contains in a bytea column Perl code wich
>>> our software reads from the table and executes it with Perl. But, why
>>> the psql tryes to understand this code when it should INSERT it into the
>>> table?
>
> The perl fragment you show is similar to what's reported in the error
> message, but it doesn't quite match, so I'm not 100% sold on the
> theory that that's somehow not been quoted correctly.  However,
> regardless of the exact details, it seems like the most likely theory
> about what is happening is that the dump file is corrupt and the
> corruption is causing the de-gzipped output to be missing or
> duplicating chunks of text.  (Given the way gzip compression works,
> that wouldn't be a very surprising symptom.)  So that leads me to
> wonder what was done to the dump file in between creation and use.
> One idea, seeing that the dump file was not given a ".gz" extension
> that would reflect its compressed state, is that something thought it
> was plain text and tried to do a newline conversion on it.  If it was
> passed through email that would be a really plausible mechanism...
>

I have to check if the dump file was moved from one host to another, but
even if so, it was moved by scp.

I think, that a

gzip -dc foo

will work, regardless of the file names extensiom not beeing .gz

I think also, if the file have been corrupted on transport, gzip -dc ...
would complain about.

matthias



--
Sent from my Ubuntu phone
http://www.unixarea.de/
NO to the EU! NEIN zur EU!

Re: error messages (autovaccum canceled and syntax errors) while loading a DUMP

From

Tom Lane

Date:

25 June 2020, 23:25:00

Matthias Apitz <guru@unixarea.de> writes:
> On Thursday, 25 June 2020 21:41:54 CEST, Tom Lane <tgl@sss.pgh.pa.us> 
> wrote:
>> regardless of the exact details, it seems like the most likely theory
>> about what is happening is that the dump file is corrupt and the
>> corruption is causing the de-gzipped output to be missing or
>> duplicating chunks of text.

> I think, that a
> gzip -dc foo
> will work, regardless of the file names extensiom not beeing .gz

Agreed, that gzip command won't care.  I was concerned about what
might've happened in between.

> I think also, if the file have been corrupted on transport, gzip -dc ... 
> would complain about.

Maybe.  It'd be unlikely to be able to tell before reaching the CRC
checksum at the end of the file, and it seems likely that it never
does reach the end in this usage ... are you allowing the psql run
to complete?  Even if you are, you might miss gzip's one-line complaint
in between all the whining from psql.

            regards, tom lane

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Matthias Apitz

Date:

27 June 2020, 11:37:22

El día Donnerstag, Juni 25, 2020 a las 04:25:00 -0400, Tom Lane escribió:

> Matthias Apitz <guru@unixarea.de> writes:
> > On Thursday, 25 June 2020 21:41:54 CEST, Tom Lane <tgl@sss.pgh.pa.us> 
> > wrote:
> >> regardless of the exact details, it seems like the most likely theory
> >> about what is happening is that the dump file is corrupt and the
> >> corruption is causing the de-gzipped output to be missing or
> >> duplicating chunks of text.
> 
> > I think, that a
> > gzip -dc foo
> > will work, regardless of the file names extensiom not beeing .gz
> 
> Agreed, that gzip command won't care.  I was concerned about what
> might've happened in between.
> 
> ...

I restarted the server, created a new database with:

$ /usr/local/sisis-pap/pgsql/bin/createdb -U sisis -T template0 testdump

and loaded the DUMP while no other processes were connected to the
server with:

$ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis -dtestdump

all went fine (table creations, COPYs into them, creating indexs)
without any error message in the terminal. In the serverlog only these
messages came out:

2020-06-27 10:16:38.778 CEST [18094] LOG:  database system is ready to accept connections

2020-06-27 10:21:26.062 CEST [18096] LOG:  checkpoints are occurring too frequently (25 seconds apart)
2020-06-27 10:21:26.062 CEST [18096] HINT:  Consider increasing the configuration parameter "max_wal_size".
2020-06-27 10:21:52.436 CEST [18096] LOG:  checkpoints are occurring too frequently (26 seconds apart)
2020-06-27 10:21:52.436 CEST [18096] HINT:  Consider increasing the configuration parameter "max_wal_size".
2020-06-27 10:22:07.424 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:22:07.424 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.d01buch"
2020-06-27 10:22:14.545 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:22:14.545 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.d02zus"
2020-06-27 10:22:16.051 CEST [18249] ERROR:  canceling autovacuum task
2020-06-27 10:22:16.051 CEST [18249] CONTEXT:  automatic analyze of table "testdump.public.d03geb"
2020-06-27 10:22:18.331 CEST [18249] ERROR:  canceling autovacuum task
2020-06-27 10:22:18.331 CEST [18249] CONTEXT:  automatic analyze of table "testdump.public.d11loesch"
2020-06-27 10:22:19.718 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:22:19.718 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.d11rueck"
2020-06-27 10:22:23.034 CEST [18249] ERROR:  canceling autovacuum task
2020-06-27 10:22:23.034 CEST [18249] CONTEXT:  automatic analyze of table "testdump.public.d35buchnotiz"
2020-06-27 10:22:38.902 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:22:38.902 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_statistic"
2020-06-27 10:22:59.332 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:22:59.332 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_targetlog"
2020-06-27 10:23:01.493 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:23:01.493 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_targettab"
2020-06-27 10:23:02.631 CEST [18302] ERROR:  canceling autovacuum task
2020-06-27 10:23:02.631 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_tasktab"

The messages about 'ERROR:  canceling autovacuum task' appeared while
the indexes were created. The database has around 400 tables and the
uncompressed dump is around 3.6 GByte:

$ gzip -dc newanna_export.dmp | wc -c
3643850597

So, the syntax error messages were caused by some other process (and we
have already an idea which cron job it was). What must be done re/ the
messages about 'ERROR:  canceling autovacuum task', or can we just
ignore them?

Thanks

    matthias

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Adrian Klaver

Date:

27 June 2020, 17:21:21

On 6/27/20 1:37 AM, Matthias Apitz wrote:
> El día Donnerstag, Juni 25, 2020 a las 04:25:00 -0400, Tom Lane escribió:
> 
>> Matthias Apitz <guru@unixarea.de> writes:
>>> On Thursday, 25 June 2020 21:41:54 CEST, Tom Lane <tgl@sss.pgh.pa.us>
>>> wrote:
>>>> regardless of the exact details, it seems like the most likely theory
>>>> about what is happening is that the dump file is corrupt and the
>>>> corruption is causing the de-gzipped output to be missing or
>>>> duplicating chunks of text.
>>
>>> I think, that a
>>> gzip -dc foo
>>> will work, regardless of the file names extensiom not beeing .gz
>>
>> Agreed, that gzip command won't care.  I was concerned about what
>> might've happened in between.
>>
>> ...
> 
> I restarted the server, created a new database with:
> 
> $ /usr/local/sisis-pap/pgsql/bin/createdb -U sisis -T template0 testdump
> 
> and loaded the DUMP while no other processes were connected to the
> server with:
> 
> $ gzip -dc newanna_export.dmp | /usr/local/sisis-pap/pgsql/bin/psql -U sisis -dtestdump
> 
> all went fine (table creations, COPYs into them, creating indexs)
> without any error message in the terminal. In the serverlog only these
> messages came out:
> 
> 2020-06-27 10:16:38.778 CEST [18094] LOG:  database system is ready to accept connections
> 
> 2020-06-27 10:21:26.062 CEST [18096] LOG:  checkpoints are occurring too frequently (25 seconds apart)
> 2020-06-27 10:21:26.062 CEST [18096] HINT:  Consider increasing the configuration parameter "max_wal_size".
> 2020-06-27 10:21:52.436 CEST [18096] LOG:  checkpoints are occurring too frequently (26 seconds apart)
> 2020-06-27 10:21:52.436 CEST [18096] HINT:  Consider increasing the configuration parameter "max_wal_size".
> 2020-06-27 10:22:07.424 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:07.424 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.d01buch"
> 2020-06-27 10:22:14.545 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:14.545 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.d02zus"
> 2020-06-27 10:22:16.051 CEST [18249] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:16.051 CEST [18249] CONTEXT:  automatic analyze of table "testdump.public.d03geb"
> 2020-06-27 10:22:18.331 CEST [18249] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:18.331 CEST [18249] CONTEXT:  automatic analyze of table "testdump.public.d11loesch"
> 2020-06-27 10:22:19.718 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:19.718 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.d11rueck"
> 2020-06-27 10:22:23.034 CEST [18249] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:23.034 CEST [18249] CONTEXT:  automatic analyze of table "testdump.public.d35buchnotiz"
> 2020-06-27 10:22:38.902 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:38.902 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_statistic"
> 2020-06-27 10:22:59.332 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:22:59.332 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_targetlog"
> 2020-06-27 10:23:01.493 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:23:01.493 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_targettab"
> 2020-06-27 10:23:02.631 CEST [18302] ERROR:  canceling autovacuum task
> 2020-06-27 10:23:02.631 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_tasktab"
> 
> The messages about 'ERROR:  canceling autovacuum task' appeared while
> the indexes were created. The database has around 400 tables and the
> uncompressed dump is around 3.6 GByte:
> 
> $ gzip -dc newanna_export.dmp | wc -c
> 3643850597
> 
> So, the syntax error messages were caused by some other process (and we
> have already an idea which cron job it was). What must be done re/ the
> messages about 'ERROR:  canceling autovacuum task', or can we just
> ignore them?

 From what I understand they are occurring because the machine is to 
busy doing the restore to get to the autovacuum task in a timely manner. 
So I would say ignore and check back later to see that the autovacuum is 
working. Given that it is ANALYZE that is being cancelled I would run a 
manual ANALYZE after the restore is done to update the database statistics.

> 
> Thanks
> 
>     matthias
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Matthias Apitz

Date:

27 June 2020, 20:52:29

El día Samstag, Juni 27, 2020 a las 07:21:21 -0700, Adrian Klaver escribió:

> > 2020-06-27 10:23:02.631 CEST [18302] ERROR:  canceling autovacuum task
> > 2020-06-27 10:23:02.631 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_tasktab"
> > 
> From what I understand they are occurring because the machine is to busy
> doing the restore to get to the autovacuum task in a timely manner. So I
> would say ignore and check back later to see that the autovacuum is working.
> Given that it is ANALYZE that is being cancelled I would run a manual
> ANALYZE after the restore is done to update the database statistics.

The machine is a development server and no one was working on it (today
is Saturday) apart of me. It has 4 modern and fast CPU,

Running ANALYZE VERBOSE does not give any unusual output. Only for each
table lines like:

...
INFO:  analyzing "public.z39t_term"
INFO:  "z39t_term": scanned 2 of 2 pages, containing 135 live rows and 0 dead rows; 135 rows in sample, 135 estimated
totalrows
 
INFO:  analyzing "public.z39t_trunc"
INFO:  "z39t_trunc": scanned 1 of 1 pages, containing 135 live rows and 0 dead rows; 135 rows in sample, 135 estimated
totalrows
 
...

How could I check that the autovacuum is working?

Thanks

    matthias
-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!

Re: error messages (autovaccum canceled and syntax errors) while loading a DUMP

From

Tom Lane

Date:

27 June 2020, 21:07:31

Matthias Apitz <guru@unixarea.de> writes:
> El día Samstag, Juni 27, 2020 a las 07:21:21 -0700, Adrian Klaver escribió:
>>> 2020-06-27 10:23:02.631 CEST [18302] ERROR:  canceling autovacuum task
>>> 2020-06-27 10:23:02.631 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_tasktab"

>> From what I understand they are occurring because the machine is to busy
>> doing the restore to get to the autovacuum task in a timely manner. So I
>> would say ignore and check back later to see that the autovacuum is working.
>> Given that it is ANALYZE that is being cancelled I would run a manual
>> ANALYZE after the restore is done to update the database statistics.

> The machine is a development server and no one was working on it (today
> is Saturday) apart of me. It has 4 modern and fast CPU,

I think more likely is this:

1. The restore run loads a lot of data into a table.

2. The autovacuum daemon notices all the inserts and starts an
auto-analyze run.

3. The restore run gets to the part where it tries to create indexes on
the table.  This requires a ShareLock if memory serves, which conflicts
with the ShareUpdateExclusive lock that ANALYZE is holding.  Rather than
making a foreground process wait for autovacuum, we kick autovacuum off
its lock by aborting the auto-analyze.  Hence the message(s).

4. The un-analyzed inserts are still there, so some future autovacuum
cycle will try again.

In short, yeah, you should just ignore these log messages.

            regards, tom lane

Re: error messages (autovaccum canceled and syntax errors) whileloading a DUMP

From

Adrian Klaver

Date:

28 June 2020, 01:09:54

On 6/27/20 10:52 AM, Matthias Apitz wrote:
> El día Samstag, Juni 27, 2020 a las 07:21:21 -0700, Adrian Klaver escribió:
> 
>>> 2020-06-27 10:23:02.631 CEST [18302] ERROR:  canceling autovacuum task
>>> 2020-06-27 10:23:02.631 CEST [18302] CONTEXT:  automatic analyze of table "testdump.public.idm_tasktab"
>>>
>>  From what I understand they are occurring because the machine is to busy
>> doing the restore to get to the autovacuum task in a timely manner. So I
>> would say ignore and check back later to see that the autovacuum is working.
>> Given that it is ANALYZE that is being cancelled I would run a manual
>> ANALYZE after the restore is done to update the database statistics.
> 
> The machine is a development server and no one was working on it (today
> is Saturday) apart of me. It has 4 modern and fast CPU,
> 
> Running ANALYZE VERBOSE does not give any unusual output. Only for each
> table lines like:

I would not expect that it would. The purpose for running it was to make 
sure the statistics for the tables in the database where up to date.

> 
> ...
> INFO:  analyzing "public.z39t_term"
> INFO:  "z39t_term": scanned 2 of 2 pages, containing 135 live rows and 0 dead rows; 135 rows in sample, 135 estimated
totalrows
 
> INFO:  analyzing "public.z39t_trunc"
> INFO:  "z39t_trunc": scanned 1 of 1 pages, containing 135 live rows and 0 dead rows; 135 rows in sample, 135
estimatedtotal rows
 
> ...
> 
> How could I check that the autovacuum is working?

Two ways:

1) Look in the logs for autovacuum lines.

2) Query the pg_stat_all_tables view.

https://www.postgresql.org/docs/12/monitoring-stats.html#PG-STAT-ALL-TABLES-VIEW


> 
> Thanks
> 
>     matthias
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com