Report the time taken by pgbench initialization steps.

Author: Fabien Coelho
Reviewed-by: Ibrar Ahmed
Discussion: https://postgr.es/m/alpine.DEB.2.21.1904061810510.3678%40lancre

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 8b84658ccdacd3d2967a46ac49241dd7ded4d153..23087ef0a246d38cebd813b220d13a1307b95e5b 100644 (file)
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3931,32 +3931,48 @@ checkInitSteps(const char *initialize_steps)
 static void
 runInitSteps(const char *initialize_steps)
 {
+   PQExpBufferData stats;
    PGconn     *con;
    const char *step;
+   double      run_time = 0.0;
+   bool        first = true;
+
+   initPQExpBuffer(&stats);
 
    if ((con = doConnect()) == NULL)
        exit(1);
 
    for (step = initialize_steps; *step != '\0'; step++)
    {
+       instr_time  start;
+       char       *op = NULL;
+
+       INSTR_TIME_SET_CURRENT(start);
+
        switch (*step)
        {
            case 'd':
+               op = "drop tables";
                initDropTables(con);
                break;
            case 't':
+               op = "create tables";
                initCreateTables(con);
                break;
            case 'g':
+               op = "generate";
                initGenerateData(con);
                break;
            case 'v':
+               op = "vacuum";
                initVacuum(con);
                break;
            case 'p':
+               op = "primary keys";
                initCreatePKeys(con);
                break;
            case 'f':
+               op = "foreign keys";
                initCreateFKeys(con);
                break;
            case ' ':
@@ -3967,10 +3983,30 @@ runInitSteps(const char *initialize_steps)
                PQfinish(con);
                exit(1);
        }
+
+       if (op != NULL)
+       {
+           instr_time  diff;
+           double      elapsed_sec;
+
+           INSTR_TIME_SET_CURRENT(diff);
+           INSTR_TIME_SUBTRACT(diff, start);
+           elapsed_sec = INSTR_TIME_GET_DOUBLE(diff);
+
+           if (!first)
+               appendPQExpBufferStr(&stats, ", ");
+           else
+               first = false;
+
+           appendPQExpBuffer(&stats, "%s %.2f s", op, elapsed_sec);
+
+           run_time += elapsed_sec;
+       }
    }
 
-   fprintf(stderr, "done.\n");
+   fprintf(stderr, "done in %.2f s (%s).\n", run_time, stats.data);
    PQfinish(con);
+   termPQExpBuffer(&stats);
 }
 
 /*

diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 3b097a91b28c44a81840710f777bbfc4522631a6..5a2fdb9acb948615762d324a0b0d9f7f6880abb9 100644 (file)
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -94,7 +94,7 @@ pgbench(
    [qr{^$}],
    [
        qr{creating tables},       qr{vacuuming},
-       qr{creating primary keys}, qr{done\.}
+       qr{creating primary keys}, qr{done in \d+\.\d\d s }
    ],
    'pgbench scale 1 initialization',);
 
@@ -109,7 +109,8 @@ pgbench(
        qr{vacuuming},
        qr{creating primary keys},
        qr{creating foreign keys},
-       qr{done\.}
+       qr{(?!vacuuming)}, # no vacuum
+       qr{done in \d+\.\d\d s }
    ],
    'pgbench scale 1 initialization');
 
@@ -124,7 +125,8 @@ pgbench(
        qr{creating primary keys},
        qr{.* of .* tuples \(.*\) done},
        qr{creating foreign keys},
-       qr{done\.}
+       qr{(?!vacuuming)}, # no vacuum
+       qr{done in \d+\.\d\d s }
    ],
    'pgbench --init-steps');