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.

[amanda-tarafa]

What about the other methods, like BlockingUnaryCall and client streaming and bidi streaming?

[robertvoinescu-work]

Added BlockingUnary. I did not include client & duplex streaming becasue we don't have any methods using those protocols. Looking at them now they would require some additional work to implement - we'd need to parse the database name from the Context.CallOptions instead of the request object because duplex and client streaming don't expose the request to the interceptor (i.e. no IDatabaseNameProvider to work with).

It would be "deadcode", but if we wanted to add we could implement a special IDatabaseNameProvider that would parse databasename from context.CallOptions. Let me know what you think.

[amanda-tarafa]

Also replying here because this does not show in code anymore.

No we don't want deadcode, do leave a note on the interceptor explaining that we don't implement the behavior for client side methods that we don't use like ...

[amanda-tarafa]

Is this a requirement? In principle the application can open the stream (by sending the first request) and it may be a while till it attempts to read some data?

[robertvoinescu-work]

This is really good point. I'm seeing there might be some discrepancies across libraries. I've reached out to Spanner team for clarity and am still waiting on a response. In the meantime I removed the stream wrapper and went with when the initial response for establishing a stream is received to instrument. I will update here again once I've clarified the point.

[amanda-tarafa]

I didn't see anything for streams in the PR. It's fine if you are planning to include that in a following PR, but just want to double check that's what's happening. If that's the case, leave a TODO(b/.....) on the interceptor code saying that you will do this in another PR.

[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.

[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.