PATCH: pgbench - break out timing data for initialization phases
This patch breaks out the timing info for the individual initialization phases.
Today without the patch:
pgrun pgbench -i -s 2000 -F 90 -q
dropping old tables...
creating tables...
generating data...
…
200000000 of 200000000 tuples (100%) done (elapsed 171.39 s, remaining 0.00 s)
vacuuming...
creating primary keys...
done.
With patch & default init options:
pgrun pgbench -i -s 2000 -F 90 -q
dropping old tables...
creating tables...
generating data...
…
200000000 of 200000000 tuples (100%) done (elapsed 166.53 s, remaining 0.00 s)
vacuuming...
creating primary keys...
total time: 312.94 s (drop 0.00 s, tables 0.03 s, insert 166.58 s, commit 0.51 s, primary 92.59 s, foreign 0.00 s, vacuum 53.23 s)
done.
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.
pgbench -i -s 2000 -F 90 -q -I d
dropping old tables...
total time: 1.96 s (drop 1.96 s, tables 0.00 s, insert 0.00 s, commit 0.00 s, primary 0.00 s, foreign 0.00 s, vacuum 0.00 s)
done.
pgrun pgbench -i -s 2000 -F 90 -q -I t
creating tables...
total time: 0.08 s (drop 0.00 s, tables 0.08 s, insert 0.00 s, commit 0.00 s, primary 0.00 s, foreign 0.00 s, vacuum 0.00 s)
done.
pgrun pgbench -i -s 2000 -F 90 -q -I g
creating tables...
…
200000000 of 200000000 tuples (100%) done (elapsed 165.62 s, remaining 0.00 s)
total time: 166.33 s (drop 0.00 s, tables 0.00 s, insert 165.68 s, commit 0.66 s, primary 0.00 s, foreign 0.00 s, vacuum 0.00 s)
done.
pgrun pgbench -i -s 2000 -F 90 -q -I p
creating primary keys...
total time: 100.93 s (drop 0.00 s, tables 0.00 s, insert 0.00 s, commit 0.00 s, primary 100.93 s, foreign 0.00 s, vacuum 0.00 s)
done.
doug
Attachments:
pgbench11-init-timing-v2.patchapplication/octet-stream; name=pgbench11-init-timing-v2.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 31ea6ca06e..ff8abc5fcf 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3184,9 +3184,12 @@ disconnect_all(CState *state, int length)
* Remove old pgbench tables, if any exist
*/
static void
-initDropTables(PGconn *con)
+initDropTables(PGconn *con, double *drop_sec)
{
+ instr_time start,
+ diff;
fprintf(stderr, "dropping old tables...\n");
+ INSTR_TIME_SET_CURRENT(start);
/*
* We drop all the tables in one command, so that whether there are
@@ -3197,13 +3200,16 @@ initDropTables(PGconn *con)
"pgbench_branches, "
"pgbench_history, "
"pgbench_tellers");
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *drop_sec = INSTR_TIME_GET_DOUBLE(diff);
}
/*
* Create pgbench's standard tables
*/
static void
-initCreateTables(PGconn *con)
+initCreateTables(PGconn *con, double *table_sec)
{
/*
* The scale factor at/beyond which 32-bit integers are insufficient for
@@ -3260,8 +3266,11 @@ initCreateTables(PGconn *con)
}
};
int i;
+ instr_time start,
+ diff;
fprintf(stderr, "creating tables...\n");
+ INSTR_TIME_SET_CURRENT(start);
for (i = 0; i < lengthof(DDLs); i++)
{
@@ -3294,13 +3303,16 @@ initCreateTables(PGconn *con)
executeStatement(con, buffer);
}
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *table_sec = INSTR_TIME_GET_DOUBLE(diff);
}
/*
* Fill the standard tables with some data
*/
static void
-initGenerateData(PGconn *con)
+initGenerateData(PGconn *con, double *insert_sec, double *commit_sec)
{
char sql[256];
PGresult *res;
@@ -3430,28 +3442,42 @@ initGenerateData(PGconn *con)
fprintf(stderr, "PQendcopy failed\n");
exit(1);
}
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *insert_sec = INSTR_TIME_GET_DOUBLE(diff);
+ INSTR_TIME_SET_CURRENT(start);
executeStatement(con, "commit");
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *commit_sec = INSTR_TIME_GET_DOUBLE(diff);
}
/*
* Invoke vacuum on the standard tables
*/
static void
-initVacuum(PGconn *con)
+initVacuum(PGconn *con, double *vacuum_sec)
{
+ instr_time start,
+ diff;
+
fprintf(stderr, "vacuuming...\n");
+ INSTR_TIME_SET_CURRENT(start);
executeStatement(con, "vacuum analyze pgbench_branches");
executeStatement(con, "vacuum analyze pgbench_tellers");
executeStatement(con, "vacuum analyze pgbench_accounts");
executeStatement(con, "vacuum analyze pgbench_history");
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *vacuum_sec = INSTR_TIME_GET_DOUBLE(diff);
}
/*
* Create primary keys on the standard tables
*/
static void
-initCreatePKeys(PGconn *con)
+initCreatePKeys(PGconn *con, double *pkeys_sec)
{
static const char *const DDLINDEXes[] = {
"alter table pgbench_branches add primary key (bid)",
@@ -3459,8 +3485,11 @@ initCreatePKeys(PGconn *con)
"alter table pgbench_accounts add primary key (aid)"
};
int i;
+ instr_time start,
+ diff;
fprintf(stderr, "creating primary keys...\n");
+ INSTR_TIME_SET_CURRENT(start);
for (i = 0; i < lengthof(DDLINDEXes); i++)
{
char buffer[256];
@@ -3480,13 +3509,16 @@ initCreatePKeys(PGconn *con)
executeStatement(con, buffer);
}
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *pkeys_sec = INSTR_TIME_GET_DOUBLE(diff);
}
/*
* Create foreign key constraints between the standard tables
*/
static void
-initCreateFKeys(PGconn *con)
+initCreateFKeys(PGconn *con, double *fkeys_sec)
{
static const char *const DDLKEYs[] = {
"alter table pgbench_tellers add constraint pgbench_tellers_bid_fkey foreign key (bid) references pgbench_branches",
@@ -3496,12 +3528,18 @@ initCreateFKeys(PGconn *con)
"alter table pgbench_history add constraint pgbench_history_aid_fkey foreign key (aid) references pgbench_accounts"
};
int i;
+ instr_time start,
+ diff;
fprintf(stderr, "creating foreign keys...\n");
+ INSTR_TIME_SET_CURRENT(start);
for (i = 0; i < lengthof(DDLKEYs); i++)
{
executeStatement(con, DDLKEYs[i]);
}
+ INSTR_TIME_SET_CURRENT(diff);
+ INSTR_TIME_SUBTRACT(diff, start);
+ *fkeys_sec = INSTR_TIME_GET_DOUBLE(diff);
}
/*
@@ -3542,6 +3580,14 @@ runInitSteps(const char *initialize_steps)
{
PGconn *con;
const char *step;
+ double total_sec = 0.0,
+ drop_sec = 0.0,
+ table_sec = 0.0,
+ insert_sec = 0.0,
+ commit_sec = 0.0,
+ vacuum_sec = 0.0,
+ pkeys_sec = 0.0,
+ fkeys_sec = 0.0;
if ((con = doConnect()) == NULL)
exit(1);
@@ -3551,22 +3597,29 @@ runInitSteps(const char *initialize_steps)
switch (*step)
{
case 'd':
- initDropTables(con);
+ initDropTables(con, &drop_sec);
+ total_sec += drop_sec;
break;
case 't':
- initCreateTables(con);
+ initCreateTables(con, &table_sec);
+ total_sec += table_sec;
break;
case 'g':
- initGenerateData(con);
+ initGenerateData(con, &insert_sec, &commit_sec);
+ total_sec += insert_sec;
+ total_sec += commit_sec;
break;
case 'v':
- initVacuum(con);
+ initVacuum(con, &vacuum_sec);
+ total_sec += vacuum_sec;
break;
case 'p':
- initCreatePKeys(con);
+ initCreatePKeys(con, &pkeys_sec);
+ total_sec += pkeys_sec;
break;
case 'f':
- initCreateFKeys(con);
+ initCreateFKeys(con, &fkeys_sec);
+ total_sec += fkeys_sec;
break;
case ' ':
break; /* ignore */
@@ -3578,8 +3631,13 @@ runInitSteps(const char *initialize_steps)
}
}
- fprintf(stderr, "done.\n");
PQfinish(con);
+ fprintf(stderr, "total time: %.2f s (drop %.2f s, tables %.2f s,"
+ " insert %.2f s, commit %.2f s, primary %.2f s,"
+ " foreign %.2f s, vacuum %.2f s)\n",
+ total_sec, drop_sec, table_sec, insert_sec,
+ commit_sec, pkeys_sec, fkeys_sec, vacuum_sec);
+ fprintf(stderr, "done.\n");
}
/*
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