@matheusbsbs / matheus-bagliano / commits / 8ad575646c

trace2: add stopwatch timers

Add stopwatch timer mechanism to Trace2. Timers are an alternative to Trace2 Regions. Regions are useful for measuring the time spent in various computation phases, such as the time to read the index, time to scan for unstaged files, time to scan for untracked files, and etc. However, regions are not appropriate in all places. For example, during a checkout, it would be very inefficient to use regions to measure the total time spent inflating objects from the ODB from across the entire lifetime of the process; a per-unzip() region would flood the output and significantly slow the command; and some form of post-processing would be requried to compute the time spent in unzip(). Timers can be used to measure a series of timer intervals and emit a single summary event (at thread and/or process exit). Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>

Jeff Hostetler committed Oct 24, 2022 at 13:41 UTC 8ad575646c0b1e927a05650a1ec64125121ae591

15 files changed +786

Documentation/technical/api-trace2.txt

+90

@@ -769,6 +769,42 @@ The "value" field may be an integer or a string.

769 }

770 ------------

771

772 +`"th_timer"`::

773 + This event logs the amount of time that a stopwatch timer was

774 + running in the thread. This event is generated when a thread

775 + exits for timers that requested per-thread events.

776 ++

777 +------------

778 +{

779 + "event":"th_timer",

780 + ...

781 + "category":"my_category",

782 + "name":"my_timer",

783 + "intervals":5, # number of time it was started/stopped

784 + "t_total":0.052741, # total time in seconds it was running

785 + "t_min":0.010061, # shortest interval

786 + "t_max":0.011648 # longest interval

787 +}

788 +------------

789 +

790 +`"timer"`::

791 + This event logs the amount of time that a stopwatch timer was

792 + running aggregated across all threads. This event is generated

793 + when the process exits.

794 ++

795 +------------

796 +{

797 + "event":"timer",

798 + ...

799 + "category":"my_category",

800 + "name":"my_timer",

801 + "intervals":5, # number of time it was started/stopped

802 + "t_total":0.052741, # total time in seconds it was running

803 + "t_min":0.010061, # shortest interval

804 + "t_max":0.011648 # longest interval

805 +}

806 +------------

807 +

808 == Example Trace2 API Usage

809

810 Here is a hypothetical usage of the Trace2 API showing the intended

@@ -1200,6 +1236,60 @@ d0 | main | data | r0 | 0.002126 | 0.002126 | fsy

1238 ----------------

1239 +

1240 +Stopwatch Timer Events::

1241 +

1242 + Measure the time spent in a function call or span of code

1243 + that might be called from many places within the code

1244 + throughout the life of the process.

1245 ++

1246 +----------------

1247 +static void expensive_function(void)

1248 +{

1249 + trace2_timer_start(TRACE2_TIMER_ID_TEST1);

1250 + ...

1251 + sleep_millisec(1000); // Do something expensive

1252 + ...

1253 + trace2_timer_stop(TRACE2_TIMER_ID_TEST1);

1254 +}

1255 +

1256 +static int ut_100timer(int argc, const char **argv)

1257 +{

1258 + ...

1259 +

1260 + expensive_function();

1261 +

1262 + // Do something else 1...

1263 +

1264 + expensive_function();

1265 +

1266 + // Do something else 2...

1267 +

1268 + expensive_function();

1269 +

1270 + return 0;

1271 +}

1272 +----------------

1273 ++

1274 +In this example, we measure the total time spent in

1275 +`expensive_function()` regardless of when it is called

1276 +in the overall flow of the program.

1277 ++

1278 +----------------

1279 +$ export GIT_TRACE2_PERF_BRIEF=1

1280 +$ export GIT_TRACE2_PERF=~/log.perf

1281 +$ t/helper/test-tool trace2 100timer 3 1000

1282 +...

1283 +$ cat ~/log.perf

1284 +d0 | main | version | | | | | ...

1290 +----------------

1291 +

1292 +

1293 == Future Work

1294

1295 === Relationship to the Existing Trace Api (api-trace.txt)

Makefile

@@ -1102,6 +1102,7 @@ LIB_OBJS += trace2/tr2_tgt_event.o

1102 LIB_OBJS += trace2/tr2_tgt_normal.o

1103 LIB_OBJS += trace2/tr2_tgt_perf.o

1104 LIB_OBJS += trace2/tr2_tls.o

1105 +LIB_OBJS += trace2/tr2_tmr.o

1106 LIB_OBJS += trailer.o

1107 LIB_OBJS += transport-helper.o

1108 LIB_OBJS += transport.o

t/helper/test-trace2.c

+98

@@ -228,6 +228,101 @@ static int ut_010bug_BUG(int argc, const char **argv)

228 BUG("a %s message", "BUG");

229 }

230

231 +/*

232 + * Single-threaded timer test. Create several intervals using the

233 + * TEST1 timer. The test script can verify that an aggregate Trace2

234 + * "timer" event is emitted indicating that we started+stopped the

235 + * timer the requested number of times.

236 + */

237 +static int ut_100timer(int argc, const char **argv)

238 +{

239 + const char *usage_error =

240 + "expect <count> <ms_delay>";

241 +

242 + int count = 0;

243 + int delay = 0;

244 + int k;

245 +

246 + if (argc != 2)

247 + die("%s", usage_error);

248 + if (get_i(&count, argv[0]))

249 + die("%s", usage_error);

250 + if (get_i(&delay, argv[1]))

251 + die("%s", usage_error);

252 +

253 + for (k = 0; k < count; k++) {

254 + trace2_timer_start(TRACE2_TIMER_ID_TEST1);

255 + sleep_millisec(delay);

256 + trace2_timer_stop(TRACE2_TIMER_ID_TEST1);

257 + }

258 +

259 + return 0;

260 +}

261 +

262 +struct ut_101_data {

263 + int count;

264 + int delay;

265 +};

266 +

267 +static void *ut_101timer_thread_proc(void *_ut_101_data)

268 +{

269 + struct ut_101_data *data = _ut_101_data;

270 + int k;

271 +

272 + trace2_thread_start("ut_101");

273 +

274 + for (k = 0; k < data->count; k++) {

275 + trace2_timer_start(TRACE2_TIMER_ID_TEST2);

276 + sleep_millisec(data->delay);

277 + trace2_timer_stop(TRACE2_TIMER_ID_TEST2);

278 + }

279 +

280 + trace2_thread_exit();

281 + return NULL;

282 +}

283 +

284 +/*

285 + * Multi-threaded timer test. Create several threads that each create

286 + * several intervals using the TEST2 timer. The test script can verify

287 + * that an individual Trace2 "th_timer" events for each thread and an

288 + * aggregate "timer" event are generated.

289 + */

290 +static int ut_101timer(int argc, const char **argv)

291 +{

292 + const char *usage_error =

293 + "expect <count> <ms_delay> <threads>";

294 +

295 + struct ut_101_data data = { 0, 0 };

296 + int nr_threads = 0;

297 + int k;

298 + pthread_t *pids = NULL;

299 +

300 + if (argc != 3)

301 + die("%s", usage_error);

302 + if (get_i(&data.count, argv[0]))

303 + die("%s", usage_error);

304 + if (get_i(&data.delay, argv[1]))

305 + die("%s", usage_error);

306 + if (get_i(&nr_threads, argv[2]))

307 + die("%s", usage_error);

308 +

309 + CALLOC_ARRAY(pids, nr_threads);

310 +

311 + for (k = 0; k < nr_threads; k++) {

312 + if (pthread_create(&pids[k], NULL, ut_101timer_thread_proc, &data))

313 + die("failed to create thread[%d]", k);

314 + }

315 +

316 + for (k = 0; k < nr_threads; k++) {

317 + if (pthread_join(pids[k], NULL))

318 + die("failed to join thread[%d]", k);

319 + }

320 +

321 + free(pids);

322 +

323 + return 0;

324 +}

325 +

326 /*

327 * Usage:

328 * test-tool trace2 <ut_name_1> <ut_usage_1>

@@ -248,6 +343,9 @@ static struct unit_test ut_table[] = {

343 { ut_008bug, "008bug", "" },

344 { ut_009bug_BUG, "009bug_BUG","" },

345 { ut_010bug_BUG, "010bug_BUG","" },

346 +

347 + { ut_100timer, "100timer", "<count> <ms_delay>" },

348 + { ut_101timer, "101timer", "<count> <ms_delay> <threads>" },

349 };

350 /* clang-format on */

351

t/t0211-trace2-perf.sh

+49

@@ -173,4 +173,53 @@ test_expect_success 'using global config, perf stream, return code 0' '

173 test_cmp expect actual

174 '

175

176 +# Exercise the stopwatch timers in a loop and confirm that we have

177 +# as many start/stop intervals as expected. We cannot really test the

178 +# actual (total, min, max) timer values, so we have to assume that they

179 +# are good, but we can verify the interval count.

180 +#

181 +# The timer "test/test1" should only emit a global summary "timer" event.

182 +# The timer "test/test2" should emit per-thread "th_timer" events and a

183 +# global summary "timer" event.

184 +

185 +have_timer_event () {

186 + thread=$1 event=$2 category=$3 name=$4 intervals=$5 file=$6 &&

187 +

188 + pattern="d0|${thread}|${event}||||${category}|name:${name} intervals:${intervals}" &&

189 +

190 + grep "${pattern}" ${file}

191 +}

192 +

193 +test_expect_success 'stopwatch timer test/test1' '

194 + test_when_finished "rm trace.perf actual" &&

195 + test_config_global trace2.perfBrief 1 &&

196 + test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&

197 +

198 + # Use the timer "test1" 5 times from "main".

199 + test-tool trace2 100timer 5 10 &&

200 +

201 + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&

202 +

203 + have_timer_event "main" "timer" "test" "test1" 5 actual

204 +'

205 +

206 +test_expect_success 'stopwatch timer test/test2' '

207 + test_when_finished "rm trace.perf actual" &&

208 + test_config_global trace2.perfBrief 1 &&

209 + test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&

210 +

211 + # Use the timer "test2" 5 times each in 3 threads.

212 + test-tool trace2 101timer 5 10 3 &&

213 +

214 + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&

215 +

216 + # So we should have 3 per-thread events of 5 each.

217 + have_timer_event "th01:ut_101" "th_timer" "test" "test2" 5 actual &&

218 + have_timer_event "th02:ut_101" "th_timer" "test" "test2" 5 actual &&

219 + have_timer_event "th03:ut_101" "th_timer" "test" "test2" 5 actual &&

220 +

221 + # And we should have 15 total uses.

222 + have_timer_event "main" "timer" "test" "test2" 15 actual

223 +'

224 +

225 test_done

t/t0211/scrub_perf.perl

@@ -64,6 +64,12 @@ while (<>) {

64 goto SKIP_LINE;

65 }

66 }

67 + elsif ($tokens[$col_event] =~ m/timer/) {

68 + # This also captures "th_timer" events

69 + $tokens[$col_rest] =~ s/ total:\d+\.\d*/ total:_T_TOTAL_/;

70 + $tokens[$col_rest] =~ s/ min:\d+\.\d*/ min:_T_MIN_/;

71 + $tokens[$col_rest] =~ s/ max:\d+\.\d*/ max:_T_MAX_/;

72 + }

74 # t_abs and t_rel are either blank or a float. Replace the float

75 # with a constant for matching the HEREDOC in the test script.

trace2.c

+75

@@ -13,6 +13,7 @@

13 #include "trace2/tr2_sysenv.h"

14 #include "trace2/tr2_tgt.h"

15 #include "trace2/tr2_tls.h"

16 +#include "trace2/tr2_tmr.h"

18 static int trace2_enabled;

@@ -83,6 +84,23 @@ static void tr2_tgt_disable_builtins(void)

84 tgt_j->pfn_term();

85 }

87 +/*

88 + * The signature of this function must match the pfn_timer

89 + * method in the targets. (Think of this is an apply operation

90 + * across the set of active targets.)

91 + */

92 +static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata *meta,

93 + const struct tr2_timer *timer,

94 + int is_final_data)

95 +{

96 + struct tr2_tgt *tgt_j;

97 + int j;

98 +

99 + for_each_wanted_builtin (j, tgt_j)

100 + if (tgt_j->pfn_timer)

101 + tgt_j->pfn_timer(meta, timer, is_final_data);

102 +}

103 +

104 static int tr2main_exit_code;

105

106 /*

@@ -110,6 +128,26 @@ static void tr2main_atexit_handler(void)

128 */

129 tr2tls_pop_unwind_self();

130

131 + /*

132 + * Some timers want per-thread details. If the main thread

133 + * used one of those timers, emit the details now (before

134 + * we emit the aggregate timer values).

135 + */

136 + tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer);

137 +

138 + /*

139 + * Add stopwatch timer data for the main thread to the final

140 + * totals. And then emit the final timer values.

141 + *

142 + * Technically, we shouldn't need to hold the lock to update

143 + * and output the final_timer_block (since all other threads

144 + * should be dead by now), but it doesn't hurt anything.

145 + */

146 + tr2tls_lock();

147 + tr2_update_final_timers();

148 + tr2_emit_final_timers(tr2_tgt_emit_a_timer);

149 + tr2tls_unlock();

150 +

151 for_each_wanted_builtin (j, tgt_j)

152 if (tgt_j->pfn_atexit)

153 tgt_j->pfn_atexit(us_elapsed_absolute,

@@ -541,6 +579,21 @@ void trace2_thread_exit_fl(const char *file, int line)

579 tr2tls_pop_unwind_self();

580 us_elapsed_thread = tr2tls_region_elasped_self(us_now);

581

582 + /*

583 + * Some timers want per-thread details. If this thread used

584 + * one of those timers, emit the details now.

585 + */

586 + tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer);

587 +

588 + /*

589 + * Add stopwatch timer data from the current (non-main) thread

590 + * to the final totals. (We'll accumulate data for the main

591 + * thread later during "atexit".)

592 + */

593 + tr2tls_lock();

594 + tr2_update_final_timers();

595 + tr2tls_unlock();

596 +

597 for_each_wanted_builtin (j, tgt_j)

598 if (tgt_j->pfn_thread_exit_fl)

599 tgt_j->pfn_thread_exit_fl(file, line,

@@ -795,6 +848,28 @@ void trace2_printf_fl(const char *file, int line, const char *fmt, ...)

848 va_end(ap);

849 }

850

851 +void trace2_timer_start(enum trace2_timer_id tid)

852 +{

853 + if (!trace2_enabled)

854 + return;

855 +

856 + if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS)

857 + BUG("trace2_timer_start: invalid timer id: %d", tid);

858 +

859 + tr2_start_timer(tid);

860 +}

861 +

862 +void trace2_timer_stop(enum trace2_timer_id tid)

863 +{

864 + if (!trace2_enabled)

865 + return;

866 +

867 + if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS)

868 + BUG("trace2_timer_stop: invalid timer id: %d", tid);

869 +

870 + tr2_stop_timer(tid);

871 +}

872 +

873 const char *trace2_session_id(void)

874 {

875 return tr2_sid_get();

trace2.h

+43

@@ -51,6 +51,7 @@ struct json_writer;

51 * [] trace2_region* -- emit region nesting messages.

52 * [] trace2_data* -- emit region/thread/repo data messages.

53 * [] trace2_printf* -- legacy trace[1] messages.

54 + * [] trace2_timer* -- stopwatch timers (messages are deferred).

55 */

57 /*

@@ -485,6 +486,48 @@ void trace2_printf_fl(const char *file, int line, const char *fmt, ...);

486

487 #define trace2_printf(...) trace2_printf_fl(__FILE__, __LINE__, __VA_ARGS__)

488

489 +/*

490 + * Define the set of stopwatch timers.

491 + *

492 + * We can add more at any time, but they must be defined at compile

493 + * time (to avoid the need to dynamically allocate and synchronize

494 + * them between different threads).

495 + *

496 + * These must start at 0 and be contiguous (because we use them

497 + * elsewhere as array indexes).

498 + *

499 + * Any values added to this enum must also be added to the

500 + * `tr2_timer_metadata[]` in `trace2/tr2_tmr.c`.

501 + */

502 +enum trace2_timer_id {

503 + /*

504 + * Define two timers for testing. See `t/helper/test-trace2.c`.

505 + * These can be used for ad hoc testing, but should not be used

506 + * for permanent analysis code.

507 + */

508 + TRACE2_TIMER_ID_TEST1 = 0, /* emits summary event only */

509 + TRACE2_TIMER_ID_TEST2, /* emits summary and thread events */

510 +

511 + /* Add additional timer definitions before here. */

512 + TRACE2_NUMBER_OF_TIMERS

513 +};

514 +

515 +/*

516 + * Start/Stop the indicated stopwatch timer in the current thread.

517 + *

518 + * The time spent by the current thread between the _start and _stop

519 + * calls will be added to the thread's partial sum for this timer.

520 + *

521 + * Timer events are emitted at thread and program exit.

522 + *

523 + * Note: Since the stopwatch API routines do not generate individual

524 + * events, they do not take (file, line) arguments. Similarly, the

525 + * category and timer name values are defined at compile-time in the

526 + * timer definitions array, so they are not needed here in the API.

527 + */

528 +void trace2_timer_start(enum trace2_timer_id tid);

529 +void trace2_timer_stop(enum trace2_timer_id tid);

530 +

531 /*

532 * Optional platform-specific code to dump information about the

533 * current and any parent process(es). This is intended to allow

trace2/tr2_tgt.h

@@ -4,6 +4,10 @@

4 struct child_process;

5 struct repository;

6 struct json_writer;

7 +struct tr2_timer_metadata;

8 +struct tr2_timer;

9 +

10 +#define NS_TO_SEC(ns) ((double)(ns) / 1.0e9)

12 /*

13 * Function prototypes for a TRACE2 "target" vtable.

@@ -96,6 +100,10 @@ typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line,

100 uint64_t us_elapsed_absolute,

101 const char *fmt, va_list ap);

102

103 +typedef void(tr2_tgt_evt_timer_t)(const struct tr2_timer_metadata *meta,

104 + const struct tr2_timer *timer,

105 + int is_final_data);

106 +

107 /*

108 * "vtable" for a TRACE2 target. Use NULL if a target does not want

109 * to emit that message.

@@ -132,6 +140,7 @@ struct tr2_tgt {

140 tr2_tgt_evt_data_fl_t *pfn_data_fl;

141 tr2_tgt_evt_data_json_fl_t *pfn_data_json_fl;

142 tr2_tgt_evt_printf_va_fl_t *pfn_printf_va_fl;

143 + tr2_tgt_evt_timer_t *pfn_timer;

144 };

145 /* clang-format on */

146

trace2/tr2_tgt_event.c

+26

@@ -9,6 +9,7 @@

9 #include "trace2/tr2_sysenv.h"

10 #include "trace2/tr2_tgt.h"

11 #include "trace2/tr2_tls.h"

12 +#include "trace2/tr2_tmr.h"

14 static struct tr2_dst tr2dst_event = {

15 .sysenv_var = TR2_SYSENV_EVENT,

@@ -617,6 +618,30 @@ static void fn_data_json_fl(const char *file, int line,

618 }

619 }

620

621 +static void fn_timer(const struct tr2_timer_metadata *meta,

622 + const struct tr2_timer *timer,

623 + int is_final_data)

624 +{

625 + const char *event_name = is_final_data ? "timer" : "th_timer";

626 + struct json_writer jw = JSON_WRITER_INIT;

627 + double t_total = NS_TO_SEC(timer->total_ns);

628 + double t_min = NS_TO_SEC(timer->min_ns);

629 + double t_max = NS_TO_SEC(timer->max_ns);

630 +

631 + jw_object_begin(&jw, 0);

632 + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);

633 + jw_object_string(&jw, "category", meta->category);

634 + jw_object_string(&jw, "name", meta->name);

635 + jw_object_intmax(&jw, "intervals", timer->interval_count);

636 + jw_object_double(&jw, "t_total", 6, t_total);

637 + jw_object_double(&jw, "t_min", 6, t_min);

638 + jw_object_double(&jw, "t_max", 6, t_max);

639 + jw_end(&jw);

640 +

641 + tr2_dst_write_line(&tr2dst_event, &jw.json);

642 + jw_release(&jw);

643 +}

644 +

645 struct tr2_tgt tr2_tgt_event = {

646 .pdst = &tr2dst_event,

647

@@ -648,4 +673,5 @@ struct tr2_tgt tr2_tgt_event = {

673 .pfn_data_fl = fn_data_fl,

674 .pfn_data_json_fl = fn_data_json_fl,

675 .pfn_printf_va_fl = NULL,

676 + .pfn_timer = fn_timer,

677 };

trace2/tr2_tgt_normal.c

+23

@@ -8,6 +8,7 @@

8 #include "trace2/tr2_tbuf.h"

9 #include "trace2/tr2_tgt.h"

10 #include "trace2/tr2_tls.h"

11 +#include "trace2/tr2_tmr.h"

13 static struct tr2_dst tr2dst_normal = {

14 .sysenv_var = TR2_SYSENV_NORMAL,

@@ -329,6 +330,27 @@ static void fn_printf_va_fl(const char *file, int line,

330 strbuf_release(&buf_payload);

331 }

332

333 +static void fn_timer(const struct tr2_timer_metadata *meta,

334 + const struct tr2_timer *timer,

335 + int is_final_data)

336 +{

337 + const char *event_name = is_final_data ? "timer" : "th_timer";

338 + struct strbuf buf_payload = STRBUF_INIT;

339 + double t_total = NS_TO_SEC(timer->total_ns);

340 + double t_min = NS_TO_SEC(timer->min_ns);

341 + double t_max = NS_TO_SEC(timer->max_ns);

342 +

343 + strbuf_addf(&buf_payload, ("%s %s/%s"

344 + " intervals:%"PRIu64

345 + " total:%8.6f min:%8.6f max:%8.6f"),

346 + event_name, meta->category, meta->name,

347 + timer->interval_count,

348 + t_total, t_min, t_max);

349 +

350 + normal_io_write_fl(__FILE__, __LINE__, &buf_payload);

351 + strbuf_release(&buf_payload);

352 +}

353 +

354 struct tr2_tgt tr2_tgt_normal = {

355 .pdst = &tr2dst_normal,

356

@@ -360,4 +382,5 @@ struct tr2_tgt tr2_tgt_normal = {

382 .pfn_data_fl = NULL,

383 .pfn_data_json_fl = NULL,

384 .pfn_printf_va_fl = fn_printf_va_fl,

385 + .pfn_timer = fn_timer,

386 };

trace2/tr2_tgt_perf.c

+24

@@ -10,6 +10,7 @@

10 #include "trace2/tr2_tbuf.h"

11 #include "trace2/tr2_tgt.h"

12 #include "trace2/tr2_tls.h"

13 +#include "trace2/tr2_tmr.h"

15 static struct tr2_dst tr2dst_perf = {

16 .sysenv_var = TR2_SYSENV_PERF,

@@ -555,6 +556,28 @@ static void fn_printf_va_fl(const char *file, int line,

556 strbuf_release(&buf_payload);

557 }

558

559 +static void fn_timer(const struct tr2_timer_metadata *meta,

560 + const struct tr2_timer *timer,

561 + int is_final_data)

562 +{

563 + const char *event_name = is_final_data ? "timer" : "th_timer";

564 + struct strbuf buf_payload = STRBUF_INIT;

565 + double t_total = NS_TO_SEC(timer->total_ns);

566 + double t_min = NS_TO_SEC(timer->min_ns);

567 + double t_max = NS_TO_SEC(timer->max_ns);

568 +

569 + strbuf_addf(&buf_payload, ("name:%s"

570 + " intervals:%"PRIu64

571 + " total:%8.6f min:%8.6f max:%8.6f"),

572 + meta->name,

573 + timer->interval_count,

574 + t_total, t_min, t_max);

575 +

576 + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, NULL, NULL,

577 + meta->category, &buf_payload);

578 + strbuf_release(&buf_payload);

579 +}

580 +

581 struct tr2_tgt tr2_tgt_perf = {

582 .pdst = &tr2dst_perf,

583

@@ -586,4 +609,5 @@ struct tr2_tgt tr2_tgt_perf = {

609 .pfn_data_fl = fn_data_fl,

610 .pfn_data_json_fl = fn_data_json_fl,

611 .pfn_printf_va_fl = fn_printf_va_fl,

612 + .pfn_timer = fn_timer,

613 };

trace2/tr2_tls.c

+10

@@ -181,3 +181,13 @@ int tr2tls_locked_increment(int *p)

181

182 return current_value;

183 }

184 +

185 +void tr2tls_lock(void)

186 +{

187 + pthread_mutex_lock(&tr2tls_mutex);

188 +}

189 +

190 +void tr2tls_unlock(void)

191 +{

192 + pthread_mutex_unlock(&tr2tls_mutex);

193 +}

trace2/tr2_tls.h

+10

@@ -2,6 +2,7 @@

2 #define TR2_TLS_H

4 #include "strbuf.h"

5 +#include "trace2/tr2_tmr.h"

7 /*

8 * Notice: the term "TLS" refers to "thread-local storage" in the

@@ -20,6 +21,9 @@ struct tr2tls_thread_ctx {

21 size_t alloc;

22 size_t nr_open_regions; /* plays role of "nr" in ALLOC_GROW */

23 int thread_id;

24 + struct tr2_timer_block timer_block;

25 + unsigned int used_any_timer:1;

26 + unsigned int used_any_per_thread_timer:1;

27 };

29 /*

@@ -107,4 +111,10 @@ int tr2tls_locked_increment(int *p);

111 */

112 void tr2tls_start_process_clock(void);

113

114 +/*

115 + * Explicitly lock/unlock our mutex.

116 + */

117 +void tr2tls_lock(void);

118 +void tr2tls_unlock(void);

119 +

120 #endif /* TR2_TLS_H */

trace2/tr2_tmr.c new

+182

@@ -0,0 +1,182 @@

1 +#include "cache.h"

2 +#include "thread-utils.h"

3 +#include "trace2/tr2_tgt.h"

4 +#include "trace2/tr2_tls.h"

5 +#include "trace2/tr2_tmr.h"

6 +

7 +#define MY_MAX(a, b) ((a) > (b) ? (a) : (b))

8 +#define MY_MIN(a, b) ((a) < (b) ? (a) : (b))

9 +

10 +/*

11 + * A global timer block to aggregate values from the partial sums from

12 + * each thread.

13 + */

14 +static struct tr2_timer_block final_timer_block; /* access under tr2tls_mutex */

15 +

16 +/*

17 + * Define metadata for each stopwatch timer.

18 + *

19 + * This array must match "enum trace2_timer_id" and the values

20 + * in "struct tr2_timer_block.timer[*]".

21 + */

22 +static struct tr2_timer_metadata tr2_timer_metadata[TRACE2_NUMBER_OF_TIMERS] = {

23 + [TRACE2_TIMER_ID_TEST1] = {

24 + .category = "test",

25 + .name = "test1",

26 + .want_per_thread_events = 0,

27 + },

28 + [TRACE2_TIMER_ID_TEST2] = {

29 + .category = "test",

30 + .name = "test2",

31 + .want_per_thread_events = 1,

32 + },

33 +

34 + /* Add additional metadata before here. */

35 +};

36 +

37 +void tr2_start_timer(enum trace2_timer_id tid)

38 +{

39 + struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

40 + struct tr2_timer *t = &ctx->timer_block.timer[tid];

41 +

42 + t->recursion_count++;

43 + if (t->recursion_count > 1)

44 + return; /* ignore recursive starts */

45 +

46 + t->start_ns = getnanotime();

47 +}

48 +

49 +void tr2_stop_timer(enum trace2_timer_id tid)

50 +{

51 + struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

52 + struct tr2_timer *t = &ctx->timer_block.timer[tid];

53 + uint64_t ns_now;

54 + uint64_t ns_interval;

55 +

56 + assert(t->recursion_count > 0);

57 +

58 + t->recursion_count--;

59 + if (t->recursion_count)

60 + return; /* still in recursive call(s) */

61 +

62 + ns_now = getnanotime();

63 + ns_interval = ns_now - t->start_ns;

64 +

65 + t->total_ns += ns_interval;

66 +

67 + /*

68 + * min_ns was initialized to zero (in the xcalloc()) rather

69 + * than UINT_MAX when the block of timers was allocated,

70 + * so we should always set both the min_ns and max_ns values

71 + * the first time that the timer is used.

72 + */

73 + if (!t->interval_count) {

74 + t->min_ns = ns_interval;

75 + t->max_ns = ns_interval;

76 + } else {

77 + t->min_ns = MY_MIN(ns_interval, t->min_ns);

78 + t->max_ns = MY_MAX(ns_interval, t->max_ns);

79 + }

80 +

81 + t->interval_count++;

82 +

83 + ctx->used_any_timer = 1;

84 + if (tr2_timer_metadata[tid].want_per_thread_events)

85 + ctx->used_any_per_thread_timer = 1;

86 +}

87 +

88 +void tr2_update_final_timers(void)

89 +{

90 + struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

91 + enum trace2_timer_id tid;

92 +

93 + if (!ctx->used_any_timer)

94 + return;

95 +

96 + /*

97 + * Accessing `final_timer_block` requires holding `tr2tls_mutex`.

98 + * We assume that our caller is holding the lock.

99 + */

100 +

101 + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) {

102 + struct tr2_timer *t_final = &final_timer_block.timer[tid];

103 + struct tr2_timer *t = &ctx->timer_block.timer[tid];

104 +

105 + if (t->recursion_count) {

106 + /*

107 + * The current thread is exiting with

108 + * timer[tid] still running.

109 + *

110 + * Technically, this is a bug, but I'm going

111 + * to ignore it.

112 + *

113 + * I don't think it is worth calling die()

114 + * for. I don't think it is worth killing the

115 + * process for this bookkeeping error. We

116 + * might want to call warning(), but I'm going

117 + * to wait on that.

118 + *

119 + * The downside here is that total_ns won't

120 + * include the current open interval (now -

121 + * start_ns). I can live with that.

122 + */

123 + }

124 +

125 + if (!t->interval_count)

126 + continue; /* this timer was not used by this thread */

127 +

128 + t_final->total_ns += t->total_ns;

129 +

130 + /*

131 + * final_timer_block.timer[tid].min_ns was initialized to

132 + * was initialized to zero rather than UINT_MAX, so we should

133 + * always set both the min_ns and max_ns values the first time

134 + * that we add a partial sum into it.

135 + */

136 + if (!t_final->interval_count) {

137 + t_final->min_ns = t->min_ns;

138 + t_final->max_ns = t->max_ns;

139 + } else {

140 + t_final->min_ns = MY_MIN(t_final->min_ns, t->min_ns);

141 + t_final->max_ns = MY_MAX(t_final->max_ns, t->max_ns);

142 + }

143 +

144 + t_final->interval_count += t->interval_count;

145 + }

146 +}

147 +

148 +void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply)

149 +{

150 + struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

151 + enum trace2_timer_id tid;

152 +

153 + if (!ctx->used_any_per_thread_timer)

154 + return;

155 +

156 + /*

157 + * For each timer, if the timer wants per-thread events and

158 + * this thread used it, emit it.

159 + */

160 + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++)

161 + if (tr2_timer_metadata[tid].want_per_thread_events &&

162 + ctx->timer_block.timer[tid].interval_count)

163 + fn_apply(&tr2_timer_metadata[tid],

164 + &ctx->timer_block.timer[tid],

165 + 0);

166 +}

167 +

168 +void tr2_emit_final_timers(tr2_tgt_evt_timer_t *fn_apply)

169 +{

170 + enum trace2_timer_id tid;

171 +

172 + /*

173 + * Accessing `final_timer_block` requires holding `tr2tls_mutex`.

174 + * We assume that our caller is holding the lock.

175 + */

176 +

177 + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++)

178 + if (final_timer_block.timer[tid].interval_count)

179 + fn_apply(&tr2_timer_metadata[tid],

180 + &final_timer_block.timer[tid],

181 + 1);

182 +}

trace2/tr2_tmr.h new

+140

@@ -0,0 +1,140 @@

1 +#ifndef TR2_TMR_H

2 +#define TR2_TMR_H

3 +

4 +#include "trace2.h"

5 +#include "trace2/tr2_tgt.h"

6 +

7 +/*

8 + * Define a mechanism to allow "stopwatch" timers.

9 + *

10 + * Timers can be used to measure "interesting" activity that does not

11 + * fit the "region" model, such as code called from many different

12 + * regions (like zlib) and/or where data for individual calls are not

13 + * interesting or are too numerous to be efficiently logged.

14 + *

15 + * Timer values are accumulated during program execution and emitted

16 + * to the Trace2 logs at program exit.

17 + *

18 + * To make this model efficient, we define a compile-time fixed set of

19 + * timers and timer ids using a "timer block" array in thread-local

20 + * storage. This gives us constant time access to each timer within

21 + * each thread, since we want start/stop operations to be as fast as

22 + * possible. This lets us avoid the complexities of dynamically

23 + * allocating a timer on the first use by a thread and/or possibly

24 + * sharing that timer definition with other concurrent threads.

25 + * However, this does require that we define time the set of timers at

26 + * compile time.

27 + *

28 + * Each thread uses the timer block in its thread-local storage to

29 + * compute partial sums for each timer (without locking). When a

30 + * thread exits, those partial sums are (under lock) added to the

31 + * global final sum.

32 + *

33 + * Using this "timer block" model costs ~48 bytes per timer per thread

34 + * (we have about six uint64 fields per timer). This does increase

35 + * the size of the thread-local storage block, but it is allocated (at

36 + * thread create time) and not on the thread stack, so I'm not worried

37 + * about the size.

38 + *

39 + * Partial sums for each timer are optionally emitted when a thread

40 + * exits.

41 + *

42 + * Final sums for each timer are emitted between the "exit" and

43 + * "atexit" events.

44 + *

45 + * A parallel "timer metadata" table contains the "category" and "name"

46 + * fields for each timer. This eliminates the need to include those

47 + * args in the various timer APIs.

48 + */

49 +

50 +/*

51 + * The definition of an individual timer and used by an individual

52 + * thread.

53 + */

54 +struct tr2_timer {

55 + /*

56 + * Total elapsed time for this timer in this thread in nanoseconds.

57 + */

58 + uint64_t total_ns;

59 +

60 + /*

61 + * The maximum and minimum interval values observed for this

62 + * timer in this thread.

63 + */

64 + uint64_t min_ns;

65 + uint64_t max_ns;

66 +

67 + /*

68 + * The value of the clock when this timer was started in this

69 + * thread. (Undefined when the timer is not active in this

70 + * thread.)

71 + */

72 + uint64_t start_ns;

73 +

74 + /*

75 + * Number of times that this timer has been started and stopped

76 + * in this thread. (Recursive starts are ignored.)

77 + */

78 + uint64_t interval_count;

79 +

80 + /*

81 + * Number of nested starts on the stack in this thread. (We

82 + * ignore recursive starts and use this to track the recursive

83 + * calls.)

84 + */

85 + unsigned int recursion_count;

86 +};

87 +

88 +/*

89 + * Metadata for a timer.

90 + */

91 +struct tr2_timer_metadata {

92 + const char *category;

93 + const char *name;

94 +

95 + /*

96 + * True if we should emit per-thread events for this timer

97 + * when individual threads exit.

98 + */

99 + unsigned int want_per_thread_events:1;

100 +};

101 +

102 +/*

103 + * A compile-time fixed-size block of timers to insert into

104 + * thread-local storage. This wrapper is used to avoid quirks

105 + * of C and the usual need to pass an array size argument.

106 + */

107 +struct tr2_timer_block {

108 + struct tr2_timer timer[TRACE2_NUMBER_OF_TIMERS];

109 +};

110 +

111 +/*

112 + * Private routines used by trace2.c to actually start/stop an

113 + * individual timer in the current thread.

114 + */

115 +void tr2_start_timer(enum trace2_timer_id tid);

116 +void tr2_stop_timer(enum trace2_timer_id tid);

117 +

118 +/*

119 + * Add the current thread's timer data to the global totals.

120 + * This is called during thread-exit.

121 + *

122 + * Caller must be holding the tr2tls_mutex.

123 + */

124 +void tr2_update_final_timers(void);

125 +

126 +/*

127 + * Emit per-thread timer data for the current thread.

128 + * This is called during thread-exit.

129 + */

130 +void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply);

131 +

132 +/*

133 + * Emit global total timer values.

134 + * This is called during atexit handling.

135 + *

136 + * Caller must be holding the tr2tls_mutex.

137 + */

138 +void tr2_emit_final_timers(tr2_tgt_evt_timer_t *fn_apply);

139 +

140 +#endif /* TR2_TMR_H */