refactor(log): reduce compile time LOG_LEVEL granularity
This commit is contained in:
bfredl
parent
6cab36e5b7
commit
2ba224e152
|
|
@ -135,6 +135,7 @@ endif()
|
|||
option(LOG_LIST_ACTIONS "Add list actions logging" OFF)
|
||||
|
||||
option(CLANG_ASAN_UBSAN "Enable Clang address & undefined behavior sanitizer for nvim binary." OFF)
|
||||
option(LOG_DEBUG "Enable debug log messages even in a release build" OFF)
|
||||
option(CLANG_MSAN "Enable Clang memory sanitizer for nvim binary." OFF)
|
||||
option(CLANG_TSAN "Enable Clang thread sanitizer for nvim binary." OFF)
|
||||
|
||||
|
|
|
|||
|
|
@ -33,7 +33,6 @@
|
|||
NIX_CFLAGS_COMPILE = " -ggdb -Og";
|
||||
|
||||
cmakeBuildType = "Debug";
|
||||
cmakeFlags = oa.cmakeFlags ++ [ "-DMIN_LOG_LEVEL=0" ];
|
||||
|
||||
disallowedReferences = [ ];
|
||||
});
|
||||
|
|
@ -45,7 +44,6 @@
|
|||
}).overrideAttrs (oa: {
|
||||
cmakeFlags = oa.cmakeFlags ++ [
|
||||
"-DLUACHECK_PRG=${luacheck}/bin/luacheck"
|
||||
"-DMIN_LOG_LEVEL=0"
|
||||
"-DENABLE_LTO=OFF"
|
||||
] ++ final.lib.optionals final.stdenv.isLinux [
|
||||
# https://github.com/google/sanitizers/wiki/AddressSanitizerFlags
|
||||
|
|
|
|||
|
|
@ -31,9 +31,10 @@
|
|||
# often. You can disable it explicitly:
|
||||
# CMAKE_EXTRA_FLAGS += -DENABLE_LTO=OFF
|
||||
|
||||
# Log levels: 0 (DEBUG), 1 (INFO), 2 (WARNING), 3 (ERROR)
|
||||
# Default is 1 (INFO) unless CMAKE_BUILD_TYPE is Release or RelWithDebInfo.
|
||||
# CMAKE_EXTRA_FLAGS += -DMIN_LOG_LEVEL=1
|
||||
# Log levels: DEBUG, INFO, WARNING, ERROR
|
||||
# For Debug builds all log levels are used
|
||||
# For Release and RelWithDebInfo builds only WARNING and ERROR are used, unless:
|
||||
# CMAKE_EXTRA_FLAGS += -DLOG_DEBUG
|
||||
|
||||
# By default, nvim uses bundled versions of its required third-party
|
||||
# dependencies.
|
||||
|
|
|
|||
|
|
@ -373,19 +373,16 @@ else()
|
|||
${EXTERNAL_SOURCES} PROPERTIES COMPILE_FLAGS "${COMPILE_FLAGS} -Wno-conversion -Wno-missing-noreturn -Wno-missing-format-attribute -Wno-double-promotion -Wno-strict-prototypes -Wno-misleading-indentation")
|
||||
endif()
|
||||
|
||||
# Log level (MIN_LOG_LEVEL in log.h)
|
||||
# Log level (NVIM_LOG_DEBUG in log.h)
|
||||
if($ENV{CI})
|
||||
set(MIN_LOG_LEVEL 3)
|
||||
endif()
|
||||
if("${MIN_LOG_LEVEL}" MATCHES "^$")
|
||||
# Minimize logging for release-type builds.
|
||||
target_compile_definitions(main_lib INTERFACE MIN_LOG_LEVEL=$<IF:$<CONFIG:Debug>,1,3>)
|
||||
# Don't debug log on CI, it gets too verbose in the main build log.
|
||||
# TODO(bfredl): debug log level also exposes some errors with EXITFREE in ASAN build.
|
||||
set(LOG_DEBUG FALSE)
|
||||
elseif(LOG_DEBUG)
|
||||
target_compile_definitions(nvim PRIVATE NVIM_LOG_DEBUG)
|
||||
else()
|
||||
if(NOT MIN_LOG_LEVEL MATCHES "^[0-3]$")
|
||||
message(FATAL_ERROR "invalid MIN_LOG_LEVEL: " ${MIN_LOG_LEVEL})
|
||||
endif()
|
||||
message(STATUS "MIN_LOG_LEVEL=${MIN_LOG_LEVEL}")
|
||||
target_compile_definitions(main_lib INTERFACE MIN_LOG_LEVEL=${MIN_LOG_LEVEL})
|
||||
# Minimize logging for release-type builds.
|
||||
target_compile_definitions(nvim PRIVATE $<$<CONFIG:Debug>:NVIM_LOG_DEBUG>)
|
||||
endif()
|
||||
|
||||
if(CLANG_ASAN_UBSAN OR CLANG_MSAN OR CLANG_TSAN)
|
||||
|
|
|
|||
|
|
@ -29,17 +29,17 @@ Logs
|
|||
|
||||
Low-level log messages sink to `$NVIM_LOG_FILE`.
|
||||
|
||||
UI events are logged at DEBUG level (`LOGLVL_DBG`).
|
||||
UI events are logged at DEBUG level.
|
||||
|
||||
rm -rf build/
|
||||
make CMAKE_EXTRA_FLAGS="-DMIN_LOG_LEVEL=0"
|
||||
make CMAKE_EXTRA_FLAGS="-DLOG_DEBUG"
|
||||
|
||||
Use `LOG_CALLSTACK()` (Linux only) to log the current stacktrace. To log to an
|
||||
alternate file (e.g. stderr) use `LOG_CALLSTACK_TO_FILE(FILE*)`. Requires
|
||||
`-no-pie` ([ref](https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=860394#15)):
|
||||
|
||||
rm -rf build/
|
||||
make CMAKE_EXTRA_FLAGS="-DMIN_LOG_LEVEL=0 -DCMAKE_C_FLAGS=-no-pie"
|
||||
make CMAKE_EXTRA_FLAGS="-DLOG_DEBUG -DCMAKE_C_FLAGS=-no-pie"
|
||||
|
||||
Many log messages have a shared prefix, such as "UI" or "RPC". Use the shell to
|
||||
filter the log, e.g. at DEBUG level you might want to exclude UI messages:
|
||||
|
|
|
|||
|
|
@ -209,7 +209,7 @@ Channel *channel_alloc(ChannelStreamType type)
|
|||
|
||||
void channel_create_event(Channel *chan, const char *ext_source)
|
||||
{
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_INF
|
||||
#ifdef NVIM_LOG_DEBUG
|
||||
const char *source;
|
||||
|
||||
if (ext_source) {
|
||||
|
|
|
|||
|
|
@ -257,9 +257,8 @@ for i = 1, #functions do
|
|||
|
||||
output:write('Object handle_'..fn.name..'(uint64_t channel_id, Array args, Arena* arena, Error *error)')
|
||||
output:write('\n{')
|
||||
output:write('\n#if MIN_LOG_LEVEL <= LOGLVL_DBG')
|
||||
output:write('\n logmsg(LOGLVL_DBG, "RPC: ", NULL, -1, true, "ch %" PRIu64 ": invoke '
|
||||
..fn.name..'", channel_id);')
|
||||
output:write('\n#ifdef NVIM_LOG_DEBUG')
|
||||
output:write('\n DLOG("RPC: ch %" PRIu64 ": invoke '..fn.name..'", channel_id);')
|
||||
output:write('\n#endif')
|
||||
output:write('\n Object ret = NIL;')
|
||||
-- Declare/initialize variables that will hold converted arguments
|
||||
|
|
|
|||
|
|
@ -1095,15 +1095,3 @@ void vim_unescape_ks(char *p)
|
|||
}
|
||||
*d = NUL;
|
||||
}
|
||||
|
||||
/// Logs a single key as a human-readable keycode.
|
||||
void log_key(int log_level, int key)
|
||||
{
|
||||
if (log_level < MIN_LOG_LEVEL) {
|
||||
return;
|
||||
}
|
||||
char *keyname = key == K_EVENT
|
||||
? "K_EVENT"
|
||||
: (char *)get_special_key_name(key, mod_mask);
|
||||
LOG(log_level, "input: %s", keyname);
|
||||
}
|
||||
|
|
|
|||
|
|
@ -141,9 +141,13 @@ bool logmsg(int log_level, const char *context, const char *func_name, int line_
|
|||
return false;
|
||||
}
|
||||
|
||||
if (log_level < MIN_LOG_LEVEL) {
|
||||
#ifndef NVIM_LOG_DEBUG
|
||||
// This should rarely happen (callsites are compiled out), but to be sure.
|
||||
// TODO(bfredl): allow log levels to be configured at runtime
|
||||
if (log_level < LOGLVL_WRN) {
|
||||
return false;
|
||||
}
|
||||
#endif
|
||||
|
||||
#ifdef EXITFREE
|
||||
// Logging after we've already started freeing all our memory will only cause
|
||||
|
|
|
|||
|
|
@ -17,54 +17,29 @@
|
|||
# define NVIM_PROBE(name, n, ...)
|
||||
#endif
|
||||
|
||||
#define LOGLVL_TRC 0
|
||||
#define LOGLVL_DBG 1
|
||||
#define LOGLVL_INF 2
|
||||
#define LOGLVL_WRN 3
|
||||
#define LOGLVL_ERR 4
|
||||
|
||||
#define DLOG(...)
|
||||
#define DLOGN(...)
|
||||
#define ILOG(...)
|
||||
#define ILOGN(...)
|
||||
#define WLOG(...)
|
||||
#define WLOGN(...)
|
||||
#define ELOG(...)
|
||||
#define ELOGN(...)
|
||||
|
||||
#ifndef MIN_LOG_LEVEL
|
||||
# define MIN_LOG_LEVEL LOGLVL_INF
|
||||
#endif
|
||||
|
||||
#define LOG(level, ...) logmsg((level), NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_DBG
|
||||
# undef DLOG
|
||||
# undef DLOGN
|
||||
#ifdef NVIM_LOG_DEBUG
|
||||
# define DLOG(...) logmsg(LOGLVL_DBG, NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
# define DLOGN(...) logmsg(LOGLVL_DBG, NULL, __func__, __LINE__, false, __VA_ARGS__)
|
||||
#endif
|
||||
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_INF
|
||||
# undef ILOG
|
||||
# undef ILOGN
|
||||
# define ILOG(...) logmsg(LOGLVL_INF, NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
# define ILOGN(...) logmsg(LOGLVL_INF, NULL, __func__, __LINE__, false, __VA_ARGS__)
|
||||
#else
|
||||
# define DLOG(...)
|
||||
# define DLOGN(...)
|
||||
# define ILOG(...)
|
||||
# define ILOGN(...)
|
||||
#endif
|
||||
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_WRN
|
||||
# undef WLOG
|
||||
# undef WLOGN
|
||||
# define WLOG(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
# define WLOGN(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, false, __VA_ARGS__)
|
||||
#endif
|
||||
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_ERR
|
||||
# undef ELOG
|
||||
# undef ELOGN
|
||||
# define ELOG(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
# define ELOGN(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, false, __VA_ARGS__)
|
||||
#endif
|
||||
#define WLOG(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
#define WLOGN(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, false, __VA_ARGS__)
|
||||
#define ELOG(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, true, __VA_ARGS__)
|
||||
#define ELOGN(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, false, __VA_ARGS__)
|
||||
|
||||
#ifdef HAVE_EXECINFO_BACKTRACE
|
||||
# define LOG_CALLSTACK() log_callstack(__func__, __LINE__)
|
||||
|
|
|
|||
|
|
@ -39,7 +39,73 @@
|
|||
#include "nvim/ui.h"
|
||||
#include "nvim/ui_client.h"
|
||||
|
||||
#if MIN_LOG_LEVEL > LOGLVL_DBG
|
||||
#ifdef NVIM_LOG_DEBUG
|
||||
# define REQ "[request] "
|
||||
# define RES "[response] "
|
||||
# define NOT "[notify] "
|
||||
# define ERR "[error] "
|
||||
|
||||
// Cannot define array with negative offsets, so this one is needed to be added
|
||||
// to MSGPACK_UNPACK_\* values.
|
||||
# define MUR_OFF 2
|
||||
|
||||
static const char *const msgpack_error_messages[] = {
|
||||
[MSGPACK_UNPACK_EXTRA_BYTES + MUR_OFF] = "extra bytes found",
|
||||
[MSGPACK_UNPACK_CONTINUE + MUR_OFF] = "incomplete string",
|
||||
[MSGPACK_UNPACK_PARSE_ERROR + MUR_OFF] = "parse error",
|
||||
[MSGPACK_UNPACK_NOMEM_ERROR + MUR_OFF] = "not enough memory",
|
||||
};
|
||||
|
||||
static void log_close(FILE *f)
|
||||
{
|
||||
fputc('\n', f);
|
||||
fflush(f);
|
||||
fclose(f);
|
||||
log_unlock();
|
||||
}
|
||||
|
||||
static void log_server_msg(uint64_t channel_id, msgpack_sbuffer *packed)
|
||||
{
|
||||
msgpack_unpacked unpacked;
|
||||
msgpack_unpacked_init(&unpacked);
|
||||
DLOGN("RPC ->ch %" PRIu64 ": ", channel_id);
|
||||
const msgpack_unpack_return result =
|
||||
msgpack_unpack_next(&unpacked, packed->data, packed->size, NULL);
|
||||
switch (result) {
|
||||
case MSGPACK_UNPACK_SUCCESS: {
|
||||
uint64_t type = unpacked.data.via.array.ptr[0].via.u64;
|
||||
log_lock();
|
||||
FILE *f = open_log_file();
|
||||
fprintf(f, type ? (type == 1 ? RES : NOT) : REQ);
|
||||
msgpack_object_print(f, unpacked.data);
|
||||
log_close(f);
|
||||
msgpack_unpacked_destroy(&unpacked);
|
||||
break;
|
||||
}
|
||||
case MSGPACK_UNPACK_EXTRA_BYTES:
|
||||
case MSGPACK_UNPACK_CONTINUE:
|
||||
case MSGPACK_UNPACK_PARSE_ERROR:
|
||||
case MSGPACK_UNPACK_NOMEM_ERROR: {
|
||||
log_lock();
|
||||
FILE *f = open_log_file();
|
||||
fprintf(f, ERR);
|
||||
fprintf(f, "%s", msgpack_error_messages[result + MUR_OFF]);
|
||||
log_close(f);
|
||||
break;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
static void log_client_msg(uint64_t channel_id, bool is_request, const char *name)
|
||||
{
|
||||
DLOGN("RPC <-ch %" PRIu64 ": ", channel_id);
|
||||
log_lock();
|
||||
FILE *f = open_log_file();
|
||||
fprintf(f, "%s: %s", is_request ? REQ : RES, name);
|
||||
log_close(f);
|
||||
}
|
||||
|
||||
#else
|
||||
# define log_client_msg(...)
|
||||
# define log_server_msg(...)
|
||||
#endif
|
||||
|
|
@ -71,7 +137,7 @@ void rpc_start(Channel *channel)
|
|||
|
||||
if (channel->streamtype != kChannelStreamInternal) {
|
||||
Stream *out = channel_outstream(channel);
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_DBG
|
||||
#ifdef NVIM_LOG_DEBUG
|
||||
Stream *in = channel_instream(channel);
|
||||
DLOG("rpc ch %" PRIu64 " in-stream=%p out-stream=%p", channel->id,
|
||||
(void *)in, (void *)out);
|
||||
|
|
@ -668,70 +734,3 @@ const char *rpc_client_name(Channel *chan)
|
|||
|
||||
return NULL;
|
||||
}
|
||||
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_DBG
|
||||
# define REQ "[request] "
|
||||
# define RES "[response] "
|
||||
# define NOT "[notify] "
|
||||
# define ERR "[error] "
|
||||
|
||||
// Cannot define array with negative offsets, so this one is needed to be added
|
||||
// to MSGPACK_UNPACK_\* values.
|
||||
# define MUR_OFF 2
|
||||
|
||||
static const char *const msgpack_error_messages[] = {
|
||||
[MSGPACK_UNPACK_EXTRA_BYTES + MUR_OFF] = "extra bytes found",
|
||||
[MSGPACK_UNPACK_CONTINUE + MUR_OFF] = "incomplete string",
|
||||
[MSGPACK_UNPACK_PARSE_ERROR + MUR_OFF] = "parse error",
|
||||
[MSGPACK_UNPACK_NOMEM_ERROR + MUR_OFF] = "not enough memory",
|
||||
};
|
||||
|
||||
static void log_server_msg(uint64_t channel_id, msgpack_sbuffer *packed)
|
||||
{
|
||||
msgpack_unpacked unpacked;
|
||||
msgpack_unpacked_init(&unpacked);
|
||||
DLOGN("RPC ->ch %" PRIu64 ": ", channel_id);
|
||||
const msgpack_unpack_return result =
|
||||
msgpack_unpack_next(&unpacked, packed->data, packed->size, NULL);
|
||||
switch (result) {
|
||||
case MSGPACK_UNPACK_SUCCESS: {
|
||||
uint64_t type = unpacked.data.via.array.ptr[0].via.u64;
|
||||
log_lock();
|
||||
FILE *f = open_log_file();
|
||||
fprintf(f, type ? (type == 1 ? RES : NOT) : REQ);
|
||||
msgpack_object_print(f, unpacked.data);
|
||||
log_close(f);
|
||||
msgpack_unpacked_destroy(&unpacked);
|
||||
break;
|
||||
}
|
||||
case MSGPACK_UNPACK_EXTRA_BYTES:
|
||||
case MSGPACK_UNPACK_CONTINUE:
|
||||
case MSGPACK_UNPACK_PARSE_ERROR:
|
||||
case MSGPACK_UNPACK_NOMEM_ERROR: {
|
||||
log_lock();
|
||||
FILE *f = open_log_file();
|
||||
fprintf(f, ERR);
|
||||
fprintf(f, "%s", msgpack_error_messages[result + MUR_OFF]);
|
||||
log_close(f);
|
||||
break;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
static void log_client_msg(uint64_t channel_id, bool is_request, const char *name)
|
||||
{
|
||||
DLOGN("RPC <-ch %" PRIu64 ": ", channel_id);
|
||||
log_lock();
|
||||
FILE *f = open_log_file();
|
||||
fprintf(f, "%s: %s", is_request ? REQ : RES, name);
|
||||
log_close(f);
|
||||
}
|
||||
|
||||
static void log_close(FILE *f)
|
||||
{
|
||||
fputc('\n', f);
|
||||
fflush(f);
|
||||
fclose(f);
|
||||
log_unlock();
|
||||
}
|
||||
#endif
|
||||
|
|
|
|||
|
|
@ -92,8 +92,9 @@ getkey:
|
|||
may_sync_undo();
|
||||
}
|
||||
|
||||
#if MIN_LOG_LEVEL <= LOGLVL_DBG
|
||||
log_key(LOGLVL_DBG, key);
|
||||
#ifdef NVIM_LOG_DEBUG
|
||||
char *keyname = key == K_EVENT ? "K_EVENT" : (char *)get_special_key_name(key, mod_mask);
|
||||
DLOG("input: %s", keyname);
|
||||
#endif
|
||||
|
||||
int execute_result = s->execute(s, key);
|
||||
|
|
|
|||
|
|
@ -63,9 +63,7 @@ static int pending_has_mouse = -1;
|
|||
|
||||
static Array call_buf = ARRAY_DICT_INIT;
|
||||
|
||||
#if MIN_LOG_LEVEL > LOGLVL_DBG
|
||||
# define ui_log(funname)
|
||||
#else
|
||||
#ifdef NVIM_LOG_DEBUG
|
||||
static size_t uilog_seen = 0;
|
||||
static const char *uilog_last_event = NULL;
|
||||
|
||||
|
|
@ -89,6 +87,8 @@ static void ui_log(const char *funname)
|
|||
uilog_last_event = funname;
|
||||
}
|
||||
}
|
||||
#else
|
||||
# define ui_log(funname)
|
||||
#endif
|
||||
|
||||
// UI_CALL invokes a function on all registered UI instances.
|
||||
|
|
|
|||
|
|
@ -58,7 +58,6 @@ main() {
|
|||
includes="$includes -I/host-includes"
|
||||
|
||||
local defines=
|
||||
defines="$defines -DMIN_LOG_LEVEL=9999"
|
||||
defines="$defines -DINCLUDE_GENERATED_DECLARATIONS"
|
||||
|
||||
test -z "$compile" && defines="$defines -DUSE_KLEE"
|
||||
|
|
|
|||
Loading…
Reference in New Issue