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 259b724)

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})

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,22 +409,22 @@ 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 {
 		pos += ret;
 	}
 
 	/* 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);

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;