statement_timeout issue

Hi,

On 2018-05-04 09:52:35 -0700, Ian Harding wrote:

I know there are a lot of moving parts to this issue but I think I've
eliminated most of them and the problem comes down to the postgresql server
generating a statement_timeout error after 10 seconds when the connection
statement_timeout is actually set to 15 minutes.

My web server gets a database handle which it keeps for the duration of the
function that generates the response. Multiple queries can be sent and
will use the same handle.

After getting the handle I issue "show statement_timeout" and log the
result which shows 15 minutes.

84876:May 4 08:31:06 seattle-vm-1-0 nsd: STATEMENT_TIMEOUT IS:
84877-May 4 08:31:06 seattle-vm-1-0 nsd: statement_timeout = 15min

Then I send a query, and it generates a statement_timeout error after 10
seconds.

The log has a CONTEXT which indicates a foreign key lookup was going on at
the time which is fine...

2018-05-04 04:05:20 PDT [62028]: [82-1] ERROR: canceling statement due to
statement timeout
2018-05-04 04:05:20 PDT [62028]: [83-1] CONTEXT: SQL statement "SELECT 1
FROM ONLY "public"."clients" x WHERE "c_id" OPERATOR(pg_catalog.=) $1 FOR
KEY SHARE OF x"
2018-05-04 04:05:20 PDT [62028]: [84-1] STATEMENT: INSERT /*

Is there anything I'm not thinking of?

Probably some part of your application, or a function you're calling
from there, is setting a different timeout.

Greetings,

Andres Freund

On 05/04/2018 09:52 AM, Ian Harding wrote:

I know there are a lot of moving parts to this issue but I think I've
eliminated most of them and the problem comes down to the postgresql
server generating a statement_timeout error after 10 seconds when the
connection statement_timeout is actually set to 15 minutes.

My web server gets a database handle which it keeps for the duration of
the function that generates the response.  Multiple queries can be sent
and will use the same handle.

After getting the handle I issue "show statement_timeout" and log the
result which shows 15 minutes.

84876:May  4 08:31:06 seattle-vm-1-0 nsd: STATEMENT_TIMEOUT IS:
84877-May  4 08:31:06 seattle-vm-1-0 nsd: statement_timeout = 15min

Then I send a query, and it generates a statement_timeout error after 10
seconds.

To follow up on Andres's suggestion, when you do the above do:

select * from pg_settings where name = 'statement_timeout';

and see what the source field is pointing to.

The log has a CONTEXT which indicates a foreign key lookup was going on
at the time which is fine...

2018-05-04 04:05:20 PDT [62028]: [82-1] ERROR:  canceling statement due
to statement timeout
2018-05-04 04:05:20 PDT [62028]: [83-1] CONTEXT:  SQL statement "SELECT
1 FROM ONLY "public"."clients" x WHERE "c_id" OPERATOR(pg_catalog.=) $1
FOR KEY SHARE OF x"
2018-05-04 04:05:20 PDT [62028]: [84-1] STATEMENT:  INSERT /*

Is there anything I'm not thinking of?

Thanks!

- Ian

--
Adrian Klaver
adrian.klaver@aklaver.com

On Fri, May 4, 2018 at 10:22 AM, Andres Freund <andres@anarazel.de> wrote:

Hi,

On 2018-05-04 09:52:35 -0700, Ian Harding wrote:

I know there are a lot of moving parts to this issue but I think I've
eliminated most of them and the problem comes down to the postgresql

server

generating a statement_timeout error after 10 seconds when the connection
statement_timeout is actually set to 15 minutes.

My web server gets a database handle which it keeps for the duration of

the

function that generates the response. Multiple queries can be sent and
will use the same handle.

After getting the handle I issue "show statement_timeout" and log the
result which shows 15 minutes.

84876:May 4 08:31:06 seattle-vm-1-0 nsd: STATEMENT_TIMEOUT IS:
84877-May 4 08:31:06 seattle-vm-1-0 nsd: statement_timeout = 15min

Then I send a query, and it generates a statement_timeout error after 10
seconds.

The log has a CONTEXT which indicates a foreign key lookup was going on

at

the time which is fine...

2018-05-04 04:05:20 PDT [62028]: [82-1] ERROR: canceling statement due

to

statement timeout
2018-05-04 04:05:20 PDT [62028]: [83-1] CONTEXT: SQL statement "SELECT 1
FROM ONLY "public"."clients" x WHERE "c_id" OPERATOR(pg_catalog.=) $1 FOR
KEY SHARE OF x"
2018-05-04 04:05:20 PDT [62028]: [84-1] STATEMENT: INSERT /*

Is there anything I'm not thinking of?

Probably some part of your application, or a function you're calling
from there, is setting a different timeout.

That's what I thought, but I'm using the same db handle and only sending
plain SQL on base tables. Only triggers, rules and foreign keys should be
in play I think...

I don't remember setting a statement timeout in a trigger, that seems kind
of crazy.