From schmidt@dltmail.de Thu Mar  14 07:29:17 2019
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 1h4Knu-0005Lj-Dr
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 07:29:26 +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 1h4Knt-0001C4-3m
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 07:29:25 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <schmidt@dltmail.de>)
	id 1h4Kns-00018Z-PH
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 07:29:24 +0000
Received: from marty.mivaro.de ([185.181.105.214])
	by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <schmidt@dltmail.de>)
	id 1h4Knp-00008q-LR
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 07:29:23 +0000
Received: from BN7PR08MB4307.namprd08.prod.outlook.com (unknown
 [40.97.229.69])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(No client certificate requested)
	(Authenticated sender: schmidt@dltmail.de)
	by marty.mivaro.de (Postfix) with ESMTPSA id 205151C092F
	for <pgsql-performance@lists.postgresql.org>;
 Thu, 14 Mar 2019 08:29:18 +0100 (CET)
From: Stephan Schmidt <schmidt@dltmail.de>
To: "pgsql-performance@lists.postgresql.org"
	<pgsql-performance@lists.postgresql.org>
Subject: impact of auto explain on overall performance
Thread-Topic: impact of auto explain on overall performance
Thread-Index: AQHU2jcBEBkdeKfdb0S9kkw1CLB18g==
X-MS-Exchange-MessageSentRepresentingType: 1
Date: Thu, 14 Mar 2019 07:29:17 +0000
Message-ID: 
	<BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
Accept-Language: de-DE, en-US
Content-Language: de-DE
X-MS-Has-Attach: 
X-MS-Exchange-Organization-SCL: -1
X-MS-TNEF-Correlator: 
X-MS-Exchange-Organization-RecordReviewCfmType: 0
Content-Type: multipart/alternative;
	boundary="_000_BN7PR08MB4307BF020C74744E2638C21DE84B0BN7PR08MB4307namp_"
MIME-Version: 1.0
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

--_000_BN7PR08MB4307BF020C74744E2638C21DE84B0BN7PR08MB4307namp_
Content-Type: text/plain; charset="Windows-1252"
Content-Transfer-Encoding: quoted-printable

Hello,

i=92m currently working on a high Performance Database and want to make sur=
e that whenever there are slow queries during regular operations i=92ve got=
 all Information about the query in my logs. So auto_explain come to mind, =
but the documentation explicitly states that it Comes at a cost. My Questio=
n is, how big is the latency added by auto_explain in percentage or ms ?

Best regards,

stephan

--_000_BN7PR08MB4307BF020C74744E2638C21DE84B0BN7PR08MB4307namp_
Content-Type: text/html; charset="Windows-1252"
Content-Transfer-Encoding: quoted-printable

<html xmlns:o=3D"urn:schemas-microsoft-com:office:office" xmlns:w=3D"urn:sc=
hemas-microsoft-com:office:word" xmlns:m=3D"http://schemas.microsoft.com/of=
fice/2004/12/omml" xmlns=3D"http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv=3D"Content-Type" content=3D"text/html; charset=3DWindows-1=
252">
<meta name=3D"Generator" content=3D"Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
	{font-family:"Cambria Math";
	panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
	{font-family:Calibri;
	panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
	{margin:0cm;
	margin-bottom:.0001pt;
	font-size:11.0pt;
	font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
	{mso-style-priority:99;
	color:blue;
	text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
	{mso-style-priority:99;
	color:#954F72;
	text-decoration:underline;}
.MsoChpDefault
	{mso-style-type:export-only;}
@page WordSection1
	{size:612.0pt 792.0pt;
	margin:70.85pt 70.85pt 2.0cm 70.85pt;}
div.WordSection1
	{page:WordSection1;}
--></style>
</head>
<body lang=3D"DE" link=3D"blue" vlink=3D"#954F72">
<div class=3D"WordSection1">
<p class=3D"MsoNormal">Hello,</p>
<p class=3D"MsoNormal"><o:p>&nbsp;</o:p></p>
<p class=3D"MsoNormal">i=92m currently working on a high Performance Databa=
se and want to make sure that whenever there are slow queries during regula=
r operations i=92ve got all Information about the query in my logs. So auto=
_explain come to mind, but the documentation
 explicitly states that it Comes at a cost. My Question is, how big is the =
latency added by auto_explain in percentage or ms ?</p>
<p class=3D"MsoNormal"><o:p>&nbsp;</o:p></p>
<p class=3D"MsoNormal">Best regards,</p>
<p class=3D"MsoNormal"><o:p>&nbsp;</o:p></p>
<p class=3D"MsoNormal">stephan<o:p></o:p></p>
</div>
</body>
</html>

--_000_BN7PR08MB4307BF020C74744E2638C21DE84B0BN7PR08MB4307namp_--




From pryzby@telsasoft.com Thu Mar  14 08:23:00 2019
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 1h4Ldt-0008Kb-CA
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 08:23:09 +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 1h4Lds-0003ac-0b
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 08:23:08 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <pryzby@telsasoft.com>)
	id 1h4Ldr-0003aU-G4
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 08:23:07 +0000
Received: from mail-io1-xd31.google.com ([2607:f8b0:4864:20::d31])
	by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <pryzby@telsasoft.com>)
	id 1h4Ldn-0001U8-Lo
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 08:23:05 +0000
Received: by mail-io1-xd31.google.com with SMTP id u12so4243188iop.11
        for <pgsql-performance@lists.postgresql.org>;
 Thu, 14 Mar 2019 01:23:03 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=telsasoft-com.20150623.gappssmtp.com; s=20150623;
        h=date:from:to:cc:subject:message-id:references:mime-version
         :content-disposition:content-transfer-encoding:in-reply-to
         :user-agent;
        bh=+cRJL+U+PRMhdYqZRLVRUFSu9VP45wpuL4uXGemRpus=;
        b=OVqPeMhOqZqItPThWUVoXT8jewVdb78WaAqiyYZ5WzVvWNS3t3scOcMaesS9tTNEOe
         j8oxJGHR2NozguvXwnf09VodJIdzBTW0+qG2Wj8xlwZNuOoWAEfCpgTEFJ9f6U3sIBPK
         2GETE1b7MBYIvN1h+a/2opk7rPcjg0zy27sAlJYglu1cJcv+o1tJam6lxD0l3pqCBk9D
         V68fGiLx09fhFRsSaz7zHheWeFsgrRq2ycnorvSeHlou6LOGGuAmKykUtwl6k/9z3zXa
         0aZ8Vh/D0myyaBzdSlK4vFGjvPHGKBdMhmQs8mFZTOiSeRZX4MAIxbOkNPOQdixprOSN
         Gz3Q==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=1e100.net; s=20161025;
        h=x-gm-message-state:date:from:to:cc:subject:message-id:references
         :mime-version:content-disposition:content-transfer-encoding
         :in-reply-to:user-agent;
        bh=+cRJL+U+PRMhdYqZRLVRUFSu9VP45wpuL4uXGemRpus=;
        b=To0z4rXEVYuIqrbGsWCk+PU5IRNGG5nNXA0Zyp59gzfm4bAqjefWoB+ytegjalUJL9
         BSd5SxWFJxoNe1o5es8MKMsZenrtLcK3mcraY7eMT/vajuGRE3ZU+r7KKbU/hG7z9FCy
         dOpViZ/jpX8vsitjiDpvVUPcFI+XoZUlZpDTOpFFqba/l2Wp6Lp4qAvXJD5KrMgb52/D
         mIySAqxtDEIo1XVUQisyvaKsPCTEYDxezaPBOkWhvUXL+gC/avdUCG2nbKK+UYrMGeaC
         GrIU42PdA+nInXKwDFEyEdWmAB8ZlWYo1dcumYqAc2JaQttS18Na6gAwLv5PXVwCKQqP
         tT4A==
X-Gm-Message-State: APjAAAXIHB9OrUaXeA1okInriv9cWgvDNR0Jf16QWdjM2L0CBLZA74yD
	sJEzIyWVlbjK94LUGxUOoTD8s2mUZd0=
X-Google-Smtp-Source: 
 APXvYqypPdAMrdEyfWgHEla09OYETRYqbiVGxRmbt5L79QRwK4lG6qwoDs4mXlhrMIRKy7ANw7/aWw==
X-Received: by 2002:a6b:d304:: with SMTP id s4mr23047411iob.228.1552551782739;
        Thu, 14 Mar 2019 01:23:02 -0700 (PDT)
Received: from pryzbyj (charmander.telsasoft.com. [50.244.222.1])
        by smtp.gmail.com with ESMTPSA id
 b137sm836869itc.39.2019.03.14.01.23.01
        (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128);
        Thu, 14 Mar 2019 01:23:02 -0700 (PDT)
Received: by pryzbyj (Postfix, from userid 1000)
	id D640E80100A; Thu, 14 Mar 2019 03:23:00 -0500 (CDT)
Date: Thu, 14 Mar 2019 03:23:00 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Stephan Schmidt <schmidt@dltmail.de>
Cc: pgsql-performance@lists.postgresql.org
Subject: Re: impact of auto explain on overall performance
Message-ID: <20190314082300.GC6030@telsasoft.com>
References: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
User-Agent: Mutt/1.5.23 (2014-03-12)
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

On Thu, Mar 14, 2019 at 07:29:17AM +0000, Stephan Schmidt wrote:
> i’m currently working on a high Performance Database and want to make sure that whenever there are slow queries during regular operations i’ve got all Information about the query in my logs. So auto_explain come to mind, but the documentation explicitly states that it Comes at a cost. My Question is, how big is the latency added by auto_explain in percentage or ms ?

https://www.postgresql.org/docs/current/auto-explain.html
|log_analyze
...
|When this parameter is on, per-plan-node timing occurs for all statements executed, whether or not they run long enough to actually get logged. This can have an extremely negative impact on performance. Turning off auto_explain.log_timing ameliorates the performance cost, at the price of obtaining less information.

|auto_explain.log_timing (boolean)
|auto_explain.log_timing controls whether per-node timing information is printed when an execution plan is logged; it's equivalent to the TIMING option of EXPLAIN. The overhead of repeatedly reading the system clock can slow down queries significantly on some systems, so it may be useful to set this parameter to off when only actual row counts, and not exact times, are needed. This parameter has no effect unless auto_explain.log_analyze is enabled. This parameter is on by default. Only superusers can change this setting.

I believe the cost actually varies significantly with the type of plan "node",
with "nested loops" incurring much higher overhead.

I think you could compare using explain(analyze) vs explain(analyze,timing
off).  While you're at it, compare without explain at all.

I suspect the overhead is inconsequential if you set log_timing=off and set
log_min_duration such that only the slowest queries are logged.

Then, you can manually run "explain (analyze,costs on)" on any problematic
queries to avoid interfering with production clients.

Justin




From adrien.nayrat@anayrat.info Thu Mar  14 09:08:39 2019
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 1h4MM3-00029O-Kg
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 09:08:47 +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 1h4MM2-0006TF-3f
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 09:08:46 +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 <adrien.nayrat@anayrat.info>)
	id 1h4MM1-0006P5-Po
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 09:08:45 +0000
Received: from smtpout1.mo803.mail-out.ovh.net ([79.137.123.219])
	by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <adrien.nayrat@anayrat.info>)
	id 1h4MLy-0002Si-Lq
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 09:08:45 +0000
Received: from DAG4EX1.emp.local (unknown [10.108.54.236])
	by mo803.mail-out.ovh.net (Postfix) with ESMTPS id 8510E46523E;
	Thu, 14 Mar 2019 10:08:40 +0100 (CET)
Received: from [192.168.33.239] (62.23.36.114) by DAG4EX1.emp.local
 (172.16.2.7) with Microsoft SMTP Server (version=TLS1_2,
 cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.1.1531.3; Thu, 14 Mar
 2019 10:08:39 +0100
Subject: Re: impact of auto explain on overall performance
To: Justin Pryzby <pryzby@telsasoft.com>, Stephan Schmidt <schmidt@dltmail.de>
CC: <pgsql-performance@lists.postgresql.org>
References: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
 <20190314082300.GC6030@telsasoft.com>
From: Adrien NAYRAT <adrien.nayrat@anayrat.info>
Message-ID: <335b5599-2a6d-4d3e-a801-794642ec16d7@anayrat.info>
Date: Thu, 14 Mar 2019 10:08:39 +0100
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101
 Thunderbird/60.5.3
MIME-Version: 1.0
In-Reply-To: <20190314082300.GC6030@telsasoft.com>
Content-Type: text/plain; charset="utf-8"; format=flowed
Content-Language: en-US-large
Content-Transfer-Encoding: 8bit
X-Originating-IP: [62.23.36.114]
X-ClientProxiedBy: EX4.emp.local (172.16.2.4) To DAG4EX1.emp.local
 (172.16.2.7)
X-Ovh-Tracer-Id: 1880252846379727437
X-VR-SPAMSTATE: OK
X-VR-SPAMSCORE: -100
X-VR-SPAMCAUSE: 
 gggruggvucftvghtrhhoucdtuddrgedutddrhedugdduvdekucetufdoteggodetrfdotffvucfrrhhofhhilhgvmecuqfggjfdpvefjgfevmfevgfenuceurghilhhouhhtmecuhedttdenucesvcftvggtihhpihgvnhhtshculddquddttddm
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

On 3/14/19 9:23 AM, Justin Pryzby wrote:
> On Thu, Mar 14, 2019 at 07:29:17AM +0000, Stephan Schmidt wrote:
>> i’m currently working on a high Performance Database and want to make sure that whenever there are slow queries during regular operations i’ve got all Information about the query in my logs. So auto_explain come to mind, but the documentation explicitly states that it Comes at a cost. My Question is, how big is the latency added by auto_explain in percentage or ms ?
> 
> https://www.postgresql.org/docs/current/auto-explain.html
> |log_analyze
> ...
> |When this parameter is on, per-plan-node timing occurs for all statements executed, whether or not they run long enough to actually get logged. This can have an extremely negative impact on performance. Turning off auto_explain.log_timing ameliorates the performance cost, at the price of obtaining less information.
> 
> |auto_explain.log_timing (boolean)
> |auto_explain.log_timing controls whether per-node timing information is printed when an execution plan is logged; it's equivalent to the TIMING option of EXPLAIN. The overhead of repeatedly reading the system clock can slow down queries significantly on some systems, so it may be useful to set this parameter to off when only actual row counts, and not exact times, are needed. This parameter has no effect unless auto_explain.log_analyze is enabled. This parameter is on by default. Only superusers can change this setting.
> 
> I believe the cost actually varies significantly with the type of plan "node",
> with "nested loops" incurring much higher overhead.
> 
> I think you could compare using explain(analyze) vs explain(analyze,timing
> off).  While you're at it, compare without explain at all.
> 
> I suspect the overhead is inconsequential if you set log_timing=off and set
> log_min_duration such that only the slowest queries are logged.
> 
> Then, you can manually run "explain (analyze,costs on)" on any problematic
> queries to avoid interfering with production clients.
> 
> Justin
> 

You should also consider auto_explain.sample_rate: 
auto_explain.sample_rate causes auto_explain to only explain a fraction 
of the statements in each session. The default is 1, meaning explain all 
the queries. In case of nested statements, either all will be explained 
or none. Only superusers can change this setting.

This option is available since 9.6

Regards




From jeff.janes@gmail.com Thu Mar  14 17:50:07 2019
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 1h4UUv-0006fA-6F
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 17:50:29 +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 1h4UUt-0008RY-IQ
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 17:50:27 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <jeff.janes@gmail.com>)
	id 1h4UUt-0008Ma-59
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 17:50:27 +0000
Received: from mail-vk1-xa43.google.com ([2607:f8b0:4864:20::a43])
	by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <jeff.janes@gmail.com>)
	id 1h4UUm-00064p-GJ
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 17:50:25 +0000
Received: by mail-vk1-xa43.google.com with SMTP id p20so601092vki.2
        for <pgsql-performance@lists.postgresql.org>;
 Thu, 14 Mar 2019 10:50:20 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=gmail.com; s=20161025;
        h=mime-version:references:in-reply-to:from:date:message-id:subject:to
         :cc;
        bh=xDcy4ed9KTelIHgd81HETC9oNWUYnJaXEG8VJn0Vj0o=;
        b=uOaL2VywGbGdUxuud0BJ2a5MUl+QUZI6d3zZFS/DGIDVqQRUZztxXMmmZr3kPEGEYL
         6w7DWEeZL9+KS9sm6MzAT81L7kbjvH2hi1rS6Bwl10FyTE7mJ434rydwFB2v5quMDooR
         ZVW6Fv85ZAaCa+pSsoVf/r8XD83RvrTav/EgmsEt53omb3oyawLHl5cKzjT4BaI/8oGy
         ET92JG0lfMxQHWqBuvUsekgAxadeB5BPcByyv4+n6Cu4HQ25omZQSK87b3vGBqicZSuv
         wvkeccyu56wkbzeFJ+2908fx+kU67Q2uAz2Q8eBreMXV/+i+14P+kHZ1RnJzawnV+Go4
         gC6A==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=1e100.net; s=20161025;
        h=x-gm-message-state:mime-version:references:in-reply-to:from:date
         :message-id:subject:to:cc;
        bh=xDcy4ed9KTelIHgd81HETC9oNWUYnJaXEG8VJn0Vj0o=;
        b=jDuoqNBzvfoXMyYhgk70GGh+uZpkpIZb9PUggVvqtqn7NTttEOGEiISiGxrM6qYFRL
         Pyq167d1gVXU+KlelVmlSMi7E1ipX+u79UqusK6X0uhx/DSfbUZqp15zEdANdIGRj8m+
         R37cv6G0X4bI7SKOL8JijgkJo+GbIPIWiLgDAlLD9hkPNWbzxmJ9TUQh6rhqyyLaQBgc
         E7DMDWyejmk1GKt70dJSuewhi2jIEqWayRnoItYRhMTEjNTZIhgEjJ9nv4qFhlCf3NQo
         lRpZUizIrzB/zi0UnXXw5fzJNQbHLZXWNzrZFSWEncLKbWn8nTndSUA/7CHYH9+5o7hy
         BGRg==
X-Gm-Message-State: APjAAAVLwM98+egPly2lzAmXaSlB3VH4k5FFFJ43GZe3IQb/1yhqVzp0
	ui450YEj7fUfvrA8dg/lXCGcQFmnJRwkjIk0N/63d6c=
X-Google-Smtp-Source: 
 APXvYqxb9t9wKWVh+FxBxUGmFCApNgJWjgse9tbWP7arOmET+CBTr0vY88u+tuAc5us90rian18eVIwXprwsb8X/1RA=
X-Received: by 2002:a1f:55c7:: with SMTP id
 j190mr26671986vkb.42.1552585819067;
 Thu, 14 Mar 2019 10:50:19 -0700 (PDT)
MIME-Version: 1.0
References: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
In-Reply-To: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
From: Jeff Janes <jeff.janes@gmail.com>
Date: Thu, 14 Mar 2019 13:50:07 -0400
Message-ID: 
 <CAMkU=1xO_k+Ho7Qc9Wxuo7gP-_dfwNoEBwsC--A4e=_DTte5KQ@mail.gmail.com>
Subject: Re: impact of auto explain on overall performance
To: Stephan Schmidt <schmidt@dltmail.de>
Cc: "pgsql-performance@lists.postgresql.org"
 <pgsql-performance@lists.postgresql.org>
Content-Type: multipart/alternative; boundary="0000000000003aa5840584118e3d"
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

--0000000000003aa5840584118e3d
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

On Thu, Mar 14, 2019 at 3:29 AM Stephan Schmidt <schmidt@dltmail.de> wrote:

> Hello,
>
>
>
> i=E2=80=99m currently working on a high Performance Database and want to =
make sure
> that whenever there are slow queries during regular operations i=E2=80=99=
ve got all
> Information about the query in my logs. So auto_explain come to mind, but
> the documentation explicitly states that it Comes at a cost. My Question
> is, how big is the latency added by auto_explain in percentage or ms ?
>

You will have to measure it yourself and see.  It depends on your hardware,
OS, and OS version, and PostgreSQL version.  And the nature of your
queries.  If you have auto_explain.log_timing=3Don, then I find that large
sorts are the worst impacted.  So if you have a lot of those, you should be
careful.

On older kernels, I would run with auto_explain.log_timing=3Doff.  On newer
kernels where you can read the clock from user-space, I run with
auto_explain.log_timing=3Don.  I find the slowdown noticeable with careful
investigation (around 3%, last time I carefully investigated it), but
usually well worth paying to have actual data to work with when I find slow
queries in the log.  I made a special role with auto_explain disabled for
use with a few reporting queries with large sorts, both to circumvent the
overhead and to avoid spamming the log with slow queries I already know
about.

Cheers,

Jeff

>

--0000000000003aa5840584118e3d
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div dir=3D"ltr"><div dir=3D"ltr"><div dir=3D"ltr">On Thu,=
 Mar 14, 2019 at 3:29 AM Stephan Schmidt &lt;<a href=3D"mailto:schmidt@dltm=
ail.de">schmidt@dltmail.de</a>&gt; wrote:<br></div><div class=3D"gmail_quot=
e"><blockquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;bord=
er-left:1px solid rgb(204,204,204);padding-left:1ex">





<div lang=3D"DE">
<div class=3D"gmail-m_-4337377284142686525WordSection1">
<p class=3D"MsoNormal">Hello,</p>
<p class=3D"MsoNormal"><u></u>=C2=A0<u></u></p>
<p class=3D"MsoNormal">i=E2=80=99m currently working on a high Performance =
Database and want to make sure that whenever there are slow queries during =
regular operations i=E2=80=99ve got all Information about the query in my l=
ogs. So auto_explain come to mind, but the documentation
 explicitly states that it Comes at a cost. My Question is, how big is the =
latency added by auto_explain in percentage or ms ?</p></div></div></blockq=
uote><div><br></div><div>You will have to measure it yourself and see.=C2=
=A0 It depends on your hardware, OS, and OS version, and PostgreSQL version=
.=C2=A0 And the nature of your queries.=C2=A0 If you have auto_explain.log_=
timing=3Don, then I find that large sorts are the worst impacted.=C2=A0 So =
if you have a lot of those, you should be careful.</div><div><br></div><div=
>On older kernels, I would run with auto_explain.log_timing=3Doff.=C2=A0 On=
 newer kernels where you can read the clock from user-space, I run with aut=
o_explain.log_timing=3Don.=C2=A0 I find the slowdown noticeable with carefu=
l investigation (around 3%, last time I carefully investigated it), but usu=
ally well worth paying to have actual data to work with when I find slow qu=
eries in the log.=C2=A0 I made a special role with auto_explain disabled fo=
r use with a few reporting queries with large sorts, both to circumvent the=
 overhead and to avoid spamming the log with slow queries I already know ab=
out.</div><div><br></div><div>Cheers,</div><div><br></div><div>Jeff</div><b=
lockquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;border-le=
ft:1px solid rgb(204,204,204);padding-left:1ex"><div lang=3D"DE"><div class=
=3D"gmail-m_-4337377284142686525WordSection1">
</div>
</div>

</blockquote></div></div></div></div>

--0000000000003aa5840584118e3d--




From schneider@ardentperf.com Thu Mar  14 19:58:18 2019
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 1h4WUm-0005WA-6A
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 19:58:28 +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 1h4WUk-0007tX-Dk
	for pgsql-performance@arkaria.postgresql.org; Thu, 14 Mar 2019 19:58:26 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <schneider@ardentperf.com>)
	id 1h4WUj-0007tP-Vg
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 19:58:26 +0000
Received: from mail-pf1-x441.google.com ([2607:f8b0:4864:20::441])
	by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <schneider@ardentperf.com>)
	id 1h4WUg-0000Va-DC
	for pgsql-performance@lists.postgresql.org; Thu, 14 Mar 2019 19:58:24 +0000
Received: by mail-pf1-x441.google.com with SMTP id q17so4558107pfh.10
        for <pgsql-performance@lists.postgresql.org>;
 Thu, 14 Mar 2019 12:58:22 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=ardentperf-com.20150623.gappssmtp.com; s=20150623;
        h=subject:to:references:from:message-id:date:user-agent:mime-version
         :in-reply-to:content-language:content-transfer-encoding;
        bh=eVydF0abNPS3fs0kr2HEbWDeDw7qsKguCPOnFr3yPag=;
        b=fm5fPZaF8XWTs8+A9MVdCeiivL55/xU/f6xZqjZeoIDqSmT3K9nU4zkgRlIq/3Wpj+
         z40HGn8rJgfalzJwXTyweiQoqgXx8n+5/SAEwHkmeKUqpnk/L1g6WF14iWCYoMYMXXTc
         lrrB+m2p7cyN1v7LFo/Lw2Fn54iTi0OCzqi3rmfGb4Da4Zjs2sinIGDdGvOgn2v+iXV/
         cBPar3sGpejShx5gQFHYN8mWLsAk0jojiGdfdD9OVVcqLFxEBXULfwIaCX4t4VjClTLb
         2GkbkQTedyH9YzhNahETN0SFudDzIT5GFXRILXpo5lTRH+EX73Wr8A2Ir4wQMNGYpJEr
         UQ1Q==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=1e100.net; s=20161025;
        h=x-gm-message-state:subject:to:references:from:message-id:date
         :user-agent:mime-version:in-reply-to:content-language
         :content-transfer-encoding;
        bh=eVydF0abNPS3fs0kr2HEbWDeDw7qsKguCPOnFr3yPag=;
        b=Ljxkgrdyu5ECxNPI23oz59YFfypZswlk3FHPlI6WMXPuTE8ATSl+YJblG7fB/xzkYC
         VvEl1SKCOoMmWrKUjgbJiJwpMVh9qPQexSJEfMmNe/Epx2+UI0/GKFNh2n/cHvUJHoLl
         hhGFW2HXWgFYj3H47zGps4ST2z9CQ2CERIfXLPTAm9vOwbMMrftK4ZFrK9KzGYi+Hk9K
         3JwwFUmhEIH9wkXS+wKR3amsIetYVjNMyIyL+eXGuzwEm4OaNVNx9/m47VOvLqEPBjiP
         yXdlPDzX6NFgTSFhBX+6ooJeQrL/A5LDPHtYzQWvhhcXewS2FruXTSMmVT3ODLeHj/yg
         JEDg==
X-Gm-Message-State: APjAAAWQMkWbdHy6WD2W0EdkFBELptl6jrdnStTjLkRNg494DyOJOnQy
	y9/uQT3FeL1o3sRUJJ9LjzrsR2eK5BQ=
X-Google-Smtp-Source: 
 APXvYqyrW26tnP6f/aPP3QnZ9nQk+vm8j8ugBvtQfBUdBjWA/dGrA0DvYTFpMf28yYiz8QHDiSFaCg==
X-Received: by 2002:a62:b248:: with SMTP id x69mr44780pfe.256.1552593500352;
        Thu, 14 Mar 2019 12:58:20 -0700 (PDT)
Received: from 186590ce269b.ant.amazon.com (54-240-196-174.amazon.com.
 [54.240.196.174])
        by smtp.gmail.com with ESMTPSA id
 h184sm35371733pfc.78.2019.03.14.12.58.19
        (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128);
        Thu, 14 Mar 2019 12:58:19 -0700 (PDT)
Subject: Re: impact of auto explain on overall performance
To: Stephan Schmidt <schmidt@dltmail.de>,
 "pgsql-performance@lists.postgresql.org"
 <pgsql-performance@lists.postgresql.org>
References: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
From: Jeremy Schneider <schneider@ardentperf.com>
Message-ID: <50a93298-5e11-f625-9a78-57d02ea80404@ardentperf.com>
Date: Thu, 14 Mar 2019 12:58:18 -0700
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:60.0)
 Gecko/20100101 Thunderbird/60.5.2
MIME-Version: 1.0
In-Reply-To: 
 <BN7PR08MB4307BF020C74744E2638C21DE84B0@BN7PR08MB4307.namprd08.prod.outlook.com>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 8bit
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

On 3/14/19 00:29, Stephan Schmidt wrote:
> i’m currently working on a high Performance Database and want to make
> sure that whenever there are slow queries during regular operations i’ve
> got all Information about the query in my logs. So auto_explain come to
> mind, but the documentation explicitly states that it Comes at a cost.
> My Question is, how big is the latency added by auto_explain in
> percentage or ms ?

One thought - what if the problem query is a 4ms query that just went to
6ms but it's executed millions of times per second? That would create a
150% increase to the load on the system.

The approach I've had the most success with is to combine active session
sampling (from pg_stat_activity) with pg_stat_statements (ideally with
periodic snapshots) to identify problematic SQL statements, then use
explain analyze after you've identified them.

There are a handful of extensions on the internet that can do active
session sampling for you, and I've seen a few scripts that can be put
into a scheduler to capture snapshots of stats tables.

Maybe something to consider in addition to the auto_explain stuff.

-Jeremy

-- 
http://about.me/jeremy_schneider