Thread: 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,
vacuum50.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
phasesare 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