Thread: 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)
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
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 <unnamed>: 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
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 ?
Mariel Cherkassky <mariel.cherkassky@gmail.com> 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 *<unnamed>: 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
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);
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.
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..
Mariel Cherkassky <mariel.cherkassky@gmail.com> 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