Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)

On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak <wolakk(at)gmail(dot)com> wrote:

> On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh <gurjeet(at)singh(dot)im> wrote:
>
>> On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk(at)gmail(dot)com> 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 = 0.000,0025 s per statement
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/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L278
>> [2]:
>> https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L262
>>
>> Best regards,
>> Gurjeet
>> http://Gurje.et
>>
>