From ab40f131aa781a28f0593715d233af1c19ae951a Mon Sep 17 00:00:00 2001 From: Marina Polyakova Date: Wed, 5 Sep 2018 19:39:41 +0300 Subject: [PATCH v11 4/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. --- src/bin/pgbench/pgbench.c | 1019 ++++++++++++++++++------------------- 1 file changed, 485 insertions(+), 534 deletions(-) diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 8da11209ad..18742fcd56 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -661,17 +661,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; -typedef enum DebugLevel -{ - NO_DEBUG = 0, /* no debugging output (except PGBENCH_DEBUG) */ - DEBUG_ERRORS, /* print only error messages, retries and - * failures */ - DEBUG_ALL /* print all debugging output (throttling, - * executed/sent/received commands etc.) */ -} DebugLevel; - -static DebugLevel debug_level = NO_DEBUG; /* debug flag */ - /* Builtin test scripts */ typedef struct BuiltinScript { @@ -718,6 +707,41 @@ static const BuiltinScript builtin_script[] = } }; +typedef enum ErrorLevel +{ + /* + * To report throttling, executed/sent/received commands etc. + */ + DEBUG, + + /* + * To report a normal error of the SQL/meta command and process the + * transaction after it (its end/retry). + */ + LOG, + + /* + * To report: + * - abortion of the client (something serious e.g. connection with the + * backend was lost); + * - the log messages of the main program; + * - PGBENCH_DEBUG messages. + */ + LOG_PGBENCH, + + /* + * To report the error messages of the main program and immediately call + * exit(1). + */ + FATAL +} ErrorLevel; + +/* + * By default there are no debug messages or detailed reports about + * retried/failed transactions. + */ +static ErrorLevel log_level = LOG_PGBENCH; + /* Function prototypes */ static void setNullValue(PgBenchValue *pv); @@ -729,17 +753,21 @@ 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); +static void pgbench_error_va(ErrorLevel elevel, const char *fmt, + va_list *args) pg_attribute_printf(2, 0); /* callback functions for our flex lexer */ static const PsqlScanCallbacks pgbench_callbacks = { NULL, /* don't need get_variable functionality */ - pgbench_error + pgbench_simple_error }; @@ -880,7 +908,8 @@ 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_PGBENCH, "invalid input syntax for integer: \"%s\"\n", + str); /* process digits */ while (*ptr && isdigit((unsigned char) *ptr)) @@ -888,7 +917,9 @@ 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_PGBENCH, + "value \"%s\" is out of range for type bigint\n", + str); result = tmp; } @@ -899,7 +930,8 @@ gotdigits: ptr++; if (*ptr != '\0') - fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str); + pgbench_error(LOG_PGBENCH, "invalid input syntax for integer: \"%s\"\n", + str); return ((sign < 0) ? -result : result); } @@ -1312,8 +1344,8 @@ accumStats(StatsData *stats, bool skipped, double lat, double lag, break; default: /* internal error which should never occur */ - fprintf(stderr, "unexpected error status: %d\n", estatus); - exit(1); + pgbench_error(FATAL, "unexpected error status: %d\n", estatus); + break; } } @@ -1325,10 +1357,7 @@ executeStatement(PGconn *con, const char *sql) res = PQexec(con, sql); if (PQresultStatus(res) != PGRES_COMMAND_OK) - { - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); - } + pgbench_error(FATAL, "%s", PQerrorMessage(con)); PQclear(res); } @@ -1340,10 +1369,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"); - } + pgbench_error(LOG_PGBENCH, + "%s(ignoring this error and continuing anyway)\n", + PQerrorMessage(con)); PQclear(res); } @@ -1388,8 +1416,8 @@ doConnect(void) if (!conn) { - fprintf(stderr, "connection to database \"%s\" failed\n", - dbName); + pgbench_error(LOG_PGBENCH, "connection to database \"%s\" failed\n", + dbName); return NULL; } @@ -1407,8 +1435,8 @@ 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)); + pgbench_error(LOG_PGBENCH, "connection to database \"%s\" failed:\n%s", + dbName, PQerrorMessage(conn)); PQfinish(conn); return NULL; } @@ -1546,10 +1574,8 @@ makeVariableValue(Variable *var) if (sscanf(var->svalue, "%lf%c", &dv, &xs) != 1) { - if (debug_level >= DEBUG_ERRORS) - 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); @@ -1619,7 +1645,7 @@ enlargeVariables(Variables *variables, int needed) * 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). Because this can be used by client - * commands, print an error message only in debug mode. The caller can print his + * commands, print an error message at the level LOG. The caller can print his * own error message. */ static Variable * @@ -1636,9 +1662,8 @@ lookupCreateVariable(Variables *variables, const char *context, char *name) */ if (!valid_variable_name(name)) { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "%s: invalid variable name: \"%s\"\n", - context, name); + pgbench_error(LOG, "%s: invalid variable name: \"%s\"\n", + context, name); return NULL; } @@ -1671,8 +1696,8 @@ putVariable(Variables *variables, const char *context, char *name, var = lookupCreateVariable(variables, context, name); if (!var) { - fprintf(stderr, "%s: error while setting variable \"%s\"\n", - context, name); + pgbench_error(LOG_PGBENCH, "%s: error while setting variable \"%s\"\n", + context, name); return false; } @@ -1690,7 +1715,7 @@ putVariable(Variables *variables, const char *context, char *name, /* * Assign a value to a variable, creating it if need be. * Returns false on failure (bad name). Because this can be used by client - * commands, print an error message only in debug mode. The caller can print his + * commands, print an error message at the level LOG. The caller can print his * own error message. */ static bool @@ -1702,9 +1727,8 @@ putVariableValue(Variables *variables, const char *context, char *name, var = lookupCreateVariable(variables, context, name); if (!var) { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "%s: error while setting variable \"%s\"\n", - context, name); + pgbench_error(LOG, "%s: error while setting variable \"%s\"\n", + context, name); return false; } @@ -1719,7 +1743,7 @@ putVariableValue(Variables *variables, const char *context, char *name, /* * Assign an integer value to a variable, creating it if need be. * Returns false on failure (bad name). Because this can be used by client - * commands, print an error message only in debug mode. The caller can print his + * commands, print an error message at the level LOG. The caller can print his * own error message. */ static bool @@ -1861,9 +1885,10 @@ coerceToBool(PgBenchValue *pval, bool *bval) } else /* NULL, INT or DOUBLE */ { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "cannot coerce %s to boolean\n", - valueTypeName(pval)); + /* call the function valueTypeName only if necessary */ + if (LOG >= log_level) + pgbench_error(LOG, "cannot coerce %s to boolean\n", + valueTypeName(pval)); *bval = false; /* suppress uninitialized-variable warnings */ return false; } @@ -1908,8 +1933,7 @@ coerceToInt(PgBenchValue *pval, int64 *ival) if (dval < PG_INT64_MIN || PG_INT64_MAX < dval) { - if (debug_level >= DEBUG_ERRORS) - 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; @@ -1917,8 +1941,10 @@ coerceToInt(PgBenchValue *pval, int64 *ival) } else /* BOOLEAN or NULL */ { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "cannot coerce %s to int\n", valueTypeName(pval)); + /* call the function valueTypeName only if necessary */ + if (LOG >= log_level) + pgbench_error(LOG, "cannot coerce %s to int\n", + valueTypeName(pval)); return false; } } @@ -1939,9 +1965,10 @@ coerceToDouble(PgBenchValue *pval, double *dval) } else /* BOOLEAN or NULL */ { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "cannot coerce %s to double\n", - valueTypeName(pval)); + /* call the function valueTypeName only if necessary */ + if (LOG >= log_level) + pgbench_error(LOG, "cannot coerce %s to double\n", + valueTypeName(pval)); return false; } } @@ -2122,9 +2149,8 @@ evalStandardFunc(TState *thread, CState *st, if (l != NULL) { - if (debug_level >= DEBUG_ERRORS) - 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; } @@ -2247,8 +2273,7 @@ evalStandardFunc(TState *thread, CState *st, case PGBENCH_MOD: if (ri == 0) { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "division by zero\n"); + pgbench_error(LOG, "division by zero\n"); return false; } /* special handling of -1 divisor */ @@ -2259,9 +2284,8 @@ evalStandardFunc(TState *thread, CState *st, /* overflow check (needed for INT64_MIN) */ if (li == PG_INT64_MIN) { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, - "bigint out of range\n"); + pgbench_error(LOG, + "bigint out of range\n"); return false; } else @@ -2365,17 +2389,20 @@ evalStandardFunc(TState *thread, CState *st, Assert(nargs == 1); - fprintf(stderr, "debug(script=%d,command=%d): ", - st->use_file, st->command + 1); + pgbench_error(LOG_PGBENCH, "debug(script=%d,command=%d): ", + st->use_file, st->command + 1); if (varg->type == PGBT_NULL) - fprintf(stderr, "null\n"); + pgbench_error(LOG_PGBENCH, "null\n"); else if (varg->type == PGBT_BOOLEAN) - fprintf(stderr, "boolean %s\n", varg->u.bval ? "true" : "false"); + pgbench_error(LOG_PGBENCH, "boolean %s\n", + varg->u.bval ? "true" : "false"); else if (varg->type == PGBT_INT) - fprintf(stderr, "int " INT64_FORMAT "\n", varg->u.ival); + pgbench_error(LOG_PGBENCH, "int " INT64_FORMAT "\n", + varg->u.ival); else if (varg->type == PGBT_DOUBLE) - fprintf(stderr, "double %.*g\n", DBL_DIG, varg->u.dval); + pgbench_error(LOG_PGBENCH, "double %.*g\n", + DBL_DIG, varg->u.dval); else /* internal error, unexpected type */ Assert(0); @@ -2501,15 +2528,13 @@ evalStandardFunc(TState *thread, CState *st, /* check random range */ if (imin > imax) { - if (debug_level >= DEBUG_ERRORS) - 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 */ - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "random range is too large\n"); + pgbench_error(LOG, "random range is too large\n"); return false; } @@ -2531,10 +2556,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param < MIN_GAUSSIAN_PARAM) { - if (debug_level >= DEBUG_ERRORS) - 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; } @@ -2546,10 +2570,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0 || param == 1.0 || param > MAX_ZIPFIAN_PARAM) { - if (debug_level >= DEBUG_ERRORS) - 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, @@ -2561,10 +2584,9 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0) { - if (debug_level >= DEBUG_ERRORS) - 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; } @@ -2675,9 +2697,8 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval if ((var = lookupVariable(&st->variables, expr->u.variable.varname)) == NULL) { - if (debug_level >= DEBUG_ERRORS) - fprintf(stderr, "undefined variable \"%s\"\n", - expr->u.variable.varname); + pgbench_error(LOG, "undefined variable \"%s\"\n", + expr->u.variable.varname); return false; } @@ -2696,9 +2717,12 @@ 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); + pgbench_error(FATAL, + "unexpected enode type in evaluation: %d\n", + expr->etype); + + /* keep compiler quiet */ + return false; } } @@ -2771,17 +2795,15 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) } else if ((arg = getVariable(variables, argv[i] + 1)) == NULL) { - if (debug_level >= DEBUG_ERRORS) - 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) { - if (debug_level >= DEBUG_ERRORS) - 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; } @@ -2798,8 +2820,9 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) { if (system(command)) { - if (!timer_exceeded && debug_level >= DEBUG_ERRORS) - fprintf(stderr, "%s: could not launch shell command\n", argv[0]); + if (!timer_exceeded) + pgbench_error(LOG, "%s: could not launch shell command\n", + argv[0]); return false; } return true; @@ -2808,21 +2831,20 @@ 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) { - if (debug_level >= DEBUG_ERRORS) - 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 && debug_level >= DEBUG_ERRORS) - fprintf(stderr, "%s: could not read result of shell command\n", argv[0]); + if (!timer_exceeded) + pgbench_error(LOG, "%s: could not read result of shell command\n", + argv[0]); (void) pclose(fp); return false; } if (pclose(fp) < 0) { - if (debug_level >= DEBUG_ERRORS) - 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; } @@ -2832,10 +2854,9 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) endptr++; if (*res == '\0' || *endptr != '\0') { - if (debug_level >= DEBUG_ERRORS) - 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(variables, "setshell", variable, retval)) @@ -2860,9 +2881,9 @@ preparedStatementName(char *buffer, int file, int state) static void commandFailed(CState *st, const char *cmd, const char *message) { - fprintf(stderr, - "client %d got an error in command %d (%s) of script %d; %s\n", - st->id, st->command, cmd, st->use_file, message); + pgbench_error(LOG, + "client %d got an error in command %d (%s) of script %d; %s\n", + st->id, st->command, cmd, st->use_file, message); } /* @@ -2874,9 +2895,9 @@ clientAborted(CState *st, const char *message) const Command *command = sql_script[st->use_file].commands[st->command]; Assert(command->type == SQL_COMMAND); - fprintf(stderr, - "client %d aborted in command %d (SQL) of script %d; %s\n", - st->id, st->command, st->use_file, message); + pgbench_error(LOG_PGBENCH, + "client %d aborted in command %d (SQL) of script %d; %s\n", + st->id, st->command, st->use_file, message); } /* return a script number with a weighted choice. */ @@ -2911,8 +2932,7 @@ sendCommand(CState *st, Command *command) sql = pg_strdup(command->argv[0]); sql = assignVariables(&st->variables, sql); - if (debug_level >= DEBUG_ALL) - 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); } @@ -2923,8 +2943,7 @@ sendCommand(CState *st, Command *command) getQueryParams(&st->variables, command, params); - if (debug_level >= DEBUG_ALL) - 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); } @@ -2949,7 +2968,7 @@ 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)); + pgbench_error(LOG_PGBENCH, "%s", PQerrorMessage(st->con)); PQclear(res); } st->prepared[st->use_file] = true; @@ -2958,8 +2977,7 @@ sendCommand(CState *st, Command *command) getQueryParams(&st->variables, command, params); preparedStatementName(name, st->use_file, st->command); - if (debug_level >= DEBUG_ALL) - 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); } @@ -2968,9 +2986,8 @@ sendCommand(CState *st, Command *command) if (r == 0) { - if (debug_level >= DEBUG_ALL) - 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]); return false; } else @@ -2987,14 +3004,12 @@ sendRollback(CState *st) if (querymode == QUERY_SIMPLE) { - if (debug_level >= DEBUG_ALL) - fprintf(stderr, "client %d sending %s\n", st->id, rollback_cmd); + pgbench_error(DEBUG, "client %d sending %s\n", st->id, rollback_cmd); r = PQsendQuery(st->con, rollback_cmd); } else if (querymode == QUERY_EXTENDED) { - if (debug_level >= DEBUG_ALL) - fprintf(stderr, "client %d sending %s\n", st->id, rollback_cmd); + pgbench_error(DEBUG, "client %d sending %s\n", st->id, rollback_cmd); r = PQsendQueryParams(st->con, rollback_cmd, 0, NULL, NULL, NULL, NULL, 0); } @@ -3006,13 +3021,12 @@ sendRollback(CState *st) res = PQprepare(st->con, prepared_name, rollback_cmd, 0, NULL); if (PQresultStatus(res) != PGRES_COMMAND_OK) - fprintf(stderr, "%s", PQerrorMessage(st->con)); + pgbench_error(LOG_PGBENCH, "%s", PQerrorMessage(st->con)); PQclear(res); st->rollback_prepared = true; } - if (debug_level >= DEBUG_ALL) - fprintf(stderr, "client %d sending %s\n", st->id, prepared_name); + pgbench_error(DEBUG, "client %d sending %s\n", st->id, prepared_name); r = PQsendQueryPrepared(st->con, prepared_name, 0, NULL, NULL, NULL, 0); } @@ -3021,9 +3035,8 @@ sendRollback(CState *st) if (r == 0) { - if (debug_level >= DEBUG_ALL) - fprintf(stderr, "client %d could not send %s\n", - st->id, rollback_cmd); + pgbench_error(DEBUG, "client %d could not send %s\n", + st->id, rollback_cmd); return false; } else @@ -3044,9 +3057,8 @@ evaluateSleep(Variables *variables, int argc, char **argv, int *usecs) { if ((var = getVariable(variables, argv[1] + 1)) == NULL) { - if (debug_level >= DEBUG_ERRORS) - 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); @@ -3220,7 +3232,8 @@ getTransactionStatus(PGconn *con, bool *in_tx_block) /* PQTRANS_UNKNOWN is expected given a broken connection */ if (PQstatus(con) == CONNECTION_BAD) { /* there's something wrong */ - fprintf(stderr, "perhaps the backend died while processing\n"); + pgbench_error(LOG_PGBENCH, + "perhaps the backend died while processing\n"); return false; } case PQTRANS_ACTIVE: @@ -3229,7 +3242,8 @@ getTransactionStatus(PGconn *con, bool *in_tx_block) * We cannot find out whether we are in a transaction block or not. * Internal error which should never occur. */ - fprintf(stderr, "unexpected transaction status %d\n", tx_status); + pgbench_error(LOG_PGBENCH, "unexpected transaction status %d\n", + tx_status); return false; } @@ -3295,9 +3309,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) st->use_file = chooseScript(thread); - if (debug_level >= DEBUG_ALL) - 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; @@ -3374,9 +3387,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) } st->state = CSTATE_THROTTLE; - if (debug_level >= DEBUG_ALL) - 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; /* @@ -3408,8 +3421,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_PGBENCH, + "client %d aborted while establishing connection\n", + st->id); st->state = CSTATE_ABORTED; break; } @@ -3496,12 +3510,17 @@ doCustom(TState *thread, CState *st, StatsData *agg) i; char **argv = command->argv; - if (debug_level >= DEBUG_ALL) + /* + * The variable name can be quite large so do not use a + * static buffer. + */ + if (DEBUG >= log_level) { - fprintf(stderr, "client %d executing \\%s", st->id, argv[0]); + pgbench_error(DEBUG, "client %d executing \\%s", + st->id, argv[0]); for (i = 1; i < argc; i++) - fprintf(stderr, " %s", argv[i]); - fprintf(stderr, "\n"); + pgbench_error(DEBUG, " %s", argv[i]); + pgbench_error(DEBUG, "\n"); } if (command->meta == META_SLEEP) @@ -3517,9 +3536,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (!evaluateSleep(&st->variables, argc, argv, &usec)) { - if (debug_level >= DEBUG_ERRORS) - commandFailed(st, "sleep", - "execution of meta-command failed"); + commandFailed(st, "sleep", + "execution of meta-command failed"); st->estatus = ESTATUS_META_COMMAND_ERROR; st->state = CSTATE_ERROR; break; @@ -3552,9 +3570,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (!evaluateExpr(thread, st, expr, &result)) { - if (debug_level >= DEBUG_ERRORS) - commandFailed(st, argv[0], - "evaluation of meta-command failed"); + commandFailed(st, argv[0], + "evaluation of meta-command failed"); st->estatus = ESTATUS_META_COMMAND_ERROR; st->state = CSTATE_ERROR; break; @@ -3565,9 +3582,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (!putVariableValue(&st->variables, argv[0], argv[1], &result)) { - if (debug_level >= DEBUG_ERRORS) - commandFailed(st, "set", - "assignment of meta-command failed"); + commandFailed(st, "set", + "assignment of meta-command failed"); st->estatus = ESTATUS_META_COMMAND_ERROR; st->state = CSTATE_ERROR; break; @@ -3630,9 +3646,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) } else if (!ret) /* on error */ { - if (debug_level >= DEBUG_ERRORS) - commandFailed(st, "setshell", - "execution of meta-command failed"); + commandFailed(st, "setshell", + "execution of meta-command failed"); st->estatus = ESTATUS_META_COMMAND_ERROR; st->state = CSTATE_ERROR; break; @@ -3654,9 +3669,8 @@ doCustom(TState *thread, CState *st, StatsData *agg) } else if (!ret) /* on error */ { - if (debug_level >= DEBUG_ERRORS) - commandFailed(st, "shell", - "execution of meta-command failed"); + commandFailed(st, "shell", + "execution of meta-command failed"); st->estatus = ESTATUS_META_COMMAND_ERROR; st->state = CSTATE_ERROR; break; @@ -3775,8 +3789,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) */ case CSTATE_WAIT_RESULT: command = sql_script[st->use_file].commands[st->command]; - if (debug_level >= DEBUG_ALL) - 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 */ clientAborted(st, @@ -3806,8 +3819,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) case PGRES_FATAL_ERROR: st->estatus = getSQLErrorStatus( PQresultErrorField(res, PG_DIAG_SQLSTATE)); - if (debug_level >= DEBUG_ERRORS) - commandFailed(st, "SQL", PQerrorMessage(st->con)); + commandFailed(st, "SQL", PQerrorMessage(st->con)); PQclear(res); discard_response(st); st->state = CSTATE_ERROR; @@ -3824,13 +3836,12 @@ doCustom(TState *thread, CState *st, StatsData *agg) * Wait for the rollback command to complete */ case CSTATE_WAIT_ROLLBACK_RESULT: - if (debug_level >= DEBUG_ALL) - fprintf(stderr, "client %d receiving\n", st->id); + pgbench_error(DEBUG, "client %d receiving\n", st->id); if (!PQconsumeInput(st->con)) { - fprintf(stderr, - "client %d aborted while rolling back the transaction after an error; perhaps the backend died while processing\n", - st->id); + pgbench_error(LOG_PGBENCH, + "client %d aborted while rolling back the transaction after an error; perhaps the backend died while processing\n", + st->id); st->state = CSTATE_ABORTED; break; } @@ -3854,9 +3865,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) st->state = CSTATE_FAILURE; break; default: - fprintf(stderr, - "client %d aborted while rolling back the transaction after an error; %s\n", - st->id, PQerrorMessage(st->con)); + pgbench_error(LOG_PGBENCH, + "client %d aborted while rolling back the transaction after an error; %s\n", + st->id, PQerrorMessage(st->con)); PQclear(res); st->state = CSTATE_ABORTED; break; @@ -3930,9 +3941,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) * It is assumed that the function getTransactionStatus * has already printed a more detailed error message. */ - fprintf(stderr, - "client %d aborted while receiving the transaction status\n", - st->id); + pgbench_error(LOG_PGBENCH, + "client %d aborted while receiving the transaction status\n", + st->id); st->state = CSTATE_ABORTED; break; } @@ -3942,9 +3953,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) /* Try to rollback a (failed) transaction block. */ if (!sendRollback(st)) { - fprintf(stderr, - "client %d aborted: failed to send sql command for rolling back the failed transaction\n", - st->id); + pgbench_error(LOG_PGBENCH, + "client %d aborted: failed to send sql command for rolling back the failed transaction\n", + st->id); st->state = CSTATE_ABORTED; } else @@ -3975,18 +3986,24 @@ doCustom(TState *thread, CState *st, StatsData *agg) /* * Inform that the transaction will be retried after the error. */ - if (debug_level >= DEBUG_ERRORS) + if (LOG >= log_level) { - fprintf(stderr, - "client %d repeats the transaction after the error (try %d", - st->id, st->retries + 1); + char buff[512]; + int buff_size = 0; + if (max_tries) - fprintf(stderr, "/%d", max_tries); + buff_size += snprintf(buff + buff_size, + sizeof(buff) - buff_size, + "/%d", max_tries); if (latency_limit) - fprintf(stderr, - ", %.3f%% of the maximum time of tries was used", - getLatencyUsed(st, &now)); - fprintf(stderr, ")\n"); + buff_size += snprintf(buff + buff_size, + sizeof(buff) - buff_size, + ", %.3f%% of the maximum time of tries was used", + getLatencyUsed(st, &now)); + pgbench_error(LOG, + "client %d repeats the transaction after the error (try %d%s)\n", + st->id, st->retries + 1, + buff_size ? buff : ""); } /* @@ -4016,18 +4033,24 @@ doCustom(TState *thread, CState *st, StatsData *agg) * If this is a serialization or deadlock failure, inform that * the failed transaction will not be retried. */ - if (debug_level >= DEBUG_ERRORS && canRetryError(st->estatus)) + if (LOG >= log_level && canRetryError(st->estatus)) { - fprintf(stderr, - "client %d ends the failed transaction (try %d", - st->id, st->retries + 1); + char buff[512]; + int buff_size = 0; + if (max_tries) - fprintf(stderr, "/%d", max_tries); + buff_size += snprintf(buff + buff_size, + sizeof(buff) - buff_size, + "/%d", max_tries); if (latency_limit) - fprintf(stderr, - ", %.3f%% of the maximum time of tries was used", - getLatencyUsed(st, &now)); - fprintf(stderr, ")\n"); + buff_size += snprintf(buff + buff_size, + sizeof(buff) - buff_size, + ", %.3f%% of the maximum time of tries was used", + getLatencyUsed(st, &now)); + pgbench_error(LOG, + "client %d ends the failed transaction (try %d%s)\n", + st->id, st->retries + 1, + buff_size ? buff : ""); } /* @@ -4052,10 +4075,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(FATAL, + "end of script reached within a conditional, missing \\endif\n"); /* * We must complete all the transaction blocks that were @@ -4068,17 +4089,17 @@ doCustom(TState *thread, CState *st, StatsData *agg) * It is assumed that the function getTransactionStatus * has already printed a more detailed error message. */ - fprintf(stderr, - "client %d aborted while receiving the transaction status\n", - st->id); + pgbench_error(LOG_PGBENCH, + "client %d aborted while receiving the transaction status\n", + st->id); st->state = CSTATE_ABORTED; break; } if (in_tx_block) { - fprintf(stderr, - "client %d aborted: end of script reached without completing the last transaction\n", - st->id); + pgbench_error(LOG_PGBENCH, + "client %d aborted: end of script reached without completing the last transaction\n", + st->id); st->state = CSTATE_ABORTED; break; } @@ -4255,9 +4276,9 @@ doLog(TState *thread, CState *st, break; default: /* internal error which should never occur */ - fprintf(stderr, "unexpected error status: %d\n", - st->estatus); - exit(1); + pgbench_error(FATAL, "unexpected error status: %d\n", + st->estatus); + break; } } else @@ -4335,7 +4356,7 @@ disconnect_all(CState *state, int length) static void initDropTables(PGconn *con) { - fprintf(stderr, "dropping old tables...\n"); + pgbench_error(LOG_PGBENCH, "dropping old tables...\n"); /* * We drop all the tables in one command, so that whether there are @@ -4410,7 +4431,7 @@ initCreateTables(PGconn *con) }; int i; - fprintf(stderr, "creating tables...\n"); + pgbench_error(LOG_PGBENCH, "creating tables...\n"); for (i = 0; i < lengthof(DDLs); i++) { @@ -4463,7 +4484,7 @@ initGenerateData(PGconn *con) remaining_sec; int log_interval = 1; - fprintf(stderr, "generating data...\n"); + pgbench_error(LOG_PGBENCH, "generating data...\n"); /* * we do all of this in one transaction to enable the backend's @@ -4508,10 +4529,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); - } + pgbench_error(FATAL, "%s", PQerrorMessage(con)); PQclear(res); INSTR_TIME_SET_CURRENT(start); @@ -4525,10 +4543,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(FATAL, "PQputline failed\n"); /* * If we want to stick with the original logging, print a message each @@ -4542,10 +4557,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_PGBENCH, + 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)) @@ -4559,9 +4576,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_PGBENCH, + 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); @@ -4570,15 +4590,9 @@ initGenerateData(PGconn *con) } if (PQputline(con, "\\.\n")) - { - fprintf(stderr, "very last PQputline failed\n"); - exit(1); - } + pgbench_error(FATAL, "very last PQputline failed\n"); if (PQendcopy(con)) - { - fprintf(stderr, "PQendcopy failed\n"); - exit(1); - } + pgbench_error(FATAL, "PQendcopy failed\n"); executeStatement(con, "commit"); } @@ -4589,7 +4603,7 @@ initGenerateData(PGconn *con) static void initVacuum(PGconn *con) { - fprintf(stderr, "vacuuming...\n"); + pgbench_error(LOG_PGBENCH, "vacuuming...\n"); executeStatement(con, "vacuum analyze pgbench_branches"); executeStatement(con, "vacuum analyze pgbench_tellers"); executeStatement(con, "vacuum analyze pgbench_accounts"); @@ -4609,7 +4623,7 @@ initCreatePKeys(PGconn *con) }; int i; - fprintf(stderr, "creating primary keys...\n"); + pgbench_error(LOG_PGBENCH, "creating primary keys...\n"); for (i = 0; i < lengthof(DDLINDEXes); i++) { char buffer[256]; @@ -4646,7 +4660,7 @@ initCreateFKeys(PGconn *con) }; int i; - fprintf(stderr, "creating foreign keys...\n"); + pgbench_error(LOG_PGBENCH, "creating foreign keys...\n"); for (i = 0; i < lengthof(DDLKEYs); i++) { executeStatement(con, DDLKEYs[i]); @@ -4666,20 +4680,15 @@ checkInitSteps(const char *initialize_steps) const char *step; if (initialize_steps[0] == '\0') - { - fprintf(stderr, "no initialization steps specified\n"); - exit(1); - } + pgbench_error(FATAL, "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(FATAL, + "unrecognized initialization step \"%c\"\n" + "allowed steps are: \"d\", \"t\", \"g\", \"v\", \"p\", \"f\"\n", + *step); } } @@ -4720,14 +4729,15 @@ runInitSteps(const char *initialize_steps) case ' ': break; /* ignore */ default: - fprintf(stderr, "unrecognized initialization step \"%c\"\n", - *step); + pgbench_error(LOG_PGBENCH, + "unrecognized initialization step \"%c\"\n", + *step); PQfinish(con); exit(1); } } - fprintf(stderr, "done.\n"); + pgbench_error(LOG_PGBENCH, "done.\n"); PQfinish(con); } @@ -4765,8 +4775,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_PGBENCH, + "statement has too many arguments (maximum is %d): %s\n", + MAX_ARGS - 1, cmd->argv[0]); pg_free(name); return false; } @@ -4787,13 +4798,13 @@ 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; fflush(stdout); va_start(ap, fmt); - vfprintf(stderr, _(fmt), ap); + pgbench_error_va(LOG_PGBENCH, fmt, &ap); va_end(ap); } @@ -4814,24 +4825,24 @@ 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); + pgbench_error(LOG_PGBENCH, "%s:%d: %s", source, lineno, msg); if (more != NULL) - fprintf(stderr, " (%s)", more); + pgbench_error(LOG_PGBENCH, " (%s)", more); if (column >= 0 && line == NULL) - fprintf(stderr, " at column %d", column + 1); + pgbench_error(LOG_PGBENCH, " at column %d", column + 1); if (command != NULL) - fprintf(stderr, " in command \"%s\"", command); - fprintf(stderr, "\n"); + pgbench_error(LOG_PGBENCH, " in command \"%s\"", command); + pgbench_error(LOG_PGBENCH, "\n"); if (line != NULL) { - fprintf(stderr, "%s\n", line); + pgbench_error(LOG_PGBENCH, "%s\n", line); if (column >= 0) { int i; for (i = 0; i < column; i++) - fprintf(stderr, " "); - fprintf(stderr, "^ error found here\n"); + pgbench_error(LOG_PGBENCH, " "); + pgbench_error(LOG_PGBENCH, "^ error found here\n"); } } exit(1); @@ -5083,10 +5094,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(FATAL, "condition error in script \"%s\" command %d: %s\n", + desc, cmdn, msg); } /* @@ -5284,20 +5293,14 @@ process_file(const char *filename, int weight) if (strcmp(filename, "-") == 0) fd = stdin; else if ((fd = fopen(filename, "r")) == NULL) - { - fprintf(stderr, "could not open file \"%s\": %s\n", - filename, strerror(errno)); - exit(1); - } + pgbench_error(FATAL, "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); - } + pgbench_error(FATAL, "could not read file \"%s\": %s\n", + filename, strerror(errno)); if (fd != stdin) fclose(fd); @@ -5320,10 +5323,10 @@ listAvailableScripts(void) { int i; - fprintf(stderr, "Available builtin scripts:\n"); + pgbench_error(LOG_PGBENCH, "Available builtin scripts:\n"); for (i = 0; i < lengthof(builtin_script); i++) - fprintf(stderr, "\t%s\n", builtin_script[i].name); - fprintf(stderr, "\n"); + pgbench_error(LOG_PGBENCH, "\t%s\n", builtin_script[i].name); + pgbench_error(LOG_PGBENCH, "\n"); } /* return builtin script "name" if unambiguous, fails if not found */ @@ -5350,10 +5353,12 @@ findBuiltin(const char *name) /* error cases */ if (found == 0) - fprintf(stderr, "no builtin script found for name \"%s\"\n", name); + pgbench_error(LOG_PGBENCH, "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_PGBENCH, + "ambiguous builtin name: %d builtin scripts found for prefix \"%s\"\n", + found, name); listAvailableScripts(); exit(1); @@ -5385,17 +5390,11 @@ 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(FATAL, "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(FATAL, + "weight specification out of range (0 .. %u): " INT64_FORMAT "\n", + INT_MAX, (int64) wtmp); weight = wtmp; } else @@ -5412,16 +5411,12 @@ static void 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(FATAL, "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(FATAL, "at most %d SQL scripts are allowed\n", + MAX_SCRIPTS); CheckConditional(script); @@ -5710,9 +5705,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_PGBENCH, + "cannot seed random from a strong source, none available: use \"time\" or an unsigned integer value.\n"); return false; } } @@ -5723,15 +5717,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_PGBENCH, + "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_PGBENCH, "setting random seed to %u\n", iseed); srandom(iseed); /* no precision loss: 32 bit unsigned int cast to 64 bit int */ random_seed = iseed; @@ -5866,10 +5860,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(FATAL, + "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) { @@ -5901,51 +5893,39 @@ main(int argc, char **argv) pgport = pg_strdup(optarg); break; case 'd': - debug_level = DEBUG_ALL; + log_level = 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(FATAL, "invalid number of clients: \"%s\"\n", + optarg); #ifdef HAVE_GETRLIMIT #ifdef RLIMIT_NOFILE /* most platforms use RLIMIT_NOFILE */ if (getrlimit(RLIMIT_NOFILE, &rlim) == -1) #else /* but BSD doesn't ... */ if (getrlimit(RLIMIT_OFILE, &rlim) == -1) #endif /* RLIMIT_NOFILE */ - { - fprintf(stderr, "getrlimit failed: %s\n", strerror(errno)); - exit(1); - } + pgbench_error(FATAL, "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(FATAL, + "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; case 'j': /* jobs */ benchmarking_option_set = true; nthreads = atoi(optarg); if (nthreads <= 0) - { - fprintf(stderr, "invalid number of threads: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, "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(FATAL, + "threads are not supported on this platform; use -j1\n"); #endif /* !ENABLE_THREAD_SAFETY */ break; case 'C': @@ -5960,29 +5940,22 @@ main(int argc, char **argv) scale_given = true; scale = atoi(optarg); if (scale <= 0) - { - fprintf(stderr, "invalid scaling factor: \"%s\"\n", optarg); - exit(1); - } + pgbench_error(FATAL, "invalid scaling factor: \"%s\"\n", + optarg); break; case 't': benchmarking_option_set = true; nxacts = atoi(optarg); if (nxacts <= 0) - { - fprintf(stderr, "invalid number of transactions: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, + "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(FATAL, "invalid duration: \"%s\"\n", optarg); break; case 'U': login = pg_strdup(optarg); @@ -6028,11 +6001,9 @@ main(int argc, char **argv) benchmarking_option_set = true; if ((p = strchr(optarg, '=')) == NULL || p == optarg || *(p + 1) == '\0') - { - fprintf(stderr, "invalid variable definition: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, + "invalid variable definition: \"%s\"\n", + optarg); *p++ = '\0'; if (!putVariable(&state[0].variables, "option", optarg, p)) @@ -6043,10 +6014,8 @@ main(int argc, char **argv) initialization_option_set = true; fillfactor = atoi(optarg); if (fillfactor < 10 || fillfactor > 100) - { - fprintf(stderr, "invalid fillfactor: \"%s\"\n", optarg); - exit(1); - } + pgbench_error(FATAL, "invalid fillfactor: \"%s\"\n", + optarg); break; case 'M': benchmarking_option_set = true; @@ -6054,21 +6023,16 @@ main(int argc, char **argv) if (strcmp(optarg, QUERYMODE[querymode]) == 0) break; if (querymode >= NUM_QUERYMODE) - { - fprintf(stderr, "invalid query mode (-M): \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, "invalid query mode (-M): \"%s\"\n", + optarg); break; case 'P': benchmarking_option_set = true; progress = atoi(optarg); if (progress <= 0) - { - fprintf(stderr, "invalid thread progress delay: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, + "invalid thread progress delay: \"%s\"\n", + optarg); break; case 'R': { @@ -6078,10 +6042,8 @@ main(int argc, char **argv) benchmarking_option_set = true; if (throttle_value <= 0.0) - { - fprintf(stderr, "invalid rate limit: \"%s\"\n", optarg); - exit(1); - } + pgbench_error(FATAL, "invalid rate limit: \"%s\"\n", + optarg); /* Invert rate limit into a time offset */ throttle_delay = (int64) (1000000.0 / throttle_value); } @@ -6091,11 +6053,8 @@ main(int argc, char **argv) double limit_ms = atof(optarg); if (limit_ms <= 0.0) - { - fprintf(stderr, "invalid latency limit: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, "invalid latency limit: \"%s\"\n", + optarg); benchmarking_option_set = true; latency_limit = (int64) (limit_ms * 1000); } @@ -6116,20 +6075,16 @@ main(int argc, char **argv) benchmarking_option_set = true; 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(FATAL, "invalid sampling rate: \"%s\"\n", + optarg); break; case 5: /* aggregate-interval */ benchmarking_option_set = true; agg_interval = atoi(optarg); if (agg_interval <= 0) - { - fprintf(stderr, "invalid number of seconds for aggregation: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, + "invalid number of seconds for aggregation: \"%s\"\n", + optarg); break; case 6: /* progress-timestamp */ progress_timestamp = true; @@ -6146,10 +6101,8 @@ main(int argc, char **argv) case 9: /* random-seed */ 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(FATAL, + "error while setting random seed from --random-seed option\n"); break; case 10: /* failures-detailed */ benchmarking_option_set = true; @@ -6160,12 +6113,9 @@ main(int argc, char **argv) int32 max_tries_arg = atoi(optarg); if (max_tries_arg < 0) - { - fprintf(stderr, - "invalid number of maximum tries: \"%s\"\n", - optarg); - exit(1); - } + pgbench_error(FATAL, + "invalid number of maximum tries: \"%s\"\n", + optarg); benchmarking_option_set = true; @@ -6182,12 +6132,13 @@ main(int argc, char **argv) case 12: /* print-errors */ benchmarking_option_set = true; /* do not conflict with the option --debug */ - if (debug_level < DEBUG_ERRORS) - debug_level = DEBUG_ERRORS; + if (log_level > LOG) + log_level = LOG; break; default: - fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); - exit(1); + pgbench_error(FATAL, + _("Try \"%s --help\" for more information.\n"), + progname); break; } } @@ -6224,10 +6175,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(FATAL, "total script weight must not be zero\n"); /* show per script stats if several scripts are used */ if (num_scripts > 1) @@ -6259,10 +6207,8 @@ main(int argc, char **argv) if (is_init_mode) { if (benchmarking_option_set) - { - fprintf(stderr, "some of the specified options cannot be used in initialization (-i) mode\n"); - exit(1); - } + pgbench_error(FATAL, + "some of the specified options cannot be used in initialization (-i) mode\n"); if (initialize_steps == NULL) initialize_steps = pg_strdup(DEFAULT_INIT_STEPS); @@ -6294,17 +6240,13 @@ main(int argc, char **argv) else { if (initialization_option_set) - { - fprintf(stderr, "some of the specified options cannot be used in benchmarking mode\n"); - exit(1); - } + pgbench_error(FATAL, + "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(FATAL, + "specify either a number of transactions (-t) or a duration (-T), not both\n"); /* Use DEFAULT_NXACTS if neither nxacts nor duration is specified. */ if (nxacts <= 0 && duration <= 0) @@ -6312,54 +6254,42 @@ 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(FATAL, + "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(FATAL, + "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(FATAL, + "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(FATAL, + "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(FATAL, + "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(FATAL, + "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(FATAL, + "--progress-timestamp is allowed only under --progress\n"); if (!max_tries) { if (retry && !latency_limit) { - fprintf(stderr, "an infinite number of transaction tries can only be used with the option --latency-limit\n"); - exit(1); + pgbench_error(FATAL, + "an infinite number of transaction tries can only be used with the option --latency-limit\n"); } else if (!retry) { @@ -6393,18 +6323,17 @@ main(int argc, char **argv) { if (!putVariableValue(&state[i].variables, "startup", var->name, &var->value)) - { - fprintf(stderr, - "error when setting the startup variable \"%s\" for client %d\n", - var->name, i); - exit(1); - } + pgbench_error(FATAL, + "error when setting the startup variable \"%s\" for client %d\n", + var->name, i); } else { if (!putVariable(&state[i].variables, "startup", var->name, var->svalue)) - exit(1); + pgbench_error(FATAL, + "error when setting the startup variable \"%s\" for client %d\n", + var->name, i); } } } @@ -6417,7 +6346,7 @@ main(int argc, char **argv) initRandomState(&state[i].random_state); } - if (debug_level >= DEBUG_ALL) + if (DEBUG >= log_level) { if (duration <= 0) printf("pghost: %s pgport: %s nclients: %d nxacts: %d dbName: %s\n", @@ -6433,11 +6362,8 @@ main(int argc, char **argv) exit(1); if (PQstatus(con) == CONNECTION_BAD) - { - fprintf(stderr, "connection to database \"%s\" failed\n", dbName); - fprintf(stderr, "%s", PQerrorMessage(con)); - exit(1); - } + pgbench_error(FATAL, "connection to database \"%s\" failed\n%s", + dbName, PQerrorMessage(con)); if (internal_script_used) { @@ -6450,28 +6376,26 @@ main(int argc, char **argv) { char *sqlState = PQresultErrorField(res, PG_DIAG_SQLSTATE); - fprintf(stderr, "%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)); - } - + pgbench_error(LOG_PGBENCH, + "%sPerhaps you need to do initialization (\"pgbench -i\") in database \"%s\"\n", + PQerrorMessage(con), PQdb(con)); + else + pgbench_error(LOG_PGBENCH, "%s", PQerrorMessage(con)); 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); - } + pgbench_error(FATAL, + "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_PGBENCH, + "scale option ignored, using count from pgbench_branches table (%d)\n", + scale); } /* @@ -6483,12 +6407,9 @@ main(int argc, char **argv) for (i = 0; i < nclients; i++) { if (!putVariableInt(&state[i].variables, "startup", "scale", scale)) - { - fprintf(stderr, - "error when setting the startup variable \"scale\" for client %d\n", - i); - exit(1); - } + pgbench_error(FATAL, + "error when setting the startup variable \"scale\" for client %d\n", + i); } } @@ -6500,12 +6421,9 @@ main(int argc, char **argv) { for (i = 0; i < nclients; i++) if (!putVariableInt(&state[i].variables, "startup", "client_id", i)) - { - fprintf(stderr, - "error when setting the startup variable \"client_id\" for client %d\n", - i); - exit(1); - } + pgbench_error(FATAL, + "error when setting the startup variable \"client_id\" for client %d\n", + i); } /* set default seed for hash functions */ @@ -6519,12 +6437,9 @@ main(int argc, char **argv) for (i = 0; i < nclients; i++) if (!putVariableInt(&state[i].variables, "startup", "default_seed", (int64) seed)) - { - fprintf(stderr, - "error when setting the startup variable \"default_seed\" for client %d\n", - i); - exit(1); - } + pgbench_error(FATAL, + "error when setting the startup variable \"default_seed\" for client %d\n", + i); } /* set random seed unless overwritten */ @@ -6533,27 +6448,24 @@ main(int argc, char **argv) for (i = 0; i < nclients; i++) if (!putVariableInt(&state[i].variables, "startup", "random_seed", random_seed)) - { - fprintf(stderr, - "error when setting the startup variable \"random_seed\" for client %d\n", - i); - exit(1); - } + pgbench_error(FATAL, + "error when setting the startup variable \"random_seed\" for client %d\n", + i); } if (!is_no_vacuum) { - fprintf(stderr, "starting vacuum..."); + pgbench_error(LOG_PGBENCH, "starting vacuum..."); tryExecuteStatement(con, "vacuum pgbench_branches"); tryExecuteStatement(con, "vacuum pgbench_tellers"); tryExecuteStatement(con, "truncate pgbench_history"); - fprintf(stderr, "end.\n"); + pgbench_error(LOG_PGBENCH, "end.\n"); if (do_vacuum_accounts) { - fprintf(stderr, "starting vacuum pgbench_accounts..."); + pgbench_error(LOG_PGBENCH, "starting vacuum pgbench_accounts..."); tryExecuteStatement(con, "vacuum analyze pgbench_accounts"); - fprintf(stderr, "end.\n"); + pgbench_error(LOG_PGBENCH, "end.\n"); } } PQfinish(con); @@ -6612,10 +6524,8 @@ main(int argc, char **argv) int err = pthread_create(&thread->thread, NULL, threadRun, thread); if (err != 0 || thread->thread == INVALID_THREAD) - { - fprintf(stderr, "could not create thread: %s\n", strerror(err)); - exit(1); - } + pgbench_error(FATAL, "could not create thread: %s\n", + strerror(err)); } else { @@ -6729,8 +6639,8 @@ threadRun(void *arg) if (thread->logfile == NULL) { - fprintf(stderr, "could not open logfile \"%s\": %s\n", - logpath, strerror(errno)); + pgbench_error(LOG_PGBENCH, "could not open logfile \"%s\": %s\n", + logpath, strerror(errno)); goto done; } } @@ -6809,8 +6719,8 @@ threadRun(void *arg) if (sock < 0) { - fprintf(stderr, "invalid socket: %s", - PQerrorMessage(st->con)); + pgbench_error(LOG_PGBENCH, "invalid socket: %s", + PQerrorMessage(st->con)); goto done; } @@ -6886,7 +6796,8 @@ threadRun(void *arg) continue; } /* must be something wrong */ - fprintf(stderr, "select() failed: %s\n", strerror(errno)); + pgbench_error(LOG_PGBENCH, "select() failed: %s\n", + strerror(errno)); goto done; } } @@ -6911,8 +6822,8 @@ threadRun(void *arg) if (sock < 0) { - fprintf(stderr, "invalid socket: %s", - PQerrorMessage(st->con)); + pgbench_error(LOG_PGBENCH, "invalid socket: %s", + PQerrorMessage(st->con)); goto done; } @@ -6957,6 +6868,10 @@ threadRun(void *arg) stdev; char tbuf[315]; + /* buffer for an optional part of the progress message */ + char pbuf[512]; + int pbuf_size = 0; + /* * Add up the statistics of all threads. * @@ -7024,27 +6939,35 @@ 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); - if (failures > 0) - fprintf(stderr, ", " INT64_FORMAT " failed", failures); + pbuf_size += snprintf(pbuf + pbuf_size, + sizeof(pbuf) - pbuf_size, + ", " INT64_FORMAT " failed", + failures); if (throttle_delay) { - fprintf(stderr, ", lag %.3f ms", lag); + pbuf_size += snprintf(pbuf + pbuf_size, + sizeof(pbuf) - pbuf_size, + ", lag %.3f ms", lag); if (latency_limit) - fprintf(stderr, ", " INT64_FORMAT " skipped", - cur.skipped - last.skipped); + pbuf_size += snprintf(pbuf + pbuf_size, + sizeof(pbuf) - pbuf_size, + ", " INT64_FORMAT " skipped", + cur.skipped - last.skipped); } /* it can be non-zero only if max_tries is not equal to one */ if (retried > 0) - fprintf(stderr, - ", " INT64_FORMAT " retried, " INT64_FORMAT " retries", - retried, cur.retries - last.retries); - fprintf(stderr, "\n"); + pbuf_size += snprintf( + pbuf + pbuf_size, + sizeof(pbuf) - pbuf_size, + ", " INT64_FORMAT " retried, " INT64_FORMAT " retries", + retried, cur.retries - last.retries); + + pgbench_error(LOG_PGBENCH, + "progress: %s, %.1f tps, lat %.3f ms stddev %.3f%s\n", + tbuf, tps, latency, stdev, pbuf_size ? pbuf : ""); last = cur; last_report = now; @@ -7128,10 +7051,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(FATAL, "failed to set timer\n"); } /* partial pthread implementation for Windows */ @@ -7201,3 +7121,34 @@ pthread_join(pthread_t th, void **thread_return) } #endif /* WIN32 */ + +static void +pgbench_error(ErrorLevel elevel, const char *fmt,...) +{ + va_list ap; + + va_start(ap, fmt); + pgbench_error_va(elevel, fmt, &ap); + va_end(ap); +} + +static void +pgbench_error_va(ErrorLevel elevel, const char *fmt, va_list *args) +{ + /* Determine whether message is enabled for log output */ + if (elevel < log_level) + return; + + if (!fmt || !fmt[0]) + { + /* internal error which should never occur */ + /* do not call pgbench_error recursively */ + fprintf(stderr, "unexpected empty error message\n"); + exit(1); + } + + vfprintf(stderr, _(fmt), *args); + + if (elevel >= FATAL) + exit(1); +} -- 2.17.1