query that canceled isnt logged
Hey all, I'm trying to analyze a weird situation that I have seen in my db. Sometimes my app fails to start because of the following msg : SQL State : null Error Code : 0 Message: Cannot create PoolableConnectionFactory (ERROR: canceling statement due to user request) In the db at the same time I saw the same msg : 2019-12-08 00:04:56 IST DB 10035 ERROR: canceling statement due to user request 2019-12-08 00:04:56 IST DB 10035 STATEMENT: select 1 as test I thought that it might be related to the validation query that is set to 2 seconds (when I change the validation query from "select 1 as test" to "select pg_sleep(10)" ) the same behavior was reproduced . Therefore, my theory was that the validation query is taking more than 2 seconds. I decided to log all the statements(log_statements=all) that are running in order to see for how long the validation query is running in the db (log_min_duration_statement wont be helpful here because the query is canceled and I wont be able to see its duration..). The weird thing is that I dont see before that error any log message that indicate that the query was running. I hoped to see the following msg in the db log : 2019-12-08 00:04:55 IST DB 2695 LOG: *execute *: select 1 as test but I dont see any execute msg of this query , I just see the ERROR msg : 2019-12-08 00:04:56 IST DB 10035 ERROR: canceling statement due to user request 2019-12-08 00:04:56 IST DB 10035 STATEMENT: select 1 as test Any idea why I the query isnt logged but I still get the ERROR msg ?
Re: query that canceled isnt logged
Mariel Cherkassky writes: > ... > Therefore, my theory was that the validation query is taking more than 2 > seconds. I decided to log all the statements(log_statements=all) that are > running in order to see for how long the validation query is running in the > db (log_min_duration_statement wont be helpful here because the query is > canceled and I wont be able to see its duration..). > The weird thing is that I dont see before that error any log message that > indicate that the query was running. I hoped to see the following msg in > the db log : > 2019-12-08 00:04:55 IST DB 2695 LOG: *execute *: select 1 as test > but I dont see any execute msg of this query , I just see the ERROR msg : > 2019-12-08 00:04:56 IST DB 10035 ERROR: canceling statement due to user > request > 2019-12-08 00:04:56 IST DB 10035 STATEMENT: select 1 as test Hm. Perhaps you should *also* turn on log_min_duration_statement = 0, so that the parse and bind phases log something. Maybe one of them is taking a long time (hard to see why...) regards, tom lane
Re: query that canceled isnt logged
What do you mean by live queries ? If I'll try to run the following query and cancel it manually(ctrl+c) : select pg_sleep(10) I will see in the logs the following messages : 2019-12-08 17:16:34 IST postgres 30797 LOG: statement: select pg_sleep(10); 2019-12-08 17:16:36 IST postgres 30797 ERROR: canceling statement due to user request 2019-12-08 17:16:36 IST postgres 30797 STATEMENT: select pg_sleep(10); The first message indicates that I run this query (logged because I set log_statements to all) and the two next messages appear because I canceled the query. When it happens to my application I dont see the first message that indicates that I run it and thats what I'm trying to understand. >
Re: query that canceled isnt logged
that is the first thing I did but it isnt logged even when this parameter is set, I guess because it is canceled before it finishes to run - which is weird..
Re: query that canceled isnt logged
Mariel Cherkassky writes: > If I'll try to run the following query and cancel it manually(ctrl+c) : > select pg_sleep(10) > I will see in the logs the following messages : > 2019-12-08 17:16:34 IST postgres 30797 LOG: statement: select > pg_sleep(10); > 2019-12-08 17:16:36 IST postgres 30797 ERROR: canceling statement due to > user request > 2019-12-08 17:16:36 IST postgres 30797 STATEMENT: select pg_sleep(10); Note that that's going through "simple query" protocol (which is why it says "statement:") but your application is evidently using "extended query" protocol (because you see "execute ...:", at least when it's working correctly). I wonder whether the explanation is somewhere in that. The best theory I have at the moment, though, is that something is taking exclusive locks on system catalogs, blocking parsing of even trivial statements. regards, tom lane
Re: How to run in parallel in Postgres, EXECUTE_PARALLEL
>You cannot run several queries in parallel in a PostgreSQL function. > >You may want to have a look at PL/Proxy which might be used for things like >that. > >Yours, >Laurenz Albe >-- >Cybertec | https://www.cybertec-postgresql.com Hi Laurenz The code below takes 3, seconds DO $body$ DECLARE BEGIN EXECUTE 'SELECT pg_sleep(1); SELECT pg_sleep(1); SELECT pg_sleep(1);'; END $body$; Do you or anybody know if there are any plans for a function call that support the calling structure below or something like it and that then could finish in 1 second ? (If you are calling a void function, the return value should not be any problem.) DO $body$ DECLARE command_string_list text[3]; BEGIN command_string_list[0] = 'SELECT pg_sleep(1)'; command_string_list[1] = 'SELECT pg_sleep(1)'; command_string_list[2] = 'SELECT pg_sleep(1)'; EXECUTE_PARALLEL command_string_list; END $body$; The only way to this today as I understand it, is to open 3 new connections back to the database which you can be done in different ways. If we had a parallel functions like the one above it's easier to make parallel sql without using complex scripts, java, python or other system. Thanks. Lars
Re: How to run in parallel in Postgres, EXECUTE_PARALLEL
On 12/8/19 1:14 PM, Lars Aksel Opsahl wrote: > Do you or anybody know if there are any plans for a function call that > support the calling structure below or something like it and that then > could finish in 1 second ? (If you are calling a void function, the > return value should not be any problem.) > > DO > $body$ > *DECLARE* > command_string_list text[3]; > *BEGIN* > command_string_list[0] = 'SELECT pg_sleep(1)'; > command_string_list[1] = 'SELECT pg_sleep(1)'; > command_string_list[2] = 'SELECT pg_sleep(1)'; > EXECUTE_PARALLEL command_string_list; > *END* > $body$; > > The only way to this today as I understand it, is to open 3 new > connections back to the database which you can be done in different ways. Yes, correct. > If we had a parallel functions like the one above it's easier to > make parallel sql without using complex scripts, java, python or other > system. It does require one connection per statement, but with dblink it is not necessarily all that complex. For example (granted, this could use more error checking, etc.): 8< CREATE OR REPLACE FUNCTION execute_parallel(stmts text[]) RETURNS text AS $$ declare i int; retv text; conn text; connstr text; rv int; db text := current_database(); begin for i in 1..array_length(stmts,1) loop conn := 'conn' || i::text; connstr := 'dbname=' || db; perform dblink_connect(conn, connstr); rv := dblink_send_query(conn, stmts[i]); end loop; for i in 1..array_length(stmts,1) loop conn := 'conn' || i::text; select val into retv from dblink_get_result(conn) as d(val text); end loop; for i in 1..array_length(stmts,1) loop conn := 'conn' || i::text; perform dblink_disconnect(conn); end loop; return 'OK'; end; $$ language plpgsql; 8< And then: 8< \timing DO $$ declare stmts text[]; begin stmts[1] = 'select pg_sleep(1)'; stmts[2] = 'select pg_sleep(1)'; stmts[3] = 'select pg_sleep(1)'; PERFORM execute_parallel(stmts); end; $$ LANGUAGE plpgsql; DO Time: 1010.831 ms (00:01.011) 8< HTH, Joe -- Crunchy Data - http://crunchydata.com PostgreSQL Support for Secure Enterprises Consulting, Training, & Open Source Development signature.asc Description: OpenPGP digital signature
Re: How to run in parallel in Postgres, EXECUTE_PARALLEL
> From: Joe Conway > Sent: Sunday, December 8, 2019 9:04 PM > To: Lars Aksel Opsahl; Laurenz Albe; [email protected] > Subject: Re: How to run in parallel in Postgres, EXECUTE_PARALLEL > > On 12/8/19 1:14 PM, Lars Aksel Opsahl wrote: > > Do you or anybody know if there are any plans for a function call that > > support the calling structure below or something like it and that then > > could finish in 1 second ? (If you are calling a void function, the > > return value should not be any problem.) > > > > DO > > $body$ > > *DECLARE* > > command_string_list text[3]; > > *BEGIN* > > command_string_list[0] = 'SELECT pg_sleep(1)'; > > command_string_list[1] = 'SELECT pg_sleep(1)'; > > command_string_list[2] = 'SELECT pg_sleep(1)'; > > EXECUTE_PARALLEL command_string_list; > > *END* > > $body$; > > > > The only way to this today as I understand it, is to open 3 new > > connections back to the database which you can be done in different ways. > > Yes, correct. > > > If we had a parallel functions like the one above it's easier to > > make parallel sql without using complex scripts, java, python or other > > system. > > It does require one connection per statement, but with dblink it is not > necessarily all that complex. For example (granted, this could use more > error checking, etc.): > > 8< > CREATE OR REPLACE FUNCTION > execute_parallel(stmts text[]) > RETURNS text AS > $$ > declare > i int; > retv text; > conn text; > connstr text; > rv int; > db text := current_database(); > begin > for i in 1..array_length(stmts,1) loop > conn := 'conn' || i::text; > connstr := 'dbname=' || db; > perform dblink_connect(conn, connstr); > rv := dblink_send_query(conn, stmts[i]); > end loop; > for i in 1..array_length(stmts,1) loop > conn := 'conn' || i::text; > select val into retv > from dblink_get_result(conn) as d(val text); > end loop; > for i in 1..array_length(stmts,1) loop > conn := 'conn' || i::text; > perform dblink_disconnect(conn); > end loop; > return 'OK'; > end; > $$ language plpgsql; > 8< > > And then: > > 8< > \timing > DO $$ > declare > stmts text[]; > begin > stmts[1] = 'select pg_sleep(1)'; > stmts[2] = 'select pg_sleep(1)'; > stmts[3] = 'select pg_sleep(1)'; > PERFORM execute_parallel(stmts); > end; > $$ LANGUAGE plpgsql; > DO > Time: 1010.831 ms (00:01.011) > 8< > > HTH, > > Joe > -- > Crunchy Data - http://crunchydata.com > PostgreSQL Support for Secure Enterprises > Consulting, Training, & Open Source Development Hi Thanks a lot it works like a charm. https://github.com/larsop/find-overlap-and-gap/tree/use_dblink_for_parallel (The test is failing now because it seems like drop EXTENSION dblink; is not cleaning up every thing) As you say we need some error handling. And maybe some retry if not enough free connections and a parameter for max parallel connections and so on. So far this is best solution I have seen. Thanks. Lars
Specific query taking time to process
Hi team, Could you please help me with this strange issue I am facing in my current live server I am maintaining. There is a specific search query I am running to get list of Documents and their metadata from several table in the DB. We are running Postgres 9.6.9 on Amazon RDS (db.m5.4xlarge instance) Our current DB consists of 500GB of data and indexes. Most of the rows in table are consist of 454,078,915 With the fresh DB with the restore of the DATA without any indexes Search query performs relatively quick and most of the time its less than a second. But after 3 weeks of use of the DB it sudenly started to slowdown only for this perticular query and it takes 20+ seconds to respond. If I do a restore the DB again then it continues to work fine and the symptom pops out after 3 weeks time. I am just suspecting is there any cache or index maxing out causes this issue? Could you please guide me what can it be the root cause of this issue? Thank you, Fahiz
Re: Specific query taking time to process
On Sat, Dec 07, 2019 at 08:05:59PM +, Fahiz Mohamed wrote: > There is a specific search query I am running to get list of Documents and > their metadata from several table in the DB. > We are running Postgres 9.6.9 on Amazon RDS (db.m5.4xlarge instance) > > Our current DB consists of 500GB of data and indexes. Most of the rows in > table are consist of 454,078,915 454M rows or ?? > With the fresh DB with the restore of the DATA without any indexes Search > query performs relatively quick and most of the time its less than a second. > But after 3 weeks of use of the DB it sudenly started to slowdown only for > this perticular query and it takes 20+ seconds to respond. If I do a restore > the DB again then it continues to work fine and the symptom pops out after 3 > weeks time. > > I am just suspecting is there any cache or index maxing out causes this issue? > > Could you please guide me what can it be the root cause of this issue? https://wiki.postgresql.org/wiki/Slow_Query_Questions Could you send explain ANALYZE (attach here as txt attachment or link on depesz) now and compared with shortly after a restore ? Justin
