From 29c1740fd3ad0921c6460e57d6745ea700ef6399 Mon Sep 17 00:00:00 2001 From: Marina Polyakova Date: Tue, 7 Aug 2018 13:28:35 +0300 Subject: [PATCH v10 2/4] Pgbench errors: use a separate function to report a debug/log/error message This is most important when it is used to report client failures that do not cause an aborts and this depends on the level of debugging. Rename the already used function pgbench_error() to pgbench_simple_error() for flex lexer errors. Also export the function appendPQExpBufferVA from libpq. --- src/bin/pgbench/pgbench.c | 846 +++++++++++++++++++++++-------------- src/interfaces/libpq/exports.txt | 1 + src/interfaces/libpq/pqexpbuffer.c | 4 +- src/interfaces/libpq/pqexpbuffer.h | 8 + 4 files changed, 530 insertions(+), 329 deletions(-) diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 988e37b..c45cd44 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -484,8 +484,6 @@ static int num_scripts; /* number of scripts in sql_script[] */ static int num_commands = 0; /* total number of Command structs */ static int64 total_weight = 0; -static int debug = 0; /* debug flag */ - /* Builtin test scripts */ typedef struct BuiltinScript { @@ -532,6 +530,31 @@ static const BuiltinScript builtin_script[] = } }; +typedef enum ErrorLevel +{ + /* + * To report throttling, executed/sent/received commands etc. + */ + DEBUG, + + /* + * To report: + * - abortion of the client (something bad e.g. the SQL/meta command failed + * or the connection with the backend was lost); + * - the log messages of the main program; + * - PGBENCH_DEBUG messages. + */ + LOG, + + /* + * To report the error messages of the main program and immediately call + * exit(1). + */ + ERROR +} ErrorLevel; + +static ErrorLevel log_min_messages = LOG; /* no debug by default */ + /* Function prototypes */ static void setNullValue(PgBenchValue *pv); @@ -543,17 +566,19 @@ static void doLog(TState *thread, CState *st, StatsData *agg, bool skipped, double latency, double lag); static void processXactStats(TState *thread, CState *st, instr_time *now, bool skipped, StatsData *agg); -static void pgbench_error(const char *fmt,...) pg_attribute_printf(1, 2); +static void pgbench_simple_error(const char *fmt,...) pg_attribute_printf(1, 2); static void addScript(ParsedScript script); static void *threadRun(void *arg); static void setalarm(int seconds); static void finishCon(CState *st); +static void pgbench_error(ErrorLevel elevel, + const char *fmt,...) pg_attribute_printf(2, 3); /* callback functions for our flex lexer */ static const PsqlScanCallbacks pgbench_callbacks = { NULL, /* don't need get_variable functionality */ - pgbench_error + pgbench_simple_error }; @@ -691,7 +716,7 @@ strtoint64(const char *str) /* require at least one digit */ if (!isdigit((unsigned char) *ptr)) - fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str); + pgbench_error(LOG, "invalid input syntax for integer: \"%s\"\n", str); /* process digits */ while (*ptr && isdigit((unsigned char) *ptr)) @@ -699,7 +724,10 @@ strtoint64(const char *str) int64 tmp = result * 10 + (*ptr++ - '0'); if ((tmp / 10) != result) /* overflow? */ - fprintf(stderr, "value \"%s\" is out of range for type bigint\n", str); + { + pgbench_error(LOG, "value \"%s\" is out of range for type bigint\n", + str); + } result = tmp; } @@ -710,7 +738,7 @@ gotdigits: ptr++; if (*ptr != '\0') - fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str); + pgbench_error(LOG, "invalid input syntax for integer: \"%s\"\n", str); return ((sign < 0) ? -result : result); } @@ -1098,8 +1126,10 @@ executeStatement(PGconn *con, const char *sql) res = PQexec(con, sql); if (PQresultStatus(res) != PGRES_COMMAND_OK) { - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); + /* we are sure that the function PQerrorMessage is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "%s", PQerrorMessage(con)); } PQclear(res); } @@ -1113,8 +1143,11 @@ tryExecuteStatement(PGconn *con, const char *sql) res = PQexec(con, sql); if (PQresultStatus(res) != PGRES_COMMAND_OK) { - fprintf(stderr, "%s", PQerrorMessage(con)); - fprintf(stderr, "(ignoring this error and continuing anyway)\n"); + /* we are sure that the function PQerrorMessage is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "%s(ignoring this error and continuing anyway)\n", + PQerrorMessage(con)); } PQclear(res); } @@ -1160,8 +1193,8 @@ doConnect(void) if (!conn) { - fprintf(stderr, "connection to database \"%s\" failed\n", - dbName); + pgbench_error(LOG, "connection to database \"%s\" failed\n", + dbName); return NULL; } @@ -1179,8 +1212,11 @@ doConnect(void) /* check to see that the backend connection was successfully made */ if (PQstatus(conn) == CONNECTION_BAD) { - fprintf(stderr, "connection to database \"%s\" failed:\n%s", - dbName, PQerrorMessage(conn)); + /* we are sure that the function PQerrorMessage is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "connection to database \"%s\" failed:\n%s", + dbName, PQerrorMessage(conn)); PQfinish(conn); return NULL; } @@ -1318,9 +1354,9 @@ makeVariableValue(Variable *var) if (sscanf(var->svalue, "%lf%c", &dv, &xs) != 1) { - fprintf(stderr, - "malformed variable \"%s\" value: \"%s\"\n", - var->name, var->svalue); + pgbench_error(LOG, + "malformed variable \"%s\" value: \"%s\"\n", + var->name, var->svalue); return false; } setDoubleValue(&var->value, dv); @@ -1365,10 +1401,11 @@ valid_variable_name(const char *name) /* * Lookup a variable by name, creating it if need be. * Caller is expected to assign a value to the variable. - * Returns NULL on failure (bad name). + * On failure (bad name): if this is a client run returns NULL; exits the + * program otherwise. */ static Variable * -lookupCreateVariable(CState *st, const char *context, char *name) +lookupCreateVariable(CState *st, const char *context, char *name, bool client) { Variable *var; @@ -1383,8 +1420,12 @@ lookupCreateVariable(CState *st, const char *context, char *name) */ if (!valid_variable_name(name)) { - fprintf(stderr, "%s: invalid variable name: \"%s\"\n", - context, name); + /* + * About the error level used: if we process client commands, it a + * normal failure; otherwise it is not and we exit the program. + */ + pgbench_error(client ? LOG : ERROR, + "%s: invalid variable name: \"%s\"\n", context, name); return NULL; } @@ -1412,16 +1453,14 @@ lookupCreateVariable(CState *st, const char *context, char *name) } /* Assign a string value to a variable, creating it if need be */ -/* Returns false on failure (bad name) */ -static bool +/* Exits on failure (bad name) */ +static void putVariable(CState *st, const char *context, char *name, const char *value) { Variable *var; char *val; - var = lookupCreateVariable(st, context, name); - if (!var) - return false; + var = lookupCreateVariable(st, context, name, false); /* dup then free, in case value is pointing at this variable */ val = pg_strdup(value); @@ -1430,19 +1469,20 @@ putVariable(CState *st, const char *context, char *name, const char *value) free(var->svalue); var->svalue = val; var->value.type = PGBT_NO_VALUE; - - return true; } -/* Assign a value to a variable, creating it if need be */ -/* Returns false on failure (bad name) */ +/* + * Assign a value to a variable, creating it if need be. + * On failure (bad name): if this is a client run returns false; exits the + * program otherwise. + */ static bool putVariableValue(CState *st, const char *context, char *name, - const PgBenchValue *value) + const PgBenchValue *value, bool client) { Variable *var; - var = lookupCreateVariable(st, context, name); + var = lookupCreateVariable(st, context, name, client); if (!var) return false; @@ -1454,15 +1494,19 @@ putVariableValue(CState *st, const char *context, char *name, return true; } -/* Assign an integer value to a variable, creating it if need be */ -/* Returns false on failure (bad name) */ +/* + * Assign an integer value to a variable, creating it if need be. + * On failure (bad name): if this is a client run returns false; exits the + * program otherwise. + */ static bool -putVariableInt(CState *st, const char *context, char *name, int64 value) +putVariableInt(CState *st, const char *context, char *name, int64 value, + bool client) { PgBenchValue val; setIntValue(&val, value); - return putVariableValue(st, context, name, &val); + return putVariableValue(st, context, name, &val, client); } /* @@ -1593,7 +1637,11 @@ coerceToBool(PgBenchValue *pval, bool *bval) } else /* NULL, INT or DOUBLE */ { - fprintf(stderr, "cannot coerce %s to boolean\n", valueTypeName(pval)); + /* we are sure that the function valueTypeName only is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "cannot coerce %s to boolean\n", + valueTypeName(pval)); *bval = false; /* suppress uninitialized-variable warnings */ return false; } @@ -1638,7 +1686,7 @@ coerceToInt(PgBenchValue *pval, int64 *ival) if (dval < PG_INT64_MIN || PG_INT64_MAX < dval) { - fprintf(stderr, "double to int overflow for %f\n", dval); + pgbench_error(LOG, "double to int overflow for %f\n", dval); return false; } *ival = (int64) dval; @@ -1646,7 +1694,10 @@ coerceToInt(PgBenchValue *pval, int64 *ival) } else /* BOOLEAN or NULL */ { - fprintf(stderr, "cannot coerce %s to int\n", valueTypeName(pval)); + /* we are sure that the function valueTypeName is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "cannot coerce %s to int\n", valueTypeName(pval)); return false; } } @@ -1667,7 +1718,10 @@ coerceToDouble(PgBenchValue *pval, double *dval) } else /* BOOLEAN or NULL */ { - fprintf(stderr, "cannot coerce %s to double\n", valueTypeName(pval)); + /* we are sure that the function valueTypeName is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "cannot coerce %s to double\n", valueTypeName(pval)); return false; } } @@ -1848,8 +1902,8 @@ evalStandardFunc(TState *thread, CState *st, if (l != NULL) { - fprintf(stderr, - "too many function arguments, maximum is %d\n", MAX_FARGS); + pgbench_error(LOG, "too many function arguments, maximum is %d\n", + MAX_FARGS); return false; } @@ -1972,7 +2026,7 @@ evalStandardFunc(TState *thread, CState *st, case PGBENCH_MOD: if (ri == 0) { - fprintf(stderr, "division by zero\n"); + pgbench_error(LOG, "division by zero\n"); return false; } /* special handling of -1 divisor */ @@ -1983,7 +2037,8 @@ evalStandardFunc(TState *thread, CState *st, /* overflow check (needed for INT64_MIN) */ if (li == PG_INT64_MIN) { - fprintf(stderr, "bigint out of range\n"); + pgbench_error(LOG, + "bigint out of range\n"); return false; } else @@ -2084,22 +2139,48 @@ evalStandardFunc(TState *thread, CState *st, case PGBENCH_DEBUG: { PgBenchValue *varg = &vargs[0]; + PQExpBufferData errmsg_buf; Assert(nargs == 1); - fprintf(stderr, "debug(script=%d,command=%d): ", - st->use_file, st->command + 1); + /* + * We are sure that the allocated memory for the message is + * always used. + */ + Assert(LOG >= log_min_messages); + + initPQExpBuffer(&errmsg_buf); + printfPQExpBuffer(&errmsg_buf, + "debug(script=%d,command=%d): ", + st->use_file, st->command + 1); if (varg->type == PGBT_NULL) - fprintf(stderr, "null\n"); + { + appendPQExpBuffer(&errmsg_buf, "null\n"); + } else if (varg->type == PGBT_BOOLEAN) - fprintf(stderr, "boolean %s\n", varg->u.bval ? "true" : "false"); + { + appendPQExpBuffer(&errmsg_buf, + "boolean %s\n", + varg->u.bval ? "true" : "false"); + } else if (varg->type == PGBT_INT) - fprintf(stderr, "int " INT64_FORMAT "\n", varg->u.ival); + { + appendPQExpBuffer(&errmsg_buf, + "int " INT64_FORMAT "\n", varg->u.ival); + } else if (varg->type == PGBT_DOUBLE) - fprintf(stderr, "double %.*g\n", DBL_DIG, varg->u.dval); + { + appendPQExpBuffer(&errmsg_buf, + "double %.*g\n", DBL_DIG, varg->u.dval); + } else /* internal error, unexpected type */ + { Assert(0); + } + + pgbench_error(LOG, "%s", errmsg_buf.data); + termPQExpBuffer(&errmsg_buf); *retval = *varg; @@ -2223,13 +2304,13 @@ evalStandardFunc(TState *thread, CState *st, /* check random range */ if (imin > imax) { - fprintf(stderr, "empty range given to random\n"); + pgbench_error(LOG, "empty range given to random\n"); return false; } else if (imax - imin < 0 || (imax - imin) + 1 < 0) { /* prevent int overflows in random functions */ - fprintf(stderr, "random range is too large\n"); + pgbench_error(LOG, "random range is too large\n"); return false; } @@ -2251,9 +2332,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param < MIN_GAUSSIAN_PARAM) { - fprintf(stderr, - "gaussian parameter must be at least %f " - "(not %f)\n", MIN_GAUSSIAN_PARAM, param); + pgbench_error(LOG, + "gaussian parameter must be at least %f (not %f)\n", + MIN_GAUSSIAN_PARAM, param); return false; } @@ -2265,9 +2346,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0 || param == 1.0 || param > MAX_ZIPFIAN_PARAM) { - fprintf(stderr, - "zipfian parameter must be in range (0, 1) U (1, %d]" - " (got %f)\n", MAX_ZIPFIAN_PARAM, param); + pgbench_error(LOG, + "zipfian parameter must be in range (0, 1) U (1, %d] (got %f)\n", + MAX_ZIPFIAN_PARAM, param); return false; } setIntValue(retval, @@ -2279,9 +2360,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0) { - fprintf(stderr, - "exponential parameter must be greater than zero" - " (got %f)\n", param); + pgbench_error(LOG, + "exponential parameter must be greater than zero (got %f)\n", + param); return false; } @@ -2392,8 +2473,8 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval if ((var = lookupVariable(st, expr->u.variable.varname)) == NULL) { - fprintf(stderr, "undefined variable \"%s\"\n", - expr->u.variable.varname); + pgbench_error(LOG, "undefined variable \"%s\"\n", + expr->u.variable.varname); return false; } @@ -2411,10 +2492,15 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval retval); default: - /* internal error which should never occur */ - fprintf(stderr, "unexpected enode type in evaluation: %d\n", - expr->etype); - exit(1); + { + /* internal error which should never occur */ + pgbench_error(ERROR, + "unexpected enode type in evaluation: %d\n", + expr->etype); + + /* keep compiler quiet */ + return false; + } } } @@ -2487,15 +2573,15 @@ runShellCommand(CState *st, char *variable, char **argv, int argc) } else if ((arg = getVariable(st, argv[i] + 1)) == NULL) { - fprintf(stderr, "%s: undefined variable \"%s\"\n", - argv[0], argv[i]); + pgbench_error(LOG, "%s: undefined variable \"%s\"\n", + argv[0], argv[i]); return false; } arglen = strlen(arg); if (len + arglen + (i > 0 ? 1 : 0) >= SHELL_COMMAND_SIZE - 1) { - fprintf(stderr, "%s: shell command is too long\n", argv[0]); + pgbench_error(LOG, "%s: shell command is too long\n", argv[0]); return false; } @@ -2513,7 +2599,10 @@ runShellCommand(CState *st, char *variable, char **argv, int argc) if (system(command)) { if (!timer_exceeded) - fprintf(stderr, "%s: could not launch shell command\n", argv[0]); + { + pgbench_error(LOG, "%s: could not launch shell command\n", + argv[0]); + } return false; } return true; @@ -2522,19 +2611,22 @@ runShellCommand(CState *st, char *variable, char **argv, int argc) /* Execute the command with pipe and read the standard output. */ if ((fp = popen(command, "r")) == NULL) { - fprintf(stderr, "%s: could not launch shell command\n", argv[0]); + pgbench_error(LOG, "%s: could not launch shell command\n", argv[0]); return false; } if (fgets(res, sizeof(res), fp) == NULL) { if (!timer_exceeded) - fprintf(stderr, "%s: could not read result of shell command\n", argv[0]); + { + pgbench_error(LOG, "%s: could not read result of shell command\n", + argv[0]); + } (void) pclose(fp); return false; } if (pclose(fp) < 0) { - fprintf(stderr, "%s: could not close shell command\n", argv[0]); + pgbench_error(LOG, "%s: could not close shell command\n", argv[0]); return false; } @@ -2544,11 +2636,12 @@ runShellCommand(CState *st, char *variable, char **argv, int argc) endptr++; if (*res == '\0' || *endptr != '\0') { - fprintf(stderr, "%s: shell command must return an integer (not \"%s\")\n", - argv[0], res); + pgbench_error(LOG, + "%s: shell command must return an integer (not \"%s\")\n", + argv[0], res); return false; } - if (!putVariableInt(st, "setshell", variable, retval)) + if (!putVariableInt(st, "setshell", variable, retval, true)) return false; #ifdef DEBUG @@ -2567,9 +2660,9 @@ preparedStatementName(char *buffer, int file, int state) static void commandFailed(CState *st, const char *cmd, const char *message) { - fprintf(stderr, - "client %d aborted in command %d (%s) of script %d; %s\n", - st->id, st->command, cmd, st->use_file, message); + pgbench_error(LOG, + "client %d aborted in command %d (%s) of script %d; %s\n", + st->id, st->command, cmd, st->use_file, message); } /* return a script number with a weighted choice. */ @@ -2604,8 +2697,7 @@ sendCommand(CState *st, Command *command) sql = pg_strdup(command->argv[0]); sql = assignVariables(st, sql); - if (debug) - fprintf(stderr, "client %d sending %s\n", st->id, sql); + pgbench_error(DEBUG, "client %d sending %s\n", st->id, sql); r = PQsendQuery(st->con, sql); free(sql); } @@ -2616,8 +2708,7 @@ sendCommand(CState *st, Command *command) getQueryParams(st, command, params); - if (debug) - fprintf(stderr, "client %d sending %s\n", st->id, sql); + pgbench_error(DEBUG, "client %d sending %s\n", st->id, sql); r = PQsendQueryParams(st->con, sql, command->argc - 1, NULL, params, NULL, NULL, 0); } @@ -2642,7 +2733,15 @@ sendCommand(CState *st, Command *command) res = PQprepare(st->con, name, commands[j]->argv[0], commands[j]->argc - 1, NULL); if (PQresultStatus(res) != PGRES_COMMAND_OK) - fprintf(stderr, "%s", PQerrorMessage(st->con)); + { + /* + * We are sure that the function PQerrorMessage is always + * called. + */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "%s", PQerrorMessage(st->con)); + } PQclear(res); } st->prepared[st->use_file] = true; @@ -2651,8 +2750,7 @@ sendCommand(CState *st, Command *command) getQueryParams(st, command, params); preparedStatementName(name, st->use_file, st->command); - if (debug) - fprintf(stderr, "client %d sending %s\n", st->id, name); + pgbench_error(DEBUG, "client %d sending %s\n", st->id, name); r = PQsendQueryPrepared(st->con, name, command->argc - 1, params, NULL, NULL, 0); } @@ -2661,9 +2759,8 @@ sendCommand(CState *st, Command *command) if (r == 0) { - if (debug) - fprintf(stderr, "client %d could not send %s\n", - st->id, command->argv[0]); + pgbench_error(DEBUG, "client %d could not send %s\n", + st->id, command->argv[0]); st->ecnt++; return false; } @@ -2685,8 +2782,8 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs) { if ((var = getVariable(st, argv[1] + 1)) == NULL) { - fprintf(stderr, "%s: undefined variable \"%s\"\n", - argv[0], argv[1]); + pgbench_error(LOG, "%s: undefined variable \"%s\"\n", + argv[0], argv[1]); return false; } usec = atoi(var); @@ -2749,9 +2846,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) st->use_file = chooseScript(thread); - if (debug) - fprintf(stderr, "client %d executing script \"%s\"\n", st->id, - sql_script[st->use_file].desc); + pgbench_error(DEBUG, "client %d executing script \"%s\"\n", + st->id, sql_script[st->use_file].desc); if (throttle_delay > 0) st->state = CSTATE_START_THROTTLE; @@ -2824,9 +2920,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) } st->state = CSTATE_THROTTLE; - if (debug) - fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n", - st->id, wait); + pgbench_error(DEBUG, + "client %d throttling " INT64_FORMAT " us\n", + st->id, wait); break; /* @@ -2858,8 +2954,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) start = now; if ((st->con = doConnect()) == NULL) { - fprintf(stderr, "client %d aborted while establishing connection\n", - st->id); + pgbench_error(LOG, + "client %d aborted while establishing connection\n", + st->id); st->state = CSTATE_ABORTED; break; } @@ -2937,12 +3034,19 @@ doCustom(TState *thread, CState *st, StatsData *agg) i; char **argv = command->argv; - if (debug) + /* allocate memory for the message only if necessary */ + if (DEBUG >= log_min_messages) { - fprintf(stderr, "client %d executing \\%s", st->id, argv[0]); + PQExpBufferData errmsg_buf; + + initPQExpBuffer(&errmsg_buf); + printfPQExpBuffer(&errmsg_buf, "client %d executing \\%s", + st->id, argv[0]); for (i = 1; i < argc; i++) - fprintf(stderr, " %s", argv[i]); - fprintf(stderr, "\n"); + appendPQExpBuffer(&errmsg_buf, " %s", argv[i]); + appendPQExpBufferChar(&errmsg_buf, '\n'); + pgbench_error(DEBUG, "%s", errmsg_buf.data); + termPQExpBuffer(&errmsg_buf); } if (command->meta == META_SLEEP) @@ -2997,7 +3101,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (command->meta == META_SET) { - if (!putVariableValue(st, argv[0], argv[1], &result)) + if (!putVariableValue(st, argv[0], argv[1], &result, + true)) { commandFailed(st, "set", "assignment of meta-command failed"); st->state = CSTATE_ABORTED; @@ -3197,8 +3302,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) */ case CSTATE_WAIT_RESULT: command = sql_script[st->use_file].commands[st->command]; - if (debug) - fprintf(stderr, "client %d receiving\n", st->id); + pgbench_error(DEBUG, "client %d receiving\n", st->id); if (!PQconsumeInput(st->con)) { /* there's something wrong */ commandFailed(st, "SQL", "perhaps the backend died while processing"); @@ -3284,8 +3388,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) /* conditional stack must be empty */ if (!conditional_stack_empty(st->cstack)) { - fprintf(stderr, "end of script reached within a conditional, missing \\endif\n"); - exit(1); + pgbench_error(ERROR, + "end of script reached within a conditional, missing \\endif\n"); } if (is_connect) @@ -3484,7 +3588,7 @@ disconnect_all(CState *state, int length) static void initDropTables(PGconn *con) { - fprintf(stderr, "dropping old tables...\n"); + pgbench_error(LOG, "dropping old tables...\n"); /* * We drop all the tables in one command, so that whether there are @@ -3559,7 +3663,7 @@ initCreateTables(PGconn *con) }; int i; - fprintf(stderr, "creating tables...\n"); + pgbench_error(LOG, "creating tables...\n"); for (i = 0; i < lengthof(DDLs); i++) { @@ -3612,7 +3716,7 @@ initGenerateData(PGconn *con) remaining_sec; int log_interval = 1; - fprintf(stderr, "generating data...\n"); + pgbench_error(LOG, "generating data...\n"); /* * we do all of this in one transaction to enable the backend's @@ -3658,8 +3762,10 @@ initGenerateData(PGconn *con) res = PQexec(con, "copy pgbench_accounts from stdin"); if (PQresultStatus(res) != PGRES_COPY_IN) { - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); + /* we are sure that the function PQerrorMessage is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "%s", PQerrorMessage(con)); } PQclear(res); @@ -3674,10 +3780,7 @@ initGenerateData(PGconn *con) INT64_FORMAT "\t" INT64_FORMAT "\t%d\t\n", j, k / naccounts + 1, 0); if (PQputline(con, sql)) - { - fprintf(stderr, "PQputline failed\n"); - exit(1); - } + pgbench_error(ERROR, "PQputline failed\n"); /* * If we want to stick with the original logging, print a message each @@ -3691,10 +3794,12 @@ initGenerateData(PGconn *con) elapsed_sec = INSTR_TIME_GET_DOUBLE(diff); remaining_sec = ((double) scale * naccounts - j) * elapsed_sec / j; - fprintf(stderr, INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n", - j, (int64) naccounts * scale, - (int) (((int64) j * 100) / (naccounts * (int64) scale)), - elapsed_sec, remaining_sec); + pgbench_error(LOG, + INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n", + j, (int64) naccounts * scale, + (int) (((int64) j * 100) / + (naccounts * (int64) scale)), + elapsed_sec, remaining_sec); } /* let's not call the timing for each row, but only each 100 rows */ else if (use_quiet && (j % 100 == 0)) @@ -3708,9 +3813,12 @@ initGenerateData(PGconn *con) /* have we reached the next interval (or end)? */ if ((j == scale * naccounts) || (elapsed_sec >= log_interval * LOG_STEP_SECONDS)) { - fprintf(stderr, INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n", - j, (int64) naccounts * scale, - (int) (((int64) j * 100) / (naccounts * (int64) scale)), elapsed_sec, remaining_sec); + pgbench_error(LOG, + INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n", + j, (int64) naccounts * scale, + (int) (((int64) j * 100) / + (naccounts * (int64) scale)), + elapsed_sec, remaining_sec); /* skip to the next interval */ log_interval = (int) ceil(elapsed_sec / LOG_STEP_SECONDS); @@ -3719,15 +3827,9 @@ initGenerateData(PGconn *con) } if (PQputline(con, "\\.\n")) - { - fprintf(stderr, "very last PQputline failed\n"); - exit(1); - } + pgbench_error(ERROR, "very last PQputline failed\n"); if (PQendcopy(con)) - { - fprintf(stderr, "PQendcopy failed\n"); - exit(1); - } + pgbench_error(ERROR, "PQendcopy failed\n"); executeStatement(con, "commit"); } @@ -3738,7 +3840,7 @@ initGenerateData(PGconn *con) static void initVacuum(PGconn *con) { - fprintf(stderr, "vacuuming...\n"); + pgbench_error(LOG, "vacuuming...\n"); executeStatement(con, "vacuum analyze pgbench_branches"); executeStatement(con, "vacuum analyze pgbench_tellers"); executeStatement(con, "vacuum analyze pgbench_accounts"); @@ -3758,7 +3860,7 @@ initCreatePKeys(PGconn *con) }; int i; - fprintf(stderr, "creating primary keys...\n"); + pgbench_error(LOG, "creating primary keys...\n"); for (i = 0; i < lengthof(DDLINDEXes); i++) { char buffer[256]; @@ -3795,7 +3897,7 @@ initCreateFKeys(PGconn *con) }; int i; - fprintf(stderr, "creating foreign keys...\n"); + pgbench_error(LOG, "creating foreign keys...\n"); for (i = 0; i < lengthof(DDLKEYs); i++) { executeStatement(con, DDLKEYs[i]); @@ -3815,19 +3917,16 @@ checkInitSteps(const char *initialize_steps) const char *step; if (initialize_steps[0] == '\0') - { - fprintf(stderr, "no initialization steps specified\n"); - exit(1); - } + pgbench_error(ERROR, "no initialization steps specified\n"); for (step = initialize_steps; *step != '\0'; step++) { if (strchr("dtgvpf ", *step) == NULL) { - fprintf(stderr, "unrecognized initialization step \"%c\"\n", - *step); - fprintf(stderr, "allowed steps are: \"d\", \"t\", \"g\", \"v\", \"p\", \"f\"\n"); - exit(1); + pgbench_error(ERROR, + "unrecognized initialization step \"%c\"\n" + "allowed steps are: \"d\", \"t\", \"g\", \"v\", \"p\", \"f\"\n", + *step); } } } @@ -3869,14 +3968,14 @@ runInitSteps(const char *initialize_steps) case ' ': break; /* ignore */ default: - fprintf(stderr, "unrecognized initialization step \"%c\"\n", - *step); + pgbench_error(LOG, "unrecognized initialization step \"%c\"\n", + *step); PQfinish(con); exit(1); } } - fprintf(stderr, "done.\n"); + pgbench_error(LOG, "done.\n"); PQfinish(con); } @@ -3914,8 +4013,9 @@ parseQuery(Command *cmd) if (cmd->argc >= MAX_ARGS) { - fprintf(stderr, "statement has too many arguments (maximum is %d): %s\n", - MAX_ARGS - 1, cmd->argv[0]); + pgbench_error(LOG, + "statement has too many arguments (maximum is %d): %s\n", + MAX_ARGS - 1, cmd->argv[0]); pg_free(name); return false; } @@ -3936,14 +4036,28 @@ parseQuery(Command *cmd) * Simple error-printing function, might be needed by lexer */ static void -pgbench_error(const char *fmt,...) +pgbench_simple_error(const char *fmt,...) { va_list ap; + PQExpBufferData errmsg_buf; + bool done; + + /* We are sure that the allocated memory for the message is always used. */ + Assert(LOG >= log_min_messages); fflush(stdout); - va_start(ap, fmt); - vfprintf(stderr, _(fmt), ap); - va_end(ap); + initPQExpBuffer(&errmsg_buf); + + /* Loop in case we have to retry after enlarging the buffer. */ + do + { + va_start(ap, fmt); + done = appendPQExpBufferVA(&errmsg_buf, fmt, ap); + va_end(ap); + } while (!done); + + pgbench_error(LOG, "%s", errmsg_buf.data); + termPQExpBuffer(&errmsg_buf); } /* @@ -3963,26 +4077,35 @@ syntax_error(const char *source, int lineno, const char *line, const char *command, const char *msg, const char *more, int column) { - fprintf(stderr, "%s:%d: %s", source, lineno, msg); + PQExpBufferData errmsg_buf; + + /* we are sure that the allocated memory for the message is always used */ + Assert(LOG >= log_min_messages); + + initPQExpBuffer(&errmsg_buf); + printfPQExpBuffer(&errmsg_buf, "%s:%d: %s", source, lineno, msg); if (more != NULL) - fprintf(stderr, " (%s)", more); + appendPQExpBuffer(&errmsg_buf, " (%s)", more); if (column >= 0 && line == NULL) - fprintf(stderr, " at column %d", column + 1); + appendPQExpBuffer(&errmsg_buf, " at column %d", column + 1); if (command != NULL) - fprintf(stderr, " in command \"%s\"", command); - fprintf(stderr, "\n"); + appendPQExpBuffer(&errmsg_buf, " in command \"%s\"", command); + appendPQExpBufferChar(&errmsg_buf, '\n'); if (line != NULL) { - fprintf(stderr, "%s\n", line); + appendPQExpBuffer(&errmsg_buf, "%s\n", line); if (column >= 0) { int i; for (i = 0; i < column; i++) - fprintf(stderr, " "); - fprintf(stderr, "^ error found here\n"); + appendPQExpBufferChar(&errmsg_buf, ' '); + appendPQExpBufferStr(&errmsg_buf, "^ error found here\n"); } } + + pgbench_error(LOG, "%s", errmsg_buf.data); + termPQExpBuffer(&errmsg_buf); exit(1); } @@ -4232,10 +4355,8 @@ process_backslash_command(PsqlScanState sstate, const char *source) static void ConditionError(const char *desc, int cmdn, const char *msg) { - fprintf(stderr, - "condition error in script \"%s\" command %d: %s\n", - desc, cmdn, msg); - exit(1); + pgbench_error(ERROR, "condition error in script \"%s\" command %d: %s\n", + desc, cmdn, msg); } /* @@ -4434,18 +4555,22 @@ process_file(const char *filename, int weight) fd = stdin; else if ((fd = fopen(filename, "r")) == NULL) { - fprintf(stderr, "could not open file \"%s\": %s\n", - filename, strerror(errno)); - exit(1); + /* we are sure that the function strerror is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "could not open file \"%s\": %s\n", + filename, strerror(errno)); } buf = read_file_contents(fd); if (ferror(fd)) { - fprintf(stderr, "could not read file \"%s\": %s\n", - filename, strerror(errno)); - exit(1); + /* we are sure that the function strerror is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "could not read file \"%s\": %s\n", + filename, strerror(errno)); } if (fd != stdin) @@ -4468,11 +4593,19 @@ static void listAvailableScripts(void) { int i; + PQExpBufferData errmsg_buf; - fprintf(stderr, "Available builtin scripts:\n"); + /* we are sure that the allocated memory for the message is always used */ + Assert(LOG >= log_min_messages); + + initPQExpBuffer(&errmsg_buf); + printfPQExpBuffer(&errmsg_buf, "Available builtin scripts:\n"); for (i = 0; i < lengthof(builtin_script); i++) - fprintf(stderr, "\t%s\n", builtin_script[i].name); - fprintf(stderr, "\n"); + appendPQExpBuffer(&errmsg_buf, "\t%s\n", builtin_script[i].name); + appendPQExpBufferChar(&errmsg_buf, '\n'); + + pgbench_error(LOG, "%s", errmsg_buf.data); + termPQExpBuffer(&errmsg_buf); } /* return builtin script "name" if unambiguous, fails if not found */ @@ -4499,10 +4632,11 @@ findBuiltin(const char *name) /* error cases */ if (found == 0) - fprintf(stderr, "no builtin script found for name \"%s\"\n", name); + pgbench_error(LOG, "no builtin script found for name \"%s\"\n", name); else /* found > 1 */ - fprintf(stderr, - "ambiguous builtin name: %d builtin scripts found for prefix \"%s\"\n", found, name); + pgbench_error(LOG, + "ambiguous builtin name: %d builtin scripts found for prefix \"%s\"\n", + found, name); listAvailableScripts(); exit(1); @@ -4534,16 +4668,12 @@ parseScriptWeight(const char *option, char **script) errno = 0; wtmp = strtol(sep + 1, &badp, 10); if (errno != 0 || badp == sep + 1 || *badp != '\0') - { - fprintf(stderr, "invalid weight specification: %s\n", sep); - exit(1); - } + pgbench_error(ERROR, "invalid weight specification: %s\n", sep); if (wtmp > INT_MAX || wtmp < 0) { - fprintf(stderr, - "weight specification out of range (0 .. %u): " INT64_FORMAT "\n", - INT_MAX, (int64) wtmp); - exit(1); + pgbench_error(ERROR, + "weight specification out of range (0 .. %u): " INT64_FORMAT "\n", + INT_MAX, (int64) wtmp); } weight = wtmp; } @@ -4562,14 +4692,14 @@ addScript(ParsedScript script) { if (script.commands == NULL || script.commands[0] == NULL) { - fprintf(stderr, "empty command list for script \"%s\"\n", script.desc); - exit(1); + pgbench_error(ERROR, "empty command list for script \"%s\"\n", + script.desc); } if (num_scripts >= MAX_SCRIPTS) { - fprintf(stderr, "at most %d SQL scripts are allowed\n", MAX_SCRIPTS); - exit(1); + pgbench_error(ERROR, "at most %d SQL scripts are allowed\n", + MAX_SCRIPTS); } CheckConditional(script); @@ -4754,9 +4884,8 @@ set_random_seed(const char *seed) if (!pg_strong_random(&iseed, sizeof(iseed))) #endif { - fprintf(stderr, - "cannot seed random from a strong source, none available: " - "use \"time\" or an unsigned integer value.\n"); + pgbench_error(LOG, + "cannot seed random from a strong source, none available: use \"time\" or an unsigned integer value.\n"); return false; } } @@ -4767,15 +4896,15 @@ set_random_seed(const char *seed) if (sscanf(seed, "%u%c", &iseed, &garbage) != 1) { - fprintf(stderr, - "unrecognized random seed option \"%s\": expecting an unsigned integer, \"time\" or \"rand\"\n", - seed); + pgbench_error(LOG, + "unrecognized random seed option \"%s\": expecting an unsigned integer, \"time\" or \"rand\"\n", + seed); return false; } } if (seed != NULL) - fprintf(stderr, "setting random seed to %u\n", iseed); + pgbench_error(LOG, "setting random seed to %u\n", iseed); srandom(iseed); /* no precision loss: 32 bit unsigned int cast to 64 bit int */ random_seed = iseed; @@ -4907,8 +5036,8 @@ main(int argc, char **argv) /* set random seed early, because it may be used while parsing scripts. */ if (!set_random_seed(getenv("PGBENCH_RANDOM_SEED"))) { - fprintf(stderr, "error while setting random seed from PGBENCH_RANDOM_SEED environment variable\n"); - exit(1); + pgbench_error(ERROR, + "error while setting random seed from PGBENCH_RANDOM_SEED environment variable\n"); } while ((c = getopt_long(argc, argv, "iI:h:nvp:dqb:SNc:j:Crs:t:T:U:lf:D:F:M:P:R:L:", long_options, &optindex)) != -1) @@ -4941,16 +5070,15 @@ main(int argc, char **argv) pgport = pg_strdup(optarg); break; case 'd': - debug++; + log_min_messages = DEBUG; break; case 'c': benchmarking_option_set = true; nclients = atoi(optarg); if (nclients <= 0 || nclients > MAXCLIENTS) { - fprintf(stderr, "invalid number of clients: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, "invalid number of clients: \"%s\"\n", + optarg); } #ifdef HAVE_GETRLIMIT #ifdef RLIMIT_NOFILE /* most platforms use RLIMIT_NOFILE */ @@ -4959,15 +5087,20 @@ main(int argc, char **argv) if (getrlimit(RLIMIT_OFILE, &rlim) == -1) #endif /* RLIMIT_NOFILE */ { - fprintf(stderr, "getrlimit failed: %s\n", strerror(errno)); - exit(1); + /* + * We are sure that the function strerror is always called. + */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "getrlimit failed: %s\n", + strerror(errno)); } if (rlim.rlim_cur < nclients + 3) { - fprintf(stderr, "need at least %d open files, but system limit is %ld\n", - nclients + 3, (long) rlim.rlim_cur); - fprintf(stderr, "Reduce number of clients, or use limit/ulimit to increase the system limit.\n"); - exit(1); + pgbench_error(ERROR, + "need at least %d open files, but system limit is %ld\n" + "Reduce number of clients, or use limit/ulimit to increase the system limit.\n", + nclients + 3, (long) rlim.rlim_cur); } #endif /* HAVE_GETRLIMIT */ break; @@ -4976,15 +5109,14 @@ main(int argc, char **argv) nthreads = atoi(optarg); if (nthreads <= 0) { - fprintf(stderr, "invalid number of threads: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, "invalid number of threads: \"%s\"\n", + optarg); } #ifndef ENABLE_THREAD_SAFETY if (nthreads != 1) { - fprintf(stderr, "threads are not supported on this platform; use -j1\n"); - exit(1); + pgbench_error(ERROR, + "threads are not supported on this platform; use -j1\n"); } #endif /* !ENABLE_THREAD_SAFETY */ break; @@ -5001,8 +5133,8 @@ main(int argc, char **argv) scale = atoi(optarg); if (scale <= 0) { - fprintf(stderr, "invalid scaling factor: \"%s\"\n", optarg); - exit(1); + pgbench_error(ERROR, "invalid scaling factor: \"%s\"\n", + optarg); } break; case 't': @@ -5010,19 +5142,16 @@ main(int argc, char **argv) nxacts = atoi(optarg); if (nxacts <= 0) { - fprintf(stderr, "invalid number of transactions: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, + "invalid number of transactions: \"%s\"\n", + optarg); } break; case 'T': benchmarking_option_set = true; duration = atoi(optarg); if (duration <= 0) - { - fprintf(stderr, "invalid duration: \"%s\"\n", optarg); - exit(1); - } + pgbench_error(ERROR, "invalid duration: \"%s\"\n", optarg); break; case 'U': login = pg_strdup(optarg); @@ -5069,14 +5198,13 @@ main(int argc, char **argv) if ((p = strchr(optarg, '=')) == NULL || p == optarg || *(p + 1) == '\0') { - fprintf(stderr, "invalid variable definition: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, + "invalid variable definition: \"%s\"\n", + optarg); } *p++ = '\0'; - if (!putVariable(&state[0], "option", optarg, p)) - exit(1); + putVariable(&state[0], "option", optarg, p); } break; case 'F': @@ -5084,8 +5212,8 @@ main(int argc, char **argv) fillfactor = atoi(optarg); if (fillfactor < 10 || fillfactor > 100) { - fprintf(stderr, "invalid fillfactor: \"%s\"\n", optarg); - exit(1); + pgbench_error(ERROR, "invalid fillfactor: \"%s\"\n", + optarg); } break; case 'M': @@ -5095,9 +5223,8 @@ main(int argc, char **argv) break; if (querymode >= NUM_QUERYMODE) { - fprintf(stderr, "invalid query mode (-M): \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, "invalid query mode (-M): \"%s\"\n", + optarg); } break; case 'P': @@ -5105,9 +5232,9 @@ main(int argc, char **argv) progress = atoi(optarg); if (progress <= 0) { - fprintf(stderr, "invalid thread progress delay: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, + "invalid thread progress delay: \"%s\"\n", + optarg); } break; case 'R': @@ -5119,8 +5246,8 @@ main(int argc, char **argv) if (throttle_value <= 0.0) { - fprintf(stderr, "invalid rate limit: \"%s\"\n", optarg); - exit(1); + pgbench_error(ERROR, "invalid rate limit: \"%s\"\n", + optarg); } /* Invert rate limit into a time offset */ throttle_delay = (int64) (1000000.0 / throttle_value); @@ -5132,9 +5259,8 @@ main(int argc, char **argv) if (limit_ms <= 0.0) { - fprintf(stderr, "invalid latency limit: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, "invalid latency limit: \"%s\"\n", + optarg); } benchmarking_option_set = true; latency_limit = (int64) (limit_ms * 1000); @@ -5157,8 +5283,8 @@ main(int argc, char **argv) sample_rate = atof(optarg); if (sample_rate <= 0.0 || sample_rate > 1.0) { - fprintf(stderr, "invalid sampling rate: \"%s\"\n", optarg); - exit(1); + pgbench_error(ERROR, "invalid sampling rate: \"%s\"\n", + optarg); } break; case 5: /* aggregate-interval */ @@ -5166,9 +5292,9 @@ main(int argc, char **argv) agg_interval = atoi(optarg); if (agg_interval <= 0) { - fprintf(stderr, "invalid number of seconds for aggregation: \"%s\"\n", - optarg); - exit(1); + pgbench_error(ERROR, + "invalid number of seconds for aggregation: \"%s\"\n", + optarg); } break; case 6: /* progress-timestamp */ @@ -5187,13 +5313,14 @@ main(int argc, char **argv) benchmarking_option_set = true; if (!set_random_seed(optarg)) { - fprintf(stderr, "error while setting random seed from --random-seed option\n"); - exit(1); + pgbench_error(ERROR, + "error while setting random seed from --random-seed option\n"); } break; default: - fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); - exit(1); + pgbench_error(ERROR, + _("Try \"%s --help\" for more information.\n"), + progname); break; } } @@ -5230,10 +5357,7 @@ main(int argc, char **argv) total_weight += sql_script[i].weight; if (total_weight == 0 && !is_init_mode) - { - fprintf(stderr, "total script weight must not be zero\n"); - exit(1); - } + pgbench_error(ERROR, "total script weight must not be zero\n"); /* show per script stats if several scripts are used */ if (num_scripts > 1) @@ -5266,8 +5390,8 @@ main(int argc, char **argv) { if (benchmarking_option_set) { - fprintf(stderr, "some of the specified options cannot be used in initialization (-i) mode\n"); - exit(1); + pgbench_error(ERROR, + "some of the specified options cannot be used in initialization (-i) mode\n"); } if (initialize_steps == NULL) @@ -5301,15 +5425,15 @@ main(int argc, char **argv) { if (initialization_option_set) { - fprintf(stderr, "some of the specified options cannot be used in benchmarking mode\n"); - exit(1); + pgbench_error(ERROR, + "some of the specified options cannot be used in benchmarking mode\n"); } } if (nxacts > 0 && duration > 0) { - fprintf(stderr, "specify either a number of transactions (-t) or a duration (-T), not both\n"); - exit(1); + pgbench_error(ERROR, + "specify either a number of transactions (-t) or a duration (-T), not both\n"); } /* Use DEFAULT_NXACTS if neither nxacts nor duration is specified. */ @@ -5319,45 +5443,47 @@ main(int argc, char **argv) /* --sampling-rate may be used only with -l */ if (sample_rate > 0.0 && !use_log) { - fprintf(stderr, "log sampling (--sampling-rate) is allowed only when logging transactions (-l)\n"); - exit(1); + pgbench_error(ERROR, + "log sampling (--sampling-rate) is allowed only when logging transactions (-l)\n"); } /* --sampling-rate may not be used with --aggregate-interval */ if (sample_rate > 0.0 && agg_interval > 0) { - fprintf(stderr, "log sampling (--sampling-rate) and aggregation (--aggregate-interval) cannot be used at the same time\n"); - exit(1); + pgbench_error(ERROR, + "log sampling (--sampling-rate) and aggregation (--aggregate-interval) cannot be used at the same time\n"); } if (agg_interval > 0 && !use_log) { - fprintf(stderr, "log aggregation is allowed only when actually logging transactions\n"); - exit(1); + pgbench_error(ERROR, + "log aggregation is allowed only when actually logging transactions\n"); } if (!use_log && logfile_prefix) { - fprintf(stderr, "log file prefix (--log-prefix) is allowed only when logging transactions (-l)\n"); - exit(1); + pgbench_error(ERROR, + "log file prefix (--log-prefix) is allowed only when logging transactions (-l)\n"); } if (duration > 0 && agg_interval > duration) { - fprintf(stderr, "number of seconds for aggregation (%d) must not be higher than test duration (%d)\n", agg_interval, duration); - exit(1); + pgbench_error(ERROR, + "number of seconds for aggregation (%d) must not be higher than test duration (%d)\n", + agg_interval, duration); } if (duration > 0 && agg_interval > 0 && duration % agg_interval != 0) { - fprintf(stderr, "duration (%d) must be a multiple of aggregation interval (%d)\n", duration, agg_interval); - exit(1); + pgbench_error(ERROR, + "duration (%d) must be a multiple of aggregation interval (%d)\n", + duration, agg_interval); } if (progress_timestamp && progress == 0) { - fprintf(stderr, "--progress-timestamp is allowed only under --progress\n"); - exit(1); + pgbench_error(ERROR, + "--progress-timestamp is allowed only under --progress\n"); } /* @@ -5383,15 +5509,12 @@ main(int argc, char **argv) if (var->value.type != PGBT_NO_VALUE) { - if (!putVariableValue(&state[i], "startup", - var->name, &var->value)) - exit(1); + putVariableValue(&state[i], "startup", + var->name, &var->value, false); } else { - if (!putVariable(&state[i], "startup", - var->name, var->svalue)) - exit(1); + putVariable(&state[i], "startup", var->name, var->svalue); } } } @@ -5404,7 +5527,7 @@ main(int argc, char **argv) initRandomState(&state[i].random_state); } - if (debug) + if (DEBUG >= log_min_messages) { if (duration <= 0) printf("pghost: %s pgport: %s nclients: %d nxacts: %d dbName: %s\n", @@ -5421,9 +5544,11 @@ main(int argc, char **argv) if (PQstatus(con) == CONNECTION_BAD) { - fprintf(stderr, "connection to database \"%s\" failed\n", dbName); - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); + /* we are sure that the function PQerrorMessage is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "connection to database \"%s\" failed\n%s", + dbName, PQerrorMessage(con)); } if (internal_script_used) @@ -5436,29 +5561,44 @@ main(int argc, char **argv) if (PQresultStatus(res) != PGRES_TUPLES_OK) { char *sqlState = PQresultErrorField(res, PG_DIAG_SQLSTATE); + PQExpBufferData errmsg_buf; - fprintf(stderr, "%s", PQerrorMessage(con)); + /* + * we are sure that the allocated memory for the message is always + * used + */ + Assert(LOG >= log_min_messages); + + initPQExpBuffer(&errmsg_buf); + printfPQExpBuffer(&errmsg_buf, "%s", PQerrorMessage(con)); if (sqlState && strcmp(sqlState, ERRCODE_UNDEFINED_TABLE) == 0) { - fprintf(stderr, "Perhaps you need to do initialization (\"pgbench -i\") in database \"%s\"\n", PQdb(con)); + appendPQExpBuffer(&errmsg_buf, + "Perhaps you need to do initialization (\"pgbench -i\") in database \"%s\"\n", + PQdb(con)); } + pgbench_error(LOG, "%s", errmsg_buf.data); + termPQExpBuffer(&errmsg_buf); exit(1); } scale = atoi(PQgetvalue(res, 0, 0)); if (scale < 0) { - fprintf(stderr, "invalid count(*) from pgbench_branches: \"%s\"\n", - PQgetvalue(res, 0, 0)); - exit(1); + /* we are sure that the function PQgetvalue is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, + "invalid count(*) from pgbench_branches: \"%s\"\n", + PQgetvalue(res, 0, 0)); } PQclear(res); /* warn if we override user-given -s switch */ if (scale_given) - fprintf(stderr, - "scale option ignored, using count from pgbench_branches table (%d)\n", - scale); + pgbench_error(LOG, + "scale option ignored, using count from pgbench_branches table (%d)\n", + scale); } /* @@ -5468,10 +5608,7 @@ main(int argc, char **argv) if (lookupVariable(&state[0], "scale") == NULL) { for (i = 0; i < nclients; i++) - { - if (!putVariableInt(&state[i], "startup", "scale", scale)) - exit(1); - } + putVariableInt(&state[i], "startup", "scale", scale, false); } /* @@ -5481,8 +5618,7 @@ main(int argc, char **argv) if (lookupVariable(&state[0], "client_id") == NULL) { for (i = 0; i < nclients; i++) - if (!putVariableInt(&state[i], "startup", "client_id", i)) - exit(1); + putVariableInt(&state[i], "startup", "client_id", i, false); } /* set default seed for hash functions */ @@ -5494,31 +5630,35 @@ main(int argc, char **argv) (uint64) (random() & 0xFFFF); for (i = 0; i < nclients; i++) - if (!putVariableInt(&state[i], "startup", "default_seed", (int64) seed)) - exit(1); + { + putVariableInt(&state[i], "startup", "default_seed", (int64) seed, + false); + } } /* set random seed unless overwritten */ if (lookupVariable(&state[0], "random_seed") == NULL) { for (i = 0; i < nclients; i++) - if (!putVariableInt(&state[i], "startup", "random_seed", random_seed)) - exit(1); + { + putVariableInt(&state[i], "startup", "random_seed", random_seed, + false); + } } if (!is_no_vacuum) { - fprintf(stderr, "starting vacuum..."); + pgbench_error(LOG, "starting vacuum..."); tryExecuteStatement(con, "vacuum pgbench_branches"); tryExecuteStatement(con, "vacuum pgbench_tellers"); tryExecuteStatement(con, "truncate pgbench_history"); - fprintf(stderr, "end.\n"); + pgbench_error(LOG, "end.\n"); if (do_vacuum_accounts) { - fprintf(stderr, "starting vacuum pgbench_accounts..."); + pgbench_error(LOG, "starting vacuum pgbench_accounts..."); tryExecuteStatement(con, "vacuum analyze pgbench_accounts"); - fprintf(stderr, "end.\n"); + pgbench_error(LOG, "end.\n"); } } PQfinish(con); @@ -5578,8 +5718,11 @@ main(int argc, char **argv) if (err != 0 || thread->thread == INVALID_THREAD) { - fprintf(stderr, "could not create thread: %s\n", strerror(err)); - exit(1); + /* we are sure that the function strerror is always called */ + Assert(ERROR >= log_min_messages); + + pgbench_error(ERROR, "could not create thread: %s\n", + strerror(err)); } } else @@ -5688,8 +5831,11 @@ threadRun(void *arg) if (thread->logfile == NULL) { - fprintf(stderr, "could not open logfile \"%s\": %s\n", - logpath, strerror(errno)); + /* we are sure that the function strerror is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "could not open logfile \"%s\": %s\n", + logpath, strerror(errno)); goto done; } } @@ -5767,8 +5913,14 @@ threadRun(void *arg) if (sock < 0) { - fprintf(stderr, "invalid socket: %s", - PQerrorMessage(st->con)); + /* + * We are sure that the function PQerrorMessage is always + * called. + */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "invalid socket: %s", + PQerrorMessage(st->con)); goto done; } @@ -5844,7 +5996,11 @@ threadRun(void *arg) continue; } /* must be something wrong */ - fprintf(stderr, "select() failed: %s\n", strerror(errno)); + + /* we are sure that the function strerror is always called */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "select() failed: %s\n", strerror(errno)); goto done; } } @@ -5868,8 +6024,14 @@ threadRun(void *arg) if (sock < 0) { - fprintf(stderr, "invalid socket: %s", - PQerrorMessage(st->con)); + /* + * We are sure that the function PQerrorMessage is always + * called. + */ + Assert(LOG >= log_min_messages); + + pgbench_error(LOG, "invalid socket: %s", + PQerrorMessage(st->con)); goto done; } @@ -5911,6 +6073,7 @@ threadRun(void *arg) lag, stdev; char tbuf[315]; + PQExpBufferData progress_buf; /* * Add up the statistics of all threads. @@ -5968,18 +6131,29 @@ threadRun(void *arg) snprintf(tbuf, sizeof(tbuf), "%.1f s", total_run); } - fprintf(stderr, - "progress: %s, %.1f tps, lat %.3f ms stddev %.3f", - tbuf, tps, latency, stdev); + /* + * We are sure that the allocated memory for the message is + * always used. + */ + Assert(LOG >= log_min_messages); + + initPQExpBuffer(&progress_buf); + printfPQExpBuffer(&progress_buf, + "progress: %s, %.1f tps, lat %.3f ms stddev %.3f", + tbuf, tps, latency, stdev); if (throttle_delay) { - fprintf(stderr, ", lag %.3f ms", lag); + appendPQExpBuffer(&progress_buf, ", lag %.3f ms", lag); if (latency_limit) - fprintf(stderr, ", " INT64_FORMAT " skipped", - cur.skipped - last.skipped); + appendPQExpBuffer(&progress_buf, + ", " INT64_FORMAT " skipped", + cur.skipped - last.skipped); } - fprintf(stderr, "\n"); + appendPQExpBufferChar(&progress_buf, '\n'); + + pgbench_error(LOG, "%s", progress_buf.data); + termPQExpBuffer(&progress_buf); last = cur; last_report = now; @@ -6063,10 +6237,7 @@ setalarm(int seconds) !CreateTimerQueueTimer(&timer, queue, win32_timer_callback, NULL, seconds * 1000, 0, WT_EXECUTEINTIMERTHREAD | WT_EXECUTEONLYONCE)) - { - fprintf(stderr, "failed to set timer\n"); - exit(1); - } + pgbench_error(ERROR, "failed to set timer\n"); } /* partial pthread implementation for Windows */ @@ -6136,3 +6307,26 @@ pthread_join(pthread_t th, void **thread_return) } #endif /* WIN32 */ + +static void +pgbench_error(ErrorLevel elevel, const char *fmt,...) +{ + va_list ap; + + /* Determine whether message is enabled for log output */ + if (elevel < log_min_messages) + return; + + if (!fmt || !fmt[0]) + { + /* internal error which should never occur */ + pgbench_error(ERROR, "empty error message cannot be reported\n"); + } + + va_start(ap, fmt); + vfprintf(stderr, _(fmt), ap); + va_end(ap); + + if (elevel >= ERROR) + exit(1); +} diff --git a/src/interfaces/libpq/exports.txt b/src/interfaces/libpq/exports.txt index d6a38d0..e983abc 100644 --- a/src/interfaces/libpq/exports.txt +++ b/src/interfaces/libpq/exports.txt @@ -172,3 +172,4 @@ PQsslAttribute 169 PQsetErrorContextVisibility 170 PQresultVerboseErrorMessage 171 PQencryptPasswordConn 172 +appendPQExpBufferVA 173 diff --git a/src/interfaces/libpq/pqexpbuffer.c b/src/interfaces/libpq/pqexpbuffer.c index 86b16e6..3db2d4c 100644 --- a/src/interfaces/libpq/pqexpbuffer.c +++ b/src/interfaces/libpq/pqexpbuffer.c @@ -37,8 +37,6 @@ /* All "broken" PQExpBuffers point to this string. */ static const char oom_buffer[1] = ""; -static bool appendPQExpBufferVA(PQExpBuffer str, const char *fmt, va_list args) pg_attribute_printf(2, 0); - /* * markPQExpBufferBroken @@ -282,7 +280,7 @@ appendPQExpBuffer(PQExpBuffer str, const char *fmt,...) * Attempt to format data and append it to str. Returns true if done * (either successful or hard failure), false if need to retry. */ -static bool +bool appendPQExpBufferVA(PQExpBuffer str, const char *fmt, va_list args) { size_t avail; diff --git a/src/interfaces/libpq/pqexpbuffer.h b/src/interfaces/libpq/pqexpbuffer.h index 771602a..b70b868 100644 --- a/src/interfaces/libpq/pqexpbuffer.h +++ b/src/interfaces/libpq/pqexpbuffer.h @@ -158,6 +158,14 @@ extern void printfPQExpBuffer(PQExpBuffer str, const char *fmt,...) pg_attribute extern void appendPQExpBuffer(PQExpBuffer str, const char *fmt,...) pg_attribute_printf(2, 3); /*------------------------ + * appendPQExpBufferVA + * Shared guts of printfPQExpBuffer/appendPQExpBuffer. + * Attempt to format data and append it to str. Returns true if done + * (either successful or hard failure), false if need to retry. + */ +extern bool appendPQExpBufferVA(PQExpBuffer str, const char *fmt, va_list args) pg_attribute_printf(2, 0); + +/*------------------------ * appendPQExpBufferStr * Append the given string to a PQExpBuffer, allocating more space * if necessary. -- 2.7.4