From: "Vitale, Anthony, Sony Music" <anthony.vitale@sonymusic.com>
To: "pgsql-performance@lists.postgresql.org"
	<pgsql-performance@lists.postgresql.org>
Subject: Question on what Duration in the log 
Thread-Topic: Question on what Duration in the log 
Thread-Index: AdupWdJu7qK2OBciTYGQY3RX/oz9PA==
Date: Wed, 9 Apr 2025 14:27:08 +0000
Message-ID: 
 <AS8PR02MB100787E253E044418232962DC99B42@AS8PR02MB10078.eurprd02.prod.outlook.com>
Accept-Language: en-US
Content-Language: en-US
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: 
 =?us-ascii?Q?DuJ9GTAzwV+pfv7sPRxps653aMQ4yRCLnC3lZ4yHEq7SZWAQzktQOoO4QBjk?=
 =?us-ascii?Q?j9Tg13NMwWIDOxdWm0hiXfdFLCmP6wUwiKqygGI9Aoi3Q6Un7qNGxUHpF/yj?=
 =?us-ascii?Q?xTe0RGnBd6QMDBmMTlIO0TEZgdlprZoxVGzkhYvGOUsS7MLgemveM6VaDG5B?=
 =?us-ascii?Q?RT6R/l3lARuyu2i9qwAW+rfQy/RGaCxL/0E2/a/tyuK5rVQ5f2RuKK2hSENo?=
 =?us-ascii?Q?wcNMF+FYv010+rmNRi7+kaok/Zmf45f5yjBnqjLlaLVhApt1D9YAPJhX2fkG?=
 =?us-ascii?Q?DBStpwqLzz8zQ3ff2xjkwX4FcbICaj8DGpAugoP4dFiplgMl5YchrWiHxGb6?=
 =?us-ascii?Q?e5fsiiasrxjSb9k8s/dVM3a4tuZqDg8N1Pa6ZrcyEcAOMabdcJfbodU1z3d6?=
 =?us-ascii?Q?zCW5G82+2VoZ1JIVrvmzELDxFEcWDyvsrNL0sP3Sd75mwXV5wz5j4FujlIDU?=
 =?us-ascii?Q?NZ7GVurzAT106XGpJteOlSwv4RfuyIioC3h47kEA2BogopPciCL9AbJBmTYn?=
 =?us-ascii?Q?FLK5aKmuwsvMMlbY6EFQAJ3firdM2n6FArM9jlEdDktxqDErx03HJREIdTkW?=
 =?us-ascii?Q?/NG3DfcizDwxWTxOj67kQ/nNi84U2h04i9Tf3DPzhzxGQs+GHGPh+c1q1UGp?=
 =?us-ascii?Q?VaP/Ovo4VoHbyTUmJ6ZT5wDSi5ITOV2x3FUZVtIiVh3MDNrWVogTm22vb4tl?=
 =?us-ascii?Q?06rt1ybQU3Q/bEk5Qwvnq4FmazpZUyo4UqgNa3Ie6RIU2OsqvM8dxx7+U6Uc?=
 =?us-ascii?Q?baEWRFmYM83oY8HtD3dlVFlXmpLxISO9Oe+jbY6t61cDUxI/9veN3+9VuowG?=
 =?us-ascii?Q?7sXFu9VxF1L50cjDlWu2l4VS0yBNInb0ZeVcbG9L9VPxTwI7stZu4MK5lVgs?=
 =?us-ascii?Q?NYZfPho46zFu5vymhs7GJAdczFl/bLsYgoIwIgOTaEuUw61fe/U6HinBlO56?=
 =?us-ascii?Q?uKyAvNYg2hHBtkZa7EbZUIl2pqUKsVMqm60OvRNpE5kElkQ6d89RtPN6fCxd?=
 =?us-ascii?Q?m5tDXRGbCwRT+18KAHkx8XIgaOW/AjfylHCg/tIBJxuZSn6Oak1sr1P39jLs?=
 =?us-ascii?Q?b830Ynl+N3IIQtwZLTjEmBfu648REOi2rpLxeXKhdCMGAR5Sl5Q6MKgwBdaq?=
 =?us-ascii?Q?5cEzPjBWCq0JBb2TUl0YHRww5PMX/UPzQD2UGr69NDTgdpAspcaw3rH0TXIi?=
 =?us-ascii?Q?ZS5GsQXjRlpU+Qx3ithOmfkLVoPlWY36v8TZhN0LyozIAWcXu64dvtu+/jUI?=
 =?us-ascii?Q?2AZYOHG1srgGrCtgX3FYnPnIDWwkbijB0fZxJCE9qtF+eq04/W2jtNYPIJ4g?=
 =?us-ascii?Q?gQYggktVkCLe1OcZyrFG6BuwqkOzY7WgT7Ej5jhqND8zMGdZTzuVZ4agY77X?=
 =?us-ascii?Q?BiH2YTJz3/OU9hhf4zbzq27Ow1hLx5p0pjxovc3Zja9HisLeoFiR6gkWDdJC?=
 =?us-ascii?Q?FqOaI5H/wzyNwMoHUJyYPrYz5OIDsb+voneJWhhBN9rKUSwTeRUX+eoRm17e?=
 =?us-ascii?Q?UWC6Avv5T8g7hIXvOGAv1op8i1N+iJ4UZ6NNMY/+3zu1Wm9bA4U4aXQ1FDLV?=
 =?us-ascii?Q?pFc1wH3p8Kw++9v4qMSzWirJA1ojfMum9a3TLGgVkYJuJQHztdCR/0XG5R6G?=
 =?us-ascii?Q?Qw=3D=3D?=
Content-Type: multipart/alternative;
	boundary="_000_AS8PR02MB100787E253E044418232962DC99B42AS8PR02MB10078eu_"
MIME-Version: 1.0
X-OriginatorOrg: sonymusic.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-AuthSource: AS8PR02MB10078.eurprd02.prod.outlook.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 
 fc046a6c-782e-4d04-074c-08dd77729c67
X-MS-Exchange-CrossTenant-originalarrivaltime: 09 Apr 2025 14:27:09.0165
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: f0aff3b7-91a5-4aae-af71-c63e1dda2049
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: 
 LeHy1ToiZC06Rv7U6WgTXWkbCoRbFmX7SyYV387Hgk3/jXqnjOWWyKz17RFDcElBp3JK+fdGHxRzxc+8/C1OgvZeWkg0QJcndDBrEWo5Uck=
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DU5PR02MB10549
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>
Archived-At: 
 <https://www.postgresql.org/message-id/AS8PR02MB100787E253E044418232962DC99B42%40AS8PR02MB10078.eurprd02.prod.outlook.com>
Precedence: bulk

--_000_AS8PR02MB100787E253E044418232962DC99B42AS8PR02MB10078eu_
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable

Hello All

In my PG Version 14 log I have set to log the duration of sql (Example of o=
ne log row below).

2025-04-08 07:31:57 UTC:XXX(55994):XXX:[8949]:LOG:  duration: 6555.756 ms  =
execute S_381: {Actual Parameterized Sql executed}


This Shows the Execution of a JDBC Server Side Prepared statement (i.e S_38=
1) which took 6.5 seconds.

When I run the Sql using explain analyze it runs shows an execution time of=
 73 ms

Planning Time: 0.773 ms
Execution Time: 73.578 ms

I am trying to understand the duration of 6.5 seconds and if it represents =
the time to execute the sql (Since the plan already exists)  itself or the =
full time needed to execute the sql as well as for the last row to be fetch=
ed by the program.

The result set of the query does return 50,000+ rows

Is there anywhere that explains what exactly the duration in the log repres=
ents.

Thanks
Anthony Vitale


--_000_AS8PR02MB100787E253E044418232962DC99B42AS8PR02MB10078eu_
Content-Type: text/html; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable

<html xmlns:v=3D"urn:schemas-microsoft-com:vml" xmlns:o=3D"urn:schemas-micr=
osoft-com:office:office" xmlns:w=3D"urn:schemas-microsoft-com:office:word" =
xmlns:m=3D"http://schemas.microsoft.com/office/2004/12/omml" xmlns=3D"http:=
//www.w3.org/TR/REC-html40">
<head>
<meta http-equiv=3D"Content-Type" content=3D"text/html; charset=3Dus-ascii"=
>
<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:Aptos;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
	{margin:0in;
	font-size:12.0pt;
	font-family:"Aptos",sans-serif;
	mso-ligatures:standardcontextual;}
span.EmailStyle17
	{mso-style-type:personal-compose;
	font-family:"Aptos",sans-serif;
	color:windowtext;}
.MsoChpDefault
	{mso-style-type:export-only;}
@page WordSection1
	{size:8.5in 11.0in;
	margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
	{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext=3D"edit" spidmax=3D"1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext=3D"edit">
<o:idmap v:ext=3D"edit" data=3D"1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang=3D"EN-US" link=3D"#467886" vlink=3D"#96607D" style=3D"word-wrap:=
break-word">
<div class=3D"WordSection1">
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">Hello All<o:p></o:p=
></span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">In my PG Version 14=
 log I have set to log the duration of sql (Example of one log row below).<=
o:p></o:p></span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal" style=3D"background:#F3F3F7"><span style=3D"font-siz=
e:9.0pt;font-family:&quot;Courier New&quot;;color:#424650;mso-ligatures:non=
e">2025-04-08 07:31:57 UTC:XXX(55994):XXX:[8949]:LOG:&nbsp; duration: 6555.=
756 ms&nbsp; execute S_381: {Actual Parameterized Sql executed}<o:p></o:p><=
/span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">This Shows the Exec=
ution of a JDBC Server Side Prepared statement (i.e S_381) which took 6.5 s=
econds.<o:p></o:p></span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">When I run the Sql =
using explain analyze it runs shows an execution time of 73 ms<o:p></o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal" style=3D"text-indent:.5in"><span style=3D"font-size:=
11.0pt">Planning Time: 0.773 ms<o:p></o:p></span></p>
<p class=3D"MsoNormal" style=3D"text-indent:.5in"><span style=3D"font-size:=
11.0pt">Execution Time: 73.578 ms<o:p></o:p></span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">I am trying to unde=
rstand the duration of 6.5 seconds and if it represents the time to execute=
 the sql (Since the plan already exists) &nbsp;itself or the full time need=
ed to execute the sql as well as for the
 last row to be fetched by the program.<o:p></o:p></span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">The result set of t=
he query does return 50,000+ rows<o:p></o:p></span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">Is there anywhere t=
hat explains what exactly the duration in the log represents.<o:p></o:p></s=
pan></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt"><o:p>&nbsp;</o:p></=
span></p>
<p class=3D"MsoNormal"><span style=3D"font-size:11.0pt">Thanks<o:p></o:p></=
span></p>
<p class=3D"MsoNormal"><b><span style=3D"font-size:11.0pt;font-family:&quot=
;Arial&quot;,sans-serif;color:#1F497D;mso-ligatures:none">Anthony Vitale<br=
>
<br>
</span></b><span style=3D"font-size:11.0pt;color:#1F497D;mso-ligatures:none=
"><o:p></o:p></span></p>
<p class=3D"MsoNormal"><o:p>&nbsp;</o:p></p>
</div>
</body>
</html>

--_000_AS8PR02MB100787E253E044418232962DC99B42AS8PR02MB10078eu_--