Added cl_perf_timer. Updated global trace to include timers.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216
diff --git a/CMakeLists.txt b/CMakeLists.txt
index 03724b6..c63107b 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 0000000..f8fa2f3
--- /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 0000000..b646c7b
--- /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 ca49a70..ae582d1 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;