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 1pVlfz-0004Dx-MP for pgsql-hackers@arkaria.postgresql.org; Sat, 25 Feb 2023 03:56: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 1pVlfy-0006Ta-Bb for pgsql-hackers@arkaria.postgresql.org; Sat, 25 Feb 2023 03:56:46 +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 1pVlfx-0006TR-SE for pgsql-hackers@lists.postgresql.org; Sat, 25 Feb 2023 03:56:46 +0000 Received: from mail-oi1-x232.google.com ([2607:f8b0:4864:20::232]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1pVlfv-0001KW-5j for pgsql-hackers@lists.postgresql.org; Sat, 25 Feb 2023 03:56:44 +0000 Received: by mail-oi1-x232.google.com with SMTP id o12so1008872oik.6 for ; Fri, 24 Feb 2023 19:56:43 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; t=1677297402; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=cwGTv2g3XohoMOuLeNgl1vrMK3rdg7Q+9bQcx6CBVnc=; b=kCYZAZpoiXnuaHq7It0RLnDUNrY8M6sZhbyh/DIoLZLvMxdLF0MUn2vQL2IYtn1tIZ S+N7riUqR/bq8O0VygvtTw7g/kdq351fbWc9062SQrU237+NQ8gbdj2am/jAYTH3WdfM xxBtGoUBCJ8RkCkTsujqEIq0HkIWc7H1oNKDeD4Nentt9gV9BeilK62FOhN1R4bDvJd4 9eL4jfEHiZEGQ/RmcXJARyRLJpWKM7cpc6AMkQc5DZ7ilR/I6q5BJLFgVp7pCwsHPTIU 7uXQAtQSpa0MjnXGxWHD/a6rDusbQqwQy4EGrLBbIznuQT6+FJkSd3nUGG4l6+QRnCwq Jnww== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; t=1677297402; 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=cwGTv2g3XohoMOuLeNgl1vrMK3rdg7Q+9bQcx6CBVnc=; b=374b1EPX4jHMuQBaFe6qdTYOtDNiSDHwr/CXqkXf8BBsmzn2M421KYWHive4nxphsT i8XKAOjO4cgukPj36qFNyWbhW+h+exx/WY08QaWv1EFyxm/SCo3ggwkA+FFBdm5yZfTn WocXsK5CG8F6o0amto3JthdXtbCt8YJFYGaYUFmle2BtytOfa2EgEWe6O4cdm7DHKYD8 vM+muWdmAXYUcRuz5/QRjFfo+B6LNm7ea3/qm3P6bLsNNvKICqGw7J6lSElonITLJ/bI mGcxvZ3Xt3U9PZwS2dtqtgGQY5DO1R63wbNpCqyQMtKozxb39p/Yq0TzmHa5aq5z5kX/ Z9vQ== X-Gm-Message-State: AO0yUKVj6scBYilb1AeF20tdNk9+gOFqSMuTTp4a16AUp4Rpxg+AvEbx mRxGVq38aPgWp9qxqKUA63Of2bCkQk97VS9hJ2w= X-Google-Smtp-Source: AK7set/qDm0IY5FaNyYxezVUvfKBXecw+M7qfporV0uvRDi2OA4BysZ6YHaRgHXG1eXTWnJRkIsK7o71vYGAKVIGU6s= X-Received: by 2002:a05:6808:659:b0:37a:ca40:c1fc with SMTP id z25-20020a056808065900b0037aca40c1fcmr1611999oih.6.1677297402091; Fri, 24 Feb 2023 19:56:42 -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: Fri, 24 Feb 2023 22:56:16 -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="000000000000d59e5005f57e3bf9" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --000000000000d59e5005f57e3bf9 Content-Type: text/plain; charset="UTF-8" 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 love that my proposal for %T in the prompt, triggered some great > conversations. > > > > This is not instead of that. That lets me run a query and come back > HOURS later, and know it finished before 7PM like it was supposed to! > > Neat! I have this info embedded in my Bash prompt [1], but many a > times this is not sufficient to reconstruct the time it took to run > the shell command. > ... > > I think like ROW_COUNT, it should not change because of internal > commands. > > +1 > > > So, you guys +1 this thing, give additional comments. When the feedback > settles, I commit to making it happen. > > This is definitely a useful feature. I agree with everything in the > proposed UI (reporting in milliseconds, don't track internal commands' > timing). > > I think 'duration' or 'elapsed' would be a better words in this > context. So perhaps the name could be one of :sql_exec_duration (sql > prefix feels superfluous), :exec_duration, :command_duration, or > :elapsed_time. > I chose that prefix because it sorts near ROW_COUNT (LOL) when you do \SET I agree that the name wasn't perfect... I like SQL_EXEC_ELAPSED keeping the result closer to ROW_COUNT, and it literally ONLY applies to SQL > 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. Thanks! > > [1]: > https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L278 > [2]: > https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L262 > > Best regards, > Gurjeet > http://Gurje.et > --000000000000d59e5005f57e3bf9 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
On Fri, Feb 24, 2023 at 2:11 AM Gurjeet S= ingh <gurjeet@singh.im> wrote= :
On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk@gmail.com> wrote:
>=C2=A0 =C2=A0I love that my proposal for %T in the prompt, triggered so= me great conversations.
>
>=C2=A0 =C2=A0This is not instead of that.=C2=A0 That lets me run a quer= y and come back HOURS later, and know it finished before 7PM like it was su= pposed to!

Neat! I have this info embedded in my Bash prompt [1], but many a
times this is not sufficient to reconstruct the time it took to run
the shell command.
...
>=C2=A0 =C2=A0I think like ROW_COUNT, it should not change becaus= e of internal commands.

+1

> So, you guys +1 this thing, give additional comments.=C2=A0 When the f= eedback settles, I commit to making it happen.

This is definitely a useful feature. I agree with everything in the
proposed UI (reporting in milliseconds, don't track internal commands&#= 39;
timing).

I think 'duration' or 'elapsed' would be a better words in = this
context. So perhaps the name could be one of :sql_exec_duration (sql
prefix feels superfluous), :exec_duration, :command_duration, or
:elapsed_time.

I chose that prefix beca= use it sorts near ROW_COUNT (LOL) when you do \SET

I agree that the name wasn't perfect...
I like SQL_EXEC_ELAP= SED
keeping the result closer to ROW_COUNT, and it literally ONLY= applies to SQL


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.

Thanks!

[1]: https= ://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.b= ashrc#L278
[2]: https= ://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.b= ashrc#L262

Best regards,
Gurjeet
http://Gur= je.et
--000000000000d59e5005f57e3bf9--