From msalais@msym.fr Thu Sep 9 18:13:33 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOOYW-0001VR-9t for pgsql-performance@arkaria.postgresql.org; Thu, 09 Sep 2021 18:13:48 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mOOYT-0004OW-KU for pgsql-performance@arkaria.postgresql.org; Thu, 09 Sep 2021 18:13:45 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOOYT-0004OO-CW for pgsql-performance@lists.postgresql.org; Thu, 09 Sep 2021 18:13:45 +0000 Received: from mout.kundenserver.de ([217.72.192.75]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOOYN-0004SU-Jh for pgsql-performance@postgresql.org; Thu, 09 Sep 2021 18:13:44 +0000 Received: from ANAT ([78.197.128.121]) by mrelayeu.kundenserver.de (mreue109 [212.227.15.184]) with ESMTPSA (Nemesis) id 1MxUfn-1n8wdC1uvp-00xu2v for ; Thu, 09 Sep 2021 20:13:35 +0200 From: "Michel SALAIS" To: Subject: sql execution time in pg_stat_statements Date: Thu, 9 Sep 2021 20:13:33 +0200 Message-ID: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_0060_01D7A5B7.2B0253D0" X-Mailer: Microsoft Outlook 16.0 Thread-Index: Adelpel537/e59LkRrKfXMwWz7SC1w== Content-Language: fr X-Provags-ID: V03:K1:lE+3IejuKFbTtG/jaoRs73RjW77VlQWYzELLGXd8YfT4GOQiCRJ 3qY9bxPAtDd4tjcXbIJ3PJOlQS8fMlx9THzv+gHYvDSfhqf7meF60USg8b2XZPXwlKevbRR Aa6zjszP/2JD83JSkfrc1OxmOezST79L4w7GSZfkSw9lphkNrZ7xpIwXtoXtCVaMO8CLdMh WvYxzCY0iiht7Yqh3DJhQ== X-Spam-Flag: NO X-UI-Out-Filterresults: notjunk:1;V03:K0:xbFypsmvLnY=:0uy8YEPmhjTVbEeNkmmLx+ KpaKIhm032ndx6Ou/Qdjt5P6zxBxy+t0LCjww2fZyv51asDnW4cg7uXa7NbZbt+TiGfD+Tbsv lFXzy+n8ZD/2HsnzjBoXwoGt4JQ32WisB6QvoFRLAMfYsEl6J8M9P/n61fRr9ymitKMgt5w/z I4km+Z2gRivWoR+1ULxMPhiio5LDXi7u4Frjv8CIw12nc5M8tq57+8ccMAhLoSKjp2F08O3hd 7zXBEqY5nHygJ6Ogc02tiWU6NeAXxs5rhXeeGsSTG4MfEYRVqp5DzMqv+PaZfYIr0S2w91Amm sTB8LCTIZsseC/L9bRQofKtsFffTO6f4AocTRsvCaV7jhWizAF5Zs7shoVeEwH9dnrRV2xzk7 sDmT3d9kG+SurJnTf33ex61cK0XVKtv4varxxRk37HD9XRrtjUKju1u14SiKstFbc2+imhrzD O/Fp1mrA58Hs3p3G5wTJSLwW3IodoqCiFMkZ1BYY3dGF3tVzd1xDEcm//wyp1AaZ2OnkhX8V5 WAI4QDi2BvuExbAxyblPKT9xV0zXvQxLfIaH5I1AFNlow4kW//HK+iDKW+f40lR9OymggkyWg tMBYYCU0cluHgcqoPV75H1Y0GJc4XG6xO0moDJByyAO7s1fOIMBBS2ACC1RXzJ6gADz849rmx JeeOb+DtvVHAhFybPZULAza9SDiTYHSFfSa3gzmptkacLFVwLbOkiBSLyyu99MdDeFd0yhSUD Fw3TIH+cdouokj8mV+hy/ffjMW7gpIhsSHYGfQ== List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This is a multipart message in MIME format. ------=_NextPart_000_0060_01D7A5B7.2B0253D0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Hi all, I think that total_time in pg_stat_statements is cpu time + possible waits. So, can I say that: Total_sql_time = total_time + blk_read_time + blk_write_time Documentation is not clear at all on that. Thanks in advance Michel SALAIS ------=_NextPart_000_0060_01D7A5B7.2B0253D0 Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable

Hi all,

 

I think that total_time in pg_stat_statements is cpu time + = possible waits. So, can I say that:

Total_sql_time =3D total_time + = blk_read_time + blk_write_time

 

Documentation is not clear at all = on that.

 

Thanks in advance

 

Michel = SALAIS

------=_NextPart_000_0060_01D7A5B7.2B0253D0-- From msalais@msym.fr Thu Sep 9 18:49:32 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOP7F-0002zu-6K for pgsql-performance@arkaria.postgresql.org; Thu, 09 Sep 2021 18:49:41 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mOP7D-0007Ic-Lp for pgsql-performance@arkaria.postgresql.org; Thu, 09 Sep 2021 18:49:39 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOP7D-0007FC-D2 for pgsql-performance@lists.postgresql.org; Thu, 09 Sep 2021 18:49:39 +0000 Received: from mout.kundenserver.de ([212.227.126.130]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOP7A-0004sO-Qd for pgsql-performance@postgresql.org; Thu, 09 Sep 2021 18:49:38 +0000 Received: from ANAT ([78.197.128.121]) by mrelayeu.kundenserver.de (mreue010 [212.227.15.168]) with ESMTPSA (Nemesis) id 1MuDLZ-1nERrn20Bp-00uc9Z for ; Thu, 09 Sep 2021 20:49:34 +0200 From: "Michel SALAIS" To: References: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> In-Reply-To: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> Subject: RE: sql execution time in pg_stat_statements Date: Thu, 9 Sep 2021 20:49:32 +0200 Message-ID: <006601d7a5ab$6e01c780$4a055680$@msym.fr> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_0067_01D7A5BC.318BD000" X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQJfVqXLzTD3tJt7ImS9sFGS32Fv3aqMqCKw Content-Language: fr X-Provags-ID: V03:K1:sHRf5UbPJUD57pQUHlX5Oi3N1JQgGE8etmCoJ8SW2Mbidk51e55 2zXi3LITd+bgGg+zWhLGXCRYxUekkBrsBg0Ahe5cm0LjEIoCVlbI8pTK5+CWZialJExVeFk Q/xWn/pLdjGK5zaS2S0QVKqGltptOwWrQaa1hqDS1mMfeEI7ZdzHd+g25TcPV5/wuEgjn8y 4LKAQOlOJvbc4Anavq6tA== X-Spam-Flag: NO X-UI-Out-Filterresults: notjunk:1;V03:K0:92tjx7lGCLc=:mgC2jgX9aLnMobgs0MiqMw ZcauDBcB4km3Epqc9h7/tslrf1mIuc/khV789eco8+E4UOb8Vsj/PdNb74AvF+FCsontfRC1Q A6NUvpmHieHz8SYWRTlTCMCxBdYMov70RJPF0vewhvlHWpkiFV690o0c88NxugteJpbY2EuX+ 3/yUzoFqtZNK8WcMwjx6B88ix/LM1EfDVXR815zJuQA4U9zRXa1bRLQIpuiS/5v7Jcvgjt3EN cRWNYS40iHLuXbmvb5cInMYDoIIuWNa7WM9Mf1diAg2wsJD3cJG964bXpTD0ZsQJEVrLWe8Yo bNgZ9vrTfnp18PAxWJXnFDm0MLQUorosyR3i3TG75UK5JIiwY/Cf7dCS4OFrbw6n9RsdLGUBt oAPziRFo65JW31/tlEH1bRMFAnDRdz799mmWOPPdHUtFFYFOFGwoG6bxOO4gwR4EFCg+lagqt doZOxzM2GAZfEp8Rhni9EHcQOVMnUJY6MQaot6ms9g1nc9qLkoHXHK7BkKvG6gftbrUj8lfqN p0ddHgOKQ+JYUcWuI5WCYhne5ijrtbG9/FQfqmZcxHl7cJz3SmPLynMw+0RHWYWIZZVemLSV2 l96m9eFNj1WHF+JU+RHYI14wjKSIdUipW2QJHFIaT7hZM/h8S4lp129mCsTD75ifuRMRapLpB +peJPTV7DQpBh6LQUW0aBDcaZoFl0Ur+Bl+RWrSlTkMn2KZ40F0KpuEMMpemSCXcjXlLg/kvV e6ZJARLM+9G+WXYc57Ab1u4/klqH6MO/USxOBg== List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This is a multipart message in MIME format. ------=_NextPart_000_0067_01D7A5BC.318BD000 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Just to say that for PostgreSQL 13, total_time is replaced by =93total_exec_time + total_plan_time=94 =20 Michel SALAIS De : Michel SALAIS =20 Envoy=E9 : jeudi 9 septembre 2021 20:14 =C0 : pgsql-performance@postgresql.org Objet : sql execution time in pg_stat_statements =20 Hi all, =20 I think that total_time in pg_stat_statements is cpu time + possible = waits. So, can I say that: Total_sql_time =3D total_time + blk_read_time + blk_write_time =20 Documentation is not clear at all on that. =20 Thanks in advance=20 =20 Michel SALAIS ------=_NextPart_000_0067_01D7A5BC.318BD000 Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable

Just to say that for PostgreSQL 13, = total_time is replaced by “total_exec_time + = total_plan_time”

 

Michel = SALAIS

De : Michel SALAIS <msalais@msym.fr> =
Envoy=E9 : jeudi 9 septembre 2021 = 20:14
=C0 : = pgsql-performance@postgresql.org
Objet : sql execution = time in pg_stat_statements

 

Hi = all,

 

I think that total_time in = pg_stat_statements is cpu time + possible waits. So, can I say = that:

Total_sql_time =3D total_time + blk_read_time + = blk_write_time

 

Documentation is not clear at all on = that.

 

Thanks in advance

 

Michel = SALAIS

------=_NextPart_000_0067_01D7A5BC.318BD000-- From rjuju123@gmail.com Fri Sep 10 05:18:29 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOYw3-0001ap-BI for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 05:18:47 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mOYw1-0002Up-Ll for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 05:18:45 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOYw1-0002Ug-CD for pgsql-performance@lists.postgresql.org; Fri, 10 Sep 2021 05:18:45 +0000 Received: from mail-qt1-x834.google.com ([2607:f8b0:4864:20::834]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1mOYvz-0002NM-9v for pgsql-performance@postgresql.org; Fri, 10 Sep 2021 05:18:45 +0000 Received: by mail-qt1-x834.google.com with SMTP id r21so451553qtw.11 for ; Thu, 09 Sep 2021 22:18:42 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc:content-transfer-encoding; bh=FT9XvJ8ST8xnmzHyOapGe8zP0BDIhyYxUG/hJJ2UR/c=; b=An9OW//pFWHAxvJB3OfRvEXZJBlRn+CMUN29uCGAs4jSAUcea620OuXPAvzCWRddzP 176wNJxMw/4Eb0+ZyosyrDR0v105XbXKOHHcth2TK1NrR/TtIC7QVtTyl1x+KIp13UAz NS2GiAOw1cjyAhnLQGsdGh2UrJ7/V0ynJFaDE5EBYQcxkyW3LVjh2IRF0/j6jCmqNY9y UPGWLu4b7qHXUuPyYBHlcfaH8RBRB5sOQj0OsrtH379DyDbM1wbJyWeOU0N+zHNO2YF1 OWoNzVUjIGaBfSiPg4vxD6jhxA/XrfkeIZbSk/Hba4AIkC+PucFfdEGS+75DnvTIJDN+ 6y/Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc:content-transfer-encoding; bh=FT9XvJ8ST8xnmzHyOapGe8zP0BDIhyYxUG/hJJ2UR/c=; b=5g3jaeIfdHFZlQU3Y6fYUO51gz9F7iHDcFKmDBr371xVag8/AQLOzds65FIey+nMUK /JRs46a8Mqf7GiGQWoBgIao7dzy2PzI+fBrA4ObZE+CxNCn5L0NBcRRF2sibrdsDLxPs XFPYeK5k5onDIrjUX0w0R7QCU9D4vx0EyR5UJRHn0FKs/QZWDefe6JeOYMyXk0776uJc 9qIsc9cKtofIqyishbRAk82FnMyAXo6tffBLD6tVDAby4T6HB8aYsCF7waxdXVhyH0+j 9kv2yZB+wwDlw2IxirVACaCvSOZUNxroU8kLnsDR+G+xiQTSuVQaiDwpYS3ePQCPM2RM SIGg== X-Gm-Message-State: AOAM532wZPoDW0PfgvecXNI7spH9noQV+jf8BUAdio2W/xvCI/cQDtLi 2tUqbn5B7RMPNuMAJO0C/K6WIuIn9JqzKr0Jkbfr/4FolnY= X-Google-Smtp-Source: ABdhPJzL9T5xyCSz2o5gPvkrWDT0NcoBleasnR9oyR6t0F803vFdHsN/GCKQAbAf82oYM+IYuA2NnJ5b7Hba5+JAL38= X-Received: by 2002:ac8:7051:: with SMTP id y17mr6294065qtm.117.1631251121548; Thu, 09 Sep 2021 22:18:41 -0700 (PDT) MIME-Version: 1.0 References: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> <006601d7a5ab$6e01c780$4a055680$@msym.fr> In-Reply-To: <006601d7a5ab$6e01c780$4a055680$@msym.fr> From: Julien Rouhaud Date: Fri, 10 Sep 2021 13:18:29 +0800 Message-ID: Subject: Re: sql execution time in pg_stat_statements To: Michel SALAIS Cc: postgres performance list Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk On Fri, Sep 10, 2021 at 2:49 AM Michel SALAIS wrote: > > I think that total_time in pg_stat_statements is cpu time + possible wait= s. So, can I say that: > > Total_sql_time =3D total_time + blk_read_time + blk_write_time > > Documentation is not clear at all on that. In version 12 and below, total_time is the elapsed time between the execution start and stop, so it includes all underlying events. That includes any IO activity, wait events or nested statements (if pg_stat_statemetns.track is set to all). This corresponds to the new total_exec_time field in version 13 and later. > Just to say that for PostgreSQL 13, total_time is replaced by =E2=80=9Cto= tal_exec_time + total_plan_time=E2=80=9D Indeed, as this version also tracks planning activity. From msalais@msym.fr Fri Sep 10 17:12:48 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOk5D-0004JC-Sd for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 17:12:59 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mOk5C-0002Q9-Q5 for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 17:12:58 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOk5C-0002Q1-Hk for pgsql-performance@lists.postgresql.org; Fri, 10 Sep 2021 17:12:58 +0000 Received: from mout.kundenserver.de ([217.72.192.74]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOk56-0008Me-6T for pgsql-performance@postgresql.org; Fri, 10 Sep 2021 17:12:58 +0000 Received: from ANAT ([78.197.128.121]) by mrelayeu.kundenserver.de (mreue107 [212.227.15.184]) with ESMTPSA (Nemesis) id 1M8xwu-1mKsSd1UyU-006BH9; Fri, 10 Sep 2021 19:12:49 +0200 From: "Michel SALAIS" To: "'Julien Rouhaud'" Cc: "'postgres performance list'" References: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> <006601d7a5ab$6e01c780$4a055680$@msym.fr> In-Reply-To: Subject: RE: sql execution time in pg_stat_statements Date: Fri, 10 Sep 2021 19:12:48 +0200 Message-ID: <007201d7a667$1516d860$3f448920$@msym.fr> MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQJfVqXLzTD3tJt7ImS9sFGS32Fv3QH0n7V9AjP2INCqbNeR0A== Content-Language: fr X-Provags-ID: V03:K1:WDetLe8aFJSkrCagc7Kci3OWJpYU9bfyQnUj9EMR19Wog1E23dl 25uml1poefI0bmjZwelzWwErez43K0/QDnE+h7SAhws8gNuhpJHSCYuJ3RMSnADrUjxTJ9p DB7JbZMZZdx3/HVUKAis6M2XRfebZYcgIubbKCwLdhp8OUSrgcvdA6WIbyFPEEsYdzM/TXV qvvfSus+Iifx4dPXUkZFQ== X-Spam-Flag: NO X-UI-Out-Filterresults: notjunk:1;V03:K0:As1a3OiWaso=:FUiWzkLC3HYAKcMLDdL6ti aQBShyNYo8P3T3m4DXPQtZlsHVuYxvdUf8b5hZaCsPYfe04W14qB/AOzqC7RoJ4gPE/kTItXa Qk7LFOgSPOfw4y7vB/tAixDBhClJNf5q+sS1UBUkONKOsAIg9pvG6VrudroOIDGi09yJ47UI2 I7hjZd5APgDS8+KTscQtm41qkTdbCzmRJHfodnB95gtIsMyoo+kdXkFZuiOF3EFekEXjhvL29 KbTYINDIDUsA/+9SOJcepxGQmeAfgHopm3xC2qp6ZjuOc19vPyQR+dvADupe+cId+2JNW7Rsn TFUMcg/kpBmTnCjwyCC4CVj81GKdo+Qs16g6+perTDRVBXURsTmzuFEqFXi2SdYl4w1oCJlIM 3IsUzeCpTrXsUVa/si/R8CZjS0YEXyMj80MwTW6Z0Dcw9RqQ4h9vsrskzuHdtQPexAWCL0sD8 U+hAveFQ6v48O95pvfiNTye2i4niy8+FFKkjL1VmOsWGUY5HLwf1/HMWnH2dEUa+mQfJGaS0m mcTHbj03b9cLAKWh2n32W/8G/v5ONo3oQpFIzpD5Qb8v474ByOh/3e/YWTK6GGNShrYoXwtJB tl3PyK27Ztg9/t6r2uMCgY90fjGlr8JTnqSHOMRZA6vkPPDpw6PcJTFvMvqPSUHsLit6Aab6B LRUlTnGW8+ua5iTMXgqTEGzdsk3obwEdRKHvmuxQjwxRfNBrBBIVQc87Dt6+HiRxZuDLnTq1O BUiwyjAi1SvydNPg8ZtLFpVxvEgMzzz19M+YRw== List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk -----Message d'origine----- De : Julien Rouhaud =20 Envoy=C3=A9 : vendredi 10 septembre 2021 07:18 =C3=80 : Michel SALAIS Cc : postgres performance list Objet : Re: sql execution time in pg_stat_statements On Fri, Sep 10, 2021 at 2:49 AM Michel SALAIS wrote: > > I think that total_time in pg_stat_statements is cpu time + possible = waits. So, can I say that: > > Total_sql_time =3D total_time + blk_read_time + blk_write_time > > Documentation is not clear at all on that. In version 12 and below, total_time is the elapsed time between the = execution start and stop, so it includes all underlying events. That = includes any IO activity, wait events or nested statements (if = pg_stat_statemetns.track is set to all). This corresponds to the new = total_exec_time field in version 13 and later. > Just to say that for PostgreSQL 13, total_time is replaced by = =E2=80=9Ctotal_exec_time + total_plan_time=E2=80=9D Indeed, as this version also tracks planning activity. -------------------------------------------------------------------------= ------- Hi, I thaught that total_time (total_exec_time + total_plan_time) included = I/O but when we have blk_read_time + blk_write_time equals several = times total_time it is difficult to continue to think that... So What is really total_time (total_exec_time + total_plan_time) ? From tgl@sss.pgh.pa.us Fri Sep 10 17:42:08 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOkXd-0005LL-Rl for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 17:42:21 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mOkXc-0000dh-Gv for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 17:42:20 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOkXc-0000dY-8W for pgsql-performance@lists.postgresql.org; Fri, 10 Sep 2021 17:42:20 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOkXV-0006uG-46 for pgsql-performance@postgresql.org; Fri, 10 Sep 2021 17:42:19 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 18AHg8TI4078765; Fri, 10 Sep 2021 13:42:08 -0400 From: Tom Lane To: "Michel SALAIS" cc: "'Julien Rouhaud'" , "'postgres performance list'" Subject: Re: sql execution time in pg_stat_statements In-reply-to: <007201d7a667$1516d860$3f448920$@msym.fr> References: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> <006601d7a5ab$6e01c780$4a055680$@msym.fr> <007201d7a667$1516d860$3f448920$@msym.fr> Comments: In-reply-to "Michel SALAIS" message dated "Fri, 10 Sep 2021 19:12:48 +0200" MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-ID: <4078763.1631295728.1@sss.pgh.pa.us> Content-Transfer-Encoding: quoted-printable Date: Fri, 10 Sep 2021 13:42:08 -0400 Message-ID: <4078764.1631295728@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk "Michel SALAIS" writes: > I thaught that total_time (total_exec_time + total_plan_time) included I= /O but when we have blk_read_time + blk_write_time equals several times t= otal_time it is difficult to continue to think that... That's an interesting report, but on the whole I'd be more inclined to disbelieve the I/O timings than the overall time. Can you create a reproducible test case where this happens? Also, exactly what PG version and pg_stat_statements version are you using? regards, tom lane From rjuju123@gmail.com Fri Sep 10 17:43:06 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOkYc-0005Ng-FC for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 17:43:22 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mOkYb-0005zL-Dk for pgsql-performance@arkaria.postgresql.org; Fri, 10 Sep 2021 17:43:21 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mOkYb-0005zD-5r for pgsql-performance@lists.postgresql.org; Fri, 10 Sep 2021 17:43:21 +0000 Received: from mail-qt1-x829.google.com ([2607:f8b0:4864:20::829]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1mOkYY-0006up-Ga for pgsql-performance@postgresql.org; Fri, 10 Sep 2021 17:43:19 +0000 Received: by mail-qt1-x829.google.com with SMTP id d11so2172125qtw.3 for ; Fri, 10 Sep 2021 10:43:18 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=anG9vwmwlxdIrwJbshwFWnVecRceFLTgbCBM3hF9wqA=; b=fwMZsWJjbDbG0qp4XApec2gJpBbvPQTX8O+zexvvpYaRaHjVFpg2r0q/nfe7axgkY1 LPlaPbWLyUsYibAYcs3+Qpb/DQPeUvX1IIvQFOx36AUu7vNhzkxJ+4JIwDTtojObYG89 JJ7vLIaSyEzX5/U7MUqnBroihFtRsCkT8cwUXecKt3cDs59+k/iHqsiTb4yTMM2JMSnc PMPi4mwTD+7yssl07skc42hqEn1nlrq9+nK9XxcZT+buEI6H4qhp/Yp2/46Bv8++o89e 3pKh+XWQC58QoGkcA0PqHgrBmNIUnMHjorBozoB4b42OziAcg4Zg7kfq1JgdQtfhkKsh OO2g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=anG9vwmwlxdIrwJbshwFWnVecRceFLTgbCBM3hF9wqA=; b=PJG6zS0VZJsfHjKYCv2wLsLHvZmjRkV9lIBWj524wxUrTSG37QcV44y+aw3DV9fnhH VGanvPOG2d1axoOjcSCyaDOJtPZ4jbq1+zNXyip1kHsZhsWFZuofiLcJ5HHycyOQ1t2a qawb/7b3hOjT7qd5h43sw5igLpUTuDf4GycbugCm9xpry4y7tBVovhEZXN9tUBcTAEUN Gz+F8B+yCUwU2ju1391cATReMKihfhvcFoQ9bkG/3JSMdFmH6pVCTDHShwM+ellnwdi+ c6sS8EfTovY/XhwADYShIWuk2xmCV/potQXMZsi5BvtogZtu894hnd1exhpfFtl31zlv WjZg== X-Gm-Message-State: AOAM533EFIoTIQfhN2xKXA88UipxxwVHIikjVu5XWIwA8fZlDXli9YSL EI6Bka6gFPEy9SXpZqmaRegi3h0+h3lsDvDNJ4M= X-Google-Smtp-Source: ABdhPJwnu/lwlAvskTeTxOgv3zNHwipHaZdzJSBJTBVFD3xiIN0fxl/IATJiPtnJdLLUeVPeUjPM9EAQ6b+cuIDDkPc= X-Received: by 2002:ac8:7ee9:: with SMTP id r9mr9255799qtc.85.1631295797484; Fri, 10 Sep 2021 10:43:17 -0700 (PDT) MIME-Version: 1.0 References: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> <006601d7a5ab$6e01c780$4a055680$@msym.fr> <007201d7a667$1516d860$3f448920$@msym.fr> In-Reply-To: <007201d7a667$1516d860$3f448920$@msym.fr> From: Julien Rouhaud Date: Sat, 11 Sep 2021 01:43:06 +0800 Message-ID: Subject: Re: sql execution time in pg_stat_statements To: Michel SALAIS Cc: postgres performance list Content-Type: text/plain; charset="UTF-8" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk On Sat, Sep 11, 2021 at 1:12 AM Michel SALAIS wrote: > > I thaught that total_time (total_exec_time + total_plan_time) included I/O but when we have blk_read_time + blk_write_time equals several times total_time it is difficult to continue to think that... Maybe not that difficult. If the queries use parallelism, the query total execution time may be say 1 second, but if there were X workers it could actually cumulate X+1 seconds of execution time, and therefore reach more than 1 second of cumulated read/write time. From msalais@msym.fr Sun Sep 19 15:41:48 2021 Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mRyx4-0004qK-Rf for pgsql-performance@arkaria.postgresql.org; Sun, 19 Sep 2021 15:41:58 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mRyx3-0003GJ-Pd for pgsql-performance@arkaria.postgresql.org; Sun, 19 Sep 2021 15:41:57 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mRyx3-0003GA-H1 for pgsql-performance@lists.postgresql.org; Sun, 19 Sep 2021 15:41:57 +0000 Received: from mout.kundenserver.de ([212.227.126.131]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mRywy-0006AN-0G for pgsql-performance@postgresql.org; Sun, 19 Sep 2021 15:41:57 +0000 Received: from ANAT ([78.197.128.121]) by mrelayeu.kundenserver.de (mreue012 [212.227.15.168]) with ESMTPSA (Nemesis) id 1N3Gok-1mrvqh0qXK-010I4V; Sun, 19 Sep 2021 17:41:49 +0200 From: "Michel SALAIS" To: "'Tom Lane'" Cc: "'Julien Rouhaud'" , "'postgres performance list'" References: <005f01d7a5a6$67784b50$3668e1f0$@msym.fr> <006601d7a5ab$6e01c780$4a055680$@msym.fr> <007201d7a667$1516d860$3f448920$@msym.fr> <4078764.1631295728@sss.pgh.pa.us> In-Reply-To: <4078764.1631295728@sss.pgh.pa.us> Subject: RE: sql execution time in pg_stat_statements Date: Sun, 19 Sep 2021 17:41:48 +0200 Message-ID: <000001d7ad6c$dc44d250$94ce76f0$@msym.fr> MIME-Version: 1.0 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQJfVqXLzTD3tJt7ImS9sFGS32Fv3QH0n7V9AjP2INACQvqRvgJgvkG4qlXIYTA= Content-Language: fr X-Provags-ID: V03:K1:6lWNVM7dJ4OOYEVJyjWNVVrm1tyXjUufw77HAoihKLrxadwoUyo lLO96Zmq0oJYjIj2WV5LdyMNdhhISA1o2Cevp/40c8KlG1WK8rcsQWFHI1SlR5Os9LTai3e 5FdBGCKIxPPMZnYaHC3Zk5Vhx4qTNtxjGBqzMj7WI2yPk8jmcew5kyhw/Zs4Q6NupByWQ8j imoUdqzk7uS9LciCzImhQ== X-Spam-Flag: NO X-UI-Out-Filterresults: notjunk:1;V03:K0:2UwcbQ8XGKU=:0e/IuIVYJDiwmQx9U4QXP6 j0TVJKH0FSfeozSPhHdwSF87TatjbXv0tOMw61fnEtrD79XmnXsws/hnEX4VBxs/df+4Vni2r Bk1O82kB8K1xWNZdk8SQYcvvQ2RKX6naX7zyThSZyqQfLE4k26JfhhQ6f8MkSwdwVAtP0GUmo rS7hiMvxqixxhyNr0FpKCvw+NnmaEWBOuoy0+adG/OKFtiTZIWuEFBOvpGdxlpmy6kMRKRYgD FIaIAhxTW7pGoLYWQt7GAvG0slnr2Q81aowprzw4GJMzhKhhuAc4WJGhbJI3ui2Peu3Zi8TiQ HPxpRS0KMj0yF7avkTGArFQnzDcsCPSB2axjp8+vewA0ct1I07/m49A9q6KRnKQqiThE9dVQX cVnG1umrWq6ILgFvA2mG0CrgaK/zjN3oLURDnMGiG3Sc1jOAVKaZdSvlArdAJQzHbDyvk8RIU vmsbND/L1CGwXHOmoMGCasY3P2e/ZmTK4GN7dBS0Pt19gatdAUnwI9wIXAIpVK5Z37sWodiS2 S/zBv/qumekyIYRTmy/M/bm8MHHcBJin5cAxZzz9OG7V1O7nUNqmHc/HatP6YCIoH+nCZLsUd S4U6QSmfaMX7jLRwDyM94z+84k7zHkcdr0lT90xyzRXhjvnO4hHhYHJQFKtuDDdSeUG0tVAsI uShjjOpE0jHVKybeq8CCkEQOhy+BF/jIsfBVCLVuRSu9DXrIodISvjld/2CxoMMQyMmFGg3LD pbP/LpqebfR7Zr1z2uglGHvWaxLsw+6xDHWyIQ== List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk Hi Tom, I was out of this list for a while. Unfortunately, I have now no access to the server where I have seen = this. Best regards Michel SALAIS -----Message d'origine----- De=A0: Tom Lane =20 Envoy=E9=A0: vendredi 10 septembre 2021 19:42 =C0=A0: Michel SALAIS Cc=A0: 'Julien Rouhaud' ; 'postgres performance = list' Objet=A0: Re: sql execution time in pg_stat_statements "Michel SALAIS" writes: > I thaught that total_time (total_exec_time + total_plan_time) included = I/O but when we have blk_read_time + blk_write_time equals several times total_time it is difficult to continue to think that... That's an interesting report, but on the whole I'd be more inclined to disbelieve the I/O timings than the overall time. Can you create a reproducible test case where this happens? Also, exactly what PG = version and pg_stat_statements version are you using? regards, tom lane