Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dqJ2s-0004a8-3q for pgsql-performance@arkaria.postgresql.org; Fri, 08 Sep 2017 13:10:06 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1dqJ2q-0004bG-Ln for pgsql-performance@arkaria.postgresql.org; Fri, 08 Sep 2017 13:10:04 +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_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1dqJ14-0001TI-G5 for pgsql-performance@postgresql.org; Fri, 08 Sep 2017 13:08:14 +0000 Received: from mail-yw0-x22c.google.com ([2607:f8b0:4002:c05::22c]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1dqJ10-000719-Rl for pgsql-performance@postgresql.org; Fri, 08 Sep 2017 13:08:13 +0000 Received: by mail-yw0-x22c.google.com with SMTP id v72so5107719ywa.3 for ; Fri, 08 Sep 2017 06:08:10 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=1yhU5i3RgoLEH75wJEJRHQIv1tv3C4T6t0Tyxut3Q1k=; b=tHlclAdRlKjEwPEhu3EmYePDDvMrzPuZd4CmixR4j/NR27+4N6svMp6XwBDXnkbcGT dSoMw85tthAewWIq2eItWwJxrto4K6NzYkwgwS52ZiIRuvTNC9b4al3uKpPDLMqACnJf DyFmhCe8jOKTiqqAiKGFModp91Ziqo11B6WxDTPeAtzaiiww0z4yyKhXcyweraurKzEx KF89tfW7+1RtpxxzUFZMdSC33nABXKwp+3yYaCaUuRxc0OX+29k4wP7lQgskSubNDyIp ETnyU6AtObfVTaHUGcS9zl/5g0MXPuCqHnXr9jnFGLM5Jus1vrkxgYJNGJR5axW/8h3B eIww== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=1yhU5i3RgoLEH75wJEJRHQIv1tv3C4T6t0Tyxut3Q1k=; b=Ai/OGGXof8ogZTLeUihm6K6LIsm3uA1SoPH6ntXLDekJmllBuHdN68A7JJ8OUvz7Yl rcSb26SoJ8H7l5ui75NVPROdLWeF92WUiNm3nYTo4D/DcWalqxdm57HiHffPQNGPowSg acqb3tahnlRhZgVEP2VgaNv7NYTpI84NF6aKI1/aUprUGsQLWhuJF11wRyNMIsWAZFG6 eyZYZP6HOPW/X4Oxvs8OT6dAj6N73g3W5CPs/pKFmMZ9NpDzJwiGB0QFvsfKpLTbHfbI HlbL7+UScyjmUsa4KoviwehJt+QwmRkCpgXGzV/waW2kb+b56vBujwrcAZM5oXrdavH0 eBWA== X-Gm-Message-State: AHPjjUhau8EEx+dSouO3daWcq9SuhWvy5Yln1laOkDAmBc7x6OpPI+R+ /hfN4ar09dw0aY4I+naZgZH7BRb1acrz X-Google-Smtp-Source: AOwi7QB/8WAKfn2jQhGg4hzwQG3Edb2du6/b2yCm0U31oc7DGTOfoELHk2atB5//wJn+yUczfxn4UQ/E4uou6M5hOww= X-Received: by 10.37.188.129 with SMTP id e1mr2399071ybk.139.1504876088661; Fri, 08 Sep 2017 06:08:08 -0700 (PDT) MIME-Version: 1.0 Received: by 10.37.73.199 with HTTP; Fri, 8 Sep 2017 06:08:08 -0700 (PDT) In-Reply-To: References: From: Neto pr Date: Fri, 8 Sep 2017 06:08:08 -0700 Message-ID: Subject: Re: Explain Analyze - actual time in loops To: Igor Neyman Cc: "pgsql-performance@postgresql.org" Content-Type: multipart/alternative; boundary="089e08267de8b21c820558ad44ee" List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --089e08267de8b21c820558ad44ee Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Igor, You're right, I confused the radix character. But even so the result is approximate to the previous message, 182 minutes,= see below: 419.113 / 1000 =3D 0.41 seconds * 26469 (loops) =3D 11093.50 seconds or 184 minutes After analyzing, I saw that in some places of the plan, it is being used Parallelism. Does this explain why the final value spent (in minutes) to go through the index (184 minutes) is greater than the total query time (66 minutes)? Regards Neto 2017-09-08 5:46 GMT-07:00 Igor Neyman : > *From:* pgsql-performance-owner@postgresql.org [mailto:pgsql-performance- > owner@postgresql.org] *On Behalf Of *Neto pr > *Sent:* Thursday, September 07, 2017 11:17 PM > *To:* pgsql-performance@postgresql.org > *Subject:* [PERFORM] Explain Analyze - actual time in loops > > > > =E2=80=A6 > > ################################ ################################### > -> Index Scan using idx_l_partkeylineitem000x on lineitem (cost =3D > 0.57..97.65 rows =3D 26 width =3D 36) > (current time =3D 23.615..419.113 rows =3D 30 loops =3D= 26469) > Index Cond: (l_partkey =3D part.p_partkey) > ################################################## ################# > According to the documentation, one should multiply the Actual Time by th= e > number of Loops. > That is: 419113 ms -> 419113/1000/60 =3D 6.9 minutes * 26469 (loops) =3D = 182.6 > minutes. > > But how does this stretch take 182.6 minutes, if the entire query ran in > 66 minutes? > > =E2=80=A6=E2=80=A6=E2=80=A6=E2=80=A6=E2=80=A6=E2=80=A6. > thank you and best regards > [] 's Neto > > Neto, > > The time you see there is in ms, so the point (=E2=80=98.=E2=80=99) you s= ee is the digital > point. > > So, it is 419.113ms or a little less than half a second (0.419sec). > > Igor Neyman > --089e08267de8b21c820558ad44ee Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Igor,

You're right, I confused the= radix character.

But even so the result is approximate to the previous = message, 182 minutes, see below:

419.113 / 1000 =3D 0.41 seconds * 26469 (loops) =3D 11093.50 second= s or 184 minutes

= After analyzing, I saw that in some places of the plan, it is being used = Parallelism. Does this explain why the final value spent (in minutes) to go through the=20 index (184 minutes) is greater than the total query time (66 minutes)?

Regards
Neto=

2017= -09-08 5:46 GMT-07:00 Igor Neyman <ineyman@perceptron.com>:

From: pgsql-performance-owner@= postgresql.org [mailto:pgsql-performance-owner@postgresql.org= ] On Behalf Of Neto pr
Sent: Thursday, September 07, 2017 11:17 PM
To: pgsql-performance@postgresql.org
Subject: [PERFORM] Explain Analyze - actual time in loops<= /u>

=C2=A0

=E2=80=A6

################################ #################= ##################
=C2=A0=C2=A0 -> Index Scan using idx_l_partkeylineitem000x on lineitem (= cost =3D 0.57..97.65 rows =3D 26 width =3D 36)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0 (current time =3D 23.615..419.113 rows =3D 30 l= oops =3D 26469)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: (l_partkey =3D part.p_partkey)
################################################## ################# According to the documentation, one should multiply the Actual Time by the = number of Loops.
That is: 419113 ms -> 419113/1000/60 =3D 6.9 minutes * 26469 (loops) =3D= 182.6 minutes.

But how does this stretch take 182.6 minutes, if the entire query ran in 66= minutes?

=E2=80=A6=E2=80=A6=E2=80=A6=E2=80=A6= =E2=80=A6=E2=80=A6.
thank you and best regards
[] 's Neto

Neto,<= u>

The ti= me you see there is in ms, so the point (=E2=80=98.=E2=80=99) you see is th= e digital point.

So, it= is 419.113ms or a little less than half a second (0.419sec).

Igor N= eyman


--089e08267de8b21c820558ad44ee--