internal/observability: Adding metricProcedure field

[elliotchance]

The metricProcedure replicates the behavior of a variety of internal libraries when converting the procedure for metrics (M3). This field is critical to being able to support log correlation with metrics. See ERD for full details.

https://docs.google.com/document/d/1B45wjZDQL0olCoENh3XYMyvCPI2A3hw8OeU2IhrtBtA

• Description and context for reviewers: one partner, one stranger
• Docs (package doc)

RELEASE NOTES:

New metricProcedure log field will contain M3-compatible lookup values for the YARPC procedure.

[CLAassistant]

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you all sign our Contributor License Agreement before we can accept your contribution.
1 out of 2 committers have signed the CLA.

✅ elliotchance
❌ elliotchance-uber
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

[biosvs]

Let's change 9 to 10 on line 224

[biosvs]

Recently we faced a problem with the strings.ToLower function consuming too much CPU, and we trying to reduce use of this func.

I have played with benchmarks a bit, and here's my implementation. It's not pretty, but as this log is called for every request, it should be acceptable to exchange prettiness for performance.

// https://docs.google.com/document/d/1B45wjZDQL0olCoENh3XYMyvCPI2A3hw8OeU2IhrtBtA
func metricProcedure(procedure, encoding string) string {
	if procedure == "" {
		return "__no_procedure__"
	}

	if encoding != "proto" && encoding != "json" && encoding != "thrift" {
		return ""
	}

	return encodeMetricProcedure(procedure, encoding == "thrift")
}

func encodeMetricProcedure(procedure string, thrift bool) string {
	var (
		b = []byte(procedure)
		w = 0
	)

	for i := 0; i < len(b); i++ {
		if b[i] == '.' {
			w = 0
			continue
		}

		if b[i] == ':' {
			if thrift {
				b[w] = '-'
				w++
				b[w] = '-'
			} else {
				b[w] = '/'
			}

			i++
		} else if 'A' <= b[i] && b[i] <= 'Z' {
			b[w] = b[i] + 32
		} else {
			b[w] = b[i]
		}

		w++
	}

	return string(b[:w])
}

Benchstat results:

goos: darwin
goarch: amd64
pkg: go.uber.org/yarpc/internal/observability
cpu: Intel(R) Core(TM) i7-9750H CPU @ 2.60GHz
                                     │ /tmp/bench-before.log │        /tmp/bench-after.log         │
                                     │        sec/op         │   sec/op     vs base                │
MetricProcedure/EmptyProcedure-12               336.4n ±  2%   334.6n ± 2%        ~ (p=0.839 n=10)
MetricProcedure/Raw-12                          503.9n ±  2%   252.0n ± 4%  -49.99% (p=0.000 n=10)
MetricProcedure/EmptyRawProcedure-12            534.5n ±  1%   340.8n ± 2%  -36.23% (p=0.000 n=10)
MetricProcedure/Proto1-12                      1052.0n ±  6%   496.4n ± 5%  -52.81% (p=0.000 n=10)
MetricProcedure/Proto2-12                      1018.0n ±  4%   475.8n ± 6%  -53.26% (p=0.000 n=10)
MetricProcedure/Thrift1-12                      959.3n ±  8%   420.7n ± 8%  -56.14% (p=0.000 n=10)
MetricProcedure/Thrift1#01-12                   866.9n ± 11%   402.8n ± 8%  -53.54% (p=0.000 n=10)
MetricProcedure/Thrift1#02-12                   690.4n ± 50%   497.1n ± 5%  -27.99% (p=0.000 n=10)
geomean                                         697.0n         393.3n       -43.58%

                                     │ /tmp/bench-before.log │          /tmp/bench-after.log           │
                                     │         B/op          │    B/op     vs base                     │
MetricProcedure/EmptyProcedure-12                 32.00 ± 0%   32.00 ± 0%         ~ (p=1.000 n=10) ¹
MetricProcedure/Raw-12                            16.00 ± 0%    0.00 ± 0%  -100.00% (p=0.000 n=10)
MetricProcedure/EmptyRawProcedure-12              32.00 ± 0%   32.00 ± 0%         ~ (p=1.000 n=10) ¹
MetricProcedure/Proto1-12                         128.0 ± 0%   112.0 ± 0%   -12.50% (p=0.000 n=10)
MetricProcedure/Proto2-12                        160.00 ± 0%   96.00 ± 0%   -40.00% (p=0.000 n=10)
MetricProcedure/Thrift1-12                        96.00 ± 0%   56.00 ± 0%   -41.67% (p=0.000 n=10)
MetricProcedure/Thrift1#01-12                     80.00 ± 0%   48.00 ± 0%   -40.00% (p=0.000 n=10)
MetricProcedure/Thrift1#02-12                     160.0 ± 0%   128.0 ± 0%   -20.00% (p=0.000 n=10)
geomean                                           67.13                    ?                       ² ³
¹ all samples are equal
² summaries must be >0 to compute geomean
³ ratios must be >0 to compute geomean

                                     │ /tmp/bench-before.log │          /tmp/bench-after.log           │
                                     │       allocs/op       │ allocs/op   vs base                     │
MetricProcedure/EmptyProcedure-12                 2.000 ± 0%   2.000 ± 0%         ~ (p=1.000 n=10) ¹
MetricProcedure/Raw-12                            1.000 ± 0%   0.000 ± 0%  -100.00% (p=0.000 n=10)
MetricProcedure/EmptyRawProcedure-12              2.000 ± 0%   2.000 ± 0%         ~ (p=1.000 n=10) ¹
MetricProcedure/Proto1-12                         5.000 ± 0%   4.000 ± 0%   -20.00% (p=0.000 n=10)
MetricProcedure/Proto2-12                         5.000 ± 0%   4.000 ± 0%   -20.00% (p=0.000 n=10)
MetricProcedure/Thrift1-12                        5.000 ± 0%   3.000 ± 0%   -40.00% (p=0.000 n=10)
MetricProcedure/Thrift1#01-12                     5.000 ± 0%   3.000 ± 0%   -40.00% (p=0.000 n=10)
MetricProcedure/Thrift1#02-12                     5.000 ± 0%   4.000 ± 0%   -20.00% (p=0.000 n=10)
geomean                                           3.252                    ?                       ² ³
¹ all samples are equal
² summaries must be >0 to compute geomean
³ ratios must be >0 to compute geomean

[biosvs]

Forgot to show benchmark itself:

func BenchmarkMetricProcedure(b *testing.B) {
	for _, tt := range []struct {
		name      string
		encoding  string
		procedure string
		expected  string
	}{
		{
			"EmptyProcedure",
			"proto", "",
			"__no_procedure__",
		},
		{
			"Raw",
			"raw", "hello",
			"",
		},
		{
			"EmptyRawProcedure",
			"raw", "",
			"__no_procedure__",
		},
		{
			"Proto1",
			"proto", "synoptic.SignalCatalog::ExecuteQuery",
			"signalcatalog/executequery",
		},
		{
			"Proto2",
			"proto", "uber.infra.net.rpc.probe.Probe::Echo",
			"probe/echo",
		},
		{
			"Thrift1",
			"thrift", "Umonitor::deleteAlert",
			"umonitor--deletealert",
		},
		{
			"Thrift1",
			"thrift", "Probe::echo",
			"probe--echo",
		},
		{
			"Thrift1",
			"json", "uber.infra.umonitor.Umonitor::UpsertAlertThresholds",
			"umonitor/upsertalertthresholds",
		},
	} {
		b.Run(tt.name, func(b *testing.B) {
			b.ReportAllocs()

			for i := 0; i < b.N; i++ {
				res := metricProcedure(tt.procedure, tt.encoding)
				assert.Equal(b, tt.expected, res)
			}
		})
	}
}