git.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Derrick Stolee <stolee@gmail.com>
To: Jeff Hostetler via GitGitGadget <gitgitgadget@gmail.com>,
	git@vger.kernel.org
Cc: Jeff Hostetler <jeffhost@microsoft.com>
Subject: Re: [PATCH 7/9] trace2: add stopwatch timers
Date: Tue, 21 Dec 2021 09:45:31 -0500	[thread overview]
Message-ID: <5f9c6997-abae-c2c7-0121-eb2d360108b8@gmail.com> (raw)
In-Reply-To: <dd4f0576254defa3ab0e73a73c9c433f28fcca5b.1640012469.git.gitgitgadget@gmail.com>

On 12/20/2021 10:01 AM, Jeff Hostetler via GitGitGadget wrote:
> From: Jeff Hostetler <jeffhost@microsoft.com>
> 
> Add a stopwatch timer mechanism to Git.

> +static void *ut_009timer_thread_proc(void *_ut_009_data)
> +{
> +	struct ut_009_data *data = _ut_009_data;
> +	int k;
> +
> +	trace2_thread_start("ut_009");
> +
> +	for (k = 0; k < data->count; k++) {
> +		trace2_timer_start(TRACE2_TIMER_ID_TEST2);
> +		sleep_millisec(data->delay);
> +		trace2_timer_stop(TRACE2_TIMER_ID_TEST2);
> +	}
> +
> +	trace2_thread_exit();
> +	return NULL;
> +}
> +
> +

nit: double newline.

> +# Exercise the stopwatch timer "test" in a loop and confirm that it was
> +# we have as many start/stop intervals as expected.  We cannot really test
> +# the (elapsed, min, max) timer values, so we assume they are good.

We can't check their values, but we could check that their labels are
emitted.

> +test_expect_success 'test stopwatch timers - summary only' '
> +	test_when_finished "rm trace.perf actual" &&
> +	test_config_global trace2.perfBrief 1 &&
> +	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
> +	test-tool trace2 008timer 5 10 &&
> +	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
> +	grep "d0|summary|timer||_T_ABS_||test|name:test1 count:5" actual

adding something like " total:.* min: .* max:.*" to the end of this
pattern might be good. You could even get really specific about the ".*"
being a floating point number, but I'm not too concerned about that. I
just want to see that these other labels stay consistent in future Git
versions.

> +# Exercise the stopwatch timer "test" in a loop and confirm that it was
> +# we have as many start/stop intervals as expected.  We cannot really test
> +# the (t_timer, t_min, t_max) timer values, so we assume they are good.
Similar, we can do something such as...

> +have_timer_event () {
> +	thread=$1
> +	name=$2
> +	count=$3
> +	file=$4
> +
> +	grep "\"event\":\"timer\".*\"thread\":\"${thread}\".*\"name\":\"${name}\".*\"count\":${count}" $file

Adding more detail to this pattern.

This helper could probably benefit from constructing the regex across
multiple string concatenations, so we can see the different pieces.
Something like

	pattern="\"event\":\"timer\""
	pattern="$pattern.*\"thread\":\"${thread}\""
	pattern="$pattern.*\"name\":\"${name}\""
	pattern="$pattern.*\"count\":\"${count}\""
	pattern="$pattern.*\"t_total\":"
	pattern="$pattern.*\"t_min\":"
	pattern="$pattern.*\"t_max\":"

	grep "$pattern" $file

> +
> +	return $?

If we used && throughout this method, would this return not be
necessary?

> +static void tr2main_emit_summary_timers(uint64_t us_elapsed_absolute)
> +{
> +	struct tr2_tgt *tgt_j;
> +	int j;
> +	struct tr2tmr_block merged;
> +
> +	memset(&merged, 0, sizeof(merged));
> +
> +	/*
> +	 * Sum across all of the per-thread stopwatch timer data into
> +	 * a single composite block of timer values.
> +	 */
> +	tr2tls_aggregate_timer_blocks(&merged);
> +
> +	/*
> +	 * Emit "summary" timer events for each composite timer value
> +	 * that had activity.
> +	 */
> +	for_each_wanted_builtin (j, tgt_j)
> +		if (tgt_j->pfn_timer)
> +			tr2tmr_emit_block(tgt_j->pfn_timer,
> +					  us_elapsed_absolute,
> +					  &merged, "summary");

I'd put braces at the for-loop level, even though this is semantically
correct without them.

> +}
> +
> +static void tr2main_emit_thread_timers(uint64_t us_elapsed_absolute)
> +{
> +	struct tr2_tgt *tgt_j;
> +	int j;
> +
> +	for_each_wanted_builtin (j, tgt_j)
> +		if (tgt_j->pfn_timer)
> +			tr2tls_emit_timer_blocks_by_thread(tgt_j->pfn_timer,
> +							   us_elapsed_absolute);

(same here)

> +/*
> + * Define the set of stopwatch timers.
> + *
> + * We can add more at any time, but they must be defined at compile
> + * time (to avoid the need to dynamically allocate and synchronize
> + * them between different threads).
> + *
> + * These must start at 0 and be contiguous (because we use them
> + * elsewhere as array indexes).

I was worried at first about using an array here, but this is essentially
one chunk of global memory per process that will not be very large, even
if we add a lot of timer IDs here. If we use this API enough that that
memory is a problem, then we can refactor the memory to be a hashmap that
only populates entries for IDs that are used by the process.

> + * Any values added to this enum must also be added to the timer definitions
> + * array.  See `trace2/tr2_tmr.c:tr2tmr_def_block[]`.
> + */
> +enum trace2_timer_id {
> +	/*
> +	 * Define two timers for testing.  See `t/helper/test-trace2.c`.
> +	 * These can be used for ad hoc testing, but should not be used
> +	 * for permanent analysis code.
> +	 */
> +	TRACE2_TIMER_ID_TEST1 = 0, /* emits summary event only */
> +	TRACE2_TIMER_ID_TEST2,     /* emits summary and thread events */
> +
> +
> +	/* Add additional timer definitions before here. */
> +	TRACE2_NUMBER_OF_TIMERS
> +};

...

> +static struct tr2tmr_def tr2tmr_def_block[TRACE2_NUMBER_OF_TIMERS] = {
> +	[TRACE2_TIMER_ID_TEST1] = { "test", "test1", 0 },
> +	[TRACE2_TIMER_ID_TEST2] = { "test", "test2", 1 },
> +};

Although this will always be populated, so maybe my thoughts about how
to reduce memory load in the hypothetical future are worthless.

> +void tr2tmr_start(enum trace2_timer_id tid)
> +{
> +	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
> +	struct tr2tmr_timer *t = &ctx->timers.timer[tid];
> +
> +	t->recursion_count++;
> +	if (t->recursion_count > 1)
> +		return; /* ignore recursive starts */
> +
> +	t->start_us = getnanotime() / 1000;

Using nanotime gives us the best precision available, and dividing
by 1000 will lose some precision. This is likely why we saw some
0.000000 values for t_min in some of your experiments. That should
be rare for real uses of this API (such as wrapping lstat() calls).

But why do we divide by 1000 here at all? 2^63 nanoseconds is
still 292 years, so we don't risk overflow. You specify uint64_t
so this isn't different on 32-bit machines.

Thanks,
-Stolee

  parent reply	other threads:[~2021-12-21 14:45 UTC|newest]

Thread overview: 55+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2021-12-20 15:01 [PATCH 0/9] Trace2 stopwatch timers and global counters Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 1/9] trace2: use size_t alloc,nr_open_regions in tr2tls_thread_ctx Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 2/9] trace2: convert tr2tls_thread_ctx.thread_name from strbuf to char* Jeff Hostetler via GitGitGadget
2021-12-20 16:31   ` Ævar Arnfjörð Bjarmason
2021-12-20 19:07     ` Jeff Hostetler
2021-12-20 19:35       ` Ævar Arnfjörð Bjarmason
2021-12-22 16:32         ` Jeff Hostetler
2021-12-21  7:33     ` Junio C Hamano
2021-12-21  7:22   ` Junio C Hamano
2021-12-22 16:28     ` Jeff Hostetler
2021-12-22 19:57       ` Junio C Hamano
2021-12-20 15:01 ` [PATCH 3/9] trace2: defer free of TLS CTX until program exit Jeff Hostetler via GitGitGadget
2021-12-21  7:30   ` Junio C Hamano
2021-12-22 21:59     ` Jeff Hostetler
2021-12-22 22:56       ` Junio C Hamano
2021-12-22 23:04         ` Jeff Hostetler
2021-12-23  7:38         ` Johannes Sixt
2021-12-23 18:18           ` Junio C Hamano
2021-12-27 18:51             ` Jeff Hostetler
2021-12-20 15:01 ` [PATCH 4/9] trace2: add thread-name override to event target Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 5/9] trace2: add thread-name override to perf target Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 6/9] trace2: add timer events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-20 16:39   ` Ævar Arnfjörð Bjarmason
2021-12-20 19:44     ` Jeff Hostetler
2021-12-21 14:20   ` Derrick Stolee
2021-12-20 15:01 ` [PATCH 7/9] trace2: add stopwatch timers Jeff Hostetler via GitGitGadget
2021-12-20 16:42   ` Ævar Arnfjörð Bjarmason
2021-12-22 21:38     ` Jeff Hostetler
2021-12-21 14:45   ` Derrick Stolee [this message]
2021-12-22 21:57     ` Jeff Hostetler
2021-12-20 15:01 ` [PATCH 8/9] trace2: add counter events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-20 16:51   ` Ævar Arnfjörð Bjarmason
2021-12-22 22:56     ` Jeff Hostetler
2021-12-20 15:01 ` [PATCH 9/9] trace2: add global counters Jeff Hostetler via GitGitGadget
2021-12-20 17:14   ` Ævar Arnfjörð Bjarmason
2021-12-22 22:18     ` Jeff Hostetler
2021-12-21 14:51 ` [PATCH 0/9] Trace2 stopwatch timers and " Derrick Stolee
2021-12-21 23:27   ` Matheus Tavares
2021-12-28 19:36 ` [PATCH v2 " Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 1/9] trace2: use size_t alloc,nr_open_regions in tr2tls_thread_ctx Jeff Hostetler via GitGitGadget
2021-12-29  0:48     ` Ævar Arnfjörð Bjarmason
2021-12-28 19:36   ` [PATCH v2 2/9] trace2: convert tr2tls_thread_ctx.thread_name from strbuf to flex array Jeff Hostetler via GitGitGadget
2021-12-29  1:11     ` Ævar Arnfjörð Bjarmason
2021-12-29 16:46       ` Jeff Hostetler
2021-12-28 19:36   ` [PATCH v2 3/9] trace2: defer free of thread local storage until program exit Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 4/9] trace2: add thread-name override to event target Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 5/9] trace2: add thread-name override to perf target Jeff Hostetler via GitGitGadget
2021-12-29  1:48     ` Ævar Arnfjörð Bjarmason
2021-12-29 17:15       ` Jeff Hostetler
2021-12-28 19:36   ` [PATCH v2 6/9] trace2: add timer events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 7/9] trace2: add stopwatch timers Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 8/9] trace2: add counter events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 9/9] trace2: add global counters Jeff Hostetler via GitGitGadget
2021-12-29  1:54   ` [PATCH v2 0/9] Trace2 stopwatch timers and " Ævar Arnfjörð Bjarmason
2021-12-30 16:42     ` Jeff Hostetler

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=5f9c6997-abae-c2c7-0121-eb2d360108b8@gmail.com \
    --to=stolee@gmail.com \
    --cc=git@vger.kernel.org \
    --cc=gitgitgadget@gmail.com \
    --cc=jeffhost@microsoft.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).