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)