PATCH: pgbench - break out timing data for initialization phases

Hello Doug,

With patch and ‘-I dtgvpf’ options:
pgrun pgbench -i -s 2000 -F 90 -q -I dtgvpf
dropping old tables...
creating tables...
generating data...
…
200000000 of 200000000 tuples (100%) done (elapsed 168.76 s, remaining 0.00 s)
vacuuming...
creating primary keys...
creating foreign keys...
total time: 353.52 s (drop 1.67 s, tables 0.11 s, insert 168.82 s, commit 0.46 s, primary 92.32 s, foreign 40.11 s, vacuum 50.03 s)
done.

I'm in favor of such a feature.

However, I think that the durations should be shown in the order in which
the initialization is performed.

I would suggest to:

- move the time measure in the initialization loop, instead of doing it
in each function, so that it is done just in one place.

- maybe store the actions in some array/list data structure, eg:
"{ char * phase; double duration; }", so that they can be kept
in order and eventually repeated.

In order to extract the commit time, I'd say that explicit begin and
commit should be separate instructions triggerred by '(' and ')'.

Also, I'm not sure of the one line display, maybe it could be done while
it is in progress, i.e. something like:
dropping table...
table drop: 1.67 s
creating table...
table creation: 0.11 s
...
In which case there is no need for storing the actions and their
durations, only the running total is needed.

--
Fabien.

On 1/29/18, 23:52, "Fabien COELHO" <coelho@cri.ensmp.fr> wrote:

Hello Doug,
Hi Fabien,

With patch and ‘-I dtgvpf’ options:
pgrun pgbench -i -s 2000 -F 90 -q -I dtgvpf
dropping old tables...
creating tables...
generating data...
…
200000000 of 200000000 tuples (100%) done (elapsed 168.76 s, remaining 0.00 s)
vacuuming...
creating primary keys...
creating foreign keys...
total time: 353.52 s (drop 1.67 s, tables 0.11 s, insert 168.82 s, commit 0.46 s, primary 92.32 s, foreign 40.11 s, vacuum 50.03 s)
done.

I'm in favor of such a feature.

However, I think that the durations should be shown in the order in which
the initialization is performed.

Agreed.

I would suggest to:

- move the time measure in the initialization loop, instead of doing it
in each function, so that it is done just in one place.

I will do this.

- maybe store the actions in some array/list data structure, eg:
"{ char * phase; double duration; }", so that they can be kept
in order and eventually repeated.

In order to extract the commit time, I'd say that explicit begin and
commit should be separate instructions triggerred by '(' and ')'.

Also, I'm not sure of the one line display, maybe it could be done while

The one line display was for ease of parsing it from the output flow.

it is in progress, i.e. something like:
dropping table...
table drop: 1.67 s
creating table...
table creation: 0.11 s
...
In which case there is no need for storing the actions and their
durations, only the running total is needed.

Doing the "in progress" way suffers from everything before 'generating data' possibly scrolling off the screen/window.
For me, it is much handier to look at one set of duration times all reported together after all of the initialize phases are done.

--
Fabien.

Thanks!
doug

Hello Doug,

Doing the "in progress" way suffers from everything before 'generating
data' possibly scrolling off the screen/window.

Yeah, that is a point.

I tend to "| less" when I want to see a long output in details, so it is
not an issue for me.

Also, I like to have an information when it is available, and not have to
wait
for the end.

Finally, note that pre data loading operations are expected to be quite
fast, thus not that significant (create table, ...). Longer operations
would occur after a large data set is loaded, thus after the large loading
progress output which scrolls the screen.

For me, it is much handier to look at one set of duration times all
reported together after all of the initialize phases are done.

Then for this apporach the duration data must be stored and then printed
in the end.

--
Fabien.

Hi,

On 2018-02-21 17:58:49 +0000, Rady, Doug wrote:

- move the time measure in the initialization loop, instead of doing it
in each function, so that it is done just in one place.

I will do this.

Given the last v11 CF is just about to start, there's no new version
yet, the patch is late in the cycle, I think we should / need to boot
this to the next CF.

Greetings,

Andres Freund

Hi Doug,

On 3/1/18 3:57 AM, Andres Freund wrote:

Hi,

On 2018-02-21 17:58:49 +0000, Rady, Doug wrote:

- move the time measure in the initialization loop, instead of doing it
in each function, so that it is done just in one place.

I will do this.

Given the last v11 CF is just about to start, there's no new version
yet, the patch is late in the cycle, I think we should / need to boot
this to the next CF.

Since this submission is in Waiting on Author state I have marked it
Returned with Feedback. Please move this entry to the next CF when you
have an updated patch.

Regards,
--
-David
david@pgmasters.net