Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
| От | Kirk Wolak |
|---|---|
| Тема | Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql) |
| Дата | |
| Msg-id | CACLU5mTcieW9O3qAoPFW+bXzA6Mo+8LS05PbycKkMVRUP99DEA@mail.gmail.com обсуждение исходный текст |
| Ответ на | Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql) (Pavel Stehule <pavel.stehule@gmail.com>) |
| Список | pgsql-hackers |
On Sun, Feb 26, 2023 at 11:45 PM Pavel Stehule <pavel.stehule@gmail.com> wrote:
po 27. 2. 2023 v 5:08 odesílatel Kirk Wolak <wolakk@gmail.com> napsal:On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak <wolakk@gmail.com> wrote:On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh <gurjeet@singh.im> wrote:On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk@gmail.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 outputSecond, 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 runsanother 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);begininsert 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)
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)
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)
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?
RegardsPavelExecutive 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 statementRoughly: 2.5usUnfortunately, my test lines look like this:Without Timingdone 0.198215 (500) total 98.862548 min 0.167614 avg 0.19772509600000000000 max 0.290659With Timingdone 0.191583 (500) total 100.729868 min 0.163280 avg 0.20145973600000000000 max 0.275787Notice 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 thevariance in the system itself really swamps this on a per statement basis. It's only impact is felton millions of PSQL queries, and that's a couple of seconds...Curious what others think before I take this any further.regards, Kirk
В списке pgsql-hackers по дате отправления:
Следующее
От: "Imseih (AWS), Sami"Дата:
Сообщение: Re: Doc update for pg_stat_statements normalization