feat(Spanner.V1): Add interceptor for Built-In Metrics

[robertvoinescu-work]

b/404948213

[gemini-code-assist]

Code Review

This pull request introduces a gRPC interceptor to record attempt-level metrics for Spanner, including attempt counts, latencies, and GFE latencies extracted from the 'server-timing' header. The implementation integrates this interceptor into the Spanner client builder. My review identified three issues: an unused field that should be removed, an incorrect usage of context.Method.Name instead of context.Method.FullName when extracting method names, and a premature return in the GFE latency parsing logic that prevents processing multiple entries in the 'server-timing' header.

[efevans]

Looks good and very clean. Now that we have the Interceptor class implementation, is this going too far including metrics, instruments, labels, and methods that are generic enough to extract into a shared library? What if we changed the underlying SpannerBuiltInMetrics static class to an abstract class that extracts the shared resources, and then each API library can extend from that and add service-specific metrics and labels? Then each library would expose an instance of their implementation as a singleton, and pass that to the Interceptor constructor to call for library-specific instrumentation.

Quick peek at the metrics and labels in SpannerBuiltInMetrics and I'm guessing database is the lone Spanner specific label, and other labels like client_name being shared with implementation-specific values that could be obtained through overriding virtual GetClientName methods.

Looking to start a discussion on this before asking for this done since it's a pretty big ask.

[efevans]

LGTM

[amanda-tarafa]

Add a sync version of this method that receives no header tasks at all? You can use that one for the blocking unary call as well.

[amanda-tarafa]

But honestly I wonder if we need to instrument here, where the call didn't even reached the service yet? Do we know what other languages did?

[robertvoinescu-work]

Done. At least in Java this seems to be the case, any failures due to faulty interceptors are caught by the exact same logic handling RPC network exceptions. I will ask spanner team for clarification if this was intentional. Leaving this open for now.

[robertvoinescu-work]

I spoke with spanner team and they said we should "record all the RPCs which are initiated [client side] and has not completed for whatever reason."

[amanda-tarafa]

We don't need to pass these as a parameters. If we ever parse more headers, then we can add parameters.

Suggested change

	EmitServerTimingMetrics(header.Value, GfeMetricPrefix, duration => s_gfeLatency.Record(duration, labels));
	EmitServerTimingMetrics(header.Value);

[robertvoinescu-work]

I spoke with Surbhi and got some clarification that we will regardless receive AFE headers - direct path enabled or not. We will need to add some additional headers to get this x-goog-spanner-enable-afe-server-timing. In the meantime I've left the code so it's easily extensible for when that is added along with a TODO.

[amanda-tarafa]

I think this works, and I think it's cleaner, and easier to follow. It's all done in place, and each character is visited as most once. Even with the spans, your code goes back and forth some times. I haven't tested it but see what you think, and also @efevans .

Suggested change

	int searchStart = 0;
	var headerSpan = header.AsSpan();
	while (searchStart < headerSpan.Length)
	{
	// Server-Timing metrics are separated by commas.
	// Example header: "other-metric; dur=5.2, gfet4t7; dur=12.5"
	var remainingHeaderSpan = headerSpan.Slice(searchStart);
	int metricEnd = remainingHeaderSpan.IndexOf(',');
	// Isolate to a single metric. Example slice: "gfet4t7; dur=12.5"
	var metricSpan = metricEnd >= 0 ? remainingHeaderSpan.Slice(0, metricEnd) : remainingHeaderSpan;
	if (metricSpan.TrimStart().StartsWith(metricPrefix.AsSpan(), StringComparison.OrdinalIgnoreCase))
	{
	// look for "dur" in the current metric, if it doesnt exist then
	// this will return -1 and we will return early
	int durIdx = metricSpan.IndexOf(GfeDurationPrefix.AsSpan());
	// Ensure 'dur' exists.
	if (durIdx >= 0)
	{
	// Skip 'dur' (3 chars) and isolate the rest. Example slice: "= 12.5 "
	var valSpan = metricSpan.Slice(durIdx + GfeDurationPrefix.Length);
	// Look for "=" so we can step past it, this should always exist.
	int eqIdx = valSpan.IndexOf('=');
	if (eqIdx >= 0)
	{
	// Carefully isolate the actual value by stepping past the '=' sign
	// Example slice: " 12.5 "
	valSpan = valSpan.Slice(eqIdx + 1);
	// Isolate the value up to an optional trailing semicolon (in case extra spec parameters
	// are ever appended to the metric block, though unexpected for gfet4t7 today).
	var semiIdx = valSpan.IndexOf(';');
	var durationSpan = semiIdx >= 0 ? valSpan.Slice(0, semiIdx) : valSpan;
	// Remove whitepace before parsing. Example: " 12.5 " -> "12.5"
	durationSpan = durationSpan.Trim();
	if (double.TryParse(durationSpan.ToString(), System.Globalization.NumberStyles.AllowDecimalPoint, System.Globalization.CultureInfo.InvariantCulture, out double duration))
	{
	recordAction(duration);
	}
	}
	}
	}
	if (metricEnd < 0)
	{
	break;
	}
	searchStart += metricEnd + 1;
	}
	int currentStart = 0;
	do
	{
	// Find the first occurrence of the metric from the point we are at.
	int metricIndex = header.IndexOf(metricPrefix, currentStart);
	if (metricIndex < 0)
	{
	return;
	}
	// Move past the first occurennce of the metric.
	currentStart = metricIndex + metricPrefix.Length;
	// Find the first of "dur" or ",".
	bool durMissing = true;
	// We don't need to continue when we have less than 3 characters left.
	for (int i = currentStart; i < header.Length - 2; i++)
	{
	// This signals the end of the metric, so we didn't find 'dur'.
	// We move past this position and attempt to find another occurrence of the metric.
	if (header[i] == ',')
	{
	currentStart = i + 1;
	break;
	}
	// We found 'dur'.
	// We move past 'dur' so we can now extract the associated value.
	if (header[i] == 'd' && header[i+1] == 'u' && header[i+2] == 'r')
	{
	durMissing = false;
	currentStart = i + 3;
	break;
	}
	}
	if (durMissing)
	{
	continue;
	}
	// If we are here, we found 'dur' and we now need to extract the associated value.
	// Go past '=' from the point we are at.
	int equalIndex = header.IndexOf('=', currentStart);
	currentStart = equalIndex + 1;
	// The metric value.
	double duration = 0;
	// We use these to build the number as we parse it.
	// Before we find the decimal separator, we multiply our accumulator by 10 for every digit.
	// But after finding the decimal separator, we'll multiply our accumulator by 1 for every digit.
	double integerMultiplier = 10;
	// Before we find the decimal separator, we have no fractional part so each digit is divided by 1.
	// After we find the decimal separator, we have to divide each digit by incremental powers of ten.
	double fractionalDividend = 1;
	double fractionalDividendModifier = 1;
	for (; currentStart < header.Length; currentStart++)
	{
	// Skip spaces, at the beginning and also at the end,
	// because it's just easier to not make the distinction.
	if (char.IsWhiteSpace(header[currentStart]))
	{
	continue;
	}
	// If we find the decimal point, swap to fractional places.
	if (header[currentStart] == '.')
	{
	integerMultiplier = 1;
	fractionalDividend = 10;
	fractionalDividendModifier = 10;
	}
	// Consume the digits and add them to our accumulator
	else if (char.IsDigit(header, currentStart))
	{
	double digit = char.GetNumericValue(header, currentStart);
	duration = (duration * integerMultiplier) + (digit / fractionalDividend);
	fractionalDividend *= fractionalDividendModifier;
	}
	// For any other character, we are done finding the value.
	else
	{
	break;
	}
	}
	recordAction(duration);
	} while (currentStart < header.Length);

[efevans]

I tried tracing this with "other-metric; dur=5.2, gfet4t7; dur=12.5" and it looks correct to me. I'm in favor of a span implementation and find the string manipulation to be easier to follow but do acknowledge even that is a trade off vs. the accumulator implementation which saves an allocation from durationSpan.ToString()

[amanda-tarafa]

Just to be clear, it's not just the allocation, a single allocation is not a problem (the first implementation was heavy on substrings but the spans take care of that). At this point it's mostly the approach of going back and forth on the string, which we don't need, e.g. going all the way to a comma, to then go back to the beginning looking for 'dur' and the digits, etc. We can do all of that at once and visit each character at most once.

This code will execute with every RPC attempt so we need to be more careful here.

[robertvoinescu-work]

Thanks Amanda. I had found myself writing something similar, but felt it was a bit hard to follow. Your in code comments help in that readability while reducing those additional iterations going back and forth on the string you mentioned. So I've added mostly this with a few changes to catch some edge cases.

[robertvoinescu-work]

@amanda-tarafa I ran some integration tests and we are still hitting this interceptor even with the request id being populated through a CallOptions header mutation. I might have missed something when we originally discussed so let me know if theres a different situation where you expect blocking unary calls not to occur.

[amanda-tarafa]

Yes, this one will always be used at least for async calls. It's the blocking one that may be unused if the caller added response header handlers. That's because the gRPC blocking client method does not expose response headers, but our client does allow to set response header handlers for both async and blocking. See the code that does that here.

[robertvoinescu-work]

I pinned this to the wrong method, I meant to pin it to the blocking unary. I ran some integration tests and found that blocking unary was still called even when we have the RequestId population as a callback (the current state of things).

But I misunderstood what you were saying originally - it's the response handler that causes the skip as you mentioned - and I just verified that.

[amanda-tarafa]

Mostly nits, a single thing that we should change immediately. The latency in blocking I think it's being miscalculated on errors.

[amanda-tarafa]

Yes, this one will always be used at least for async calls. It's the blocking one that may be unused if the caller added response header handlers. That's because the gRPC blocking client method does not expose response headers, but our client does allow to set response header handlers for both async and blocking. See the code that does that here.

[amanda-tarafa]

Do we need these to be string? Or can we just pass around the StatusCode.OK or StatusCode.Unknown and turn it to string only if we need to?

[amanda-tarafa]

Can we stop it? Maybe there's no need, but just in case it seems "cleaner".

[robertvoinescu-work]

I was looking into this earlier and I think we don't need to:
http://stackoverflow.com/questions/24140261/should-i-stop-stopwatch-at-the-end-of-the-method

It just freezes the elapsed time at the point stop is called without freeing up resources (there aren't any besides the memory for the object). Let me consider it, but I might lean towards having fewer lines of code if we can.

[amanda-tarafa]

Yes, it's not necessary regarding resource cleanup, but I think it's clearer, just "leaving the thing running" doesn't sound good I think.

And that's why in the finally down below you are overriding the original value you get on the catch, with the one that you get on the finally.

I think it will all read better if you can stop the stopwatch and then read the elapsed time.

[amanda-tarafa]

This value will be overwritten in finally, I think you want to stop the stopwatch here and after success as well, and in finally only access the the elapsed milliseconds.

[amanda-tarafa]

Why is this method defined here, but RecordAttemptMetrics is defined in the parent class? It seems random and will make things harder to find out later.

[amanda-tarafa]

Suggested change

	RecordAttemptMetrics(elapsedMs, labels);
	await RecordServerTimingMetricsAsync(call.ResponseHeadersAsync, labels).ConfigureAwait(false);
	var recordTimingTask = RecordServerTimingMetricsAsync(call.ResponseHeadersAsync, labels);
	RecordAttemptMetrics(elapsedMs, labels);
	await recordTimingTask.ConfigureAwait(false);

[amanda-tarafa]

If this one is used only by the interceptor, then let's move it there.

[robertvoinescu-work]

This is not clear here at all here, but this will be used outside of the interceptor in the ReliableStreamReader where attempt latency is defined as the time a stream is used until it dies and each stream re/creation would be considered an attempt.

[amanda-tarafa]

Then maybe bring the other one here as well, even if it's only used on the interceptor? Just to have all these on the same place.

[amanda-tarafa]

I think we can change this parameter to StatusCode, drop the constants above and use StatusCode.OK or StatusCode.Unknown in the places that we need it.