From ebced74b194be22a490b055ee9cd939a367c3150 Mon Sep 17 00:00:00 2001 From: Patrick McLean Date: Fri, 19 Mar 2021 22:48:22 -0700 Subject: [PATCH 1/3] Add isc_time_now_hires function to get current time with high resolution The current isc_time_now uses CLOCK_REALTIME_COARSE which only updates on a timer tick. This clock is generally fine for millisecond accuracy, but on servers with 100hz clocks, this clock is nowhere near accurate enough for microsecond accuracy. This commit adds a new isc_time_now_hires function that uses CLOCK_REALTIME, which gives the current time, though it is somewhat expensive to call. When microsecond accuracy is required, it may be required to use extra resources for higher accuracy. --- lib/isc/include/isc/util.h | 2 ++ lib/isc/tests/time_test.c | 4 ++-- lib/isc/unix/include/isc/time.h | 20 ++++++++++++++++++++ lib/isc/unix/time.c | 24 +++++++++++++++++++++--- lib/isc/win32/include/isc/time.h | 20 ++++++++++++++++++++ lib/isc/win32/libisc.def.in | 1 + lib/isc/win32/time.c | 9 +++++++++ 7 files changed, 75 insertions(+), 5 deletions(-) diff --git a/lib/isc/include/isc/util.h b/lib/isc/include/isc/util.h index 3c8c40b679..2d99015034 100644 --- a/lib/isc/include/isc/util.h +++ b/lib/isc/include/isc/util.h @@ -340,6 +340,8 @@ mock_assert(const int result, const char *const expression, * Time */ #define TIME_NOW(tp) RUNTIME_CHECK(isc_time_now((tp)) == ISC_R_SUCCESS) +#define TIME_NOW_HIRES(tp) \ + RUNTIME_CHECK(isc_time_now_hires((tp)) == ISC_R_SUCCESS) /*% * Alignment diff --git a/lib/isc/tests/time_test.c b/lib/isc/tests/time_test.c index e16fd3e4ed..52e0653422 100644 --- a/lib/isc/tests/time_test.c +++ b/lib/isc/tests/time_test.c @@ -128,7 +128,7 @@ isc_time_formatISO8601us_test(void **state) { UNUSED(state); setenv("TZ", "America/Los_Angeles", 1); - result = isc_time_now(&t); + result = isc_time_now_hires(&t); assert_int_equal(result, ISC_R_SUCCESS); /* check formatting: yyyy-mm-ddThh:mm:ss.ssssssZ */ @@ -236,7 +236,7 @@ isc_time_formatISO8601Lus_test(void **state) { UNUSED(state); setenv("TZ", "America/Los_Angeles", 1); - result = isc_time_now(&t); + result = isc_time_now_hires(&t); assert_int_equal(result, ISC_R_SUCCESS); /* check formatting: yyyy-mm-ddThh:mm:ss.ssssss */ diff --git a/lib/isc/unix/include/isc/time.h b/lib/isc/unix/include/isc/time.h index cb94320109..adf56fc19d 100644 --- a/lib/isc/unix/include/isc/time.h +++ b/lib/isc/unix/include/isc/time.h @@ -150,6 +150,26 @@ isc_time_now(isc_time_t *t); * in the current definition of isc_time_t. */ +isc_result_t +isc_time_now_hires(isc_time_t *t); +/*%< + * Set 't' to the current absolute time. Uses higher resolution clocks + * recommended when microsecond accuracy is required. + * + * Requires: + * + *\li 't' is a valid pointer. + * + * Returns: + * + *\li Success + *\li Unexpected error + * Getting the time from the system failed. + *\li Out of range + * The time from the system is too large to be represented + * in the current definition of isc_time_t. + */ + isc_result_t isc_time_nowplusinterval(isc_time_t *t, const isc_interval_t *i); /*%< diff --git a/lib/isc/unix/time.c b/lib/isc/unix/time.c index b7e900aa48..9ef93879d6 100644 --- a/lib/isc/unix/time.c +++ b/lib/isc/unix/time.c @@ -33,6 +33,10 @@ #define NS_PER_US 1000 /*%< Nanoseconds per microsecond. */ #define NS_PER_MS 1000000 /*%< Nanoseconds per millisecond. */ +#if defined(CLOCK_REALTIME) +#define CLOCKSOURCE_HIRES CLOCK_REALTIME +#endif /* #if defined(CLOCK_REALTIME) */ + #if defined(CLOCK_REALTIME_COARSE) #define CLOCKSOURCE CLOCK_REALTIME_COARSE #elif defined(CLOCK_REALTIME_FAST) @@ -41,6 +45,10 @@ #define CLOCKSOURCE CLOCK_REALTIME #endif /* if defined(CLOCK_REALTIME_COARSE) */ +#if !defined(CLOCKSOURCE_HIRES) +#define CLOCKSOURCE_HIRES CLOCKSOURCE +#endif /* #ifndef CLOCKSOURCE_HIRES */ + /*% *** Intervals ***/ @@ -106,14 +114,14 @@ isc_time_isepoch(const isc_time_t *t) { return (false); } -isc_result_t -isc_time_now(isc_time_t *t) { +static inline isc_result_t +time_now(isc_time_t *t, clockid_t clock) { struct timespec ts; char strbuf[ISC_STRERRORSIZE]; REQUIRE(t != NULL); - if (clock_gettime(CLOCKSOURCE, &ts) == -1) { + if (clock_gettime(clock, &ts) == -1) { strerror_r(errno, strbuf, sizeof(strbuf)); UNEXPECTED_ERROR(__FILE__, __LINE__, "%s", strbuf); return (ISC_R_UNEXPECTED); @@ -138,6 +146,16 @@ isc_time_now(isc_time_t *t) { return (ISC_R_SUCCESS); } +isc_result_t +isc_time_now_hires(isc_time_t *t) { + return time_now(t, CLOCKSOURCE_HIRES); +} + +isc_result_t +isc_time_now(isc_time_t *t) { + return time_now(t, CLOCKSOURCE); +} + isc_result_t isc_time_nowplusinterval(isc_time_t *t, const isc_interval_t *i) { struct timespec ts; diff --git a/lib/isc/win32/include/isc/time.h b/lib/isc/win32/include/isc/time.h index 71fda16433..c52a04061c 100644 --- a/lib/isc/win32/include/isc/time.h +++ b/lib/isc/win32/include/isc/time.h @@ -164,6 +164,26 @@ isc_time_now(isc_time_t *t); * in the current definition of isc_time_t. */ +isc_result_t +isc_time_now_hires(isc_time_t *t); +/*%< + * Set 't' to the current absolute time. Uses higher resolution clocks + * recommended when microsecond accuracy is required. + * + * Requires: + * + *\li 't' is a valid pointer. + * + * Returns: + * + *\li Success + *\li Unexpected error + * Getting the time from the system failed. + *\li Out of range + * The time from the system is too large to be represented + * in the current definition of isc_time_t. + */ + isc_result_t isc_time_nowplusinterval(isc_time_t *t, const isc_interval_t *i); /* diff --git a/lib/isc/win32/libisc.def.in b/lib/isc/win32/libisc.def.in index 27f7272b04..6bfc93d7f9 100644 --- a/lib/isc/win32/libisc.def.in +++ b/lib/isc/win32/libisc.def.in @@ -691,6 +691,7 @@ isc_time_isepoch isc_time_microdiff isc_time_nanoseconds isc_time_now +isc_time_now_hires isc_time_nowplusinterval isc_time_parsehttptimestamp isc_time_secondsastimet diff --git a/lib/isc/win32/time.c b/lib/isc/win32/time.c index d35cf5e370..3cce3536ff 100644 --- a/lib/isc/win32/time.c +++ b/lib/isc/win32/time.c @@ -124,6 +124,15 @@ isc_time_now(isc_time_t *t) { return (ISC_R_SUCCESS); } +isc_result_t +isc_time_now_hires(isc_time_t *t) { + REQUIRE(t != NULL); + + GetSystemTimePreciseAsFileTime(&t->absolute); + + return (ISC_R_SUCCESS); +} + isc_result_t isc_time_nowplusinterval(isc_time_t *t, const isc_interval_t *i) { ULARGE_INTEGER i1; From 56cef1495f2b72100996fc042277dc52c3328aef Mon Sep 17 00:00:00 2001 From: Patrick McLean Date: Fri, 19 Mar 2021 22:50:51 -0700 Subject: [PATCH 2/3] dig: Use high resolution clocks when microsecond accuracy is requested The TIME_NOW macro calls isc_time_now which uses CLOCK_REALTIME_COARSE for getting the current time. This is perfectly fine for millisecond, however when the user request microsecond resolutiuon, they are going to get very inaccurate results. This is especially true on a server class machine where the clock ticks may be set to 100HZ. This changes dig to use the new TIME_NOW_HIRES macro that uses the CLOCK_MONOTONIC_RAW that is more expensive, but gets the *actual* current time rather than the at the last kernel time tick. --- bin/dig/dighost.c | 19 ++++++++++++++++--- bin/dig/host.c | 6 +++++- 2 files changed, 21 insertions(+), 4 deletions(-) diff --git a/bin/dig/dighost.c b/bin/dig/dighost.c index 54bb63e5d1..178c241708 100644 --- a/bin/dig/dighost.c +++ b/bin/dig/dighost.c @@ -2866,7 +2866,11 @@ send_udp(dig_query_t *query) { isc_buffer_usedregion(&query->sendbuf, &r); debug("sending a request"); - TIME_NOW(&query->time_sent); + if (query->lookup->use_usec) { + TIME_NOW_HIRES(&query->time_sent); + } else { + TIME_NOW(&query->time_sent); + } isc_nmhandle_attach(query->handle, &query->sendhandle); @@ -3172,7 +3176,12 @@ launch_next_query(dig_query_t *query) { if (!query->first_soa_rcvd) { dig_query_t *sendquery = NULL; debug("sending a request in launch_next_query"); - TIME_NOW(&query->time_sent); + if (query->lookup->use_usec) { + TIME_NOW_HIRES(&query->time_sent); + } else { + TIME_NOW(&query->time_sent); + } + query_attach(query, &sendquery); isc_buffer_usedregion(&query->sendbuf, &r); if (keep != NULL) { @@ -3584,7 +3593,11 @@ recv_done(isc_nmhandle_t *handle, isc_result_t eresult, isc_region_t *region, goto detach_query; } - TIME_NOW(&query->time_recv); + if (query->lookup->use_usec) { + TIME_NOW_HIRES(&query->time_recv); + } else { + TIME_NOW(&query->time_recv); + } if (eresult == ISC_R_TIMEDOUT && !l->tcp_mode && l->retries > 1) { dig_query_t *newq = NULL; diff --git a/bin/dig/host.c b/bin/dig/host.c index 02d9ce0f48..b3ddc52f1a 100644 --- a/bin/dig/host.c +++ b/bin/dig/host.c @@ -151,7 +151,11 @@ received(unsigned int bytes, isc_sockaddr_t *from, dig_query_t *query) { if (!short_form) { char fromtext[ISC_SOCKADDR_FORMATSIZE]; isc_sockaddr_format(from, fromtext, sizeof(fromtext)); - TIME_NOW(&now); + if (query->lookup->use_usec) { + TIME_NOW_HIRES(&now); + } else { + TIME_NOW(&now); + } diff = (int)isc_time_microdiff(&now, &query->time_sent); printf("Received %u bytes from %s in %d ms\n", bytes, fromtext, diff / 1000); From 1933bcf1d34a344578905b31bb18d871749cb322 Mon Sep 17 00:00:00 2001 From: Evan Hunt Date: Sat, 20 Mar 2021 11:02:39 -0700 Subject: [PATCH 3/3] CHANGES --- CHANGES | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGES b/CHANGES index 08faab7bc7..54960020ae 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,6 @@ +5604. [bug] "dig -u" now uses CLOCK_REALTIME for more accurate + time reporting. [GL #2592] + 5603. [experimental] A "filter-a.so" plugin, which is similar to the "filter-aaaa.so" plugin but which omits A records instead of AAAA records, has been added. Thanks to