Skip to content
Permalink
Browse files

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

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.
  • Loading branch information...
dwsteele committed May 11, 2019
1 parent 87f36e8 commit 31d0fe5f50a1a061c3ffbf7d194fafffee6a34b7
@@ -155,6 +155,10 @@
<p>Add <code>cfgOptionUInt()</code> and <code>cfgOptionUInt64()</code> and update code to use them.</p>
</release-item>

<release-item>
<p>Improve log performance, simplify macros, rename <code>logWill()</code> to <code>logAny()</code>.</p>
</release-item>

<release-item>
<p>Use <code>THROW_ON_SYS_ERROR*()</code> to improve code coverage.</p>
</release-item>
@@ -44,7 +44,7 @@ cmdBegin(bool logOption)
ASSERT(cfgCommand() != cfgCmdNone);

// 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()
{
@@ -175,7 +175,7 @@ cmdEnd(int code, const String *errorMessage)
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.
if (logWill(cfgLogLevelDefault()))
if (logAny(cfgLogLevelDefault()))
{
MEM_CONTEXT_TEMP_BEGIN()
{
@@ -44,13 +44,13 @@ level is set to debug or trace.

#define FUNCTION_LOG_END_BASE() \
stackTraceTestStart(); \
LOG_WILL(FUNCTION_LOG_LEVEL(), 0, "(%s)", stackTraceParam()); \
LOG(FUNCTION_LOG_LEVEL(), 0, "(%s)", stackTraceParam()); \
}
#else
#define FUNCTION_LOG_BEGIN_BASE(logLevel) \
LogLevel FUNCTION_LOG_LEVEL() = STACK_TRACE_PUSH(logLevel); \
\
if (logWill(FUNCTION_LOG_LEVEL())) \
if (logAny(FUNCTION_LOG_LEVEL())) \
{ \
stackTraceParamLog();

@@ -226,7 +226,7 @@ Macros to return function results (or void)
\
STACK_TRACE_POP(false); \
\
IF_LOG_WILL(FUNCTION_LOG_LEVEL()) \
IF_LOG_ANY(FUNCTION_LOG_LEVEL()) \
{ \
char buffer[STACK_TRACE_PARAM_MAX]; \
\
@@ -261,7 +261,7 @@ Macros to return function results (or void)
{ \
STACK_TRACE_POP(false); \
\
LOG_WILL(FUNCTION_LOG_LEVEL(), 0, "=> void"); \
LOG(FUNCTION_LOG_LEVEL(), 0, "=> void"); \
} \
while(0)

@@ -122,7 +122,7 @@ exitSafe(int result, bool error, SignalType signalType)
LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, logLevelDetail, 0, errorCode(), errorMessage());

// Log the stack trace debug levels
if (logWill(logLevelDebug))
if (logAny(logLevelDebug))
{
LOG_INTERNAL(
logLevel, logLevelDebug, LOG_LEVEL_MAX, 0, errorCode(), "%s\nSTACK TRACE:\n%s", errorMessage(),
@@ -24,6 +24,7 @@ Module variables
DEBUG_UNIT_EXTERN LogLevel logLevelStdOut = logLevelError;
DEBUG_UNIT_EXTERN LogLevel logLevelStdErr = logLevelError;
DEBUG_UNIT_EXTERN LogLevel logLevelFile = logLevelOff;
DEBUG_UNIT_EXTERN LogLevel logLevelAny = logLevelError;

// Log file handles
DEBUG_UNIT_EXTERN int logHandleStdOut = STDOUT_FILENO;
@@ -103,6 +104,39 @@ logLevelStr(LogLevel 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
***********************************************************************************************************************************/
@@ -129,6 +163,8 @@ logInit(
logTimestamp = logTimestampParam;
logProcessSize = logProcessMax > 99 ? 3 : 2;

logAnySet();

FUNCTION_TEST_RETURN_VOID();
}

@@ -147,6 +183,8 @@ logFileClose(void)
logHandleFile = -1;
}

logAnySet();

FUNCTION_TEST_RETURN_VOID();
}

@@ -184,8 +222,12 @@ logFileSet(const char *logFile)

// Output the banner on first log message
logFileBanner = false;

logAnySet();
}

logAnySet();

FUNCTION_TEST_RETURN(result);
}

@@ -206,59 +248,6 @@ logClose(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
***********************************************************************************************************************************/
@@ -426,16 +415,16 @@ logInternal(
logBuffer[bufferPos] = 0;

// Determine where to log the message based on log-level-stderr
if (logWillStdErr(logLevel))
if (logLevel <= logLevelStdErr)
{
if (logRange(logLevelStdErr, logRangeMin, logRangeMax))
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");

// 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 (!logFileBanner)
@@ -24,7 +24,7 @@ void logInit(
void logClose(void);
bool logFileSet(const char *logFile);

bool logWill(LogLevel logLevel);
bool logAny(LogLevel logLevel);

LogLevel logLevelEnum(const char *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
usage.
***********************************************************************************************************************************/
#define LOG_INTERNAL(logLevel, logRangeMin, logRangeMax, processId, code, ...) \
logInternal(logLevel, logRangeMin, logRangeMax, processId, __FILE__, __func__, code, __VA_ARGS__)

#define LOG_PID(logLevel, processId, code, ...) \
LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, LOG_LEVEL_MAX, processId, code, __VA_ARGS__)
#define LOG(logLevel, code, ...) \
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
// 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_WILL(logLevel)
#define IF_LOG_ANY(logLevel)
#else
#define IF_LOG_WILL(logLevel) \
if (logWill(logLevel))
#define IF_LOG_ANY(logLevel) \
if (logAny(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, ...) \
#define LOG_INTERNAL(logLevel, logRangeMin, logRangeMax, processId, code, ...) \
do \
{ \
IF_LOG_WILL(logLevel) \
LOG_PID(logLevel, processId, code, __VA_ARGS__); \
} while(0)
IF_LOG_ANY(logLevel) \
{ \
logInternal(logLevel, logRangeMin, logRangeMax, processId, __FILE__, __func__, code, __VA_ARGS__); \
} \
} while (0)

#define LOG_ASSERT(...) \
LOG_WILL(logLevelAssert, errorTypeCode(&AssertError), __VA_ARGS__)
#define LOG_ERROR(code, ...) \
LOG_WILL(logLevelError, code, __VA_ARGS__)
#define LOG_WARN(...) \
LOG_WILL(logLevelWarn, 0, __VA_ARGS__)
#define LOG_INFO(...) \
LOG_WILL(logLevelInfo, 0, __VA_ARGS__)
#define LOG_DETAIL(...) \
LOG_WILL(logLevelDetail, 0, __VA_ARGS__)
#define LOG_DEBUG(...) \
LOG_WILL(logLevelDebug, 0, __VA_ARGS__)
#define LOG_TRACE(...) \
LOG_WILL(logLevelTrace, 0, __VA_ARGS__)
#define LOG_PID(logLevel, processId, code, ...) \
LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, LOG_LEVEL_MAX, processId, code, __VA_ARGS__)

#define LOG_ASSERT_PID(processId, ...) \
LOG_WILL_PID(logLevelAssert, processId, errorTypeCode(&AssertError), __VA_ARGS__)
LOG_PID(logLevelAssert, processId, errorTypeCode(&AssertError), __VA_ARGS__)
#define LOG_ERROR_PID(processId, code, ...) \
LOG_WILL_PID(logLevelError, processId, code, __VA_ARGS__)
LOG_PID(logLevelError, processId, code, __VA_ARGS__)
#define LOG_WARN_PID(processId, ...) \
LOG_WILL_PID(logLevelWarn, processId, 0, __VA_ARGS__)
LOG_PID(logLevelWarn, processId, 0, __VA_ARGS__)
#define LOG_INFO_PID(processId, ...) \
LOG_WILL_PID(logLevelInfo, processId, 0, __VA_ARGS__)
LOG_PID(logLevelInfo, processId, 0, __VA_ARGS__)
#define LOG_DETAIL_PID(processId, ...) \
LOG_WILL_PID(logLevelDetail, processId, 0, __VA_ARGS__)
LOG_PID(logLevelDetail, processId, 0, __VA_ARGS__)
#define LOG_DEBUG_PID(processId, ...) \
LOG_WILL_PID(logLevelDebug, processId, 0, __VA_ARGS__)
LOG_PID(logLevelDebug, processId, 0, __VA_ARGS__)
#define LOG_TRACE_PID(processId, ...) \
LOG_WILL_PID(logLevelTrace, processId, 0, __VA_ARGS__)
LOG_PID(logLevelTrace, processId, 0, __VA_ARGS__)

#define LOG(logLevel, code, ...) \
LOG_PID(logLevel, 0, code, __VA_ARGS__)

#define LOG_ASSERT(...) \
LOG(logLevelAssert, errorTypeCode(&AssertError), __VA_ARGS__)
#define LOG_ERROR(code, ...) \
LOG(logLevelError, code, __VA_ARGS__)
#define LOG_WARN(...) \
LOG(logLevelWarn, 0, __VA_ARGS__)
#define LOG_INFO(...) \
LOG(logLevelInfo, 0, __VA_ARGS__)
#define LOG_DETAIL(...) \
LOG(logLevelDetail, 0, __VA_ARGS__)
#define LOG_DEBUG(...) \
LOG(logLevelDebug, 0, __VA_ARGS__)
#define LOG_TRACE(...) \
LOG(logLevelTrace, 0, __VA_ARGS__)

/***********************************************************************************************************************************
Internal Functions
@@ -168,7 +168,7 @@ protocolClientReadOutput(ProtocolClient *this, bool outputRequired)
"%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
if (type == &AssertError || logWill(logLevelDebug))
if (type == &AssertError || logAny(logLevelDebug))
{
const String *stack = varStr(kvGet(responseKv, VARSTR(PROTOCOL_ERROR_STACK_STR)));

Oops, something went wrong.

0 comments on commit 31d0fe5

Please sign in to comment.
You can’t perform that action at this time.