From: Otto Moerbeek Date: Mon, 23 Jan 2023 14:21:47 +0000 (+0100) Subject: Add (relative) microsecond timestamps to traces X-Git-Tag: dnsdist-1.8.0-rc1~38^2~9 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6d437fecd1e21a1c6448dfc2654141813774ddd9;p=thirdparty%2Fpdns.git Add (relative) microsecond timestamps to traces --- diff --git a/pdns/logger.cc b/pdns/logger.cc index 8d34e1ca4c..e290a2c9e6 100644 --- a/pdns/logger.cc +++ b/pdns/logger.cc @@ -202,3 +202,17 @@ Logger& Logger::operator<<(const ComboAddress& ca) *this << ca.toLogString(); return *this; } + +#ifdef RECURSOR +void addTraceTS(const timeval& start, ostringstream& str) +{ + const auto & content = str.str(); + if (content.empty() || content.at(content.size() - 1) == '\n') { + timeval time{}; + gettimeofday(&time, nullptr); + auto elapsed = time - start; + auto diff = elapsed.tv_sec * 1000000 + static_cast(elapsed.tv_usec); + str << diff << ' '; + } +} +#endif diff --git a/pdns/logger.hh b/pdns/logger.hh index d05b532744..61ef70a00c 100644 --- a/pdns/logger.hh +++ b/pdns/logger.hh @@ -176,23 +176,29 @@ Logger& getLogger(); struct LogVariant { string prefix; + timeval start; // variant cannot hold references std::variant v; }; using OptLog = std::optional; + #ifndef RECURSOR // Originally there was a flag but it was never set from !RECURSOR #define VLOG(log, x) VLOG only works in recursor #else -#define VLOG(log, x) \ - if (log) { \ - if (std::holds_alternative((log)->v)) { \ + +void addTraceTS(const timeval& start, ostringstream& str); + +#define VLOG(log, x) \ + if (log) { \ + if (std::holds_alternative((log)->v)) { \ *std::get(log->v) << Logger::Warning << (log)->prefix << x; \ - } \ - else if (std::holds_alternative((log)->v)) { \ - *std::get((log)->v) << (log)->prefix << x; \ - } \ + } \ + else if (std::holds_alternative((log)->v)) { \ + addTraceTS((log)->start, *std::get((log)->v)); \ + *std::get((log)->v) << (log)->prefix << x; \ + } \ } #endif diff --git a/pdns/recursordist/pdns_recursor.cc b/pdns/recursordist/pdns_recursor.cc index 6eea0fd444..1d7ddd6ce0 100644 --- a/pdns/recursordist/pdns_recursor.cc +++ b/pdns/recursordist/pdns_recursor.cc @@ -838,11 +838,15 @@ static bool isEnabledForUDRs(const std::shared_ptr lines; - boost::split(lines, trace, boost::is_any_of("\n")); - int count = 0; - for (const string& line : lines) { - if (!line.empty()) - fprintf(filep.get(), "%04d %s\n", ++count, line.c_str()); - } - fprintf(filep.get(), "\n"); + std::array timebuf; + timestamp(timev, timebuf.data(), timebuf.size()); + fprintf(filep.get(), " us === START OF TRACE %s ===\n", timebuf.data()); + fprintf(filep.get(), "%s", trace.c_str()); + timestamp(now, timebuf.data(), timebuf.size()); + fprintf(filep.get(), "=== END OF TRACE %s ===\n", timebuf.data()); // fclose by unique_ptr does implicit flush } @@ -1092,7 +1094,6 @@ void startDoResolve(void* p) if (t_traceRegex && t_traceRegex->match(dc->d_mdp.d_qname.toString())) { sr.setLogMode(SyncRes::Store); tracedQuery = true; - sr.setId("T"); } if (!g_quiet || tracedQuery) { @@ -1313,7 +1314,7 @@ void startDoResolve(void* p) haveAnswer:; if (tracedQuery || res == -1 || res == RCode::ServFail || pw.getHeader()->rcode == RCode::ServFail) { - dumpTrace(sr.getTrace()); + dumpTrace(sr.getTrace(), sr.d_fixednow); } if (res == -1) { diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc index 9601120506..1fa55f37c0 100644 --- a/pdns/recursordist/syncres.cc +++ b/pdns/recursordist/syncres.cc @@ -469,22 +469,23 @@ bool SyncRes::s_save_parent_ns_set; unsigned int SyncRes::s_max_busy_dot_probes; bool SyncRes::s_addExtendedResolutionDNSErrors; -#define LOG(x) \ - if (d_lm == Log) { \ - g_log << Logger::Warning << x; \ - } \ - else if (d_lm == Store) { \ - d_trace << x; \ +#define LOG(x) \ + if (d_lm == Log) { \ + g_log << Logger::Warning << x; \ + } \ + else if (d_lm == Store) { \ + addTraceTS(d_fixednow, d_trace); \ + d_trace << x; \ } OptLog SyncRes::LogObject(const string& prefix) { OptLog ret; if (d_lm == Log) { - ret = {prefix, &g_log}; + ret = {prefix, d_fixednow, &g_log}; } else if (d_lm == Store) { - ret = {prefix, &d_trace}; + ret = {prefix, d_now, &d_trace}; } return ret; } @@ -517,7 +518,8 @@ static inline void accountAuthLatency(uint64_t usec, int family) } SyncRes::SyncRes(const struct timeval& now) : - d_authzonequeries(0), d_outqueries(0), d_tcpoutqueries(0), d_dotoutqueries(0), d_throttledqueries(0), d_timeouts(0), d_unreachables(0), d_totUsec(0), d_now(now), d_cacheonly(false), d_doDNSSEC(false), d_doEDNS0(false), d_qNameMinimization(s_qnameminimization), d_lm(s_lm) + d_authzonequeries(0), d_outqueries(0), d_tcpoutqueries(0), d_dotoutqueries(0), d_throttledqueries(0), d_timeouts(0), d_unreachables(0), d_totUsec(0), d_fixednow(now), d_now(now), d_cacheonly(false), d_doDNSSEC(false), d_doEDNS0(false), d_qNameMinimization(s_qnameminimization), d_lm(s_lm) + { } @@ -1042,8 +1044,7 @@ bool SyncRes::isForwardOrAuth(const DNSName& qname) const return iter != t_sstorage.domainmap->end(); } -// Will be needed in the future -static const char* timestamp(const struct timeval& tv, char* buf, size_t sz) +const char* timestamp(const struct timeval& tv, char* buf, size_t sz) { const std::string s_timestampFormat = "%Y-%m-%dT%T"; struct tm tm; diff --git a/pdns/recursordist/syncres.hh b/pdns/recursordist/syncres.hh index 50af5bf25b..ef6e27db56 100644 --- a/pdns/recursordist/syncres.hh +++ b/pdns/recursordist/syncres.hh @@ -568,6 +568,7 @@ public: unsigned int d_timeouts; unsigned int d_unreachables; unsigned int d_totUsec; + const struct timeval d_fixednow; private: ComboAddress d_requestor;