db/pgbackrest
1
0
Fork 0
mirror of https://github.com/pgbackrest/pgbackrest.git synced 2025-03-05 15:05:48 +02:00
Code Issues Releases Activity

Improve log performance, simplify macros, rename logWill() to logAny().

Browse Source 
Pre-calculate the value used by logAny() to improve performance and make it more likely to be inlined.

Move IF_LOG_ANY() into LOG_INTERNAL() to simplify the macros and improve performance of LOG() and LOG_PID().  If the message has no chance of being logged there's no reason to call logInternal().

Rename logWill() to logAny() because it seems more intuitive.
This commit is contained in:
David Steele 2019-05-11 18:20:57 -04:00
parent 87f36e814e
commit 31d0fe5f50
11 changed files with 111 additions and 130 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
doc/xml/release.xml
View File

@ -155,6 +155,10 @@
<p>Add <code>cfgOptionUInt()</code> and <code>cfgOptionUInt64()</code> and update code to use them.</p> <p>Add <code>cfgOptionUInt()</code> and <code>cfgOptionUInt64()</code> and update code to use them.</p>
</release-item> </release-item>
<release-item>
<p>Improve log performance, simplify macros, rename <code>logWill()</code> to <code>logAny()</code>.</p>
</release-item>
<release-item> <release-item>
<p>Use <code>THROW_ON_SYS_ERROR*()</code> to improve code coverage.</p> <p>Use <code>THROW_ON_SYS_ERROR*()</code> to improve code coverage.</p>
</release-item> </release-item>

4
src/command/command.c
View File

@ -44,7 +44,7 @@ cmdBegin(bool logOption)
ASSERT(cfgCommand() != cfgCmdNone); ASSERT(cfgCommand() != cfgCmdNone);
// This is fairly expensive log message to generate so skip it if it won't be output // This is fairly expensive log message to generate so skip it if it won't be output
if (logWill(cfgLogLevelDefault())) if (logAny(cfgLogLevelDefault()))
{ {
MEM_CONTEXT_TEMP_BEGIN() MEM_CONTEXT_TEMP_BEGIN()
{ {
@ -175,7 +175,7 @@ cmdEnd(int code, const String *errorMessage)
ASSERT(cfgCommand() != cfgCmdNone); ASSERT(cfgCommand() != cfgCmdNone);
// Skip this log message if it won't be output. It's not too expensive but since we skipped cmdBegin(), may as well. // Skip this log message if it won't be output. It's not too expensive but since we skipped cmdBegin(), may as well.
if (logWill(cfgLogLevelDefault())) if (logAny(cfgLogLevelDefault()))
{ {
MEM_CONTEXT_TEMP_BEGIN() MEM_CONTEXT_TEMP_BEGIN()
{ {

8
src/common/debug.h
View File

@ -44,13 +44,13 @@ level is set to debug or trace.
#define FUNCTION_LOG_END_BASE() \ #define FUNCTION_LOG_END_BASE() \
stackTraceTestStart(); \ stackTraceTestStart(); \
LOG_WILL(FUNCTION_LOG_LEVEL(), 0, "(%s)", stackTraceParam()); \ LOG(FUNCTION_LOG_LEVEL(), 0, "(%s)", stackTraceParam()); \
} }
#else #else
#define FUNCTION_LOG_BEGIN_BASE(logLevel) \ #define FUNCTION_LOG_BEGIN_BASE(logLevel) \
LogLevel FUNCTION_LOG_LEVEL() = STACK_TRACE_PUSH(logLevel); \ LogLevel FUNCTION_LOG_LEVEL() = STACK_TRACE_PUSH(logLevel); \
\ \
if (logWill(FUNCTION_LOG_LEVEL())) \ if (logAny(FUNCTION_LOG_LEVEL())) \
{ \ { \
stackTraceParamLog(); stackTraceParamLog();
@ -226,7 +226,7 @@ Macros to return function results (or void)
\ \
STACK_TRACE_POP(false); \ STACK_TRACE_POP(false); \
\ \
IF_LOG_WILL(FUNCTION_LOG_LEVEL()) \ IF_LOG_ANY(FUNCTION_LOG_LEVEL()) \
{ \ { \
char buffer[STACK_TRACE_PARAM_MAX]; \ char buffer[STACK_TRACE_PARAM_MAX]; \
\ \
@ -261,7 +261,7 @@ Macros to return function results (or void)
{ \ { \
STACK_TRACE_POP(false); \ STACK_TRACE_POP(false); \
\ \
LOG_WILL(FUNCTION_LOG_LEVEL(), 0, "=> void"); \ LOG(FUNCTION_LOG_LEVEL(), 0, "=> void"); \
} \ } \
while(0) while(0)

2
src/common/exit.c
View File

@ -122,7 +122,7 @@ exitSafe(int result, bool error, SignalType signalType)
LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, logLevelDetail, 0, errorCode(), errorMessage()); LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, logLevelDetail, 0, errorCode(), errorMessage());
// Log the stack trace debug levels // Log the stack trace debug levels
if (logWill(logLevelDebug)) if (logAny(logLevelDebug))
{ {
LOG_INTERNAL( LOG_INTERNAL(
logLevel, logLevelDebug, LOG_LEVEL_MAX, 0, errorCode(), "%s\nSTACK TRACE:\n%s", errorMessage(), logLevel, logLevelDebug, LOG_LEVEL_MAX, 0, errorCode(), "%s\nSTACK TRACE:\n%s", errorMessage(),

101
src/common/log.c
View File

@ -24,6 +24,7 @@ Module variables
DEBUG_UNIT_EXTERN LogLevel logLevelStdOut = logLevelError; DEBUG_UNIT_EXTERN LogLevel logLevelStdOut = logLevelError;
DEBUG_UNIT_EXTERN LogLevel logLevelStdErr = logLevelError; DEBUG_UNIT_EXTERN LogLevel logLevelStdErr = logLevelError;
DEBUG_UNIT_EXTERN LogLevel logLevelFile = logLevelOff; DEBUG_UNIT_EXTERN LogLevel logLevelFile = logLevelOff;
DEBUG_UNIT_EXTERN LogLevel logLevelAny = logLevelError;
// Log file handles // Log file handles
DEBUG_UNIT_EXTERN int logHandleStdOut = STDOUT_FILENO; DEBUG_UNIT_EXTERN int logHandleStdOut = STDOUT_FILENO;
@ -103,6 +104,39 @@ logLevelStr(LogLevel logLevel)
FUNCTION_TEST_RETURN(logLevelList[logLevel]); FUNCTION_TEST_RETURN(logLevelList[logLevel]);
} }
/***********************************************************************************************************************************
Check if a log level will be logged to any output
This is useful for log messages that are expensive to generate and should be skipped if they will be discarded.
***********************************************************************************************************************************/
DEBUG_UNIT_EXTERN void
logAnySet(void)
{
FUNCTION_TEST_VOID();
logLevelAny = logLevelStdOut;
if (logLevelStdErr > logLevelAny)
logLevelAny = logLevelStdErr;
if (logLevelFile > logLevelAny && logHandleFile != -1)
logLevelAny = logLevelFile;
FUNCTION_TEST_RETURN_VOID();
}
bool
logAny(LogLevel logLevel)
{
FUNCTION_TEST_BEGIN();
FUNCTION_TEST_PARAM(ENUM, logLevel);
FUNCTION_TEST_END();
ASSERT_LOG_LEVEL(logLevel);
FUNCTION_TEST_RETURN(logLevel <= logLevelAny);
}
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Initialize the log system Initialize the log system
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
@ -129,6 +163,8 @@ logInit(
logTimestamp = logTimestampParam; logTimestamp = logTimestampParam;
logProcessSize = logProcessMax > 99 ? 3 : 2; logProcessSize = logProcessMax > 99 ? 3 : 2;
logAnySet();
FUNCTION_TEST_RETURN_VOID(); FUNCTION_TEST_RETURN_VOID();
} }
@ -147,6 +183,8 @@ logFileClose(void)
logHandleFile = -1; logHandleFile = -1;
} }
logAnySet();
FUNCTION_TEST_RETURN_VOID(); FUNCTION_TEST_RETURN_VOID();
} }
@ -184,8 +222,12 @@ logFileSet(const char *logFile)
// Output the banner on first log message // Output the banner on first log message
logFileBanner = false; logFileBanner = false;
logAnySet();
} }
logAnySet();
FUNCTION_TEST_RETURN(result); FUNCTION_TEST_RETURN(result);
} }
@ -206,59 +248,6 @@ logClose(void)
FUNCTION_TEST_RETURN_VOID(); FUNCTION_TEST_RETURN_VOID();
} }
/***********************************************************************************************************************************
Check if a log level will be logged to any output
This is useful for log messages that are expensive to generate and should be skipped if they will be discarded.
***********************************************************************************************************************************/
static bool
logWillFile(LogLevel logLevel)
{
FUNCTION_TEST_BEGIN();
FUNCTION_TEST_PARAM(ENUM, logLevel);
FUNCTION_TEST_END();
ASSERT_LOG_LEVEL(logLevel);
FUNCTION_TEST_RETURN(logLevel <= logLevelFile && logHandleFile != -1);
}
static bool
logWillStdErr(LogLevel logLevel)
{
FUNCTION_TEST_BEGIN();
FUNCTION_TEST_PARAM(ENUM, logLevel);
FUNCTION_TEST_END();
ASSERT_LOG_LEVEL(logLevel);
FUNCTION_TEST_RETURN(logLevel <= logLevelStdErr);
}
static bool
logWillStdOut(LogLevel logLevel)
{
FUNCTION_TEST_BEGIN();
FUNCTION_TEST_PARAM(ENUM, logLevel);
FUNCTION_TEST_END();
ASSERT_LOG_LEVEL(logLevel);
FUNCTION_TEST_RETURN(logLevel <= logLevelStdOut);
}
bool
logWill(LogLevel logLevel)
{
FUNCTION_TEST_BEGIN();
FUNCTION_TEST_PARAM(ENUM, logLevel);
FUNCTION_TEST_END();
ASSERT_LOG_LEVEL(logLevel);
FUNCTION_TEST_RETURN(logWillStdOut(logLevel) || logWillStdErr(logLevel) || logWillFile(logLevel));
}
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Determine if the log level is in the specified range Determine if the log level is in the specified range
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
@ -426,16 +415,16 @@ logInternal(
logBuffer[bufferPos] = 0; logBuffer[bufferPos] = 0;
// Determine where to log the message based on log-level-stderr // Determine where to log the message based on log-level-stderr
if (logWillStdErr(logLevel)) if (logLevel <= logLevelStdErr)
{ {
if (logRange(logLevelStdErr, logRangeMin, logRangeMax)) if (logRange(logLevelStdErr, logRangeMin, logRangeMax))
logWriteIndent(logHandleStdErr, logBufferStdErr, indentSize - (size_t)(logBufferStdErr - logBuffer), "log to stderr"); logWriteIndent(logHandleStdErr, logBufferStdErr, indentSize - (size_t)(logBufferStdErr - logBuffer), "log to stderr");
} }
else if (logWillStdOut(logLevel) && logRange(logLevelStdOut, logRangeMin, logRangeMax)) else if (logLevel <= logLevelStdOut && logRange(logLevelStdOut, logRangeMin, logRangeMax))
logWriteIndent(logHandleStdOut, logBuffer, indentSize, "log to stdout"); logWriteIndent(logHandleStdOut, logBuffer, indentSize, "log to stdout");
// Log to file // Log to file
if (logWillFile(logLevel) && logRange(logLevelFile, logRangeMin, logRangeMax)) if (logLevel <= logLevelFile && logHandleFile != -1 && logRange(logLevelFile, logRangeMin, logRangeMax))
{ {
// If the banner has not been written // If the banner has not been written
if (!logFileBanner) if (!logFileBanner)

87
src/common/log.h
View File

@ -24,7 +24,7 @@ void logInit(
void logClose(void); void logClose(void);
bool logFileSet(const char *logFile); bool logFileSet(const char *logFile);
bool logWill(LogLevel logLevel); bool logAny(LogLevel logLevel);
LogLevel logLevelEnum(const char *logLevel); LogLevel logLevelEnum(const char *logLevel);
const char *logLevelStr(LogLevel logLevel); const char *logLevelStr(LogLevel logLevel);
@ -38,66 +38,59 @@ commonly-used values.
Note that it's possible that that not all the macros below will appear in the code. They are included for completeness and future Note that it's possible that that not all the macros below will appear in the code. They are included for completeness and future
usage. usage.
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
// Define a macro to test logAny() that can be removed when performing coverage testing. Checking logAny() saves a function call
// for logging calls that won't be output anywhere, but since the macro then contains a branch it causes coverage problems.
#ifdef DEBUG_COVERAGE
#define IF_LOG_ANY(logLevel)
#else
#define IF_LOG_ANY(logLevel) \
if (logAny(logLevel))
#endif
#define LOG_INTERNAL(logLevel, logRangeMin, logRangeMax, processId, code, ...) \ #define LOG_INTERNAL(logLevel, logRangeMin, logRangeMax, processId, code, ...) \
logInternal(logLevel, logRangeMin, logRangeMax, processId, __FILE__, __func__, code, __VA_ARGS__) do \
{ \
IF_LOG_ANY(logLevel) \
{ \
logInternal(logLevel, logRangeMin, logRangeMax, processId, __FILE__, __func__, code, __VA_ARGS__); \
} \
} while (0)
#define LOG_PID(logLevel, processId, code, ...) \ #define LOG_PID(logLevel, processId, code, ...) \
LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, LOG_LEVEL_MAX, processId, code, __VA_ARGS__) LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, LOG_LEVEL_MAX, processId, code, __VA_ARGS__)
#define LOG_ASSERT_PID(processId, ...) \
LOG_PID(logLevelAssert, processId, errorTypeCode(&AssertError), __VA_ARGS__)
#define LOG_ERROR_PID(processId, code, ...) \
LOG_PID(logLevelError, processId, code, __VA_ARGS__)
#define LOG_WARN_PID(processId, ...) \
LOG_PID(logLevelWarn, processId, 0, __VA_ARGS__)
#define LOG_INFO_PID(processId, ...) \
LOG_PID(logLevelInfo, processId, 0, __VA_ARGS__)
#define LOG_DETAIL_PID(processId, ...) \
LOG_PID(logLevelDetail, processId, 0, __VA_ARGS__)
#define LOG_DEBUG_PID(processId, ...) \
LOG_PID(logLevelDebug, processId, 0, __VA_ARGS__)
#define LOG_TRACE_PID(processId, ...) \
LOG_PID(logLevelTrace, processId, 0, __VA_ARGS__)
#define LOG(logLevel, code, ...) \ #define LOG(logLevel, code, ...) \
LOG_PID(logLevel, 0, code, __VA_ARGS__) LOG_PID(logLevel, 0, code, __VA_ARGS__)
// Define a macro to test logWill() that can be removed when performing coverage testing. Checking logWill() saves a function call
// for logging calls that won't be output anywhere, but since the macro then contains a branch it causes coverage problems.
#ifdef DEBUG_COVERAGE
#define IF_LOG_WILL(logLevel)
#else
#define IF_LOG_WILL(logLevel) \
if (logWill(logLevel))
#endif
#define LOG_WILL(logLevel, code, ...) \
do \
{ \
IF_LOG_WILL(logLevel) \
LOG(logLevel, code, __VA_ARGS__); \
} while(0)
#define LOG_WILL_PID(logLevel, processId, code, ...) \
do \
{ \
IF_LOG_WILL(logLevel) \
LOG_PID(logLevel, processId, code, __VA_ARGS__); \
} while(0)
#define LOG_ASSERT(...) \ #define LOG_ASSERT(...) \
LOG_WILL(logLevelAssert, errorTypeCode(&AssertError), __VA_ARGS__) LOG(logLevelAssert, errorTypeCode(&AssertError), __VA_ARGS__)
#define LOG_ERROR(code, ...) \ #define LOG_ERROR(code, ...) \
LOG_WILL(logLevelError, code, __VA_ARGS__) LOG(logLevelError, code, __VA_ARGS__)
#define LOG_WARN(...) \ #define LOG_WARN(...) \
LOG_WILL(logLevelWarn, 0, __VA_ARGS__) LOG(logLevelWarn, 0, __VA_ARGS__)
#define LOG_INFO(...) \ #define LOG_INFO(...) \
LOG_WILL(logLevelInfo, 0, __VA_ARGS__) LOG(logLevelInfo, 0, __VA_ARGS__)
#define LOG_DETAIL(...) \ #define LOG_DETAIL(...) \
LOG_WILL(logLevelDetail, 0, __VA_ARGS__) LOG(logLevelDetail, 0, __VA_ARGS__)
#define LOG_DEBUG(...) \ #define LOG_DEBUG(...) \
LOG_WILL(logLevelDebug, 0, __VA_ARGS__) LOG(logLevelDebug, 0, __VA_ARGS__)
#define LOG_TRACE(...) \ #define LOG_TRACE(...) \
LOG_WILL(logLevelTrace, 0, __VA_ARGS__) LOG(logLevelTrace, 0, __VA_ARGS__)
#define LOG_ASSERT_PID(processId, ...) \
LOG_WILL_PID(logLevelAssert, processId, errorTypeCode(&AssertError), __VA_ARGS__)
#define LOG_ERROR_PID(processId, code, ...) \
LOG_WILL_PID(logLevelError, processId, code, __VA_ARGS__)
#define LOG_WARN_PID(processId, ...) \
LOG_WILL_PID(logLevelWarn, processId, 0, __VA_ARGS__)
#define LOG_INFO_PID(processId, ...) \
LOG_WILL_PID(logLevelInfo, processId, 0, __VA_ARGS__)
#define LOG_DETAIL_PID(processId, ...) \
LOG_WILL_PID(logLevelDetail, processId, 0, __VA_ARGS__)
#define LOG_DEBUG_PID(processId, ...) \
LOG_WILL_PID(logLevelDebug, processId, 0, __VA_ARGS__)
#define LOG_TRACE_PID(processId, ...) \
LOG_WILL_PID(logLevelTrace, processId, 0, __VA_ARGS__)
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Internal Functions Internal Functions

2
src/protocol/client.c
View File

@ -168,7 +168,7 @@ protocolClientReadOutput(ProtocolClient *this, bool outputRequired)
"%s: %s", strPtr(this->errorPrefix), message == NULL ? "no details available" : strPtr(message)); "%s: %s", strPtr(this->errorPrefix), message == NULL ? "no details available" : strPtr(message));
// Add stack trace if the error is an assertion or debug-level logging is enabled // Add stack trace if the error is an assertion or debug-level logging is enabled
if (type == &AssertError || logWill(logLevelDebug)) if (type == &AssertError || logAny(logLevelDebug))
{ {
const String *stack = varStr(kvGet(responseKv, VARSTR(PROTOCOL_ERROR_STACK_STR))); const String *stack = varStr(kvGet(responseKv, VARSTR(PROTOCOL_ERROR_STACK_STR)));

2
test/src/common/harnessLog.c
View File

@ -20,6 +20,7 @@ Expose log internal data for unit testing/debugging
extern LogLevel logLevelFile; extern LogLevel logLevelFile;
extern int logHandleFile; extern int logHandleFile;
extern bool logFileBanner; extern bool logFileBanner;
extern void logAnySet(void);
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Default log level for testing Default log level for testing
@ -71,6 +72,7 @@ harnessLogInit(void)
snprintf(logFile, sizeof(logFile), "%s/expect.log", testExpectPath()); snprintf(logFile, sizeof(logFile), "%s/expect.log", testExpectPath());
logHandleFile = harnessLogOpen(logFile, O_WRONLY | O_CREAT | O_TRUNC, 0640); logHandleFile = harnessLogOpen(logFile, O_WRONLY | O_CREAT | O_TRUNC, 0640);
logAnySet();
FUNCTION_HARNESS_RESULT_VOID(); FUNCTION_HARNESS_RESULT_VOID();
} }

2
test/src/module/command/commandTest.c
View File

@ -31,6 +31,8 @@ testRun(void)
strLstAddZ(commandParamList, "param1"); strLstAddZ(commandParamList, "param1");
cfgCommandParamSet(commandParamList); cfgCommandParamSet(commandParamList);
harnessLogLevelSet(logLevelInfo);
TEST_RESULT_VOID(cmdBegin(true), "command begin with command parameter"); TEST_RESULT_VOID(cmdBegin(true), "command begin with command parameter");
harnessLogResult( harnessLogResult(
"P00 INFO: archive-get command begin " PROJECT_VERSION ": [param1] --compress"); "P00 INFO: archive-get command begin " PROJECT_VERSION ": [param1] --compress");

28
test/src/module/common/logTest.c
View File

@ -131,34 +131,26 @@ testRun(void)
} }
// ***************************************************************************************************************************** // *****************************************************************************************************************************
if (testBegin("logWill*()")) if (testBegin("logAny*()"))
{ {
logLevelStdOut = logLevelOff; logLevelStdOut = logLevelOff;
logLevelStdErr = logLevelOff; logLevelStdErr = logLevelOff;
logLevelFile = logLevelOff; logLevelFile = logLevelOff;
logHandleFile = -1; logHandleFile = -1;
TEST_RESULT_BOOL(logWill(logLevelError), false, "will not log"); TEST_RESULT_VOID(logAnySet(), "set log any");
TEST_RESULT_BOOL(logWillFile(logLevelError), false, "will not log file"); TEST_RESULT_BOOL(logAny(logLevelError), false, "will not log");
TEST_RESULT_BOOL(logWillStdErr(logLevelError), false, "will not log stderr");
TEST_RESULT_BOOL(logWillStdOut(logLevelError), false, "will not log stdout");
logLevelStdOut = logLevelError;
TEST_RESULT_BOOL(logWill(logLevelError), true, "will log");
TEST_RESULT_BOOL(logWillStdOut(logLevelError), true, "will log stdout");
logLevelStdOut = logLevelOff;
logLevelStdErr = logLevelError; logLevelStdErr = logLevelError;
TEST_RESULT_BOOL(logWill(logLevelError), true, "will log"); TEST_RESULT_VOID(logAnySet(), "set log any");
TEST_RESULT_BOOL(logWillStdErr(logLevelError), true, "will log stderr"); TEST_RESULT_BOOL(logAny(logLevelError), true, "will log");
logLevelStdErr = logLevelOff; logLevelFile = logLevelWarn;
logLevelFile = logLevelError; TEST_RESULT_VOID(logAnySet(), "set log any");
TEST_RESULT_BOOL(logWill(logLevelError), false, "will not log"); TEST_RESULT_BOOL(logAny(logLevelWarn), false, "will not log");
TEST_RESULT_BOOL(logWillFile(logLevelError), false, "will not log file");
logHandleFile = 1; logHandleFile = 1;
TEST_RESULT_BOOL(logWill(logLevelError), true, "will log"); TEST_RESULT_VOID(logAnySet(), "set log any");
TEST_RESULT_BOOL(logWillFile(logLevelError), true, "will log file"); TEST_RESULT_BOOL(logAny(logLevelWarn), true, "will log");
logHandleFile = -1; logHandleFile = -1;
} }

1
test/src/module/config/parseTest.c
View File

@ -14,7 +14,6 @@ Expose log internal data for unit testing/debugging
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
extern LogLevel logLevelStdOut; extern LogLevel logLevelStdOut;
extern LogLevel logLevelStdErr; extern LogLevel logLevelStdErr;
extern LogLevel logLevelFile;
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Option find test -- this is done a lot in the deprecated tests Option find test -- this is done a lot in the deprecated tests