From 17d54a79f90b4bc2d3541cefda2610d3135d0f62 Mon Sep 17 00:00:00 2001 From: Bogdan Pintea Date: Fri, 16 Aug 2019 13:09:43 +0200 Subject: [PATCH] Enh: trace in-driver execution time. Extended logging buffer (#171) * Enh: trace in-driver execution time; ext log buff. This commit adds the possibility to account for the time the execution spends within the driver. For that, it simply adds up the ticks accounted between entering and exiting any ODBC API call. With it, now one can estimate roughly how much time the driver code runs, as well as how long the driver waits for the REST calls. This time accounting is done globally and possibly across multiple threads. Its mostly useful with single-threaded use, though. The commit also adds the possibility to use a much larger logging "extended" buffer. This is useful in troubleshooting cases where larger logging meesages are required (such as when an entire server REST reply is JSON object is needed). Both of these features are disabled by default (for all build types). * addressing PR review note explicitly init global var (cherry picked from commit 259b724505e20ae7aa3dffe3a1b76b20a4882295) --- CMakeLists.txt | 6 +- driver/log.c | 67 +++++++++++++++++++---- driver/odbc.c | 24 +++++--- driver/tracing.h | 91 ++++++++++++++++++++----------- test/integration/elasticsearch.py | 1 + 5 files changed, 137 insertions(+), 52 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index eb0e5abd..c32384ae 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -135,7 +135,11 @@ if (${WIN32}) set(CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE} /DTEST_API=") set(CMAKE_C_FLAGS_MINSIZEREL "${CMAKE_C_FLAGS_RELEASE} /DTEST_API=") - # set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} /DNDEBUG") + # Only used when a long logging message is required for troubleshooting + # (like one entire server answer). + #set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} /DWITH_EXTENDED_BUFF_LOG") + # Account for the time the process spends within the driver. + #set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} /DWITH_OAPI_TIMING") else (${WIN32}) set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} -g") endif (${WIN32}) diff --git a/driver/log.c b/driver/log.c index accbc126..787a6b58 100644 --- a/driver/log.c +++ b/driver/log.c @@ -31,6 +31,13 @@ /* global file log */ esodbc_filelog_st *_gf_log = NULL; +#ifdef WITH_EXTENDED_BUFF_LOG +#define ESODBC_EXT_LOG_BUF_SIZE (ESODBC_LOG_BUF_SIZE * 1024) +static char **log_buffs = NULL; +static size_t log_buffs_cnt = 0; +static esodbc_mutex_lt log_buffs_mux = ESODBC_MUX_SINIT; +#endif /* WITH_EXTENDED_BUFF_LOG */ + BOOL log_init() { int cnt; @@ -94,6 +101,19 @@ BOOL log_init() void log_cleanup() { +# ifdef WITH_EXTENDED_BUFF_LOG + size_t i; + + if (log_buffs) { + for (i = 0; i < log_buffs_cnt; i ++) { + free(log_buffs[i]); + } + free(log_buffs); + log_buffs = NULL; + log_buffs_cnt = 0; + } +# endif /* WITH_EXTENDED_BUFF_LOG */ + if (_gf_log) { filelog_del(_gf_log); _gf_log = NULL; @@ -305,18 +325,45 @@ static inline void filelog_log(esodbc_filelog_st *log, time_t now = time(NULL); int ret; size_t pos; +# ifndef WITH_EXTENDED_BUFF_LOG char buff[ESODBC_LOG_BUF_SIZE]; + const size_t buff_sz = ESODBC_LOG_BUF_SIZE; +# else /* !WITH_EXTENDED_BUFF_LOG */ + static thread_local char *buff = NULL; + const size_t buff_sz = ESODBC_EXT_LOG_BUF_SIZE; + char **r; +# endif /* !WITH_EXTENDED_BUFF_LOG */ char ebuff[LOG_ERRNO_BUF_SIZE]; const char *sfile, *next; /* keep in sync with esodbc_log_levels */ static const char *level2str[] = { "ERROR", "WARN", "INFO", "DEBUG", }; assert(level < sizeof(level2str)/sizeof(level2str[0])); - if (ctime_s(buff, sizeof(buff), &now)) { + /* if extended logging is needed (such as when needing an entire server + * answer), the (too large for the stack) log printing buffer needs to be + * allocate on heap and tracked to be freed on lib process detach */ +# ifdef WITH_EXTENDED_BUFF_LOG + if (! buff) { + if (! (buff = malloc(buff_sz))) { + return; + } + ESODBC_MUX_LOCK(&log_buffs_mux); + if (! (r = realloc(log_buffs, (log_buffs_cnt + 1) * sizeof(char *)))) { + free(buff); + buff = NULL; + return; + } + log_buffs = r; + log_buffs[log_buffs_cnt ++] = buff; + ESODBC_MUX_UNLOCK(&log_buffs_mux); + } +# endif /* WITH_EXTENDED_BUFF_LOG */ + + if (ctime_s(buff, buff_sz, &now)) { /* writing failed */ pos = 0; } else { - pos = strnlen(buff, sizeof(buff)) - /*\n*/1; + pos = strnlen(buff, buff_sz) - /*\n*/1; /* * https://docs.microsoft.com/en-us/cpp/c-runtime-library/reference/ctime-s-ctime32-s-ctime64-s-wctime-s-wctime32-s-wctime64-s : * """ @@ -334,7 +381,7 @@ static inline void filelog_log(esodbc_filelog_st *log, } /* write the debugging prefix */ - if ((ret = snprintf(buff + pos, sizeof(buff) - pos, " - [%s] %s()@%s:%d ", + if ((ret = snprintf(buff + pos, buff_sz - pos, " - [%s] %s()@%s:%d ", level2str[level], func, sfile, lineno)) < 0) { return; } else { @@ -343,7 +390,7 @@ static inline void filelog_log(esodbc_filelog_st *log, /* write the error number details */ if (werrno) { - ret = snprintf(buff + pos, sizeof(buff) - pos, "(%d:", errno); + ret = snprintf(buff + pos, buff_sz - pos, "(%d:", errno); if (ret < 0) { return; } else { @@ -353,7 +400,7 @@ static inline void filelog_log(esodbc_filelog_st *log, if (strerror_s(ebuff, sizeof(ebuff), errno)) { return; } - ret = snprintf(buff + pos, sizeof(buff) - pos, "%s) ", ebuff); + ret = snprintf(buff + pos, buff_sz - pos, "%s) ", ebuff); if (ret < 0) { return; } else { @@ -362,7 +409,7 @@ static inline void filelog_log(esodbc_filelog_st *log, } /* write user's message */ - ret = vsnprintf(buff + pos, sizeof(buff) - pos, fmt, args); + ret = vsnprintf(buff + pos, buff_sz - pos, fmt, args); if (ret < 0) { return; } else { @@ -370,14 +417,14 @@ static inline void filelog_log(esodbc_filelog_st *log, } /* if overrunning, correct the pos, to be able to add a \n\0 */ - if (sizeof(buff) < pos + /*\n\0*/2) { - pos = sizeof(buff) - 2; + if (buff_sz < pos + /*\n\0*/2) { + pos = buff_sz - 2; } - ret = snprintf(buff + pos, sizeof(buff) - pos, "\n"); + ret = snprintf(buff + pos, buff_sz - pos, "\n"); if (0 <= ret) { pos += ret; } - assert(pos <= sizeof(buff)); + assert(pos <= buff_sz); ESODBC_MUX_LOCK(&log->mux); filelog_write(log, buff, pos); diff --git a/driver/odbc.c b/driver/odbc.c index 77ec1390..8d2e4327 100644 --- a/driver/odbc.c +++ b/driver/odbc.c @@ -24,20 +24,16 @@ RET_HDIAGS(hnd, SQL_STATE_HYC00); \ } while (0) +#ifdef WITH_OAPI_TIMING +volatile LONG64 api_ticks = 0; +clock_t thread_local in_ticks = 0; +#endif /* WITH_API_TIMING */ static BOOL driver_init() { if (! log_init()) { return FALSE; } - INFO("initializing driver."); - if (! queries_init()) { - return FALSE; - } - convert_init(); - if (! connect_init()) { - return FALSE; - } #ifndef NDEBUG if (_gf_log) { ERR("leak reporting: on."); /* force create the log handle */ @@ -49,6 +45,14 @@ static BOOL driver_init() _CrtSetReportFile(_CRT_ASSERT, _gf_log->handle); } #endif /* !NDEBUG */ + INFO("initializing driver."); + if (! queries_init()) { + return FALSE; + } + convert_init(); + if (! connect_init()) { + return FALSE; + } return TRUE; } @@ -96,6 +100,10 @@ BOOL WINAPI DllMain( ERR("leaks dumped: %d.", _CrtDumpMemoryLeaks()); } #endif /* !NDEBUG */ +#ifdef WITH_OAPI_TIMING + INFO("total in-driver time (secs): %.3f.", + (float)api_ticks / CLOCKS_PER_SEC); +#endif /* WITH_OAPI_TIMING */ INFO("process %u detaching.", GetCurrentProcessId()); log_cleanup(); break; diff --git a/driver/tracing.h b/driver/tracing.h index 76d3c49b..81ad5087 100644 --- a/driver/tracing.h +++ b/driver/tracing.h @@ -8,6 +8,7 @@ #include #include +#include #include "log.h" #define TRACE_LOG_LEVEL LOG_LEVEL_DBG @@ -20,7 +21,7 @@ #define _AVAIL(_ps) ((int)(sizeof(_BUFF)/sizeof(_BUFF[0])) - _ps) /* check if buffer limit has been reached */ -#define _CHECK_WRITE(/*written*/_n, /*position*/_ps) \ +#define _CHECK_WRITE_(/*written*/_n, /*position*/_ps) \ if (_n < 0) { /* printing failed */ \ assert(_ps < _AVAIL(0)); \ _BUFF[_ps] = '\0'; /* if previously usable, make sure it's NTS'd */\ @@ -154,7 +155,7 @@ type); \ break; \ } \ - _CHECK_WRITE(_n, _ps); \ + _CHECK_WRITE_(_n, _ps) \ } while (0) /*INDENT-ON*/ @@ -191,83 +192,107 @@ #define _OUT 1 #define _TRACE_OUT "EXIT: " -#define _TRACE_HEADER(inout, hnd) \ +/* account for the total time (across all threads!) spent within the driver: + * the time the ODBC API calls take to be serviced. */ +#ifdef WITH_OAPI_TIMING +extern volatile LONG64 api_ticks; +extern thread_local clock_t in_ticks; +# define OAPI_TIMING(inout) \ + do { \ + if (inout == _IN) { \ + in_ticks = clock(); \ + } else { /* _OUT */ \ + clock_t out_ticks = clock(); \ + if (out_ticks != (clock_t)-1 && in_ticks < out_ticks) { \ + InterlockedExchangeAdd64(&api_ticks, out_ticks - in_ticks); \ + } \ + } \ + } while (0) +#else /* WITH_API_TIMING */ +# define OAPI_TIMING +#endif /* WITH_API_TIMING */ + +#define _TRACE_HEADER_(inout, hnd) \ char _BUFF[TBUFF_SIZE]; \ int _ps = 0, _n; \ esodbc_filelog_st *_log; \ + /* no accounting of the "out" tracing, but that should be OK, this being + * most useful with release builds on non-dbg logging (when the rest of + * the tracing code is skipped anyways) */\ + OAPI_TIMING(inout); \ _log = (hnd && HDRH(hnd)->log) ? HDRH(hnd)->log : _gf_log; \ if ((! _log) || (_log->level < TRACE_LOG_LEVEL)) { \ /* skip all the printing as early as possible */ \ break; \ } \ _n = snprintf(_BUFF + _ps, _AVAIL(_ps), inout ? _TRACE_OUT : _TRACE_IN); \ - _CHECK_WRITE(_n, _ps); + _CHECK_WRITE_(_n, _ps) -#define _TRACE_FOOTER \ +#define _TRACE_FOOTER_ \ _esodbc_log(_log, TRACE_LOG_LEVEL, /*werr*/0, \ __func__, __FILE__, __LINE__, "%s.", _BUFF); #define TRACE1(inout, hnd, fmt, p0) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, SQL_NTS, 0); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE2(inout, hnd, fmt, p0, p1) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE3(inout, hnd, fmt, p0, p1, p2) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE4(inout, hnd, fmt, p0, p1, p2, p3) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ _PRINT_PARAM(fmt[3], p3, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE5(inout, hnd, fmt, p0, p1, p2, p3, p4) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ _PRINT_PARAM(fmt[3], p3, p4, 1); \ _PRINT_PARAM(fmt[4], p4, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE6(inout, hnd, fmt, p0, p1, p2, p3, p4, p5) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ _PRINT_PARAM(fmt[3], p3, p4, 1); \ _PRINT_PARAM(fmt[4], p4, p5, 1); \ _PRINT_PARAM(fmt[5], p5, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE7(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -275,12 +300,12 @@ _PRINT_PARAM(fmt[4], p4, p5, 1); \ _PRINT_PARAM(fmt[5], p5, p6, 1); \ _PRINT_PARAM(fmt[6], p6, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE8(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -289,12 +314,12 @@ _PRINT_PARAM(fmt[5], p5, p6, 1); \ _PRINT_PARAM(fmt[6], p6, p7, 1); \ _PRINT_PARAM(fmt[7], p7, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE9(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7, p8) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -304,12 +329,12 @@ _PRINT_PARAM(fmt[6], p6, p7, 1); \ _PRINT_PARAM(fmt[7], p7, p8, 1); \ _PRINT_PARAM(fmt[8], p8, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE10(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -320,12 +345,12 @@ _PRINT_PARAM(fmt[7], p7, p8, 1); \ _PRINT_PARAM(fmt[8], p8, p9, 1); \ _PRINT_PARAM(fmt[9], p9, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE11(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9, p10) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -337,13 +362,13 @@ _PRINT_PARAM(fmt[8], p8, p9, 1); \ _PRINT_PARAM(fmt[9], p9, p10, 1); \ _PRINT_PARAM(fmt[10], p10, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE12(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9, p10, \ p11) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -356,14 +381,14 @@ do { \ _PRINT_PARAM(fmt[9], p9, p10, 1); \ _PRINT_PARAM(fmt[10], p10, p11, 1); \ _PRINT_PARAM(fmt[11], p11, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) /*INDENT-OFF*/ //astyle trips on these following two defs #define TRACE13(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9, p10, \ p11, p12) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -377,13 +402,13 @@ do { \ _PRINT_PARAM(fmt[10], p10, p11, 1); \ _PRINT_PARAM(fmt[11], p11, p12, 1); \ _PRINT_PARAM(fmt[12], p12, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) #define TRACE14(inout, hnd, fmt, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9, p10, \ p11, p12, p13) \ do { \ - _TRACE_HEADER(inout, hnd); \ + _TRACE_HEADER_(inout, hnd) \ _PRINT_PARAM(fmt[0], p0, p1, 0); \ _PRINT_PARAM(fmt[1], p1, p2, 1); \ _PRINT_PARAM(fmt[2], p2, p3, 1); \ @@ -398,7 +423,7 @@ do { \ _PRINT_PARAM(fmt[11], p11, p12, 1); \ _PRINT_PARAM(fmt[12], p12, p13, 1); \ _PRINT_PARAM(fmt[13], p13, SQL_NTS, 1); \ - _TRACE_FOOTER; \ + _TRACE_FOOTER_ \ } while(0) /*INDENT-ON*/ diff --git a/test/integration/elasticsearch.py b/test/integration/elasticsearch.py index 667896bc..87605bd0 100644 --- a/test/integration/elasticsearch.py +++ b/test/integration/elasticsearch.py @@ -155,6 +155,7 @@ def _start_elasticsearch(self, es_dir): if self.is_listening(): raise Exception("an Elasticsearch instance is already running") + print("Starting Elasticsearch with: %s" % start_script) # don't daemonize to get the start logs inlined with those that this app generates es_proc = psutil.Popen(start_script, close_fds=True, creationflags=creationflags) atexit.register(Elasticsearch._stop_es, es_proc)