Added cl_perf_timer. Updated global trace to include timers.

4 files changed, 153 insertions, 2 deletions

diff --git a/CMakeLists.txt b/CMakeLists.txt
index 03724b6b9..c63107bf0 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -465,7 +465,7 @@ IF (BUILD_CLAR)
 
 	INCLUDE_DIRECTORIES(${CLAR_PATH})
 	FILE(GLOB_RECURSE SRC_TEST ${CLAR_PATH}/*/*.c ${CLAR_PATH}/*/*.h)
-	SET(SRC_CLAR "${CLAR_PATH}/main.c" "${CLAR_PATH}/clar_libgit2.c" "${CLAR_PATH}/clar_libgit2_trace.c" "${CLAR_PATH}/clar.c")
+	SET(SRC_CLAR "${CLAR_PATH}/main.c" "${CLAR_PATH}/clar_libgit2.c" "${CLAR_PATH}/clar_libgit2_trace.c" "${CLAR_PATH}/clar_libgit2_timer.c" "${CLAR_PATH}/clar.c")
 
 	ADD_CUSTOM_COMMAND(
 		OUTPUT ${CLAR_PATH}/clar.suite
diff --git a/tests/clar_libgit2_timer.c b/tests/clar_libgit2_timer.c
new file mode 100644
index 000000000..f8fa2f360
--- /dev/null
+++ b/tests/clar_libgit2_timer.c
@@ -0,0 +1,83 @@
+#include "clar_libgit2.h"
+#include "clar_libgit2_timer.h"
+#include "buffer.h"
+
+void cl_perf_timer__init(cl_perf_timer *t)
+{
+	memset(t, 0, sizeof(cl_perf_timer));
+}
+
+#if defined(GIT_WIN32)
+
+void cl_perf_timer__start(cl_perf_timer *t)
+{
+	QueryPerformanceCounter(&t->time_started);
+}
+
+void cl_perf_timer__stop(cl_perf_timer *t)
+{
+	LARGE_INTEGER time_now;
+	QueryPerformanceCounter(&time_now);
+
+	t->last.QuadPart = (time_now.QuadPart - t->time_started.QuadPart);
+	t->sum.QuadPart += (time_now.QuadPart - t->time_started.QuadPart);
+}
+
+double cl_perf_timer__last(const cl_perf_timer *t)
+{
+	LARGE_INTEGER freq;
+	double fraction;
+
+	QueryPerformanceFrequency(&freq);
+
+	fraction = ((double)t->last.QuadPart) / ((double)freq.QuadPart);
+	return fraction;
+}
+
+double cl_perf_timer__sum(const cl_perf_timer *t)
+{
+	LARGE_INTEGER freq;
+	double fraction;
+
+	QueryPerformanceFrequency(&freq);
+
+	fraction = ((double)t->sum.QuadPart) / ((double)freq.QuadPart);
+	return fraction;
+}
+
+#else
+
+#include <sys/time.h>
+
+static uint32_t now_in_ms(void)
+{
+	struct timeval now;
+	gettimeofday(&now, NULL);
+	return (uint32_t)((now.tv_sec * 1000) + (now.tv_usec / 1000));
+}
+
+void cl_perf_timer__start(cl_perf_timer *t)
+{
+	t->time_started = now_in_ms();
+}
+
+void cl_perf_timer__stop(cl_perf_timer *t)
+{
+	uint32_t now = now_in_ms();
+	t->last = (now - t->time_started);
+	t->sum += (now - t->time_started);
+}
+
+double cl_perf_timer__last(const cl_perf_timer *t)
+{
+	double fraction = ((double)t->last) / 1000;
+	return fraction;
+}
+
+double cl_perf_timer__sum(const cl_perf_timer *t)
+{
+	double fraction = ((double)t->sum) / 1000;
+	return fraction;
+}
+
+#endif
diff --git a/tests/clar_libgit2_timer.h b/tests/clar_libgit2_timer.h
new file mode 100644
index 000000000..b646c7b63
--- /dev/null
+++ b/tests/clar_libgit2_timer.h
@@ -0,0 +1,48 @@
+#ifndef __CLAR_LIBGIT2_TIMER__
+#define __CLAR_LIBGIT2_TIMER__
+
+#if defined(GIT_WIN32)
+
+struct cl_perf_timer
+{
+	/* cummulative running time across all start..stop intervals */
+	LARGE_INTEGER sum;
+	/* value of last start..stop interval */
+	LARGE_INTEGER last;
+	/* clock value at start */
+	LARGE_INTEGER time_started;
+};
+
+#define CL_PERF_TIMER_INIT {0}
+
+#else
+
+struct cl_perf_timer
+{
+	uint32_t sum;
+	uint32_t last;
+	uint32_t time_started;
+};
+
+#define CL_PERF_TIMER_INIT {0}
+
+#endif
+
+typedef struct cl_perf_timer cl_perf_timer;
+
+void cl_perf_timer__init(cl_perf_timer *t);
+void cl_perf_timer__start(cl_perf_timer *t);
+void cl_perf_timer__stop(cl_perf_timer *t);
+
+/**
+ * return value of last start..stop interval in seconds.
+ */
+double cl_perf_timer__last(const cl_perf_timer *t);
+
+/**
+ * return cummulative running time across all start..stop
+ * intervals in seconds.
+ */
+double cl_perf_timer__sum(const cl_perf_timer *t);
+
+#endif /* __CLAR_LIBGIT2_TIMER__ */
diff --git a/tests/clar_libgit2_trace.c b/tests/clar_libgit2_trace.c
index ca49a7070..ae582d1cb 100644
--- a/tests/clar_libgit2_trace.c
+++ b/tests/clar_libgit2_trace.c
@@ -1,5 +1,6 @@
 #include "clar_libgit2.h"
 #include "clar_libgit2_trace.h"
+#include "clar_libgit2_timer.h"
 #include "trace.h"
 
 
@@ -120,6 +121,16 @@ static void _load_trace_params(void)
 
 #define HR "================================================================"
 
+/**
+ * Timer to report the take spend in a test's run() method.
+ */
+static cl_perf_timer s_timer_run = CL_PERF_TIMER_INIT;
+
+/**
+ * Timer to report total time in a test (init, run, cleanup).
+ */
+static cl_perf_timer s_timer_test = CL_PERF_TIMER_INIT;
+
 void _cl_trace_cb__event_handler(
 	cl_trace_event ev,
 	const char *suite_name,
@@ -139,21 +150,30 @@ void _cl_trace_cb__event_handler(
 
 	case CL_TRACE__TEST__BEGIN:
 		git_trace(GIT_TRACE_TRACE, "\n%s::%s: Begin Test", suite_name, test_name);
+		cl_perf_timer__init(&s_timer_test);
+		cl_perf_timer__start(&s_timer_test);
 		break;
 
 	case CL_TRACE__TEST__END:
-		git_trace(GIT_TRACE_TRACE, "%s::%s: End Test", suite_name, test_name);
+		cl_perf_timer__stop(&s_timer_test);
+		git_trace(GIT_TRACE_TRACE, "%s::%s: End Test (%.3f %.3f)", suite_name, test_name,
+				  cl_perf_timer__last(&s_timer_run),
+				  cl_perf_timer__last(&s_timer_test));
 		break;
 
 	case CL_TRACE__TEST__RUN_BEGIN:
 		git_trace(GIT_TRACE_TRACE, "%s::%s: Begin Run", suite_name, test_name);
+		cl_perf_timer__init(&s_timer_run);
+		cl_perf_timer__start(&s_timer_run);
 		break;
 
 	case CL_TRACE__TEST__RUN_END:
+		cl_perf_timer__stop(&s_timer_run);
 		git_trace(GIT_TRACE_TRACE, "%s::%s: End Run", suite_name, test_name);
 		break;
 
 	case CL_TRACE__TEST__LONGJMP:
+		cl_perf_timer__stop(&s_timer_run);
 		git_trace(GIT_TRACE_TRACE, "%s::%s: Aborted", suite_name, test_name);
 		break;