pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedquery that canceled isnt logged
5+ messages / 2 participants
[nested] [flat]
* query that canceled isnt logged
@ 2019-12-08 13:08 Mariel Cherkassky <mariel.cherkassky@gmail.com>
0 siblings, 2 replies; 5+ messages in thread
From: Mariel Cherkassky @ 2019-12-08 13:08 UTC (permalink / raw)
To: pgsql-performance@lists.postgresql.org
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 *<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
Any idea why I the query isnt logged but I still get the ERROR msg ?
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: query that canceled isnt logged
@ 2019-12-08 15:05 Tom Lane <tgl@sss.pgh.pa.us>
parent: Mariel Cherkassky <mariel.cherkassky@gmail.com>
1 sibling, 1 reply; 5+ messages in thread
From: Tom Lane @ 2019-12-08 15:05 UTC (permalink / raw)
To: Mariel Cherkassky <mariel.cherkassky@gmail.com>; +Cc: pgsql-performance@lists.postgresql.org
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
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: query that canceled isnt logged
@ 2019-12-08 15:18 Mariel Cherkassky <mariel.cherkassky@gmail.com>
parent: Mariel Cherkassky <mariel.cherkassky@gmail.com>
1 sibling, 1 reply; 5+ messages in thread
From: Mariel Cherkassky @ 2019-12-08 15:18 UTC (permalink / raw)
To: MichaelDBA@sqlexec.com <michaeldba@sqlexec.com>; pgsql-performance
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.
>
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: query that canceled isnt logged
@ 2019-12-08 15:23 Mariel Cherkassky <mariel.cherkassky@gmail.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 0 replies; 5+ messages in thread
From: Mariel Cherkassky @ 2019-12-08 15:23 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-performance
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..
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: query that canceled isnt logged
@ 2019-12-08 15:42 Tom Lane <tgl@sss.pgh.pa.us>
parent: Mariel Cherkassky <mariel.cherkassky@gmail.com>
0 siblings, 0 replies; 5+ messages in thread
From: Tom Lane @ 2019-12-08 15:42 UTC (permalink / raw)
To: Mariel Cherkassky <mariel.cherkassky@gmail.com>; +Cc: MichaelDBA@sqlexec.com <michaeldba@sqlexec.com>; pgsql-performance
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
^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2019-12-08 15:42 UTC | newest]
Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2019-12-08 13:08 query that canceled isnt logged Mariel Cherkassky <mariel.cherkassky@gmail.com>
2019-12-08 15:05 ` Tom Lane <tgl@sss.pgh.pa.us>
2019-12-08 15:23 ` Mariel Cherkassky <mariel.cherkassky@gmail.com>
2019-12-08 15:18 ` Mariel Cherkassky <mariel.cherkassky@gmail.com>
2019-12-08 15:42 ` Tom Lane <tgl@sss.pgh.pa.us>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox