[HACKERS] statement_timeout is not working as expected with postgres_fdw - Mailing list pgsql-hackers

Hello All,

The query on foreign table hangs due to network down of remote server for near about 16 minutes before exiting. 

statement_timeout is expected to work in this case as well but when i tried statement_timeout, it is not working as expected.

Below is test case to reproduce the issue: [I am testing this on two different systems]

1: Set the postgres_fdw 

postgres=# CREATE SERVER myserver FOREIGN DATA WRAPPER postgres_fdw OPTIONS (host '172.16.173.237', dbname 'postgres', port '5432',keepalives '1', keepalives_interval '3',keepalives_idle '3', keepalives_count '1');

CREATE SERVER

postgres=# CREATE USER MAPPING FOR postgres SERVER myserver OPTIONS (user 'postgres', password 'edb');

CREATE USER MAPPING

postgres=# CREATE FOREIGN TABLE test(id int) SERVER myserver;

CREATE FOREIGN TABLE

postgres=# select * from test;

 id 

----

  1

 10

  2

  1

(4 rows)

postgres=# \d

            List of relations

 Schema | Name |     Type      |  Owner   

--------+------+---------------+----------

 public | test | foreign table | postgres

(1 row)

postgres=# 

postgres=# select * from pg_foreign_server ;

 srvname  | srvowner | srvfdw | srvtype | srvversion | srvacl |                                                       srvoptions                                                 

       

----------+----------+--------+---------+------------+--------+------------------------------------------------------------------------------------------------------------------

-------

 myserver |       10 |  16387 |         |            |        | {host=172.16.173.237,dbname=postgres,port=5432,keepalives=1,keepalives_interval=3,keepalives_idle=3,keepalives_co

unt=1}

(1 row)

3. Execute the insert command.

E.g: insert into test values (generate_series(1,1000000));

* You need to do network down of remote server during insert command.

postgres=# set statement_timeout to 6000;

SET

postgres=# insert into test values (generate_series(1,1000000));

WARNING:  server closed the connection unexpectedly

This probably means the server terminated abnormally

before or while processing the request.

CONTEXT:  Remote SQL command: ABORT TRANSACTION

ERROR:  could not receive data from server: No route to host

CONTEXT:  Remote SQL command: INSERT INTO public.test(id) VALUES ($1)

Time: 931427.002 ms

It was in hang state for approx 15-16 minute before exit.

In pg_log, i see below error for above query:

=========

2017-04-20 15:22:02 IST ERROR:  could not receive data from server: No route to host

2017-04-20 15:22:02 IST CONTEXT:  Remote SQL command: INSERT INTO public.test(id) VALUES ($1)

2017-04-20 15:22:02 IST STATEMENT:  insert into test values (generate_series(1,1000000));

2017-04-20 15:22:02 IST WARNING:  server closed the connection unexpectedly

This probably means the server terminated abnormally

before or while processing the request.

2017-04-20 15:22:02 IST CONTEXT:  Remote SQL command: ABORT TRANSACTION

==========

I tested the patch submitted by Ashutosh Bapat on community [https://www.postgresql.org/message-id/CAFjFpRdcWw4h0a-zrL-EiaekkPj8O0GR2M1FwZ1useSRfRm3-g%40mail.gmail.com] to make the statement_timeout working and i can see statement_timeout is working but it is taking some extra time as statement_timeout.

postgres=# set statement_timeout to 6000;

SET

postgres=# 

postgres=# \timing on

Timing is on.

postgres=# insert into test values (generate_series(1,1000000));           -- [after executing query immediately disconnect the ethernet on remote server ]

2017-04-20 07:10:51.588 IST [10467] ERROR:  canceling statement due to statement timeout

2017-04-20 07:10:51.588 IST [10467] STATEMENT:  insert into test values (generate_series(1,1000000));

2017-04-20 07:11:25.590 IST [10467] WARNING:  discarding connection 0xfe4260 because of failed cancel request: PQcancel() -- connect() failed: No route to host

WARNING:  discarding connection 0xfe4260 because of failed cancel request: PQcancel() -- connect() failed: No route to host

ERROR:  canceling statement due to statement timeout

Time: 40001.765 ms (00:40.002)

postgres=# 

postgres=# 

In above case, I got the error related to statement timeout after 6 seconds,

but it it taking more time (approx 34 sec and it is varing each time if you see below) to terminate the connection and to exit from query. As per the tcp keepavlies settings for foreign server, it should take max 6 sec to terminate the connection.

postgres=# 

postgres=# set statement_timeout to 20000;

SET

Time: 0.254 ms

postgres=# 

postgres=# insert into test values (generate_series(1,1000000));

2017-04-20 07:13:25.666 IST [10467] ERROR:  canceling statement due to statement timeout

2017-04-20 07:13:25.666 IST [10467] STATEMENT:  insert into test values (generate_series(1,1000000));

2017-04-20 07:13:43.668 IST [10467] WARNING:  discarding connection 0xfe4260 because of failed cancel request: PQcancel() -- connect() failed: No route to host

WARNING:  discarding connection 0xfe4260 because of failed cancel request: PQcancel() -- connect() failed: No route to host

ERROR:  canceling statement due to statement timeout

Time: 38004.169 ms (00:38.004)

postgres=# 

When I tested this using a local TCP connection, then query was exited immediately after statement timeout.

Suraj Kharage