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 1pWUoH-000580-Rx for pgsql-hackers@arkaria.postgresql.org; Mon, 27 Feb 2023 04:08: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 1pWUoF-000153-Sj for pgsql-hackers@arkaria.postgresql.org; Mon, 27 Feb 2023 04:08:19 +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 1pWUoF-00014f-D7 for pgsql-hackers@lists.postgresql.org; Mon, 27 Feb 2023 04:08:19 +0000 Received: from mail-oi1-x22a.google.com ([2607:f8b0:4864:20::22a]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1pWUo8-0008LU-BQ for pgsql-hackers@lists.postgresql.org; Mon, 27 Feb 2023 04:08:18 +0000 Received: by mail-oi1-x22a.google.com with SMTP id t22so4205100oiw.12 for ; Sun, 26 Feb 2023 20:08:12 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; t=1677470891; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=RvvpzEmglPWu/7EExWE5dD1La9Cm/hZlQ9H6I4r2xos=; b=VDYlcxlvdlwhE4ZkMcMYmghrO1lmmMC03ZNzBoWY7lPoAMJ0oAt4nGsz8DrUQ3yZSf IVQRCWUW1TGfgydjM8diAUnsp9Heho402ZmPF5f7a/l3upEk0PbLyZq9rpLkMteUF6D8 27TIkc/8OeNxCpZVJts+sCvONW/8r/3iGdmSiNYFVsc6dcbfp9nFhzv/QWZgOUVr+XxH 5vL3wcqCy9nGt+jjyixafj/LyAlHcu+OYGMOPWeXGdacJXgql0QLAUf0TXH2ccdRa+cK jZImE0QqR6jV5LhTxbhA1OvyFqoL1FCYwqF+/J7BSaiOMtKn16diipinHwpbw4BdjTpx pHFg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; t=1677470891; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=RvvpzEmglPWu/7EExWE5dD1La9Cm/hZlQ9H6I4r2xos=; b=zLJpFFzJsU15M5EXUwzcf+Kfm4XSGFuBMMz7Xtk1/Mhjtt/x5lYUbGMU1Wx7XsFsvK 8OufBAirspxL00d5MEQVHQyQW55XK6Txhqy3oCEPCV9LkFfcwzHmwTOItpQcVmhC5SCm EqIWrFSS+RPjGvnhqseSPvJqwkJ2yBiR5fC+KgIUTJmBKDkhgb4IcsUY0/RSNFlZUPo3 +Vn9Z4wOmHmjlhJbiby7VVvmc6MPHILIUBme7+JeMVr8gyM8daX7oQCocNN9WozNPGX3 mk14q7DOCE3gfpwW0Z/Pv27ggbprh13dHa3MshMDOxsH8hVPx2dNYiOztqgQVPE7yARU mvJA== X-Gm-Message-State: AO0yUKUJaGPmVjbO61kXe7t4ti/HXW8HNSKWK4G1JDdxlD3zfyGf5zln SlQTRQ0p0mHDOkKn9/8fWmB7txQedGAxCBy6XKI= X-Google-Smtp-Source: AK7set+CP/GgiGy93qxqfUivZIHDpE3VaU4+peXNoQUVCDBtSaFfA7yNopZO+CoO+psqFwk+9Rsn5RXy7FfWjK1Wyik= X-Received: by 2002:a54:4781:0:b0:378:573b:ca8d with SMTP id o1-20020a544781000000b00378573bca8dmr3676334oic.6.1677470891555; Sun, 26 Feb 2023 20:08:11 -0800 (PST) MIME-Version: 1.0 References: <157609.1677088525@sss.pgh.pa.us> <2f1c8cb9-6f4d-2a03-d069-c4f9c2b574ab@enterprisedb.com> <414445.1677163935@sss.pgh.pa.us> In-Reply-To: From: Kirk Wolak Date: Sun, 26 Feb 2023 23:07:45 -0500 Message-ID: Subject: Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql) To: Gurjeet Singh Cc: Maciek Sakrejda , Nikolay Samokhvalov , Tom Lane , Heikki Linnakangas , Peter Eisentraut , PostgreSQL Hackers , Pavel Stehule , Andrey Borodin , Laurenz Albe Content-Type: multipart/alternative; boundary="0000000000009cc0cd05f5a6a01e" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --0000000000009cc0cd05f5a6a01e Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Fri, Feb 24, 2023 at 10:56=E2=80=AFPM Kirk Wolak wrot= e: > On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh wrote: > >> On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak wrote: >> > ... > > I think like ROW_COUNT, it should not change because of internal >> commands. >> ... > > By using \timing, the user is explicitly opting into any overhead >> caused by time-keeping. With this feature, the timing info will be >> collected all the time. So do consider evaluating the performance >> impact this can cause on people's workloads. They may not care for the >> impact in interactive mode, but in automated scripts, even a moderate >> performance overhead would be a deal-breaker. >> > Excellent point. I run lots of long scripts, but I usually set \timing > on, just because I turn off everything else. > I tested 2,000+ lines of select 1; (Fast sql shouldn't matter, it's the > most impacted) > Honestly, it was imperceptible, Maybe approximating 0.01 seconds > With timing on: ~ seconds 0.28 > With timing of: ~ seconds 0.27 > > The \timing incurs no realistic penalty at this point. The ONLY penalty > we could face is the time to > write it to the variable, and that cannot be tested until implemented. > But I will do that. And I will > report the results of the impact. But I do not expect a big impact. We > update SQL_COUNT without an issue. > And that might be much more expensive to get. > Okay, I've written and tested this using SQL_EXEC_ELAPSED (suggested name improvement). First, the instant you have ANY output, it swamps the impact. (I settled on: SELECT 1 as v \gset xxx) for no output Second, the variability of running even a constant script is mind-blowing. Third, I've limited the output... I built this in layers (init.sql initializes the psql variables I use), run_100.sql runs another file (\i tst_2000.sql) 100 times. Resulting in 200k selects. Executive Summary: 1,000,000 statements executed, consumes ~2 - 2.5 seconds of extra time (Total) So, the per statement cost is: 2.5s / 1,000,000 =3D 0.000,0025 s per statem= ent Roughly: 2.5us Unfortunately, my test lines look like this: Without Timing done 0.198215 (500) *total *98.862548 *min* 0.167614 *avg* 0.19772509600000000000 *max *0.290659 With Timing done 0.191583 (500) *total* 100.729868 *min *0.163280 *avg *0.20145973600000000000 *max *0.275787 Notice that the With Timing had a lower min, and a lower max. But a higher average. The distance between min - avg AND min - max, is big (those are for 1,000 selects each) Are these numbers at the "So What" Level? While testing, I got the distinct impression that I am measuring something that changes, or that the variance in the system itself really swamps this on a per statement basis. It's only impact is felt on millions of PSQL queries, and that's a couple of seconds... Curious what others think before I take this any further. regards, Kirk > > Thanks! > >> >> [1]: >> https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507= a55ce/.bashrc#L278 >> [2]: >> https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507= a55ce/.bashrc#L262 >> >> Best regards, >> Gurjeet >> http://Gurje.et >> > --0000000000009cc0cd05f5a6a01e Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
On Fri, Feb 24, 2023 at 10:56=E2=80=AFPM = Kirk Wolak <wolakk@gmail.com>= wrote:
On Fri, Feb 24, 2023 a= t 2:11 AM Gurjeet Singh <gurjeet@singh.im> wrote:
=
On Thu, Feb 23, 2023 at 8= :42 PM Kirk Wolak <wolakk@gmail.com> wrote:
<= div>...=C2=A0
>=C2=A0 =C2=A0I think like ROW_COUNT, it should not change = because of internal commands.
...
By using \timing, the user is explicitly opting into any overhead
caused by time-keeping. With this feature, the timing info will be
collected all the time. So do consider evaluating the performance
impact this can cause on people's workloads. They may not care for the<= br> impact in interactive mode, but in automated scripts, even a moderate
performance overhead would be a deal-breaker.
Excellen= t point.=C2=A0 I run lots of long scripts, but I usually set \timing on, ju= st because I turn off everything else.
I tested 2,000+ lines of s= elect 1; (Fast sql shouldn't matter, it's the most impacted)
<= div>Honestly, it was imperceptible,=C2=A0 Maybe approximating 0.01 seconds<= /div>
With timing on:=C2=A0 ~ seconds 0.28
With timing of:=C2= =A0 =C2=A0~ seconds 0.27

The \timing incurs no= realistic penalty at this point.=C2=A0 The ONLY penalty we could face is t= he time to
write it to the variable, and that cannot be tested un= til implemented.=C2=A0 But I will do that.=C2=A0 And I will
repor= t the results of the impact.=C2=A0 But I do not expect a big impact.=C2=A0 = We update SQL_COUNT without an issue.
And that might be much more= expensive to get.

Okay, = I've written and tested this using SQL_EXEC_ELAPSED (suggested name imp= rovement).
First, the instant you have ANY output, it swamps the = impact. (I settled on: SELECT 1 as v \gset xxx) for no output
Sec= ond, the variability of running even a constant script is mind-blowing.
Third, I've limited the output...=C2=A0 I built this in layers (= init.sql initializes the psql variables I use), run_100.sql runs
= another file (\i tst_2000.sql) 100 times.=C2=A0 Resulting in 200k selects.<= /div>

Executive Summary:=C2=A0 1,000,000 statements exec= uted, consumes ~2 - 2.5 seconds of extra time (Total)

<= div>So, the per statement cost is: 2.5s / 1,000,000 =3D 0.000,0025 s per st= atement
Roughly: 2.5us

Unfortunately, my= test lines look like this:
Without Timing
done 0.19821= 5 (500) total 98.862548 min 0.167614 avg 0.19772509600= 000000000 max 0.290659

With Timing
done 0.191583 (500) total 100.729868 min 0.163280 av= g 0.20145973600000000000 max 0.275787

Notice that the With Timing had a lower min, and a lower max.=C2=A0 But = a higher average.
The distance between min - avg=C2=A0 AND min - = max, is big (those are for 1,000 selects each)

Are= these numbers at the "So What" Level?=C2=A0

=
While testing, I got the distinct impression that I am measuring somet= hing that changes, or that the
variance in the system itself real= ly swamps this on a per statement basis.=C2=A0 It's only impact is felt=
on millions of PSQL queries, and that's a couple of seconds.= ..

Curious what others think before I take this an= y further.

regards, Kirk=C2=A0
--0000000000009cc0cd05f5a6a01e--