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

On Sun, Feb 26, 2023 at 11:45 PM Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
wrote:

> po 27. 2. 2023 v 5:08 odesílatel Kirk Wolak <wolakk(at)gmail(dot)com> napsal:
>
>> 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:
>>>>
>>> ...
>>
>>> ...
>>>
>>> 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.
>>
>
> This is the very worst case.
>
> But nobody will run from psql 200K selects - can you try little bit more
> real but still synthetic test case?
>
> create table foo(a int);
> begin
> insert into foo values(1);
> ...
> insert into foo values(200000);
> commit;
>

*Without timing:*
postgres=# \i ins.sql
Elapsed Time: 29.518647 (seconds)
postgres=# \i ins.sql
Elapsed Time: 24.973943 (seconds)
postgres=# \i ins.sql
Elapsed Time: 21.916432 (seconds)
postgres=# \i ins.sql
Elapsed Time: 25.440978 (seconds)
postgres=# \i ins.sql
Elapsed Time: 24.848986 (seconds)

-- Because that was slower than expected, I exited, and tried again...
Getting really different results
postgres=# \i ins.sql
Elapsed Time: 17.763167 (seconds)
postgres=# \i ins.sql
Elapsed Time: 19.210436 (seconds)
postgres=# \i ins.sql
Elapsed Time: 19.903553 (seconds)
postgres=# \i ins.sql
Elapsed Time: 21.687750 (seconds)
postgres=# \i ins.sql
Elapsed Time: 19.046642 (seconds)

*With timing:*
\i ins.sql
Elapsed Time: 20.479442 (seconds)
postgres=# \i ins.sql
Elapsed Time: 21.493303 (seconds)
postgres=# \i ins.sql
Elapsed Time: 22.732409 (seconds)
postgres=# \i ins.sql
Elapsed Time: 20.246637 (seconds)
postgres=# \i ins.sql
Elapsed Time: 20.493607 (seconds)

Again, it's really hard to measure the difference as the impact, again, is
a bit below the variance.
In this case, I could see about a 1s - 2s (max) difference in total time.
for 200k statements.
Run 5 times (for 1 million).

It's a little worse than noise. But if I used the first run, the timing
version would have seemed faster.

I think this is sufficiently fast, and the patch simplifies the code. We
end up only checking "if (timing)"
in the few places that we print the timing...

Anything else to provide?

>
> Regards
>
> Pavel
>
>
>>
>> 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
>>>>
>>>