Received: from malur.postgresql.org ([217.196.149.56])
	by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <pgsql-performance-owner+archive@lists.postgresql.org>)
	id 1idy7W-0001h8-3p
	for pgsql-performance@arkaria.postgresql.org; Sun, 08 Dec 2019 15:05:14 +0000
Received: from localhost ([127.0.0.1] helo=malur.postgresql.org)
	by malur.postgresql.org with esmtp (Exim 4.89)
	(envelope-from <pgsql-performance-owner+archive@lists.postgresql.org>)
	id 1idy7U-0007qc-Ps
	for pgsql-performance@arkaria.postgresql.org; Sun, 08 Dec 2019 15:05:12 +0000
Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <tgl@sss.pgh.pa.us>)
	id 1idy7U-0007qV-Gs
	for pgsql-performance@lists.postgresql.org; Sun, 08 Dec 2019 15:05:12 +0000
Received: from sss.pgh.pa.us ([66.207.139.130])
	by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <tgl@sss.pgh.pa.us>)
	id 1idy7N-0000ef-ME
	for pgsql-performance@lists.postgresql.org; Sun, 08 Dec 2019 15:05:12 +0000
Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1])
	by sss.pgh.pa.us (8.14.4/8.14.4) with ESMTP id xB8F52X5028519;
	Sun, 8 Dec 2019 10:05:02 -0500
From: Tom Lane <tgl@sss.pgh.pa.us>
To: Mariel Cherkassky <mariel.cherkassky@gmail.com>
cc: pgsql-performance@lists.postgresql.org
Subject: Re: query that canceled isnt logged
In-reply-to: 
 <CA+t6e1nYocLRyELmm6VM81JjfwTz_QbkiSJgyUkyDHGd-DFt8A@mail.gmail.com>
References: 
 <CA+t6e1nYocLRyELmm6VM81JjfwTz_QbkiSJgyUkyDHGd-DFt8A@mail.gmail.com>
Comments: In-reply-to Mariel Cherkassky <mariel.cherkassky@gmail.com>
	message dated "Sun, 08 Dec 2019 15:08:27 +0200"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <28517.1575817502.1@sss.pgh.pa.us>
Date: Sun, 08 Dec 2019 10:05:02 -0500
Message-ID: <28518.1575817502@sss.pgh.pa.us>
List-Id: <pgsql-performance.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:pgsql-performance@lists.postgresql.org>
List-Owner: <mailto:pgsql-performance-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/pgsql-performance>
Precedence: bulk

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