From: Petr Špaček Date: Wed, 25 Mar 2020 12:21:49 +0000 (+0100) Subject: policy.DEBUG_IF: avoid creating new callbacks on every request X-Git-Tag: v5.1.0~26^2~2 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=d3eb8041eb660c4e99ba7d432472ef3699e6affc;p=thirdparty%2Fknot-resolver.git policy.DEBUG_IF: avoid creating new callbacks on every request This new approach uses per-request variables in Lua and creates new callback for each DEBUG_IF call instead of each request. --- diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua index 2a94e4d24..377433875 100644 --- a/daemon/lua/kres-gen.lua +++ b/daemon/lua/kres-gen.lua @@ -15,7 +15,7 @@ typedef struct knot_mm { typedef void *(*map_alloc_f)(void *, size_t); typedef void (*map_free_f)(void *baton, void *ptr); -typedef void (*trace_log_f) (const char *); +typedef void (*trace_log_f) (const struct kr_request *, const char *); typedef void (*trace_callback_f)(struct kr_request *); typedef enum {KNOT_ANSWER, KNOT_AUTHORITY, KNOT_ADDITIONAL} knot_section_t; typedef struct { diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh index accbdd0fc..6dd0f2d63 100755 --- a/daemon/lua/kres-gen.sh +++ b/daemon/lua/kres-gen.sh @@ -69,7 +69,7 @@ typedef struct knot_mm { typedef void *(*map_alloc_f)(void *, size_t); typedef void (*map_free_f)(void *baton, void *ptr); -typedef void (*trace_log_f) (const char *); +typedef void (*trace_log_f) (const struct kr_request *, const char *); typedef void (*trace_callback_f)(struct kr_request *); " diff --git a/daemon/lua/kres.lua b/daemon/lua/kres.lua index 349e7c266..a223a12b5 100644 --- a/daemon/lua/kres.lua +++ b/daemon/lua/kres.lua @@ -726,13 +726,21 @@ ffi.metatype( kr_query_t, { -- helper for trace_chain_callbacks -- ignores return values from successfull calls but logs tracebacks for throws -local function void_xpcall_log_tb(func, arg) - local ok, err = xpcall(func, debug.traceback, arg) +local function void_xpcall_log_tb(func, req, msg) + local ok, err = xpcall(func, debug.traceback, req, msg) if not ok then - log('error: callback %s arg %s stack traceback:\n%s', func, arg, err) + log('error: callback %s req %s msg %s stack traceback:\n%s', func, req, msg, err) end end +local function void_xpcall_finish_tb(func, req) + local ok, err = xpcall(func, debug.traceback, req) + if not ok then + log('error: callback %s req %s stack traceback:\n%s', func, req, err) + end +end + + -- Metatype for request local kr_request_t = ffi.typeof('struct kr_request') ffi.metatype( kr_request_t, { @@ -822,10 +830,10 @@ ffi.metatype( kr_request_t, { else local old_log = req.trace_log log_wrapper = ffi.cast('trace_log_f', - function(msg) + function(cbreq, msg) jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed - void_xpcall_log_tb(old_log, msg) - void_xpcall_log_tb(new_log, msg) + void_xpcall_log_tb(old_log, cbreq, msg) + void_xpcall_log_tb(new_log, cbreq, msg) end) req.trace_log = log_wrapper end @@ -838,10 +846,10 @@ ffi.metatype( kr_request_t, { function(cbreq) jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed if old_finish ~= nil then - void_xpcall_log_tb(old_finish, cbreq) + void_xpcall_finish_tb(old_finish, cbreq) end if new_finish ~= nil then - void_xpcall_log_tb(new_finish, cbreq) + void_xpcall_finish_tb(new_finish, cbreq) end -- beware: finish callbacks can call log callback if log_wrapper ~= nil then diff --git a/lib/utils.c b/lib/utils.c index 3998699f2..2755d65f6 100644 --- a/lib/utils.c +++ b/lib/utils.c @@ -134,7 +134,7 @@ static void kr_vlog_req( msg = mp_vprintf_append(mp, msg, fmt, args); if (kr_log_rtrace_enabled(req)) - req->trace_log(msg); + req->trace_log(req, msg); else /* caller is responsible for detecting verbose mode, use QRVERBOSE() macro */ printf("%s", msg); diff --git a/lib/utils.h b/lib/utils.h index a99170e69..2eb4b7636 100644 --- a/lib/utils.h +++ b/lib/utils.h @@ -37,7 +37,7 @@ typedef void (*trace_callback_f)(struct kr_request *request); /** * @brief Callback for request logging handler. * @param[in] msg Log message. Pointer is not valid after handler returns. */ -typedef void (*trace_log_f)(const char *msg); +typedef void (*trace_log_f)(const struct kr_request *request, const char *msg); #define kr_log_info printf #define kr_log_error(...) fprintf(stderr, ## __VA_ARGS__) diff --git a/modules/http/http_trace.lua b/modules/http/http_trace.lua index 153e072f4..a9764d5a1 100644 --- a/modules/http/http_trace.lua +++ b/modules/http/http_trace.lua @@ -22,7 +22,7 @@ local function serve_trace(h, _) -- Create logging handler callback local buffer = {} - local buffer_log_cb = ffi.cast('trace_log_f', function (msg) + local buffer_log_cb = ffi.cast('trace_log_f', function (_, msg) table.insert(buffer, ffi.string(msg)) end) diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua index 138a84680..683c68a96 100644 --- a/modules/policy/policy.lua +++ b/modules/policy/policy.lua @@ -528,11 +528,16 @@ function policy.DENY_MSG(msg) end end -local debug_logline_cb = ffi.cast('trace_log_f', function (msg) +local function free_cb(func) + func:free() +end + +local debug_logline_cb = ffi.cast('trace_log_f', function (_, msg) jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed -- msg typically ends with newline io.write(ffi.string(msg)) end) +ffi.gc(debug_logline_cb, free_cb) local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req) jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed @@ -543,6 +548,7 @@ local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req) 'answer packet:\n' .. tostring(req.answer)) end) +ffi.gc(debug_logfinish_cb, free_cb) -- log request packet function policy.REQTRACE(_, req) @@ -556,29 +562,31 @@ function policy.DEBUG_ALWAYS(state, req) policy.REQTRACE(state, req) end +local debug_stashlog_cb = ffi.cast('trace_log_f', function (req, msg) + jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed + + -- stash messages for conditional logging in trace_finish + local stash = req:vars()['policy_debug_stash'] + table.insert(stash, ffi.string(msg)) +end) +ffi.gc(debug_stashlog_cb, free_cb) + -- buffer verbose logs and print then only if test() returns a truthy value function policy.DEBUG_IF(test) + local debug_finish_cb = ffi.cast('trace_callback_f', function (cbreq) + jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed + if test(cbreq) then + debug_logfinish_cb(cbreq) -- unconditional version + local stash = cbreq:vars()['policy_debug_stash'] + io.write(table.concat(stash, '')) + end + end) + ffi.gc(debug_finish_cb, function (func) func:free() end) + return function (state, req) + req:vars()['policy_debug_stash'] = {} policy.QTRACE(state, req) - local priv_log_buf = {} - local priv_log_cb = ffi.cast('trace_log_f', function (msg) - jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed - - -- stash messages for conditional logging in trace_finish - table.insert(priv_log_buf, ffi.string(msg)) - end) - - local priv_finish_cb - priv_finish_cb = ffi.cast('trace_callback_f', function (cbreq) - jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed - if test(cbreq) then - debug_logfinish_cb(cbreq) -- unconditional version - io.write(table.concat(priv_log_buf, '')) - end - priv_log_cb:free() - priv_finish_cb:free() - end) - req:trace_chain_callbacks(priv_log_cb, priv_finish_cb) + req:trace_chain_callbacks(debug_stashlog_cb, debug_finish_cb) policy.REQTRACE(state, req) return end diff --git a/modules/watchdog/watchdog.lua b/modules/watchdog/watchdog.lua index f51da18b4..1a8065fdd 100644 --- a/modules/watchdog/watchdog.lua +++ b/modules/watchdog/watchdog.lua @@ -22,7 +22,7 @@ end -- logging local function add_tracer(logbuf) return function (req) - local function qrylogger(msg) + local function qrylogger(_, msg) table.insert(logbuf, ffi.string(msg)) end req.trace_log = ffi.cast('trace_log_f', qrylogger)