pgbench - use pg logging capabilities

On Tue, Dec 24, 2019 at 11:17:31AM +0100, Fabien COELHO wrote:

Some printing to stderr remain for some pgbench specific output.

Hmm. Wouldn't it make sense to output the log generated as
information from the test using pg_log_info() instead of using
fprintf(stderr) (the logs of the initial data load, progress report)?
It seems to me that this would be consistent with the other tools we
have, and being able to make a difference with the level of logs is
kind of a nice property of logging.c as you can grep easily for one
problems instead of looking at multiple patterns matching an error in
the logs. Note also an error in the scripts does not report an
error. Another thing is that messages logged would need to be
translated. I think that's nice, but perhaps others don't like that
or may think that's not a good idea. Who knows..

The patch fixes a inconsistent test case name that I noticed in passing.

@@ -157,7 +157,7 @@ my @options = (
qr{error while setting random seed from --random-seed option}
]
],
-	[ 'bad partition type', '-i --partition-method=BAD', [qr{"range"}, qr{"hash"}, qr{"BAD"}] ],
+	[ 'bad partition method', '-i --partition-method=BAD', [qr{"range"}, qr{"hash"}, qr{"BAD"}] ],
[ 'bad partition number', '-i --partitions -1', [ qr{invalid number of partitions: "-1"} ] ],

No problem with this one from me, I'll fix it if there are no
objections.
--
Michael

On 2019-12-24 11:17, Fabien COELHO wrote:

As suggested in "cce64a51", this patch make pgbench use postgres logging
capabilities.

I tried to use fatal/error/warning/info/debug where appropriate.

Some printing to stderr remain for some pgbench specific output.

The patch seems pretty straightforward, but this

+/*
+ * Convenient shorcuts
+ */
+#define fatal pg_log_fatal
+#define error pg_log_error
+#define warning pg_log_warning
+#define info pg_log_info
+#define debug pg_log_debug

seems counterproductive. Let's just use the normal function names.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On December 31, 2019 8:10:13 PM GMT+09:00, Peter Eisentraut <peter.eisentraut@2ndquadrant.com> wrote:

seems counterproductive. Let's just use the normal function names.

+1.
-- 
Michael

Bonjour Michaï¿œl, et excellente annï¿œe 2020 !

Hmm. Wouldn't it make sense to output the log generated as
information from the test using pg_log_info() instead of using
fprintf(stderr) (the logs of the initial data load, progress report)?

For the progress report, the reason I decided against is that the lines
are already long enough with data (for the progress report: tps, latency,
etc.), and prepending "pgbench info" or equivalent in front of every line
does not look very useful and make it more likely that actually useful
data could be pushed out of the terminal width.

For data load, ISTM that people are used to it like that. Moreover, I do
not think that the \r recently-added trick can work with the logging
stuff, so I left it out as well altogether.

It seems to me that this would be consistent with the other tools we
have, and being able to make a difference with the level of logs is
kind of a nice property of logging.c as you can grep easily for one
problems instead of looking at multiple patterns matching an error in
the logs. Note also an error in the scripts does not report an
error. Another thing is that messages logged would need to be
translated. I think that's nice, but perhaps others don't like that
or may think that's not a good idea. Who knows..

Dunno about translation. ISTM that pgbench is mostly not translated, not
sure why.

--
Fabien.

Hello Peter,

The patch seems pretty straightforward, but this

+/*
+ * Convenient shorcuts
+ */
+#define fatal pg_log_fatal
+#define error pg_log_error
+#define warning pg_log_warning
+#define info pg_log_info
+#define debug pg_log_debug

seems counterproductive. Let's just use the normal function names.

I'm trying to keep the column width under control, but if you like it
wider, here it is.

Compared to v1 I have also made a few changes to be more consistent when
using fatal/error/info.

--
Fabien.

On Wed, Jan 01, 2020 at 10:19:52PM +0100, Fabien COELHO wrote:

Bonjour Michaël, et excellente année 2020 !

Toi aussi! Bonne année.

Hmm. Wouldn't it make sense to output the log generated as
information from the test using pg_log_info() instead of using
fprintf(stderr) (the logs of the initial data load, progress report)?

For the progress report, the reason I decided against is that the lines are
already long enough with data (for the progress report: tps, latency, etc.),
and prepending "pgbench info" or equivalent in front of every line does not
look very useful and make it more likely that actually useful data could be
pushed out of the terminal width.

Hm. Okay. That would limit the patch to only report errors in the
first round of changes, which is fine by me.

For data load, ISTM that people are used to it like that. Moreover, I do not
think that the \r recently-added trick can work with the logging stuff, so I
left it out as well altogether.

It could be possible to create new custom options for logging.c. We
already have one as of PG_LOG_FLAG_TERSE to make the output of psql
compatible with regression tests and such. These are just thoughts
about the control of:
- the progname is appended to the error string or not.
- CR/LF as last character.

Dunno about translation. ISTM that pgbench is mostly not translated, not
sure why.

Because as a benchmark tool that's not really worth it and its output
is rather technical hence translating it would be more challenging?
Perhaps others more used to translation work could chime in the
discussion?
--
Michael

On 2020-01-01 22:55, Fabien COELHO wrote:

I'm trying to keep the column width under control, but if you like it
wider, here it is.

Compared to v1 I have also made a few changes to be more consistent when
using fatal/error/info.

The renaming of debug to debug_level seems unnecessary and unrelated.

In runShellCommand(), you removed some but not all argv[0] from the
output messages. I'm not sure what the intent was there.

I would also recommend these changes:

-       pg_log_fatal("query failed: %s", sql);
-       pg_log_error("%s", PQerrorMessage(con));
+       pg_log_fatal("query failed: %s", PQerrorMessage(con));
+       pg_log_info("query was: %s", sql);

This puts the most important information first.

-       pg_log_error("connection to database \"%s\" failed", dbName);
-       pg_log_error("%s", PQerrorMessage(conn));
+       pg_log_error("connection to database \"%s\" failed: %s",
+                    dbName, PQerrorMessage(conn));

Line break here is unnecessary.

In both cases, pg_dump has similar messages that can serve as reference.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hello Peter,

Compared to v1 I have also made a few changes to be more consistent when
using fatal/error/info.

The renaming of debug to debug_level seems unnecessary and unrelated.

Indeed. It was when I used "debug" as a shorthand for "pg_log_debug".

In runShellCommand(), you removed some but not all argv[0] from the output
messages. I'm not sure what the intent was there.

Without looking at the context I thought that argv[0] was the program
name, which is not the case here. I put it back everywhere, including the
DEBUG message.

I would also recommend these changes:

-       pg_log_fatal("query failed: %s", sql);
-       pg_log_error("%s", PQerrorMessage(con));
+       pg_log_fatal("query failed: %s", PQerrorMessage(con));
+       pg_log_info("query was: %s", sql);

This puts the most important information first.

Ok.

-       pg_log_error("connection to database \"%s\" failed", dbName);
-       pg_log_error("%s", PQerrorMessage(conn));
+       pg_log_error("connection to database \"%s\" failed: %s",
+                    dbName, PQerrorMessage(conn));

Line break here is unnecessary.

Ok. I homogeneised another similar message.

Patch v3 attached hopefully fixes all of the above.

--
Fabien.

On Fri, Jan 03, 2020 at 01:01:18PM +0100, Fabien COELHO wrote:

Without looking at the context I thought that argv[0] was the program name,
which is not the case here. I put it back everywhere, including the DEBUG
message.

The variable names in Command are confusing IMO...

Ok. I homogeneised another similar message.

Patch v3 attached hopefully fixes all of the above.

+     pg_log_error("gaussian parameter must be at least "
+                  "%f (not %f)", MIN_GAUSSIAN_PARAM, param);
I would keep all the error message strings to be on the same line.
That makes grepping for them easier on the same, and that's the usual
convention even if these are larger than 72-80 characters.

 #ifdef DEBUG
-   printf("shell parameter name: \"%s\", value: \"%s\"\n", argv[1], res);
+   pg_log_debug("%s: shell parameter name: \"%s\", value: \"%s\"", argv[0], argv[1], res);
 #endif
Worth removing this ifdef?

-       fprintf(stderr, "%s", PQerrorMessage(con));
+       pg_log_fatal("unexpected copy in result");
+       pg_log_error("%s", PQerrorMessage(con));
        exit(1);
[...]
-       fprintf(stderr, "%s", PQerrorMessage(con));
+       pg_log_fatal("cannot count number of branches");
+       pg_log_error("%s", PQerrorMessage(con));
These are inconsistent with the rest, why not combining both?

I think that I would just remove the "debug" variable defined in
pgbench.c all together, and switch the messages for the duration and
the one in executeMetaCommand to use info-level logging..
--
Michael

Bonjour Michaël,

Without looking at the context I thought that argv[0] was the program name,
which is not the case here. I put it back everywhere, including the DEBUG
message.

The variable names in Command are confusing IMO...

Somehow, yes. Note that there is a logic, it will indeed be the argv of
the called shell command… And I do not think it is the point of this patch
to solve this possible confusion.

+     pg_log_error("gaussian parameter must be at least "
+                  "%f (not %f)", MIN_GAUSSIAN_PARAM, param);

I would keep all the error message strings to be on the same line.
That makes grepping for them easier on the same, and that's the usual
convention even if these are larger than 72-80 characters.

Ok. I also did other similar cases accordingly.

#ifdef DEBUG
Worth removing this ifdef?

Yep, especially as it is the only instance. Done.

+       pg_log_fatal("unexpected copy in result");
+       pg_log_error("%s", PQerrorMessage(con));

+       pg_log_fatal("cannot count number of branches");
+       pg_log_error("%s", PQerrorMessage(con));

These are inconsistent with the rest, why not combining both?

Ok, done.

I think that I would just remove the "debug" variable defined in
pgbench.c all together, and switch the messages for the duration and the
one in executeMetaCommand to use info-level logging..

Ok, done.

Patch v4 attached addresses all these points.

--
Fabien.

On Mon, Jan 06, 2020 at 01:36:23PM +0100, Fabien COELHO wrote:

I think that I would just remove the "debug" variable defined in
pgbench.c all together, and switch the messages for the duration and the
one in executeMetaCommand to use info-level logging..

Ok, done.

Thanks. The output then gets kind of inconsistent when using --debug:
pgbench: client 2 executing script "<builtin: TPC-B (sort of)>"
client 2 executing \set aid
client 2 executing \set bid
client 2 executing \set tid
client 2 executing \set delta

My point was to just modify the code so as this uses pg_log_debug(),
with a routine doing some reverse-engineering of the Command data to
generate a string to show up in the logs. Sorry for the confusion..
And there is no need to use __pg_log_level either which should remain
internal to logging.h IMO.

We'd likely want a similar business in syntax_error() to be fully
consistent with all other code paths dealing with an error showing up
before exiting.

No idea what others think here. I may be too much pedantic.
--
Michael

Bonjour Michaï¿œl,

I think that I would just remove the "debug" variable defined in
pgbench.c all together, and switch the messages for the duration and the
one in executeMetaCommand to use info-level logging..

Ok, done.

Thanks. The output then gets kind of inconsistent when using --debug:
pgbench: client 2 executing script "<builtin: TPC-B (sort of)>"
client 2 executing \set aid
client 2 executing \set bid
client 2 executing \set tid
client 2 executing \set delta

My point was to just modify the code so as this uses pg_log_debug(),
with a routine doing some reverse-engineering of the Command data to
generate a string to show up in the logs. Sorry for the confusion..
And there is no need to use __pg_log_level either which should remain
internal to logging.h IMO.

For the first case with the output you point out, there is a loop to
generate the output. I do not think that we want to pay the cost of
generating the string and then throw it away afterwards when not under
debug, esp as string manipulation is not that cheap, so we need to enter
the thing only when under debug. However, there is no easy way to do that
without accessing __pg_log_level. It could be hidden in a macro to create,
but that's it.

For the second case I called pg_log_debug just once.

We'd likely want a similar business in syntax_error() to be fully
consistent with all other code paths dealing with an error showing up
before exiting.

The syntax error is kind of complicated because there is the location
information which is better left as is, IMHO. I moved remainder to a
PQExpBuffer and pg_log_fatal.

No idea what others think here. I may be too much pedantic.

Maybe a little:-)

Note that I submitted another patch to use PQExpBuffer wherever possible
in pgbench, especially to get rid of doubtful snprintf/strlen patterns.

Patch v5 attached tries to follow your above suggestions.

--
Fabien.

Patch v5 attached tries to follow your above suggestions.

Patch v6 makes syntax error location code more compact and tests the case.

--
Fabien.

On 2020-01-08 13:07, Fabien COELHO wrote:

Patch v5 attached tries to follow your above suggestions.

Patch v6 makes syntax error location code more compact and tests the case.

Committed.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Patch v6 makes syntax error location code more compact and tests the case.

Committed.

Thanks!

--
Fabien.

On Wed, Jan 08, 2020 at 02:27:46PM +0100, Peter Eisentraut wrote:

Committed.

That was fast.

-   if (debug)
+   if (unlikely(__pg_log_level <= PG_LOG_DEBUG))
    {
I am surprised that you kept this one, while syntax_error() has been
changed in a more modular way.
--
Michael

On 2020-01-08 15:12, Michael Paquier wrote:

On Wed, Jan 08, 2020 at 02:27:46PM +0100, Peter Eisentraut wrote:

Committed.

That was fast.

-   if (debug)
+   if (unlikely(__pg_log_level <= PG_LOG_DEBUG))
{
I am surprised that you kept this one,

I'm not happy about it, but it seems OK for now. We can continue to
improve here.

while syntax_error() has been
changed in a more modular way.

I don't follow what you mean by that.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Wed, Jan 08, 2020 at 03:31:46PM +0100, Peter Eisentraut wrote:

On 2020-01-08 15:12, Michael Paquier wrote:

while syntax_error() has been
changed in a more modular way.

I don't follow what you mean by that.

The first versions of the patch did not change syntax_error(), and the
version committed has switched to use PQExpBufferData there. I think
that we should just do the same for the debug logs executing the meta
commands. This way, we get an output consistent with what's printed
out for sending or receiving stuff. Please see the attached.
--
Michael

Bonjour Michaï¿œl,

I don't follow what you mean by that.

The first versions of the patch did not change syntax_error(), and the
version committed has switched to use PQExpBufferData there. I think
that we should just do the same for the debug logs executing the meta
commands. This way, we get an output consistent with what's printed
out for sending or receiving stuff. Please see the attached.

Yep, I thought of it, but I was not very keen on having a malloc/free
cycle just for one debug message. However under debug this is probably not
an issue.

Your patch works for me. IT can avoid some level of format interpretation
overheads by switching to Char/Str functions, see first attachement.

The other point is the test on __pg_log_level, see second attached.

--
Fabien.