Обсуждение: Postgres 12.1 : UPPER() in WHERE clause restarts server

Hi,

We have just upgraded our Postgres 9.6 database to 12.1 (pg_dumpall -> 
pg_restore on a clean installation) and now we are having some issues 
with one of our tables.

When we do the following statement:

    SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'

the Postgres service restarts.

It seems that using UPPER() in the WHERE clause is causing this. The 
same statement without UPPER() works just fine.

I have tried to emulate the issue with other tables, but 
f_gsxws_schedule seems to be the only one.
The table also has another character field that is indexed, and the same 
problem occurs there. Whenever we use UPPER() or LOWER() to do a 
case-insensitive search, the service reboots.

Looking at the table's definition, I don't see anything different with 
the other tables.

Here is what is logged:

2020-02-08 20:21:19.942 CET [83892] LOG:  server process (PID 85456) was 
terminated by signal 9: Killed: 9
2020-02-08 20:21:19.942 CET [83892] DETAIL:  Failed process was running: 
SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'
2020-02-08 20:21:19.942 CET [83892] LOG:  terminating any other active 
server processes
2020-02-08 20:21:19.943 CET [85364] WARNING:  terminating connection 
because of crash of another server process
2020-02-08 20:21:19.943 CET [85364] DETAIL:  The postmaster has 
commanded this server process to roll back the current transaction and 
exit, because another server process exited abnormally and possibly 
corrupted shared memory.
2020-02-08 20:21:19.943 CET [85364] HINT:  In a moment you should be 
able to reconnect to the database and repeat your command.
2020-02-08 20:21:19.943 CET [85360] WARNING:  terminating connection 
because of crash of another server process
2020-02-08 20:21:19.943 CET [85360] DETAIL:  The postmaster has 
commanded this server process to roll back the current transaction and 
exit, because another server process exited abnormally and possibly 
corrupted shared memory.
2020-02-08 20:21:19.943 CET [85360] HINT:  In a moment you should be 
able to reconnect to the database and repeat your command.
2020-02-08 20:21:19.943 CET [85269] WARNING:  terminating connection 
because of crash of another server process
2020-02-08 20:21:19.943 CET [85269] DETAIL:  The postmaster has 
commanded this server process to roll back the current transaction and 
exit, because another server process exited abnormally and possibly 
corrupted shared memory.
2020-02-08 20:21:19.943 CET [85269] HINT:  In a moment you should be 
able to reconnect to the database and repeat your command.
2020-02-08 20:21:19.946 CET [83892] LOG:  all server processes 
terminated; reinitializing
2020-02-08 20:21:19.988 CET [85686] LOG:  database system was 
interrupted; last known up at 2020-02-08 20:20:48 CET
2020-02-08 20:21:20.658 CET [85686] LOG:  database system was not 
properly shut down; automatic recovery in progress
2020-02-08 20:21:20.662 CET [85686] LOG:  redo starts at C/B99B45A0
2020-02-08 20:21:20.662 CET [85686] LOG:  invalid record length at 
C/B99B4688: wanted 24, got 0
2020-02-08 20:21:20.662 CET [85686] LOG:  redo done at C/B99B4650
2020-02-08 20:21:20.675 CET [83892] LOG:  database system is ready to 
accept connections


Has anyone noticed anything like this before? Any idea how to fix this?


Best regards,

Nick Renders

On 2/8/20 12:09 PM, Nick Renders wrote:
> Hi,
> 
> We have just upgraded our Postgres 9.6 database to 12.1 (pg_dumpall -> 
> pg_restore on a clean installation) and now we are having some issues 
> with one of our tables.
> 
> When we do the following statement:
> 
>      SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'
> 
> the Postgres service restarts.
> 
> It seems that using UPPER() in the WHERE clause is causing this. The 
> same statement without UPPER() works just fine.
> 
> I have tried to emulate the issue with other tables, but 
> f_gsxws_schedule seems to be the only one.
> The table also has another character field that is indexed, and the same 
> problem occurs there. Whenever we use UPPER() or LOWER() to do a 
> case-insensitive search, the service reboots.
> 
> Looking at the table's definition, I don't see anything different with 
> the other tables.
> 
> Here is what is logged:
> 

> 
> Has anyone noticed anything like this before? Any idea how to fix this?

Was the upgrade on the same machine?

Or was the machine also upgraded/updated?

I ask as there have been similar reports having to with changes in glibc 
version affecting collation.

> 
> 
> Best regards,
> 
> Nick Renders
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

On 2/8/20 12:28 PM, Marc wrote:
> Adrian,
> 
> Everything was a clean install ( MacOS Mojave and Postgres )
> 
> Export and import were done with the latest version of PGAdmin.
> 
> Please advise if we can provide you with anything ( logging etc . . . )
> 
> 
> Is there a possibility to downgrade to version 11 ?

At this point hard to tell whether this a version issue or something 
else. Probably best not to introduce too many more moving parts at this 
time.

Questions:

1) The OS and version you mention above is the same as on the production 
server below?

2) What where the exact issues you had on the production server?
The actual error messages would be very helpful.

3) Getting a stack trace of the UPPER(), LOWER() issue would be nice. 
For more info on that:

Not that familiar with MacOS, so not sure if the Linux/BSD steps would 
apply or not, still:

https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend





> 
> We upgraded over the weekend because we experienced a crash on our 
> production server with “toast” issues as result.
> 
> Thanks in advance,
> 
> Marc
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

## Nick Renders (postgres@arcict.com):

> 2020-02-08 20:21:19.942 CET [83892] LOG:  server process (PID 85456)
> was terminated by signal 9: Killed: 9

Signal 9 sounds like OOM (or manual intervention). What's in dmesg?

Regards,
Christoph

-- 
Spare Space

"Nick Renders" <postgres@arcict.com> writes:
> When we do the following statement:
>     SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'
> the Postgres service restarts.

Hm.

> Here is what is logged:
> 2020-02-08 20:21:19.942 CET [83892] LOG:  server process (PID 85456) was 
> terminated by signal 9: Killed: 9
> 2020-02-08 20:21:19.942 CET [83892] DETAIL:  Failed process was running: 
> SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'

That's mighty interesting, because signal 9 is an external SIGKILL,
not an internal-to-Postgres software fault.

If you were running on Linux I would hypothesize that your process
was getting killed by the infamous OOM killer, in which case we could
guess that for some reason this query is consuming an unreasonable
amount of memory and thereby attracting the wrath of the OOM killer.
However, I'm not aware that any such mechanism exists on macOS.

Still, since you can easily reproduce this, it'd be an idea to watch
the doomed process in "top" and see how much memory and CPU it eats
before dying.  Also look into the system log and see if there are any
relevant messages showing up there.

As Adrian suggested, a stack trace would be useful too ... although,
if this is being externally generated, it's likely that there's not
any consistent spot where it happens.  Also I'm not real sure that
it's *possible* to get a stack trace from a SIGKILL.  But if you
can get one, try to collect three or so and see if they're consistent.

Also, can you get an "EXPLAIN" of the query plan?  (I imagine EXPLAIN
ANALYZE would trigger the crash, though verifying that might be worth
the time.)

            regards, tom lane

On 2/8/20 2:24 PM, Marc wrote:
> Adrian,
> 
> Old production server was postgres 9.6 with Mac0S 10.9 so much older 
> than the “new” server. ( Now MacOS 10.14 Postgres 12.1 )
> After sudden restart of the cpu we started having issues, part of the 
> data that is lost TOAST. . . and we also started having issues when 
> TRUNCATING certain tables. The tabel where Nick reported the 
> “UPPER”-issue was not “involved”
> 
> The data we restored today on the “new” server was from before the 
> crash, and in our opinion “healthy”, didn’t run into any issue importing it.
> 
> Never had issues before, RAID system wasn’t giving any warnings neither. 
> We still presume an hardware failure, but haven’t been able to figure 
> out what exactly.
> 
> I’ll provide a log tomorrow in the morning CET.
> 
> Regarding the stack trace we’ll dig in to it to see what we can come up with
> 
> ¿ is downgrading possible ? We need to have a working system by tomorrow 
> evening CET.

I assume you are talking about taking the data dumped from the 'healthy'
9.6 instance and loading it into an 11 instance?

It would be worth a try, but if you think there is version problem why 
not just use a 9.6 instance for the new server?

If you still have issues, then:

1) Has someone created there own versions of lower() and upper() that 
are masking the default ones?

2) The schema for the problem table, in particular the index definitions 
for the problem fields.

3) Any recent changes/additions of extensions?


> 
> Thanks in advance,
> 
> 
> Marc
> 
> 
> 
> On 8 Feb 2020, at 22:18, Adrian Klaver wrote:
> 
>     On 2/8/20 12:28 PM, Marc wrote:
> 
>         Adrian,
> 
>         Everything was a clean install ( MacOS Mojave and Postgres )
> 
>         Export and import were done with the latest version of PGAdmin.
> 
>         Please advise if we can provide you with anything ( logging etc
>         . . . )
> 
> 
>         Is there a possibility to downgrade to version 11 ?
> 
>     At this point hard to tell whether this a version issue or something
>     else. Probably best not to introduce too many more moving parts at
>     this time.
> 
>     Questions:
> 
>     1) The OS and version you mention above is the same as on the
>     production server below?
> 
>     2) What where the exact issues you had on the production server?
>     The actual error messages would be very helpful.
> 
>     3) Getting a stack trace of the UPPER(), LOWER() issue would be
>     nice. For more info on that:
> 
>     Not that familiar with MacOS, so not sure if the Linux/BSD steps
>     would apply or not, still:
> 
>     https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend
> 
> 
> 
> 
>         We upgraded over the weekend because we experienced a crash on
>         our production server with “toast” issues as result.
> 
>         Thanks in advance,
> 
>         Marc
> 
>     -- 
>     Adrian Klaver
>     adrian.klaver@aklaver.com
> 
> 
> 
> *ARC - your Apple Authorised Service partner*     H.D. Saviolaan 8
>     B-1700 Dilbeek
>     Belgium
> info@arcict.com <mailto:info@arcict.com>     www.arcict.com 
> <http://www.arcict.com>
> tel. : +32 (0)2 466 50 00     fax. : +32 (0)2 466 88 33
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

On Sun, Feb 9, 2020 at 11:46 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> "Nick Renders" <postgres@arcict.com> writes:
> > When we do the following statement:
> >       SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'
> > the Postgres service restarts.
>
> Hm.
>
> > Here is what is logged:
> > 2020-02-08 20:21:19.942 CET [83892] LOG:  server process (PID 85456) was
> > terminated by signal 9: Killed: 9
> > 2020-02-08 20:21:19.942 CET [83892] DETAIL:  Failed process was running:
> > SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'
>
> That's mighty interesting, because signal 9 is an external SIGKILL,
> not an internal-to-Postgres software fault.
>
> If you were running on Linux I would hypothesize that your process
> was getting killed by the infamous OOM killer, in which case we could
> guess that for some reason this query is consuming an unreasonable
> amount of memory and thereby attracting the wrath of the OOM killer.
> However, I'm not aware that any such mechanism exists on macOS.

macOS's thing like that appears as "kernel[0]: memorystatus_thread:
idle exiting pid XXX [some program]" in system.log, which seems like a
bit of an understatement to me but that's what they call it.  Some
details here:

http://newosxbook.com/articles/MemoryPressure.html

Nick, did you see that?

Marc <postgres@arcict.com> writes:

> Adrian, Christoph, Tom,
>
> We identified as the problem being persistent on all tables with many
> records ( +600K ) and they all had a JSONB column ( we feel that
> might be related )

Did you remember to re-analyze all tables after importing the data?

Autovac probably will have done it for you for objects non-trivial in
size, but it's worth asking.

Such an omission could certainly result in poor exec plans, large memory
use and in turn automated intervention.

FWIW



>
> Luckily we were able to downgraded to version 11.6 with the same
> system MacOS 10.14.6 so that the OS impact can ruled out.
>
> We will keep the 12.1 in place so that we can run additional tests to
> assist to pin-point the issue.
>
> Feel free to ask but allow us to recover from these hectic days ;-)
>
> Many thanks for the help !
>
>
>
> Marc
>
>
> On 8 Feb 2020, at 21:09, Nick Renders wrote:
>
>     Hi,
>    
>     We have just upgraded our Postgres 9.6 database to 12.1
>     (pg_dumpall -> pg_restore on a clean installation) and now we are
>     having some issues with one of our tables.
>    
>     When we do the following statement:
>    
>     SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'
>    
>     the Postgres service restarts.
>    
>     It seems that using UPPER() in the WHERE clause is causing this.
>     The same statement without UPPER() works just fine.
>    
>     I have tried to emulate the issue with other tables, but
>     f_gsxws_schedule seems to be the only one.
>     The table also has another character field that is indexed, and
>     the same problem occurs there. Whenever we use UPPER() or LOWER()
>     to do a case-insensitive search, the service reboots.
>    
>     Looking at the table's definition, I don't see anything different
>     with the other tables.
>    
>     Here is what is logged:
>    
>     2020-02-08 20:21:19.942 CET [83892] LOG: server process (PID
>     85456) was terminated by signal 9: Killed: 9
>     2020-02-08 20:21:19.942 CET [83892] DETAIL: Failed process was
>     running: SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier)
>     = 'TEST'
>     2020-02-08 20:21:19.942 CET [83892] LOG: terminating any other
>     active server processes
>     2020-02-08 20:21:19.943 CET [85364] WARNING: terminating
>     connection because of crash of another server process
>     2020-02-08 20:21:19.943 CET [85364] DETAIL: The postmaster has
>     commanded this server process to roll back the current
>     transaction and exit, because another server process exited
>     abnormally and possibly corrupted shared memory.
>     2020-02-08 20:21:19.943 CET [85364] HINT: In a moment you should
>     be able to reconnect to the database and repeat your command.
>     2020-02-08 20:21:19.943 CET [85360] WARNING: terminating
>     connection because of crash of another server process
>     2020-02-08 20:21:19.943 CET [85360] DETAIL: The postmaster has
>     commanded this server process to roll back the current
>     transaction and exit, because another server process exited
>     abnormally and possibly corrupted shared memory.
>     2020-02-08 20:21:19.943 CET [85360] HINT: In a moment you should
>     be able to reconnect to the database and repeat your command.
>     2020-02-08 20:21:19.943 CET [85269] WARNING: terminating
>     connection because of crash of another server process
>     2020-02-08 20:21:19.943 CET [85269] DETAIL: The postmaster has
>     commanded this server process to roll back the current
>     transaction and exit, because another server process exited
>     abnormally and possibly corrupted shared memory.
>     2020-02-08 20:21:19.943 CET [85269] HINT: In a moment you should
>     be able to reconnect to the database and repeat your command.
>     2020-02-08 20:21:19.946 CET [83892] LOG: all server processes
>     terminated; reinitializing
>     2020-02-08 20:21:19.988 CET [85686] LOG: database system was
>     interrupted; last known up at 2020-02-08 20:20:48 CET
>     2020-02-08 20:21:20.658 CET [85686] LOG: database system was not
>     properly shut down; automatic recovery in progress
>     2020-02-08 20:21:20.662 CET [85686] LOG: redo starts at C/
>     B99B45A0
>     2020-02-08 20:21:20.662 CET [85686] LOG: invalid record length at
>     C/B99B4688: wanted 24, got 0
>     2020-02-08 20:21:20.662 CET [85686] LOG: redo done at C/B99B4650
>     2020-02-08 20:21:20.675 CET [83892] LOG: database system is ready
>     to accept connections
>    
>    
>     Has anyone noticed anything like this before? Any idea how to fix
>     this?
>    
>    
>     Best regards,
>    
>     Nick Renders
>    
>
>
> ARC - your Apple Authorised Service        H.D. Saviolaan 8            
> partner                                                                
>                                            B-1700 Dilbeek              
>                                            Belgium                     
> info@arcict.com                            www.arcict.com              
> tel. : +32 (0)2 466 50 00                  fax. : +32 (0)2 466 88 33   
>
>
>
>

-- 
Jerry Sievers
Postgres DBA/Development Consulting
e: postgres.consulting@comcast.net

On Mon, Feb 10, 2020 at 4:35 AM Marc <postgres@arcict.com> wrote:
> We will keep the 12.1 in place so that we can run additional tests to assist to pin-point the issue.
>
> Feel free to ask but allow us to recover from these hectic days ;-)

Here's how to get a stack so we can see what it was doing, assuming
you have the Apple developer tools installed:

1.  Find the PID of the backend you're connected to with SELECT
pg_backend_pid().
2.  "lldb -p PID" from a shell to attach to the process, then "cont"
to let it continue running.
3.  Run the query in that backend and wait for the SIGKILL.
4.  In the lldb session, type "bt".

It'll only make sense if your PostgreSQL build has debug symbols, but let's see.

Hi Thomas,

We are setting up a new test environment with 12.1.
Once it is running, I'll try out those commands and get back with the 
results.

Thanks,

Nick Renders


On 11 Feb 2020, at 2:51, Thomas Munro wrote:

> On Mon, Feb 10, 2020 at 4:35 AM Marc <postgres@arcict.com> wrote:
>> We will keep the 12.1 in place so that we can run additional tests to 
>> assist to pin-point the issue.
>>
>> Feel free to ask but allow us to recover from these hectic days ;-)
>
> Here's how to get a stack so we can see what it was doing, assuming
> you have the Apple developer tools installed:
>
> 1.  Find the PID of the backend you're connected to with SELECT
> pg_backend_pid().
> 2.  "lldb -p PID" from a shell to attach to the process, then "cont"
> to let it continue running.
> 3.  Run the query in that backend and wait for the SIGKILL.
> 4.  In the lldb session, type "bt".
>
> It'll only make sense if your PostgreSQL build has debug symbols, but 
> let's see.

We have set up a new test environment running PostgreSQL v12.2 on macOS 
10.14 and the issue is still there.
One thing I noticed, is that the returning columns do not affect the 
behaviour:

    SELECT * FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 'TEST'

and
    SELECT gwsc_sequence FROM f_gsxws_schedule WHERE UPPER(gwsc_dossier) = 
'TEST'

both kill the postgres service.


I will try to free some time next week to install the Apple developer 
tools and further analyse the problem.

Best regards,

Nick


On 11 Feb 2020, at 12:32, Nick Renders wrote:

> Hi Thomas,
>
> We are setting up a new test environment with 12.1.
> Once it is running, I'll try out those commands and get back with the 
> results.
>
> Thanks,
>
> Nick Renders
>
>
> On 11 Feb 2020, at 2:51, Thomas Munro wrote:
>
>> On Mon, Feb 10, 2020 at 4:35 AM Marc <postgres@arcict.com> wrote:
>>> We will keep the 12.1 in place so that we can run additional tests 
>>> to assist to pin-point the issue.
>>>
>>> Feel free to ask but allow us to recover from these hectic days ;-)
>>
>> Here's how to get a stack so we can see what it was doing, assuming
>> you have the Apple developer tools installed:
>>
>> 1.  Find the PID of the backend you're connected to with SELECT
>> pg_backend_pid().
>> 2.  "lldb -p PID" from a shell to attach to the process, then "cont"
>> to let it continue running.
>> 3.  Run the query in that backend and wait for the SIGKILL.
>> 4.  In the lldb session, type "bt".
>>
>> It'll only make sense if your PostgreSQL build has debug symbols, but 
>> let's see.

"Nick Renders" <postgres@arcict.com> writes:
> We have set up a new test environment running PostgreSQL v12.2 on macOS 
> 10.14 and the issue is still there.

Some nearby threads prompt these two questions:

1. Are you using your own build, or is this from EDB's installer?

2. If the latter, does turning JIT off ("set jit = off") make the
problem go away?

There is as yet no "native" support for --with-llvm on macOS,
ie Apple themselves don't provide sufficient support for that.
EDB seem to have hacked up something that sort of works, but
only sort of.

            regards, tom lane

Hi Tom,

1. we used the EDB installer.

2. turning JIT off did make the problem go away. So I guess this was 
causing the Postgres process to crash all along.

Thanks for the help,

Nick


On 24 Feb 2020, at 16:24, Tom Lane wrote:

> "Nick Renders" <postgres@arcict.com> writes:
>> We have set up a new test environment running PostgreSQL v12.2 on 
>> macOS
>> 10.14 and the issue is still there.
>
> Some nearby threads prompt these two questions:
>
> 1. Are you using your own build, or is this from EDB's installer?
>
> 2. If the latter, does turning JIT off ("set jit = off") make the
> problem go away?
>
> There is as yet no "native" support for --with-llvm on macOS,
> ie Apple themselves don't provide sufficient support for that.
> EDB seem to have hacked up something that sort of works, but
> only sort of.
>
>             regards, tom lane

On 2/27/20 9:08 AM, Marc wrote:
> Hello Tom,
> 
> To whom do we report our findings regarding this issue ?

Since it is an EDB hack I would try the contact form at the bottom of 
the this page:

https://www.enterprisedb.com/downloads/postgres-postgresql-downloads

> 
> I can offer you a Belgian waffle to go with you caffeine.
> 
> Kindest Regards,
> 
> 
> 
> Marc
> 
> 
> On 25 Feb 2020, at 10:35, Nick Renders wrote:
> 
>     Hi Tom,
> 
>     1. we used the EDB installer.
> 
>     2. turning JIT off did make the problem go away. So I guess this was
>     causing the Postgres process to crash all along.
> 
>     Thanks for the help,
> 
>     Nick
> 
> 
>     On 24 Feb 2020, at 16:24, Tom Lane wrote:
> 
>         "Nick Renders" <postgres@arcict.com> writes:
> 
>             We have set up a new test environment running PostgreSQL
>             v12.2 on macOS
>             10.14 and the issue is still there.
> 
>         Some nearby threads prompt these two questions:
> 
>         1. Are you using your own build, or is this from EDB's installer?
> 
>         2. If the latter, does turning JIT off ("set jit = off") make the
>         problem go away?
> 
>         There is as yet no "native" support for --with-llvm on macOS,
>         ie Apple themselves don't provide sufficient support for that.
>         EDB seem to have hacked up something that sort of works, but
>         only sort of.
> 
>         regards, tom lane
> 
> 
> 
> *ARC - your Apple Authorised Service partner*     H.D. Saviolaan 8
>     B-1700 Dilbeek
>     Belgium
> info@arcict.com <mailto:info@arcict.com>     www.arcict.com 
> <http://www.arcict.com>
> tel. : +32 (0)2 466 50 00     fax. : +32 (0)2 466 88 33
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Marc <postgres@arcict.com> writes:
> To whom do we report our findings regarding this issue ?

EDB is already on it:

https://www.postgresql.org/message-id/CA%2BOCxoz0bWi%2BR2WpocfkD20Lgrg69z1jQ_SZd-zmdzHW0zt%2Bbg%40mail.gmail.com

            regards, tom lane