[PATCH] pgbench log file headers
Hello Hackers!
Currently, pgbench will log individual transactions to a logfile when the
`--log` parameter flag is provided. The logfile, however, does not include
column header. It has become a fairly standard expectation of users to have
column headers present in flat files. Without the header in the pgbench log
files, new users must navigate to the docs and piece together the column
headers themselves. Most industry leading frameworks have tooling built in
to read column headers though, for example python/pandas read_csv().
We can improve the experience for users by adding column headers to pgbench
logfiles with an optional command line flag, `--log-header`. This will keep
the API backwards compatible by making users opt-in to the column headers.
It follows the existing pattern of having conditional flags in pgbench’s
API; the `--log` option would have both –log-prefix and –log-header if this
work is accepted.
The implementation considers the column headers only when the
`--log-header` flag is present. The values for the columns are taken
directly from the “Per-Transaction Logging” section in
https://www.postgresql.org/docs/current/pgbench.html and takes into account
the conditional columns `schedule_lag` and `retries`.
Below is an example of what that logfile will look like:
pgbench postgres://postgres:postgres@localhost:5432/postgres --log
--log-header
client_id transaction_no time script_no time_epoch time_us
0 1 1863 0 1699555588 791102
0 2 706 0 1699555588 791812
If the interface and overall approach makes sense, I will work on adding
documentation and tests for this too.
Respectfully,
Adam Hendel
Attachments:
v1-0001-Adds-log-header-flag-to-pgbench-which-adds-column.patchapplication/octet-stream; name=v1-0001-Adds-log-header-flag-to-pgbench-which-adds-column.patchDownload
From f4451d36624757f893d31987b42e95eb3fd6f303 Mon Sep 17 00:00:00 2001
From: Adam Hendel <hendel.adam@gmail.com>
Date: Thu, 9 Nov 2023 13:34:19 -0600
Subject: [PATCH v1] Adds --log-header flag to pgbench which adds column
headers to the log file
Previously, users would be required to manually look up column names in the
documentation when reading and processing pgbench log files. Adding
--log-header outputs column headers to the logfile itself, making it easy
to process programatically. It is an optional flag, so it maintains backwards
compatibility.
---
src/bin/pgbench/pgbench.c | 45 ++++++++++++++++++++++++++++++++++++++-
1 file changed, 44 insertions(+), 1 deletion(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index e3919395ea..189312409a 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -255,6 +255,7 @@ int64 random_seed = -1;
#define SCALE_32BIT_THRESHOLD 20000
bool use_log; /* log transaction latencies to a file */
+bool use_log_header; /* include column header in the logfile */
bool use_quiet; /* quiet logging onto stderr */
int agg_interval; /* log aggregates instead of individual
* transactions */
@@ -822,6 +823,7 @@ static void setDoubleValue(PgBenchValue *pv, double dval);
static bool evaluateExpr(CState *st, PgBenchExpr *expr,
PgBenchValue *retval);
static ConnectionStateEnum executeMetaCommand(CState *st, pg_time_usec_t *now);
+static void doLogHeader(FILE *logfile, double throttle_delay, uint32 retries);
static void doLog(TState *thread, CState *st,
StatsData *agg, bool skipped, double latency, double lag);
static void processXactStats(TState *thread, CState *st, pg_time_usec_t *now,
@@ -925,6 +927,7 @@ usage(void)
" --log-prefix=PREFIX prefix for transaction time log file\n"
" (default: \"pgbench_log\")\n"
" --max-tries=NUM max number of tries to run transaction (default: 1)\n"
+ " --log-header write column headers to logfile\n"
" --progress-timestamp use Unix epoch timestamps for progress\n"
" --random-seed=SEED set random seed (\"time\", \"rand\", integer)\n"
" --sampling-rate=NUM fraction of transactions to log (e.g., 0.01 for 1%%)\n"
@@ -4500,6 +4503,37 @@ getResultString(bool skipped, EStatus estatus)
return "failed";
}
+/*
+ * Generate the header for the --log file
+ *
+ * schedule_lag field is only present when --rate is specified
+ * retries field is only present when --max-tries != 1
+ */
+void doLogHeader(FILE *logfile, double throttle_delay, uint32 retries)
+{
+ // header fields present in all cases
+ fprintf(logfile, "client_id transaction_no time script_no time_epoch time_us");
+
+ // Append "schedule_lag" if the schedule_lag is true
+ if (throttle_delay)
+ {
+ fprintf(logfile, " schedule_lag");
+ }
+
+
+ // Append "retries" when set
+ if (retries > 1)
+ {
+ fprintf(logfile, " retries");
+ }
+
+ fprintf(logfile, "\n");
+
+ // flush the buffer to ensure the header is written immediately
+ fflush(logfile);
+}
+
+
/*
* Print log entry after completing one transaction.
*
@@ -4517,7 +4551,6 @@ doLog(TState *thread, CState *st,
pg_time_usec_t now = pg_time_now() + epoch_shift;
Assert(use_log);
-
/*
* Skip the log entry if sampling is enabled and this row doesn't belong
* to the random sample.
@@ -6628,6 +6661,7 @@ main(int argc, char **argv)
{"max-tries", required_argument, NULL, 14},
{"verbose-errors", no_argument, NULL, 15},
{"exit-on-abort", no_argument, NULL, 16},
+ {"log-header", no_argument, NULL, 17},
{NULL, 0, NULL, 0}
};
@@ -6965,6 +6999,9 @@ main(int argc, char **argv)
benchmarking_option_set = true;
exit_on_abort = true;
break;
+ case 17:
+ use_log_header = true;
+ break;
default:
/* getopt_long already emitted a complaint */
pg_log_error_hint("Try \"%s --help\" for more information.", progname);
@@ -7101,6 +7138,9 @@ main(int argc, char **argv)
if (!use_log && logfile_prefix)
pg_fatal("log file prefix (--log-prefix) is allowed only when logging transactions (-l)");
+ if (!use_log && use_log_header)
+ pg_fatal("log header (--log-header) is allowed only when logging transactions (-l)");
+
if (duration > 0 && agg_interval > duration)
pg_fatal("number of seconds for aggregation (%d) must not be higher than test duration (%d)", agg_interval, duration);
@@ -7380,6 +7420,9 @@ threadRun(void *arg)
if (thread->logfile == NULL)
pg_fatal("could not open logfile \"%s\": %m", logpath);
+ else
+ if (use_log_header)
+ doLogHeader(thread->logfile, throttle_delay, max_tries);
}
/* explicitly initialize the state machines */
--
2.39.3 (Apple Git-145)
Hi Adam. Column headers in pgbench log files seem helpful. Besides
programs, it seems helpful for humans to understand the column data as
well. I was able to apply your patch and verify that the headers are added
to the log file:
andy@MacBook-Air-4 ~/P/postgres (master)> rm pgbench_log.*
andy@MacBook-Air-4 ~/P/postgres (master)> src/bin/pgbench/pgbench
postgres://andy:@localhost:5432/postgres --log --log-header
pgbench (17devel)
....
andy@MacBook-Air-4 ~/P/postgres (master)> cat pgbench_log.*
client_id transaction_no time script_no time_epoch time_us
0 1 8435 0 1699902315 902700
0 2 1130 0 1699902315 903973
...
The generated pgbench_log.62387 log file showed headers "client_id
transaction_no time script_no time_epoch time_us". Hope that helps with
your patch acceptance journey.
Good luck!
Andrew Atkinson
On Mon, Nov 13, 2023 at 11:55 AM Adam Hendel <adam@tembo.io> wrote:
Show quoted text
Hello Hackers!
Currently, pgbench will log individual transactions to a logfile when the
`--log` parameter flag is provided. The logfile, however, does not include
column header. It has become a fairly standard expectation of users to have
column headers present in flat files. Without the header in the pgbench log
files, new users must navigate to the docs and piece together the column
headers themselves. Most industry leading frameworks have tooling built in
to read column headers though, for example python/pandas read_csv().We can improve the experience for users by adding column headers to
pgbench logfiles with an optional command line flag, `--log-header`. This
will keep the API backwards compatible by making users opt-in to the column
headers. It follows the existing pattern of having conditional flags in
pgbench’s API; the `--log` option would have both –log-prefix and
–log-header if this work is accepted.The implementation considers the column headers only when the
`--log-header` flag is present. The values for the columns are taken
directly from the “Per-Transaction Logging” section in
https://www.postgresql.org/docs/current/pgbench.html and takes into
account the conditional columns `schedule_lag` and `retries`.Below is an example of what that logfile will look like:
pgbench postgres://postgres:postgres@localhost:5432/postgres --log
--log-headerclient_id transaction_no time script_no time_epoch time_us
0 1 1863 0 1699555588 791102
0 2 706 0 1699555588 791812
If the interface and overall approach makes sense, I will work on adding
documentation and tests for this too.Respectfully,
Adam Hendel
Hi,
On 2023-11-13 11:55:07 -0600, Adam Hendel wrote:
Currently, pgbench will log individual transactions to a logfile when the
`--log` parameter flag is provided. The logfile, however, does not include
column header. It has become a fairly standard expectation of users to have
column headers present in flat files. Without the header in the pgbench log
files, new users must navigate to the docs and piece together the column
headers themselves. Most industry leading frameworks have tooling built in
to read column headers though, for example python/pandas read_csv().
The disadvantage of doing that is that a single pgbench run with --log will
generate many files when using -j, to avoid contention. The easiest way to
deal with that after the run is to cat all the log files to a larger one. If
you do that with headers present, you obviously have a few bogus rows (the
heades from the various files).
I guess you could avoid the "worst" of that by documenting that the combined
log file should be built by
cat {$log_prefix}.${pid} {$log_prefix}.${pid}.*
and only outputting the header in the file generated by the main thread.
We can improve the experience for users by adding column headers to pgbench
logfiles with an optional command line flag, `--log-header`. This will keep
the API backwards compatible by making users opt-in to the column headers.
It follows the existing pattern of having conditional flags in pgbench’s
API; the `--log` option would have both –log-prefix and –log-header if this
work is accepted.
The implementation considers the column headers only when the
`--log-header` flag is present. The values for the columns are taken
directly from the “Per-Transaction Logging” section in
https://www.postgresql.org/docs/current/pgbench.html and takes into account
the conditional columns `schedule_lag` and `retries`.Below is an example of what that logfile will look like:
pgbench postgres://postgres:postgres@localhost:5432/postgres --log
--log-headerclient_id transaction_no time script_no time_epoch time_us
Independent of your patch, but we imo ought to combine time_epoch time_us in
the log output. There's no point in forcing consumers to combine those fields,
and it makes logging more expensive... And if we touch this, we should just
switch to outputting nanoseconds instead of microseconds.
It also is quite odd that we have "time" and "time_epoch", "time_us", where
time is the elapsed time of an individual "transaction" and time_epoch +
time_us together are a wall-clock timestamp. Without differentiating between
those, the column headers seem not very useful, because one needs to look in
the documentation to understand the fields.
I don't think there's all that strong a need for backward compatibility in
pgbench. We could just change the columns as I suggest above and then always
emit the header in the "main" log file.
Greetings,
Andres Freund
Hello
On Mon, Nov 13, 2023 at 6:01 PM Andres Freund <andres@anarazel.de> wrote:
Hi,
On 2023-11-13 11:55:07 -0600, Adam Hendel wrote:
Currently, pgbench will log individual transactions to a logfile when the
`--log` parameter flag is provided. The logfile, however, does notinclude
column header. It has become a fairly standard expectation of users to
have
column headers present in flat files. Without the header in the pgbench
log
files, new users must navigate to the docs and piece together the column
headers themselves. Most industry leading frameworks have tooling builtin
to read column headers though, for example python/pandas read_csv().
The disadvantage of doing that is that a single pgbench run with --log will
generate many files when using -j, to avoid contention. The easiest way to
deal with that after the run is to cat all the log files to a larger one.
If
you do that with headers present, you obviously have a few bogus rows (the
heades from the various files).I guess you could avoid the "worst" of that by documenting that the
combined
log file should be built by
cat {$log_prefix}.${pid} {$log_prefix}.${pid}.*
and only outputting the header in the file generated by the main thread.We can improve the experience for users by adding column headers to
pgbenchlogfiles with an optional command line flag, `--log-header`. This will
keep
the API backwards compatible by making users opt-in to the column
headers.
It follows the existing pattern of having conditional flags in pgbench’s
API; the `--log` option would have both –log-prefix and –log-header ifthis
work is accepted.
The implementation considers the column headers only when the
`--log-header` flag is present. The values for the columns are taken
directly from the “Per-Transaction Logging” section in
https://www.postgresql.org/docs/current/pgbench.html and takes intoaccount
the conditional columns `schedule_lag` and `retries`.
Below is an example of what that logfile will look like:
pgbench postgres://postgres:postgres@localhost:5432/postgres --log
--log-headerclient_id transaction_no time script_no time_epoch time_us
Independent of your patch, but we imo ought to combine time_epoch time_us
in
the log output. There's no point in forcing consumers to combine those
fields,
and it makes logging more expensive... And if we touch this, we should
just
switch to outputting nanoseconds instead of microseconds.It also is quite odd that we have "time" and "time_epoch", "time_us", where
time is the elapsed time of an individual "transaction" and time_epoch +
time_us together are a wall-clock timestamp. Without differentiating
between
those, the column headers seem not very useful, because one needs to look
in
the documentation to understand the fields.
I don't think there's all that strong a need for backward compatibility in
pgbench. We could just change the columns as I suggest above and then
always
emit the header in the "main" log file.
Do you think this should be done in separate patches?
First patch: log the column headers in the "main" log file. No --log-header
flag, make it the default behavior of --log.
Next patch: collapse "time_epoch" and "time_us" in the log output and give
the "time" column a name that is more clear.
Adam
Show quoted text
Greetings,
Andres Freund
Hello,
On Mon, Nov 13, 2023 at 6:01 PM Andres Freund <andres@anarazel.de> wrote:
Hi,
On 2023-11-13 11:55:07 -0600, Adam Hendel wrote:
Currently, pgbench will log individual transactions to a logfile when the
`--log` parameter flag is provided. The logfile, however, does notinclude
column header. It has become a fairly standard expectation of users to
have
column headers present in flat files. Without the header in the pgbench
log
files, new users must navigate to the docs and piece together the column
headers themselves. Most industry leading frameworks have tooling builtin
to read column headers though, for example python/pandas read_csv().
The disadvantage of doing that is that a single pgbench run with --log will
generate many files when using -j, to avoid contention. The easiest way to
deal with that after the run is to cat all the log files to a larger one.
If
you do that with headers present, you obviously have a few bogus rows (the
heades from the various files).I guess you could avoid the "worst" of that by documenting that the
combined
log file should be built by
cat {$log_prefix}.${pid} {$log_prefix}.${pid}.*
and only outputting the header in the file generated by the main thread.We can improve the experience for users by adding column headers to
pgbench
logfiles with an optional command line flag, `--log-header`. This will
keep
the API backwards compatible by making users opt-in to the column
headers.
It follows the existing pattern of having conditional flags in pgbench’s
API; the `--log` option would have both –log-prefix and –log-header ifthis
work is accepted.
The implementation considers the column headers only when the
`--log-header` flag is present. The values for the columns are taken
directly from the “Per-Transaction Logging” section in
https://www.postgresql.org/docs/current/pgbench.html and takes intoaccount
the conditional columns `schedule_lag` and `retries`.
Below is an example of what that logfile will look like:
pgbench postgres://postgres:postgres@localhost:5432/postgres --log
--log-headerclient_id transaction_no time script_no time_epoch time_us
Independent of your patch, but we imo ought to combine time_epoch time_us
in
the log output. There's no point in forcing consumers to combine those
fields,
and it makes logging more expensive... And if we touch this, we should
just
switch to outputting nanoseconds instead of microseconds.It also is quite odd that we have "time" and "time_epoch", "time_us", where
time is the elapsed time of an individual "transaction" and time_epoch +
time_us together are a wall-clock timestamp. Without differentiating
between
those, the column headers seem not very useful, because one needs to look
in
the documentation to understand the fields.I don't think there's all that strong a need for backward compatibility in
pgbench. We could just change the columns as I suggest above and then
always
emit the header in the "main" log file.
I updated the patch to always log the header and only off the main thread.
As for the time headers, I will work on renaming/combining those in a
separate commit as:
time -> time_elapsed
time_epoch + time_us -> time_completion_us
Show quoted text
Greetings,
Andres Freund
Attachments:
v2-0001-Adds-colum-headers-to-the-log-file-produced-by-pg.patchapplication/octet-stream; name=v2-0001-Adds-colum-headers-to-the-log-file-produced-by-pg.patchDownload
From 444665735a1a57ece9c7dc0635ad523aa58a5a09 Mon Sep 17 00:00:00 2001
From: Adam Hendel <hendel.adam@gmail.com>
Date: Thu, 9 Nov 2023 13:34:19 -0600
Subject: [PATCH v2] Adds colum headers to the log file produced by pgbench
Previously, users would be required to manually look up column names in the
documentation when reading and processing pgbench log files. Adding column
headers makes it it easy to process programatically.
---
src/bin/pgbench/pgbench.c | 35 ++++++++++++++++++++++++++++++++++-
1 file changed, 34 insertions(+), 1 deletion(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index e3919395ea..78cdc68088 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -822,6 +822,7 @@ static void setDoubleValue(PgBenchValue *pv, double dval);
static bool evaluateExpr(CState *st, PgBenchExpr *expr,
PgBenchValue *retval);
static ConnectionStateEnum executeMetaCommand(CState *st, pg_time_usec_t *now);
+static void doLogHeader(FILE *logfile, double throttle_delay, uint32 retries);
static void doLog(TState *thread, CState *st,
StatsData *agg, bool skipped, double latency, double lag);
static void processXactStats(TState *thread, CState *st, pg_time_usec_t *now,
@@ -4500,6 +4501,34 @@ getResultString(bool skipped, EStatus estatus)
return "failed";
}
+/*
+ * Generates column headers for the log file
+ *
+ */
+void doLogHeader(FILE *logfile, double throttle_delay, uint32 retries)
+{
+ // header fields present in all cases
+ fprintf(logfile, "client_id transaction_no time script_no time_epoch time_us");
+
+ // Append "schedule_lag" if the schedule_lag is true
+ if (throttle_delay)
+ {
+ fprintf(logfile, " schedule_lag");
+ }
+
+ // Append "retries" when set
+ if (retries > 1)
+ {
+ fprintf(logfile, " retries");
+ }
+
+ fprintf(logfile, "\n");
+
+ // flush the buffer to ensure the header is written immediately
+ fflush(logfile);
+}
+
+
/*
* Print log entry after completing one transaction.
*
@@ -4517,7 +4546,6 @@ doLog(TState *thread, CState *st,
pg_time_usec_t now = pg_time_now() + epoch_shift;
Assert(use_log);
-
/*
* Skip the log entry if sampling is enabled and this row doesn't belong
* to the random sample.
@@ -7380,6 +7408,11 @@ threadRun(void *arg)
if (thread->logfile == NULL)
pg_fatal("could not open logfile \"%s\": %m", logpath);
+ else
+ // only log header from the main thread
+ if (thread->tid == 0) {
+ doLogHeader(thread->logfile, throttle_delay, max_tries);
+ }
}
/* explicitly initialize the state machines */
--
2.39.3 (Apple Git-145)
On Tue, 21 Nov 2023 at 09:52, Adam Hendel <adam@tembo.io> wrote:
Hello,
On Mon, Nov 13, 2023 at 6:01 PM Andres Freund <andres@anarazel.de> wrote:
Hi,
On 2023-11-13 11:55:07 -0600, Adam Hendel wrote:
Currently, pgbench will log individual transactions to a logfile when the
`--log` parameter flag is provided. The logfile, however, does not include
column header. It has become a fairly standard expectation of users to have
column headers present in flat files. Without the header in the pgbench log
files, new users must navigate to the docs and piece together the column
headers themselves. Most industry leading frameworks have tooling built in
to read column headers though, for example python/pandas read_csv().The disadvantage of doing that is that a single pgbench run with --log will
generate many files when using -j, to avoid contention. The easiest way to
deal with that after the run is to cat all the log files to a larger one. If
you do that with headers present, you obviously have a few bogus rows (the
heades from the various files).I guess you could avoid the "worst" of that by documenting that the combined
log file should be built by
cat {$log_prefix}.${pid} {$log_prefix}.${pid}.*
and only outputting the header in the file generated by the main thread.We can improve the experience for users by adding column headers to pgbench
logfiles with an optional command line flag, `--log-header`. This will keep
the API backwards compatible by making users opt-in to the column headers.
It follows the existing pattern of having conditional flags in pgbench’s
API; the `--log` option would have both –log-prefix and –log-header if this
work is accepted.The implementation considers the column headers only when the
`--log-header` flag is present. The values for the columns are taken
directly from the “Per-Transaction Logging” section in
https://www.postgresql.org/docs/current/pgbench.html and takes into account
the conditional columns `schedule_lag` and `retries`.Below is an example of what that logfile will look like:
pgbench postgres://postgres:postgres@localhost:5432/postgres --log
--log-headerclient_id transaction_no time script_no time_epoch time_us
Independent of your patch, but we imo ought to combine time_epoch time_us in
the log output. There's no point in forcing consumers to combine those fields,
and it makes logging more expensive... And if we touch this, we should just
switch to outputting nanoseconds instead of microseconds.It also is quite odd that we have "time" and "time_epoch", "time_us", where
time is the elapsed time of an individual "transaction" and time_epoch +
time_us together are a wall-clock timestamp. Without differentiating between
those, the column headers seem not very useful, because one needs to look in
the documentation to understand the fields.I don't think there's all that strong a need for backward compatibility in
pgbench. We could just change the columns as I suggest above and then always
emit the header in the "main" log file.I updated the patch to always log the header and only off the main thread. As for the time headers, I will work on renaming/combining those in a separate commit as:
One of the test has failed in CFBOT at[1]https://cirrus-ci.com/task/5139049757802496 with:
[09:15:00.526](0.000s) not ok 422 - transaction count for
/tmp/cirrus-ci-build/build/testrun/pgbench/001_pgbench_with_server/data/t_001_pgbench_with_server_main_data/001_pgbench_log_3.25193
(11)
[09:15:00.526](0.000s) # Failed test 'transaction count for
/tmp/cirrus-ci-build/build/testrun/pgbench/001_pgbench_with_server/data/t_001_pgbench_with_server_main_data/001_pgbench_log_3.25193
(11)'
# at /tmp/cirrus-ci-build/src/bin/pgbench/t/001_pgbench_with_server.pl
line 1257.
[09:15:00.526](0.000s) not ok 423 - transaction format for 001_pgbench_log_3
[09:15:00.526](0.000s) # Failed test 'transaction format for
001_pgbench_log_3'
# at /tmp/cirrus-ci-build/src/bin/pgbench/t/001_pgbench_with_server.pl
line 1257.
# Log entry not matching: client_id transaction_no time script_no
time_epoch time_us
# Running: pgbench --no-vacuum -f
/tmp/cirrus-ci-build/build/testrun/pgbench/001_pgbench_with_server/data/t_001_pgbench_with_server_main_data/001_pgbench_incomplete_transaction_block
More details for the same is available at [2]https://api.cirrus-ci.com/v1/artifact/task/5139049757802496/testrun/build/testrun/pgbench/001_pgbench_with_server/log/regress_log_001_pgbench_with_server
[1]: https://cirrus-ci.com/task/5139049757802496
[2]: https://api.cirrus-ci.com/v1/artifact/task/5139049757802496/testrun/build/testrun/pgbench/001_pgbench_with_server/log/regress_log_001_pgbench_with_server
Regards,
Vignesh
On 6 Jan 2024, at 20:20, vignesh C <vignesh21@gmail.com> wrote:
One of the test has failed in CFBOT at[1] with:
Hi Adam,
This is a kind reminder that CF entry [0]https://commitfest.postgresql.org/47/4660/ is waiting for an update. Thanks!
Best regards, Andrey Borodin.