From 3721e6b2a98dd68014521269d4d6016937fa4e6d Mon Sep 17 00:00:00 2001 From: Marina Polyakova Date: Mon, 21 May 2018 14:31:53 +0300 Subject: [PATCH v9] Pgbench errors: use the ereport() macro to report debug/log/error messages 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. If possible, use the local ErorrData structure during the errstart()/errmsg()/errfinish() calls. Otherwise use a static variable protected by a mutex if necessary. To do all of this export the function appendPQExpBufferVA from libpq. --- src/bin/pgbench/pgbench.c | 1011 ++++++++++++++++++++++++------------ src/interfaces/libpq/exports.txt | 1 + src/interfaces/libpq/pqexpbuffer.c | 4 +- src/interfaces/libpq/pqexpbuffer.h | 8 + 4 files changed, 692 insertions(+), 332 deletions(-) diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 254f125..d100cee 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -526,6 +526,93 @@ static const BuiltinScript builtin_script[] = } }; +typedef enum ErrorLevel +{ + /* + * To report throttling, executed/sent/received commands etc. + */ + ELEVEL_DEBUG, + + /* + * To report the error/log messages and/or PGBENCH_DEBUG. + */ + ELEVEL_LOG, + + /* + * To report the error messages of the main program and to exit immediately. + */ + ELEVEL_FATAL +} ErrorLevel; + +typedef struct ErrorData +{ + ErrorLevel elevel; + PQExpBufferData message; +} ErrorData; + +typedef ErrorData *Error; + +#if defined(ENABLE_THREAD_SAFETY) && defined(HAVE__VA_ARGS) +/* use the local ErrorData in ereport */ +#define LOCAL_ERROR_DATA() ErrorData edata; + +#define errstart(elevel) errstartImpl(&edata, elevel) +#define errmsg(...) errmsgImpl(&edata, __VA_ARGS__) +#define errfinish(...) errfinishImpl(&edata, __VA_ARGS__) +#else /* !(ENABLE_THREAD_SAFETY && HAVE__VA_ARGS) */ +/* use the global ErrorData in ereport... */ +#define LOCAL_ERROR_DATA() +static ErrorData edata; +static Error error = &edata; + +/* ...and protect it with a mutex if necessary */ +#ifdef ENABLE_THREAD_SAFETY +static pthread_mutex_t error_mutex = PTHREAD_MUTEX_INITIALIZER; +#endif /* ENABLE_THREAD_SAFETY */ + +#define errstart errstartImpl +#define errmsg errmsgImpl +#define errfinish errfinishImpl +#endif /* ENABLE_THREAD_SAFETY && HAVE__VA_ARGS */ + +/* + * Error reporting API: to be used in this way: + * ereport(ELEVEL_LOG, + * (errmsg("connection to database \"%s\" failed\n", dbName), + * ... other errxxx() fields as needed ...)); + * + * The error level is required, and so is a primary error message. All else is + * optional. + * + * If elevel >= ELEVEL_FATAL, the call will not return; we try to inform the + * compiler of that via abort(). However, no useful optimization effect is + * obtained unless the compiler sees elevel as a compile-time constant, else + * we're just adding code bloat. So, if __builtin_constant_p is available, use + * that to cause the second if() to vanish completely for non-constant cases. We + * avoid using a local variable because it's not necessary and prevents gcc from + * making the unreachability deduction at optlevel -O0. + */ +#ifdef HAVE__BUILTIN_CONSTANT_P +#define ereport(elevel, rest) \ + do { \ + LOCAL_ERROR_DATA() \ + if (errstart(elevel)) \ + errfinish rest; \ + if (__builtin_constant_p(elevel) && (elevel) >= ELEVEL_FATAL) \ + abort(); \ + } while(0) +#else /* !HAVE__BUILTIN_CONSTANT_P */ +#define ereport(elevel, rest) \ + do { \ + const int elevel_ = (elevel); \ + LOCAL_ERROR_DATA() \ + if (errstart(elevel_)) \ + errfinish rest; \ + if (elevel_ >= ELEVEL_FATAL) \ + abort(); \ + } while(0) +#endif /* HAVE__BUILTIN_CONSTANT_P */ + /* Function prototypes */ static void setNullValue(PgBenchValue *pv); @@ -543,6 +630,17 @@ static void *threadRun(void *arg); static void setalarm(int seconds); static void finishCon(CState *st); +#if defined(ENABLE_THREAD_SAFETY) && defined(HAVE__VA_ARGS) +static bool errstartImpl(Error error, ErrorLevel elevel); +static int errmsgImpl(Error error, + const char *fmt,...) pg_attribute_printf(2, 3); +static void errfinishImpl(Error error, int dummy,...); +#else /* !(ENABLE_THREAD_SAFETY && HAVE__VA_ARGS) */ +static bool errstartImpl(ErrorLevel elevel); +static int errmsgImpl(const char *fmt,...) pg_attribute_printf(1, 2); +static void errfinishImpl(int dummy,...); +#endif /* ENABLE_THREAD_SAFETY && HAVE__VA_ARGS */ + /* callback functions for our flex lexer */ static const PsqlScanCallbacks pgbench_callbacks = { @@ -685,7 +783,10 @@ strtoint64(const char *str) /* require at least one digit */ if (!isdigit((unsigned char) *ptr)) - fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str); + { + ereport(ELEVEL_LOG, + (errmsg("invalid input syntax for integer: \"%s\"\n", str))); + } /* process digits */ while (*ptr && isdigit((unsigned char) *ptr)) @@ -693,7 +794,11 @@ 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); + { + ereport(ELEVEL_LOG, + (errmsg("value \"%s\" is out of range for type bigint\n", + str))); + } result = tmp; } @@ -704,7 +809,10 @@ gotdigits: ptr++; if (*ptr != '\0') - fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str); + { + ereport(ELEVEL_LOG, + (errmsg("invalid input syntax for integer: \"%s\"\n", str))); + } return ((sign < 0) ? -result : result); } @@ -1091,10 +1199,7 @@ executeStatement(PGconn *con, const char *sql) res = PQexec(con, sql); if (PQresultStatus(res) != PGRES_COMMAND_OK) - { - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); - } + ereport(ELEVEL_FATAL, (errmsg("%s", PQerrorMessage(con)))); PQclear(res); } @@ -1107,8 +1212,9 @@ 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"); + ereport(ELEVEL_LOG, + (errmsg("%s(ignoring this error and continuing anyway)\n", + PQerrorMessage(con)))); } PQclear(res); } @@ -1154,8 +1260,8 @@ doConnect(void) if (!conn) { - fprintf(stderr, "connection to database \"%s\" failed\n", - dbName); + ereport(ELEVEL_LOG, + (errmsg("connection to database \"%s\" failed\n", dbName))); return NULL; } @@ -1173,8 +1279,9 @@ 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)); + ereport(ELEVEL_LOG, + (errmsg("connection to database \"%s\" failed:\n%s", + dbName, PQerrorMessage(conn)))); PQfinish(conn); return NULL; } @@ -1312,9 +1419,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); + ereport(ELEVEL_LOG, + (errmsg("malformed variable \"%s\" value: \"%s\"\n", + var->name, var->svalue))); return false; } setDoubleValue(&var->value, dv); @@ -1359,10 +1466,12 @@ 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(Variables *variables, const char *context, char *name) +lookupCreateVariable(Variables *variables, const char *context, char *name, + bool client) { Variable *var; @@ -1377,8 +1486,13 @@ lookupCreateVariable(Variables *variables, 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. + */ + ereport(client ? ELEVEL_LOG : ELEVEL_FATAL, + (errmsg("%s: invalid variable name: \"%s\"\n", + context, name))); return NULL; } @@ -1406,17 +1520,15 @@ lookupCreateVariable(Variables *variables, 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(Variables *variables, const char *context, char *name, const char *value) { Variable *var; char *val; - var = lookupCreateVariable(variables, context, name); - if (!var) - return false; + var = lookupCreateVariable(variables, context, name, false); /* dup then free, in case value is pointing at this variable */ val = pg_strdup(value); @@ -1425,19 +1537,20 @@ putVariable(Variables *variables, const char *context, char *name, 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(Variables *variables, const char *context, char *name, - const PgBenchValue *value) + const PgBenchValue *value, bool client) { Variable *var; - var = lookupCreateVariable(variables, context, name); + var = lookupCreateVariable(variables, context, name, client); if (!var) return false; @@ -1449,16 +1562,19 @@ putVariableValue(Variables *variables, 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(Variables *variables, const char *context, char *name, - int64 value) + int64 value, bool client) { PgBenchValue val; setIntValue(&val, value); - return putVariableValue(variables, context, name, &val); + return putVariableValue(variables, context, name, &val, client); } /* @@ -1590,7 +1706,8 @@ coerceToBool(PgBenchValue *pval, bool *bval) } else /* NULL, INT or DOUBLE */ { - fprintf(stderr, "cannot coerce %s to boolean\n", valueTypeName(pval)); + ereport(ELEVEL_LOG, + (errmsg("cannot coerce %s to boolean\n", valueTypeName(pval)))); *bval = false; /* suppress uninitialized-variable warnings */ return false; } @@ -1635,7 +1752,8 @@ coerceToInt(PgBenchValue *pval, int64 *ival) if (dval < PG_INT64_MIN || PG_INT64_MAX < dval) { - fprintf(stderr, "double to int overflow for %f\n", dval); + ereport(ELEVEL_LOG, + (errmsg("double to int overflow for %f\n", dval))); return false; } *ival = (int64) dval; @@ -1643,7 +1761,8 @@ coerceToInt(PgBenchValue *pval, int64 *ival) } else /* BOOLEAN or NULL */ { - fprintf(stderr, "cannot coerce %s to int\n", valueTypeName(pval)); + ereport(ELEVEL_LOG, + (errmsg("cannot coerce %s to int\n", valueTypeName(pval)))); return false; } } @@ -1664,7 +1783,8 @@ coerceToDouble(PgBenchValue *pval, double *dval) } else /* BOOLEAN or NULL */ { - fprintf(stderr, "cannot coerce %s to double\n", valueTypeName(pval)); + ereport(ELEVEL_LOG, + (errmsg("cannot coerce %s to double\n", valueTypeName(pval)))); return false; } } @@ -1845,8 +1965,9 @@ evalStandardFunc(TState *thread, CState *st, if (l != NULL) { - fprintf(stderr, - "too many function arguments, maximum is %d\n", MAX_FARGS); + ereport(ELEVEL_LOG, + (errmsg("too many function arguments, maximum is %d\n", + MAX_FARGS))); return false; } @@ -1969,7 +2090,8 @@ evalStandardFunc(TState *thread, CState *st, case PGBENCH_MOD: if (ri == 0) { - fprintf(stderr, "division by zero\n"); + ereport(ELEVEL_LOG, + (errmsg("division by zero\n"))); return false; } /* special handling of -1 divisor */ @@ -1980,7 +2102,9 @@ evalStandardFunc(TState *thread, CState *st, /* overflow check (needed for INT64_MIN) */ if (li == PG_INT64_MIN) { - fprintf(stderr, "bigint out of range\n"); + ereport( + ELEVEL_LOG, + (errmsg("bigint out of range\n"))); return false; } else @@ -2081,22 +2205,42 @@ evalStandardFunc(TState *thread, CState *st, case PGBENCH_DEBUG: { PgBenchValue *varg = &vargs[0]; + PQExpBufferData errormsg_buf; Assert(nargs == 1); - fprintf(stderr, "debug(script=%d,command=%d): ", - st->use_file, st->command + 1); + initPQExpBuffer(&errormsg_buf); + printfPQExpBuffer(&errormsg_buf, + "debug(script=%d,command=%d): ", + st->use_file, st->command + 1); if (varg->type == PGBT_NULL) - fprintf(stderr, "null\n"); + { + appendPQExpBuffer(&errormsg_buf, "null\n"); + } else if (varg->type == PGBT_BOOLEAN) - fprintf(stderr, "boolean %s\n", varg->u.bval ? "true" : "false"); + { + appendPQExpBuffer(&errormsg_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(&errormsg_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(&errormsg_buf, + "double %.*g\n", DBL_DIG, varg->u.dval); + } else /* internal error, unexpected type */ + { Assert(0); + } + + ereport(ELEVEL_LOG, (errmsg("%s", errormsg_buf.data))); + termPQExpBuffer(&errormsg_buf); *retval = *varg; @@ -2220,13 +2364,15 @@ evalStandardFunc(TState *thread, CState *st, /* check random range */ if (imin > imax) { - fprintf(stderr, "empty range given to random\n"); + ereport(ELEVEL_LOG, + (errmsg("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"); + ereport(ELEVEL_LOG, + (errmsg("random range is too large\n"))); return false; } @@ -2248,9 +2394,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); + ereport(ELEVEL_LOG, + (errmsg("gaussian parameter must be at least %f (not %f)\n", + MIN_GAUSSIAN_PARAM, param))); return false; } @@ -2262,9 +2408,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); + ereport(ELEVEL_LOG, + (errmsg("zipfian parameter must be in range (0, 1) U (1, %d] (got %f)\n", + MAX_ZIPFIAN_PARAM, param))); return false; } setIntValue(retval, @@ -2275,9 +2421,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0) { - fprintf(stderr, - "exponential parameter must be greater than zero" - " (got %f)\n", param); + ereport(ELEVEL_LOG, + (errmsg("exponential parameter must be greater than zero (got %f)\n", + param))); return false; } @@ -2388,8 +2534,9 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval if ((var = lookupVariable(&st->variables, expr->u.variable.varname)) == NULL) { - fprintf(stderr, "undefined variable \"%s\"\n", - expr->u.variable.varname); + ereport(ELEVEL_LOG, + (errmsg("undefined variable \"%s\"\n", + expr->u.variable.varname))); return false; } @@ -2408,9 +2555,9 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval default: /* internal error which should never occur */ - fprintf(stderr, "unexpected enode type in evaluation: %d\n", - expr->etype); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("unexpected enode type in evaluation: %d\n", + expr->etype))); } } @@ -2483,15 +2630,17 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) } else if ((arg = getVariable(variables, argv[i] + 1)) == NULL) { - fprintf(stderr, "%s: undefined variable \"%s\"\n", - argv[0], argv[i]); + ereport(ELEVEL_LOG, + (errmsg("%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]); + ereport(ELEVEL_LOG, + (errmsg("%s: shell command is too long\n", argv[0]))); return false; } @@ -2509,7 +2658,11 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) if (system(command)) { if (!timer_exceeded) - fprintf(stderr, "%s: could not launch shell command\n", argv[0]); + { + ereport(ELEVEL_LOG, + (errmsg("%s: could not launch shell command\n", + argv[0]))); + } return false; } return true; @@ -2518,19 +2671,25 @@ runShellCommand(Variables *variables, 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]); + ereport(ELEVEL_LOG, + (errmsg("%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]); + { + ereport(ELEVEL_LOG, + (errmsg("%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]); + ereport(ELEVEL_LOG, + (errmsg("%s: could not close shell command\n", argv[0]))); return false; } @@ -2540,11 +2699,12 @@ runShellCommand(Variables *variables, 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); + ereport(ELEVEL_LOG, + (errmsg("%s: shell command must return an integer (not \"%s\")\n", + argv[0], res))); return false; } - if (!putVariableInt(variables, "setshell", variable, retval)) + if (!putVariableInt(variables, "setshell", variable, retval, true)) return false; #ifdef DEBUG @@ -2563,9 +2723,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); + ereport(ELEVEL_LOG, + (errmsg("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. */ @@ -2600,8 +2760,7 @@ sendCommand(CState *st, Command *command) sql = pg_strdup(command->argv[0]); sql = assignVariables(&st->variables, sql); - if (debug) - fprintf(stderr, "client %d sending %s\n", st->id, sql); + ereport(ELEVEL_DEBUG, (errmsg("client %d sending %s\n", st->id, sql))); r = PQsendQuery(st->con, sql); free(sql); } @@ -2612,8 +2771,7 @@ sendCommand(CState *st, Command *command) getQueryParams(&st->variables, command, params); - if (debug) - fprintf(stderr, "client %d sending %s\n", st->id, sql); + ereport(ELEVEL_DEBUG, (errmsg("client %d sending %s\n", st->id, sql))); r = PQsendQueryParams(st->con, sql, command->argc - 1, NULL, params, NULL, NULL, 0); } @@ -2638,7 +2796,10 @@ 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)); + { + ereport(ELEVEL_LOG, + (errmsg("%s", PQerrorMessage(st->con)))); + } PQclear(res); } st->prepared[st->use_file] = true; @@ -2647,8 +2808,7 @@ sendCommand(CState *st, Command *command) getQueryParams(&st->variables, command, params); preparedStatementName(name, st->use_file, st->command); - if (debug) - fprintf(stderr, "client %d sending %s\n", st->id, name); + ereport(ELEVEL_DEBUG, (errmsg("client %d sending %s\n", st->id, name))); r = PQsendQueryPrepared(st->con, name, command->argc - 1, params, NULL, NULL, 0); } @@ -2657,9 +2817,9 @@ sendCommand(CState *st, Command *command) if (r == 0) { - if (debug) - fprintf(stderr, "client %d could not send %s\n", - st->id, command->argv[0]); + ereport(ELEVEL_DEBUG, + (errmsg("client %d could not send %s\n", + st->id, command->argv[0]))); st->ecnt++; return false; } @@ -2681,8 +2841,9 @@ evaluateSleep(Variables *variables, int argc, char **argv, int *usecs) { if ((var = getVariable(variables, argv[1] + 1)) == NULL) { - fprintf(stderr, "%s: undefined variable \"%s\"\n", - argv[0], argv[1]); + ereport(ELEVEL_LOG, + (errmsg("%s: undefined variable \"%s\"\n", + argv[0], argv[1]))); return false; } usec = atoi(var); @@ -2745,9 +2906,9 @@ 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); + ereport(ELEVEL_DEBUG, + (errmsg("client %d executing script \"%s\"\n", + st->id, sql_script[st->use_file].desc))); if (throttle_delay > 0) st->state = CSTATE_START_THROTTLE; @@ -2820,9 +2981,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); + ereport(ELEVEL_DEBUG, + (errmsg("client %d throttling " INT64_FORMAT " us\n", + st->id, wait))); break; /* @@ -2854,8 +3015,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); + ereport(ELEVEL_LOG, + (errmsg("client %d aborted while establishing connection\n", + st->id))); st->state = CSTATE_ABORTED; break; } @@ -2932,14 +3094,16 @@ doCustom(TState *thread, CState *st, StatsData *agg) int argc = command->argc, i; char **argv = command->argv; + PQExpBufferData errmsg_buf; - if (debug) - { - fprintf(stderr, "client %d executing \\%s", st->id, argv[0]); - for (i = 1; i < argc; i++) - fprintf(stderr, " %s", argv[i]); - fprintf(stderr, "\n"); - } + initPQExpBuffer(&errmsg_buf); + printfPQExpBuffer(&errmsg_buf, "client %d executing \\%s", + st->id, argv[0]); + for (i = 1; i < argc; i++) + appendPQExpBuffer(&errmsg_buf, " %s", argv[i]); + appendPQExpBufferChar(&errmsg_buf, '\n'); + ereport(ELEVEL_DEBUG, (errmsg("%s", errmsg_buf.data))); + termPQExpBuffer(&errmsg_buf); if (command->meta == META_SLEEP) { @@ -2994,7 +3158,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (command->meta == META_SET) { if (!putVariableValue(&st->variables, argv[0], - argv[1], &result)) + argv[1], &result, true)) { commandFailed(st, "set", "assignment of meta-command failed"); st->state = CSTATE_ABORTED; @@ -3197,8 +3361,8 @@ 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); + ereport(ELEVEL_DEBUG, + (errmsg("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 +3448,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); + ereport(ELEVEL_FATAL, + (errmsg("end of script reached within a conditional, missing \\endif\n"))); } if (is_connect) @@ -3484,7 +3648,7 @@ disconnect_all(CState *state, int length) static void initDropTables(PGconn *con) { - fprintf(stderr, "dropping old tables...\n"); + ereport(ELEVEL_LOG, (errmsg("dropping old tables...\n"))); /* * We drop all the tables in one command, so that whether there are @@ -3559,7 +3723,7 @@ initCreateTables(PGconn *con) }; int i; - fprintf(stderr, "creating tables...\n"); + ereport(ELEVEL_LOG, (errmsg("creating tables...\n"))); for (i = 0; i < lengthof(DDLs); i++) { @@ -3612,7 +3776,7 @@ initGenerateData(PGconn *con) remaining_sec; int log_interval = 1; - fprintf(stderr, "generating data...\n"); + ereport(ELEVEL_LOG, (errmsg("generating data...\n"))); /* * we do all of this in one transaction to enable the backend's @@ -3657,10 +3821,7 @@ initGenerateData(PGconn *con) */ res = PQexec(con, "copy pgbench_accounts from stdin"); if (PQresultStatus(res) != PGRES_COPY_IN) - { - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); - } + ereport(ELEVEL_FATAL, (errmsg("%s", PQerrorMessage(con)))); PQclear(res); INSTR_TIME_SET_CURRENT(start); @@ -3674,10 +3835,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); - } + ereport(ELEVEL_FATAL, (errmsg("PQputline failed\n"))); /* * If we want to stick with the original logging, print a message each @@ -3691,10 +3849,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); + ereport(ELEVEL_LOG, + (errmsg(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 +3868,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); + ereport(ELEVEL_LOG, + (errmsg(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 +3882,9 @@ initGenerateData(PGconn *con) } if (PQputline(con, "\\.\n")) - { - fprintf(stderr, "very last PQputline failed\n"); - exit(1); - } + ereport(ELEVEL_FATAL, (errmsg("very last PQputline failed\n"))); if (PQendcopy(con)) - { - fprintf(stderr, "PQendcopy failed\n"); - exit(1); - } + ereport(ELEVEL_FATAL, (errmsg("PQendcopy failed\n"))); executeStatement(con, "commit"); } @@ -3738,7 +3895,7 @@ initGenerateData(PGconn *con) static void initVacuum(PGconn *con) { - fprintf(stderr, "vacuuming...\n"); + ereport(ELEVEL_LOG, (errmsg("vacuuming...\n"))); executeStatement(con, "vacuum analyze pgbench_branches"); executeStatement(con, "vacuum analyze pgbench_tellers"); executeStatement(con, "vacuum analyze pgbench_accounts"); @@ -3758,7 +3915,7 @@ initCreatePKeys(PGconn *con) }; int i; - fprintf(stderr, "creating primary keys...\n"); + ereport(ELEVEL_LOG, (errmsg("creating primary keys...\n"))); for (i = 0; i < lengthof(DDLINDEXes); i++) { char buffer[256]; @@ -3795,7 +3952,7 @@ initCreateFKeys(PGconn *con) }; int i; - fprintf(stderr, "creating foreign keys...\n"); + ereport(ELEVEL_LOG, (errmsg("creating foreign keys...\n"))); for (i = 0; i < lengthof(DDLKEYs); i++) { executeStatement(con, DDLKEYs[i]); @@ -3815,19 +3972,16 @@ checkInitSteps(const char *initialize_steps) const char *step; if (initialize_steps[0] == '\0') - { - fprintf(stderr, "no initialization steps specified\n"); - exit(1); - } + ereport(ELEVEL_FATAL, (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("unrecognized initialization step \"%c\"\n" + "allowed steps are: \"d\", \"t\", \"g\", \"v\", \"p\", \"f\"\n", + *step))); } } } @@ -3869,14 +4023,15 @@ runInitSteps(const char *initialize_steps) case ' ': break; /* ignore */ default: - fprintf(stderr, "unrecognized initialization step \"%c\"\n", - *step); + ereport(ELEVEL_LOG, + (errmsg("unrecognized initialization step \"%c\"\n", + *step))); PQfinish(con); exit(1); } } - fprintf(stderr, "done.\n"); + ereport(ELEVEL_LOG, (errmsg("done.\n"))); PQfinish(con); } @@ -3914,8 +4069,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]); + ereport(ELEVEL_LOG, + (errmsg("statement has too many arguments (maximum is %d): %s\n", + MAX_ARGS - 1, cmd->argv[0]))); pg_free(name); return false; } @@ -3939,11 +4095,22 @@ static void pgbench_error(const char *fmt,...) { va_list ap; + PQExpBufferData errmsg_buf; + bool done; 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); + + ereport(ELEVEL_LOG, (errmsg("%s", errmsg_buf.data))); + termPQExpBuffer(&errmsg_buf); } /* @@ -3963,26 +4130,32 @@ 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; + + 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"); } } + + ereport(ELEVEL_LOG, (errmsg("%s", errmsg_buf.data))); + termPQExpBuffer(&errmsg_buf); exit(1); } @@ -4232,10 +4405,9 @@ 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); + ereport(ELEVEL_FATAL, + (errmsg("condition error in script \"%s\" command %d: %s\n", + desc, cmdn, msg))); } /* @@ -4434,18 +4606,18 @@ 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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("could not read file \"%s\": %s\n", + filename, strerror(errno)))); } if (fd != stdin) @@ -4468,11 +4640,16 @@ static void listAvailableScripts(void) { int i; + PQExpBufferData errmsg_buf; - fprintf(stderr, "Available builtin scripts:\n"); + 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'); + + ereport(ELEVEL_LOG, (errmsg("%s", errmsg_buf.data))); + termPQExpBuffer(&errmsg_buf); } /* return builtin script "name" if unambiguous, fails if not found */ @@ -4499,10 +4676,16 @@ findBuiltin(const char *name) /* error cases */ if (found == 0) - fprintf(stderr, "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); + { + ereport(ELEVEL_LOG, + (errmsg("no builtin script found for name \"%s\"\n", name))); + } + else + { /* found > 1 */ + ereport(ELEVEL_LOG, + (errmsg("ambiguous builtin name: %d builtin scripts found for prefix \"%s\"\n", + found, name))); + } listAvailableScripts(); exit(1); @@ -4535,15 +4718,14 @@ parseScriptWeight(const char *option, char **script) wtmp = strtol(sep + 1, &badp, 10); if (errno != 0 || badp == sep + 1 || *badp != '\0') { - fprintf(stderr, "invalid weight specification: %s\n", sep); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("weight specification out of range (0 .. %u): " INT64_FORMAT "\n", + INT_MAX, (int64) wtmp))); } weight = wtmp; } @@ -4562,14 +4744,15 @@ addScript(ParsedScript script) { if (script.commands == NULL || script.commands[0] == NULL) { - fprintf(stderr, "empty command list for script \"%s\"\n", script.desc); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("at most %d SQL scripts are allowed\n", MAX_SCRIPTS))); } CheckConditional(script); @@ -4754,9 +4937,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"); + ereport(ELEVEL_LOG, + (errmsg("cannot seed random from a strong source, none available: use \"time\" or an unsigned integer value.\n"))); return false; } } @@ -4767,15 +4949,18 @@ 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); + ereport(ELEVEL_LOG, + (errmsg("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); + { + ereport(ELEVEL_LOG, + (errmsg("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 +5092,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); + ereport(ELEVEL_FATAL, + (errmsg("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) @@ -4948,9 +5133,9 @@ main(int argc, char **argv) nclients = atoi(optarg); if (nclients <= 0 || nclients > MAXCLIENTS) { - fprintf(stderr, "invalid number of clients: \"%s\"\n", - optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid number of clients: \"%s\"\n", + optarg))); } #ifdef HAVE_GETRLIMIT #ifdef RLIMIT_NOFILE /* most platforms use RLIMIT_NOFILE */ @@ -4959,15 +5144,16 @@ main(int argc, char **argv) if (getrlimit(RLIMIT_OFILE, &rlim) == -1) #endif /* RLIMIT_NOFILE */ { - fprintf(stderr, "getrlimit failed: %s\n", strerror(errno)); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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 +5162,15 @@ main(int argc, char **argv) nthreads = atoi(optarg); if (nthreads <= 0) { - fprintf(stderr, "invalid number of threads: \"%s\"\n", - optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("threads are not supported on this platform; use -j1\n"))); } #endif /* !ENABLE_THREAD_SAFETY */ break; @@ -5001,8 +5187,9 @@ main(int argc, char **argv) scale = atoi(optarg); if (scale <= 0) { - fprintf(stderr, "invalid scaling factor: \"%s\"\n", optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid scaling factor: \"%s\"\n", + optarg))); } break; case 't': @@ -5010,9 +5197,9 @@ main(int argc, char **argv) nxacts = atoi(optarg); if (nxacts <= 0) { - fprintf(stderr, "invalid number of transactions: \"%s\"\n", - optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid number of transactions: \"%s\"\n", + optarg))); } break; case 'T': @@ -5020,8 +5207,8 @@ main(int argc, char **argv) duration = atoi(optarg); if (duration <= 0) { - fprintf(stderr, "invalid duration: \"%s\"\n", optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid duration: \"%s\"\n", optarg))); } break; case 'U': @@ -5069,14 +5256,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); + ereport(ELEVEL_FATAL, + (errmsg("invalid variable definition: \"%s\"\n", + optarg))); } *p++ = '\0'; - if (!putVariable(&state[0].variables, "option", optarg, p)) - exit(1); + putVariable(&state[0].variables, "option", optarg, p); } break; case 'F': @@ -5084,8 +5270,8 @@ main(int argc, char **argv) fillfactor = atoi(optarg); if (fillfactor < 10 || fillfactor > 100) { - fprintf(stderr, "invalid fillfactor: \"%s\"\n", optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid fillfactor: \"%s\"\n", optarg))); } break; case 'M': @@ -5095,9 +5281,9 @@ main(int argc, char **argv) break; if (querymode >= NUM_QUERYMODE) { - fprintf(stderr, "invalid query mode (-M): \"%s\"\n", - optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid query mode (-M): \"%s\"\n", + optarg))); } break; case 'P': @@ -5105,9 +5291,9 @@ main(int argc, char **argv) progress = atoi(optarg); if (progress <= 0) { - fprintf(stderr, "invalid thread progress delay: \"%s\"\n", - optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid thread progress delay: \"%s\"\n", + optarg))); } break; case 'R': @@ -5119,8 +5305,9 @@ main(int argc, char **argv) if (throttle_value <= 0.0) { - fprintf(stderr, "invalid rate limit: \"%s\"\n", optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid rate limit: \"%s\"\n", + optarg))); } /* Invert rate limit into a time offset */ throttle_delay = (int64) (1000000.0 / throttle_value); @@ -5132,9 +5319,9 @@ main(int argc, char **argv) if (limit_ms <= 0.0) { - fprintf(stderr, "invalid latency limit: \"%s\"\n", - optarg); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("invalid latency limit: \"%s\"\n", + optarg))); } benchmarking_option_set = true; latency_limit = (int64) (limit_ms * 1000); @@ -5157,8 +5344,9 @@ 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); + ereport(ELEVEL_FATAL, + (errmsg("invalid sampling rate: \"%s\"\n", + optarg))); } break; case 5: /* aggregate-interval */ @@ -5166,9 +5354,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); + ereport(ELEVEL_FATAL, + (errmsg("invalid number of seconds for aggregation: \"%s\"\n", + optarg))); } break; case 6: /* progress-timestamp */ @@ -5187,13 +5375,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); + ereport(ELEVEL_FATAL, + (errmsg("error while setting random seed from --random-seed option\n"))); } break; default: - fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg(_("Try \"%s --help\" for more information.\n"), + progname))); break; } } @@ -5231,8 +5420,8 @@ main(int argc, char **argv) if (total_weight == 0 && !is_init_mode) { - fprintf(stderr, "total script weight must not be zero\n"); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("total script weight must not be zero\n"))); } /* show per script stats if several scripts are used */ @@ -5266,8 +5455,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); + ereport(ELEVEL_FATAL, + (errmsg("some of the specified options cannot be used in initialization (-i) mode\n"))); } if (initialize_steps == NULL) @@ -5301,15 +5490,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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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 +5508,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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_FATAL, + (errmsg("--progress-timestamp is allowed only under --progress\n"))); } /* @@ -5383,15 +5574,13 @@ main(int argc, char **argv) if (var->value.type != PGBT_NO_VALUE) { - if (!putVariableValue(&state[i].variables, "startup", - var->name, &var->value)) - exit(1); + putVariableValue(&state[i].variables, "startup", var->name, + &var->value, false); } else { - if (!putVariable(&state[i].variables, "startup", - var->name, var->svalue)) - exit(1); + putVariable(&state[i].variables, "startup", var->name, + var->svalue); } } } @@ -5404,15 +5593,14 @@ main(int argc, char **argv) initRandomState(&state[i].random_state); } - if (debug) - { - if (duration <= 0) - printf("pghost: %s pgport: %s nclients: %d nxacts: %d dbName: %s\n", - pghost, pgport, nclients, nxacts, dbName); - else - printf("pghost: %s pgport: %s nclients: %d duration: %d dbName: %s\n", - pghost, pgport, nclients, duration, dbName); - } + if (duration <= 0) + ereport(ELEVEL_DEBUG, + (errmsg("pghost: %s pgport: %s nclients: %d nxacts: %d dbName: %s\n", + pghost, pgport, nclients, nxacts, dbName))); + else + ereport(ELEVEL_DEBUG, + (errmsg("pghost: %s pgport: %s nclients: %d duration: %d dbName: %s\n", + pghost, pgport, nclients, duration, dbName))); /* opening connection... */ con = doConnect(); @@ -5421,9 +5609,9 @@ 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); + ereport(ELEVEL_FATAL, + (errmsg("connection to database \"%s\" failed\n%s", + dbName, PQerrorMessage(con)))); } if (internal_script_used) @@ -5436,29 +5624,35 @@ 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)); + 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)); } + ereport(ELEVEL_LOG, (errmsg("%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); + ereport(ELEVEL_FATAL, + (errmsg("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); + ereport(ELEVEL_LOG, + (errmsg("scale option ignored, using count from pgbench_branches table (%d)\n", + scale))); } /* @@ -5469,8 +5663,8 @@ main(int argc, char **argv) { for (i = 0; i < nclients; i++) { - if (!putVariableInt(&state[i].variables, "startup", "scale", scale)) - exit(1); + putVariableInt(&state[i].variables, "startup", "scale", scale, + false); } } @@ -5481,8 +5675,8 @@ main(int argc, char **argv) if (lookupVariable(&state[0].variables, "client_id") == NULL) { for (i = 0; i < nclients; i++) - if (!putVariableInt(&state[i].variables, "startup", "client_id", i)) - exit(1); + putVariableInt(&state[i].variables, "startup", "client_id", i, + false); } /* set default seed for hash functions */ @@ -5494,33 +5688,32 @@ main(int argc, char **argv) (uint64) (random() & 0xFFFF); for (i = 0; i < nclients; i++) - if (!putVariableInt(&state[i].variables, "startup", "default_seed", - (int64) seed)) - exit(1); + putVariableInt(&state[i].variables, "startup", "default_seed", + (int64) seed, false); } /* set random seed unless overwritten */ if (lookupVariable(&state[0].variables, "random_seed") == NULL) { for (i = 0; i < nclients; i++) - if (!putVariableInt(&state[i].variables, "startup", "random_seed", - random_seed)) - exit(1); + putVariableInt(&state[i].variables, "startup", "random_seed", + random_seed, false); } if (!is_no_vacuum) { - fprintf(stderr, "starting vacuum..."); + ereport(ELEVEL_LOG, (errmsg("starting vacuum..."))); tryExecuteStatement(con, "vacuum pgbench_branches"); tryExecuteStatement(con, "vacuum pgbench_tellers"); tryExecuteStatement(con, "truncate pgbench_history"); - fprintf(stderr, "end.\n"); + ereport(ELEVEL_LOG, (errmsg("end.\n"))); if (do_vacuum_accounts) { - fprintf(stderr, "starting vacuum pgbench_accounts..."); + ereport(ELEVEL_LOG, + (errmsg("starting vacuum pgbench_accounts..."))); tryExecuteStatement(con, "vacuum analyze pgbench_accounts"); - fprintf(stderr, "end.\n"); + ereport(ELEVEL_LOG, (errmsg("end.\n"))); } } PQfinish(con); @@ -5578,8 +5771,9 @@ main(int argc, char **argv) if (err != 0 || thread->thread == INVALID_THREAD) { - fprintf(stderr, "could not create thread: %s\n", strerror(err)); - exit(1); + ereport(ELEVEL_FATAL, + (errmsg("could not create thread: %s\n", + strerror(err)))); } } else @@ -5688,8 +5882,9 @@ threadRun(void *arg) if (thread->logfile == NULL) { - fprintf(stderr, "could not open logfile \"%s\": %s\n", - logpath, strerror(errno)); + ereport(ELEVEL_LOG, + (errmsg("could not open logfile \"%s\": %s\n", + logpath, strerror(errno)))); goto done; } } @@ -5767,8 +5962,9 @@ threadRun(void *arg) if (sock < 0) { - fprintf(stderr, "invalid socket: %s", - PQerrorMessage(st->con)); + ereport(ELEVEL_LOG, + (errmsg("invalid socket: %s", + PQerrorMessage(st->con)))); goto done; } @@ -5844,7 +6040,8 @@ threadRun(void *arg) continue; } /* must be something wrong */ - fprintf(stderr, "select() failed: %s\n", strerror(errno)); + ereport(ELEVEL_LOG, + (errmsg("select() failed: %s\n", strerror(errno)))); goto done; } } @@ -5868,8 +6065,9 @@ threadRun(void *arg) if (sock < 0) { - fprintf(stderr, "invalid socket: %s", - PQerrorMessage(st->con)); + ereport(ELEVEL_LOG, + (errmsg("invalid socket: %s", + PQerrorMessage(st->con)))); goto done; } @@ -5911,6 +6109,7 @@ threadRun(void *arg) lag, stdev; char tbuf[315]; + PQExpBufferData progress_buf; /* * Add up the statistics of all threads. @@ -5968,18 +6167,23 @@ 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); + 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'); + + ereport(ELEVEL_LOG, (errmsg("%s", progress_buf.data))); + termPQExpBuffer(&progress_buf); last = cur; last_report = now; @@ -6063,10 +6267,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); - } + ereport(ELEVEL_FATAL, (errmsg("failed to set timer\n"))); } /* partial pthread implementation for Windows */ @@ -6136,3 +6337,155 @@ pthread_join(pthread_t th, void **thread_return) } #endif /* WIN32 */ + +/* + * errstartImpl --- begin an error-reporting cycle + * + * Initialize the error data and store the given parameters in it. + * Subsequently, errmsg() and perhaps other routines will be called to further + * populate the error data. Finally, errfinish() will be called to actually + * process the error report. If multiple threads can use the same error data, + * the error mutex is locked before the error data is initialized and will be + * unlocked in the end of the errfinish() call. + * + * Returns true in normal case. Returns false to short-circuit the error + * report (if the debugging level does not resolve this error/logging level). + */ +static bool +#if defined(ENABLE_THREAD_SAFETY) && defined(HAVE__VA_ARGS) +errstartImpl(Error error, ErrorLevel elevel) +#else /* !(ENABLE_THREAD_SAFETY && HAVE__VA_ARGS) */ +errstartImpl(ErrorLevel elevel) +#endif /* ENABLE_THREAD_SAFETY && HAVE__VA_ARGS */ +{ + bool start_error_reporting; + + /* Check if we have the appropriate debugging level */ + switch (elevel) + { + case ELEVEL_DEBUG: + /* + * Print the message only if there's a debugging mode for all types + * of messages. + */ + start_error_reporting = debug; + break; + case ELEVEL_LOG: + case ELEVEL_FATAL: + /* + * Always print the error/log message. + */ + start_error_reporting = true; + break; + default: + /* internal error which should never occur */ + ereport(ELEVEL_FATAL, + (errmsg("unexpected error level: %d\n", elevel))); + break; + } + + /* Initialize the error data */ + if (start_error_reporting) + { + Assert(error); + +#if defined(ENABLE_THREAD_SAFETY) && !defined(HAVE__VA_ARGS) + pthread_mutex_lock(&error_mutex); +#endif /* ENABLE_THREAD_SAFETY && !HAVE__VA_ARGS */ + + error->elevel = elevel; + initPQExpBuffer(&error->message); + } + + return start_error_reporting; +} + +/* + * errmsgImpl --- add a primary error message text to the current error + */ +static int +#if defined(ENABLE_THREAD_SAFETY) && defined(HAVE__VA_ARGS) +errmsgImpl(Error error, const char *fmt,...) +#else /* !(ENABLE_THREAD_SAFETY && HAVE__VA_ARGS) */ +errmsgImpl(const char *fmt,...) +#endif /* ENABLE_THREAD_SAFETY && HAVE__VA_ARGS */ +{ + va_list ap; + bool done; + + Assert(error); + + if (PQExpBufferBroken(&error->message)) + { + /* Already failed. */ + /* Return value does not matter. */ + return 0; + } + + /* Loop in case we have to retry after enlarging the buffer. */ + do + { + va_start(ap, fmt); + done = appendPQExpBufferVA(&error->message, fmt, ap); + va_end(ap); + } while (!done); + + /* Return value does not matter. */ + return 0; +} + +/* + * errfinishImpl --- end an error-reporting cycle + * + * Print the appropriate error report to stderr. + * + * If elevel is ELEVEL_FATAL or worse, control does not return to the caller. + * See ErrorLevel enumeration for the error level definitions. + * + * If the error message buffer is empty or broken, prints a corresponding error + * message and exits the program. + */ +static void +#if defined(ENABLE_THREAD_SAFETY) && defined(HAVE__VA_ARGS) +errfinishImpl(Error error, int dummy,...) +#else /* !(ENABLE_THREAD_SAFETY && HAVE__VA_ARGS) */ +errfinishImpl(int dummy,...) +#endif /* ENABLE_THREAD_SAFETY && HAVE__VA_ARGS */ +{ + bool error_during_reporting = false; + ErrorLevel elevel; + + Assert(error); + elevel = error->elevel; + + /* + * Immediately print the message to stderr so as not to get an endless cycle + * of errors... + */ + if (PQExpBufferDataBroken(error->message)) + { + error_during_reporting = true; + fprintf(stderr, "out of memory\n"); + } + else if (*(error->message.data) == '\0') + { + /* internal error which should never occur */ + error_during_reporting = true; + fprintf(stderr, "empty error message cannot be reported\n"); + } + else + { + fprintf(stderr, "%s", error->message.data); + } + + /* Release the error data and exit if needed */ + + termPQExpBuffer(&error->message); + +#if defined(ENABLE_THREAD_SAFETY) && !defined(HAVE__VA_ARGS) + pthread_mutex_unlock(&error_mutex); +#endif /* ENABLE_THREAD_SAFETY && !HAVE__VA_ARGS */ + + if (elevel >= ELEVEL_FATAL || error_during_reporting) + 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