From a8fb2e7e081600b8224dcdc46a5c64f47b11cd79 Mon Sep 17 00:00:00 2001 From: Sachin Survase Date: Fri, 9 Jul 2021 14:35:57 +0530 Subject: [PATCH 1/2] UOE-6646: Added label adapter_name for tls_handshake_time stat --- exchange/bidder.go | 2 +- exchange/bidder_test.go | 2 +- metrics/config/metrics.go | 6 +-- metrics/go_metrics.go | 44 ++++++++++------ metrics/go_metrics_test.go | 44 ++++++++++++---- metrics/metrics.go | 2 +- metrics/metrics_mock.go | 4 +- metrics/prometheus/prometheus.go | 76 +++++++++++++++------------ metrics/prometheus/prometheus_test.go | 59 ++++++++++++++------- 9 files changed, 153 insertions(+), 86 deletions(-) diff --git a/exchange/bidder.go b/exchange/bidder.go index c30d791d221..262d2d8d3f3 100644 --- a/exchange/bidder.go +++ b/exchange/bidder.go @@ -516,7 +516,7 @@ func (bidder *bidderAdapter) addClientTrace(ctx context.Context) context.Context TLSHandshakeDone: func(tls.ConnectionState, error) { tlsHandshakeTime := time.Now().Sub(tlsStart) - bidder.me.RecordTLSHandshakeTime(tlsHandshakeTime) + bidder.me.RecordTLSHandshakeTime(bidder.BidderName, tlsHandshakeTime) }, } return httptrace.WithClientTrace(ctx, trace) diff --git a/exchange/bidder_test.go b/exchange/bidder_test.go index 6db249ec6ed..a3a0acbe5f0 100644 --- a/exchange/bidder_test.go +++ b/exchange/bidder_test.go @@ -1523,7 +1523,7 @@ func TestCallRecordDNSTime(t *testing.T) { func TestCallRecordTLSHandshakeTime(t *testing.T) { // setup a mock metrics engine and its expectation metricsMock := &metrics.MetricsEngineMock{} - metricsMock.Mock.On("RecordTLSHandshakeTime", mock.Anything).Return() + metricsMock.Mock.On("RecordTLSHandshakeTime", mock.Anything, mock.Anything).Return() // Instantiate the bidder that will send the request. We'll make sure to use an // http.Client that runs our mock RoundTripper so DNSDone(httptrace.DNSDoneInfo{}) diff --git a/metrics/config/metrics.go b/metrics/config/metrics.go index 70738f2fd1a..6c9344b325b 100644 --- a/metrics/config/metrics.go +++ b/metrics/config/metrics.go @@ -147,9 +147,9 @@ func (me *MultiMetricsEngine) RecordDNSTime(dnsLookupTime time.Duration) { } } -func (me *MultiMetricsEngine) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) { +func (me *MultiMetricsEngine) RecordTLSHandshakeTime(bidderName openrtb_ext.BidderName, tlsHandshakeTime time.Duration) { for _, thisME := range *me { - thisME.RecordTLSHandshakeTime(tlsHandshakeTime) + thisME.RecordTLSHandshakeTime(bidderName, tlsHandshakeTime) } } @@ -338,7 +338,7 @@ func (me *DummyMetricsEngine) RecordDNSTime(dnsLookupTime time.Duration) { } // RecordTLSHandshakeTime as a noop -func (me *DummyMetricsEngine) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) { +func (me *DummyMetricsEngine) RecordTLSHandshakeTime(bidderName openrtb_ext.BidderName, tlsHandshakeTime time.Duration) { } // RecordAdapterBidReceived as a noop diff --git a/metrics/go_metrics.go b/metrics/go_metrics.go index dc4bc1f8217..f21ebc5907c 100644 --- a/metrics/go_metrics.go +++ b/metrics/go_metrics.go @@ -31,7 +31,6 @@ type Metrics struct { StoredImpCacheMeter map[CacheResult]metrics.Meter AccountCacheMeter map[CacheResult]metrics.Meter DNSLookupTimer metrics.Timer - TLSHandshakeTimer metrics.Timer // Metrics for OpenRTB requests specifically. So we can track what % of RequestsMeter are OpenRTB // and know when legacy requests have been abandoned. @@ -101,6 +100,7 @@ type AdapterMetrics struct { ConnCreated metrics.Counter ConnReused metrics.Counter ConnWaitTime metrics.Timer + TLSHandshakeTimer metrics.Timer } type MarkupDeliveryMetrics struct { @@ -131,18 +131,18 @@ func NewBlankMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderNa blankTimer := &metrics.NilTimer{} newMetrics := &Metrics{ - MetricsRegistry: registry, - RequestStatuses: make(map[RequestType]map[RequestStatus]metrics.Meter), - ConnectionCounter: metrics.NilCounter{}, - ConnectionAcceptErrorMeter: blankMeter, - ConnectionCloseErrorMeter: blankMeter, - ImpMeter: blankMeter, - LegacyImpMeter: blankMeter, - AppRequestMeter: blankMeter, - NoCookieMeter: blankMeter, - RequestTimer: blankTimer, - DNSLookupTimer: blankTimer, - TLSHandshakeTimer: blankTimer, + MetricsRegistry: registry, + RequestStatuses: make(map[RequestType]map[RequestStatus]metrics.Meter), + ConnectionCounter: metrics.NilCounter{}, + ConnectionAcceptErrorMeter: blankMeter, + ConnectionCloseErrorMeter: blankMeter, + ImpMeter: blankMeter, + LegacyImpMeter: blankMeter, + AppRequestMeter: blankMeter, + NoCookieMeter: blankMeter, + RequestTimer: blankTimer, + DNSLookupTimer: blankTimer, + //TLSHandshakeTimer: blankTimer, RequestsQueueTimer: make(map[RequestType]map[bool]metrics.Timer), PrebidCacheRequestTimerSuccess: blankTimer, PrebidCacheRequestTimerError: blankTimer, @@ -243,7 +243,7 @@ func NewMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderName, d newMetrics.AppRequestMeter = metrics.GetOrRegisterMeter("app_requests", registry) newMetrics.RequestTimer = metrics.GetOrRegisterTimer("request_time", registry) newMetrics.DNSLookupTimer = metrics.GetOrRegisterTimer("dns_lookup_time", registry) - newMetrics.TLSHandshakeTimer = metrics.GetOrRegisterTimer("tls_handshake_time", registry) + //newMetrics.TLSHandshakeTimer = metrics.GetOrRegisterTimer("tls_handshake_time", registry) newMetrics.PrebidCacheRequestTimerSuccess = metrics.GetOrRegisterTimer("prebid_cache_request_time.ok", registry) newMetrics.PrebidCacheRequestTimerError = metrics.GetOrRegisterTimer("prebid_cache_request_time.err", registry) @@ -319,6 +319,7 @@ func makeBlankAdapterMetrics(disabledMetrics config.DisabledMetrics) *AdapterMet newAdapter.ConnCreated = metrics.NilCounter{} newAdapter.ConnReused = metrics.NilCounter{} newAdapter.ConnWaitTime = &metrics.NilTimer{} + newAdapter.TLSHandshakeTimer = &metrics.NilTimer{} } for _, err := range AdapterErrors() { newAdapter.ErrorMeters[err] = blankMeter @@ -357,6 +358,7 @@ func registerAdapterMetrics(registry metrics.Registry, adapterOrAccount string, am.ConnCreated = metrics.GetOrRegisterCounter(fmt.Sprintf("%[1]s.%[2]s.connections_created", adapterOrAccount, exchange), registry) am.ConnReused = metrics.GetOrRegisterCounter(fmt.Sprintf("%[1]s.%[2]s.connections_reused", adapterOrAccount, exchange), registry) am.ConnWaitTime = metrics.GetOrRegisterTimer(fmt.Sprintf("%[1]s.%[2]s.connection_wait_time", adapterOrAccount, exchange), registry) + am.TLSHandshakeTimer = metrics.GetOrRegisterTimer(fmt.Sprintf("%[1]s.%[2]s.connection_wait_time", adapterOrAccount, exchange), registry) for err := range am.ErrorMeters { am.ErrorMeters[err] = metrics.GetOrRegisterMeter(fmt.Sprintf("%s.%s.requests.%s", adapterOrAccount, exchange, err), registry) } @@ -559,8 +561,18 @@ func (me *Metrics) RecordDNSTime(dnsLookupTime time.Duration) { me.DNSLookupTimer.Update(dnsLookupTime) } -func (me *Metrics) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) { - me.TLSHandshakeTimer.Update(tlsHandshakeTime) +func (me *Metrics) RecordTLSHandshakeTime(adapterName openrtb_ext.BidderName, tlsHandshakeTime time.Duration) { + if me.MetricsDisabled.AdapterConnectionMetrics { + return + } + + am, ok := me.AdapterMetrics[adapterName] + if !ok { + glog.Errorf("Trying to log adapter TLS Handshake metrics for %s: adapter not found", string(adapterName)) + return + } + + am.TLSHandshakeTimer.Update(tlsHandshakeTime) } // RecordAdapterBidReceived implements a part of the MetricsEngine interface. diff --git a/metrics/go_metrics_test.go b/metrics/go_metrics_test.go index 2d0b9097b11..7ebe2f3c2fe 100644 --- a/metrics/go_metrics_test.go +++ b/metrics/go_metrics_test.go @@ -210,29 +210,51 @@ func TestRecordDNSTime(t *testing.T) { } func TestRecordTLSHandshakeTime(t *testing.T) { + type testIn struct { + adapterName openrtb_ext.BidderName + tLSHandshakeDuration time.Duration + adapterMetricsEnabled bool + } + + type testOut struct { + expectedDuration time.Duration + } + testCases := []struct { - description string - tLSHandshakeDuration time.Duration - expectedDuration time.Duration + description string + in testIn + out testOut }{ { - description: "Five second TLS handshake time", - tLSHandshakeDuration: time.Second * 5, - expectedDuration: time.Second * 5, + description: "Five second TLS handshake time", + in: testIn{ + adapterName: openrtb_ext.BidderAppnexus, + tLSHandshakeDuration: time.Second * 5, + adapterMetricsEnabled: true, + }, + out: testOut{ + expectedDuration: time.Second * 5, + }, }, { - description: "Zero TLS handshake time", - tLSHandshakeDuration: time.Duration(0), - expectedDuration: time.Duration(0), + description: "Zero TLS handshake time", + in: testIn{ + adapterName: openrtb_ext.BidderAppnexus, + tLSHandshakeDuration: time.Duration(0), + adapterMetricsEnabled: true, + }, + out: testOut{ + expectedDuration: time.Duration(0), + }, }, } for _, test := range testCases { registry := metrics.NewRegistry() m := NewMetrics(registry, []openrtb_ext.BidderName{openrtb_ext.BidderAppnexus}, config.DisabledMetrics{AccountAdapterDetails: true}) - m.RecordTLSHandshakeTime(test.tLSHandshakeDuration) + m.RecordTLSHandshakeTime(test.in.adapterName, test.in.tLSHandshakeDuration) - assert.Equal(t, test.expectedDuration.Nanoseconds(), m.TLSHandshakeTimer.Sum(), test.description) + assert.Equal(t, test.out.expectedDuration.Nanoseconds(), m.AdapterMetrics[openrtb_ext.BidderAppnexus].TLSHandshakeTimer.Sum(), test.description) } } diff --git a/metrics/metrics.go b/metrics/metrics.go index 4e6a6ea7275..5966b7716f3 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -348,7 +348,7 @@ type MetricsEngine interface { RecordAdapterRequest(labels AdapterLabels) RecordAdapterConnections(adapterName openrtb_ext.BidderName, connWasReused bool, connWaitTime time.Duration) RecordDNSTime(dnsLookupTime time.Duration) - RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) + RecordTLSHandshakeTime(adapterName openrtb_ext.BidderName, tlsHandshakeTime time.Duration) RecordAdapterPanic(labels AdapterLabels) // This records whether or not a bid of a particular type uses `adm` or `nurl`. // Since the legacy endpoints don't have a bid type, it can only count bids from OpenRTB and AMP. diff --git a/metrics/metrics_mock.go b/metrics/metrics_mock.go index 54b448bbe19..b211b2faa22 100644 --- a/metrics/metrics_mock.go +++ b/metrics/metrics_mock.go @@ -72,8 +72,8 @@ func (me *MetricsEngineMock) RecordDNSTime(dnsLookupTime time.Duration) { me.Called(dnsLookupTime) } -func (me *MetricsEngineMock) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) { - me.Called(tlsHandshakeTime) +func (me *MetricsEngineMock) RecordTLSHandshakeTime(bidderName openrtb_ext.BidderName, tlsHandshakeTime time.Duration) { + me.Called(bidderName, tlsHandshakeTime) } // RecordAdapterBidReceived mock diff --git a/metrics/prometheus/prometheus.go b/metrics/prometheus/prometheus.go index 33b36fbb61c..a0a13455493 100644 --- a/metrics/prometheus/prometheus.go +++ b/metrics/prometheus/prometheus.go @@ -15,33 +15,33 @@ type Metrics struct { Registry *prometheus.Registry // General Metrics - connectionsClosed prometheus.Counter - connectionsError *prometheus.CounterVec - connectionsOpened prometheus.Counter - cookieSync prometheus.Counter - impressions *prometheus.CounterVec - impressionsLegacy prometheus.Counter - prebidCacheWriteTimer *prometheus.HistogramVec - requests *prometheus.CounterVec - requestsTimer *prometheus.HistogramVec - requestsQueueTimer *prometheus.HistogramVec - requestsWithoutCookie *prometheus.CounterVec - storedImpressionsCacheResult *prometheus.CounterVec - storedRequestCacheResult *prometheus.CounterVec - accountCacheResult *prometheus.CounterVec - storedAccountFetchTimer *prometheus.HistogramVec - storedAccountErrors *prometheus.CounterVec - storedAMPFetchTimer *prometheus.HistogramVec - storedAMPErrors *prometheus.CounterVec - storedCategoryFetchTimer *prometheus.HistogramVec - storedCategoryErrors *prometheus.CounterVec - storedRequestFetchTimer *prometheus.HistogramVec - storedRequestErrors *prometheus.CounterVec - storedVideoFetchTimer *prometheus.HistogramVec - storedVideoErrors *prometheus.CounterVec - timeoutNotifications *prometheus.CounterVec - dnsLookupTimer prometheus.Histogram - tlsHandhakeTimer prometheus.Histogram + connectionsClosed prometheus.Counter + connectionsError *prometheus.CounterVec + connectionsOpened prometheus.Counter + cookieSync prometheus.Counter + impressions *prometheus.CounterVec + impressionsLegacy prometheus.Counter + prebidCacheWriteTimer *prometheus.HistogramVec + requests *prometheus.CounterVec + requestsTimer *prometheus.HistogramVec + requestsQueueTimer *prometheus.HistogramVec + requestsWithoutCookie *prometheus.CounterVec + storedImpressionsCacheResult *prometheus.CounterVec + storedRequestCacheResult *prometheus.CounterVec + accountCacheResult *prometheus.CounterVec + storedAccountFetchTimer *prometheus.HistogramVec + storedAccountErrors *prometheus.CounterVec + storedAMPFetchTimer *prometheus.HistogramVec + storedAMPErrors *prometheus.CounterVec + storedCategoryFetchTimer *prometheus.HistogramVec + storedCategoryErrors *prometheus.CounterVec + storedRequestFetchTimer *prometheus.HistogramVec + storedRequestErrors *prometheus.CounterVec + storedVideoFetchTimer *prometheus.HistogramVec + storedVideoErrors *prometheus.CounterVec + timeoutNotifications *prometheus.CounterVec + dnsLookupTimer prometheus.Histogram + //tlsHandhakeTimer prometheus.Histogram privacyCCPA *prometheus.CounterVec privacyCOPPA *prometheus.CounterVec privacyLMT *prometheus.CounterVec @@ -62,6 +62,7 @@ type Metrics struct { adapterConnectionWaitTime *prometheus.HistogramVec adapterDuplicateBidIDCounter *prometheus.CounterVec adapterVideoBidDuration *prometheus.HistogramVec + tlsHandhakeTimer *prometheus.HistogramVec // Account Metrics accountRequests *prometheus.CounterVec @@ -283,10 +284,10 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet "Seconds to resolve DNS", standardTimeBuckets) - metrics.tlsHandhakeTimer = newHistogram(cfg, metrics.Registry, - "tls_handshake_time", - "Seconds to perform TLS Handshake", - standardTimeBuckets) + //metrics.tlsHandhakeTimer = newHistogram(cfg, metrics.Registry, + // "tls_handshake_time", + // "Seconds to perform TLS Handshake", + // standardTimeBuckets) metrics.privacyCCPA = newCounter(cfg, metrics.Registry, "privacy_ccpa", @@ -355,6 +356,12 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet "Seconds from when the connection was requested until it is either created or reused", []string{adapterLabel}, standardTimeBuckets) + + metrics.tlsHandhakeTimer = newHistogramVec(cfg, metrics.Registry, + "tls_handshake_time", + "Seconds to perform TLS Handshake", + []string{adapterLabel}, + standardTimeBuckets) } metrics.adapterRequestsTimer = newHistogramVec(cfg, metrics.Registry, @@ -622,8 +629,11 @@ func (m *Metrics) RecordDNSTime(dnsLookupTime time.Duration) { m.dnsLookupTimer.Observe(dnsLookupTime.Seconds()) } -func (m *Metrics) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) { - m.tlsHandhakeTimer.Observe(tlsHandshakeTime.Seconds()) +func (m *Metrics) RecordTLSHandshakeTime(adapterName openrtb_ext.BidderName, tlsHandshakeTime time.Duration) { + //m.tlsHandhakeTimer.Observe(tlsHandshakeTime.Seconds()) + m.tlsHandhakeTimer.With(prometheus.Labels{ + adapterLabel: string(adapterName), + }).Observe(tlsHandshakeTime.Seconds()) } func (m *Metrics) RecordAdapterPanic(labels metrics.AdapterLabels) { diff --git a/metrics/prometheus/prometheus_test.go b/metrics/prometheus/prometheus_test.go index 9b4dc2aa09e..2cdf8702364 100644 --- a/metrics/prometheus/prometheus_test.go +++ b/metrics/prometheus/prometheus_test.go @@ -1199,35 +1199,57 @@ func TestRecordDNSTime(t *testing.T) { } func TestRecordTLSHandshakeTime(t *testing.T) { - testCases := []struct { - description string + type testIn struct { + adapterName openrtb_ext.BidderName tLSHandshakeDuration time.Duration - expectedDuration float64 - expectedCount uint64 + } + + type testOut struct { + expectedDuration float64 + expectedCount uint64 + } + + testCases := []struct { + description string + in testIn + out testOut }{ { - description: "Five second DNS lookup time", - tLSHandshakeDuration: time.Second * 5, - expectedDuration: 5, - expectedCount: 1, + description: "Five second DNS lookup time", + in: testIn{ + adapterName: openrtb_ext.BidderAppnexus, + tLSHandshakeDuration: time.Second * 5, + }, + out: testOut{ + expectedDuration: 5, + expectedCount: 1, + }, }, { - description: "Zero DNS lookup time", - tLSHandshakeDuration: 0, - expectedDuration: 0, - expectedCount: 1, + description: "Zero DNS lookup time", + in: testIn{ + adapterName: openrtb_ext.BidderAppnexus, + tLSHandshakeDuration: 0, + }, + out: testOut{ + expectedDuration: 0, + expectedCount: 1, + }, }, } for i, test := range testCases { pm := createMetricsForTesting() - pm.RecordTLSHandshakeTime(test.tLSHandshakeDuration) + assertDesciptions := []string{ + fmt.Sprintf("[%d] Incorrect number of histogram entries. Desc: %s", i+1, test.description), + fmt.Sprintf("[%d] Incorrect number of histogram cumulative values. Desc: %s", i+1, test.description), + } - m := dto.Metric{} - pm.tlsHandhakeTimer.Write(&m) - histogram := *m.GetHistogram() + pm.RecordTLSHandshakeTime(test.in.adapterName, test.in.tLSHandshakeDuration) - assert.Equal(t, test.expectedCount, histogram.GetSampleCount(), "[%d] Incorrect number of histogram entries. Desc: %s\n", i, test.description) - assert.Equal(t, test.expectedDuration, histogram.GetSampleSum(), "[%d] Incorrect number of histogram cumulative values. Desc: %s\n", i, test.description) + // Assert TLS Handshake time + histogram := getHistogramFromHistogramVec(pm.tlsHandhakeTimer, adapterLabel, string(test.in.adapterName)) + assert.Equal(t, test.out.expectedCount, histogram.GetSampleCount(), assertDesciptions[0]) + assert.Equal(t, test.out.expectedDuration, histogram.GetSampleSum(), assertDesciptions[1]) } } @@ -1353,6 +1375,7 @@ func TestDisableAdapterConnections(t *testing.T) { assert.Nil(t, prometheusMetrics.adapterReusedConnections, "Counter Vector adapterReusedConnections should be nil") assert.Nil(t, prometheusMetrics.adapterCreatedConnections, "Counter Vector adapterCreatedConnections should be nil") assert.Nil(t, prometheusMetrics.adapterConnectionWaitTime, "Counter Vector adapterConnectionWaitTime should be nil") + assert.Nil(t, prometheusMetrics.tlsHandhakeTimer, "Counter Vector tlsHandhakeTimer should be nil") } func TestRecordRequestPrivacy(t *testing.T) { From b420a11bac0faa4797573337137d4dd75b52dd33 Mon Sep 17 00:00:00 2001 From: Sachin Survase Date: Fri, 9 Jul 2021 17:47:07 +0530 Subject: [PATCH 2/2] Fixed typo --- metrics/go_metrics.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/metrics/go_metrics.go b/metrics/go_metrics.go index f21ebc5907c..2529eaf4765 100644 --- a/metrics/go_metrics.go +++ b/metrics/go_metrics.go @@ -358,7 +358,7 @@ func registerAdapterMetrics(registry metrics.Registry, adapterOrAccount string, am.ConnCreated = metrics.GetOrRegisterCounter(fmt.Sprintf("%[1]s.%[2]s.connections_created", adapterOrAccount, exchange), registry) am.ConnReused = metrics.GetOrRegisterCounter(fmt.Sprintf("%[1]s.%[2]s.connections_reused", adapterOrAccount, exchange), registry) am.ConnWaitTime = metrics.GetOrRegisterTimer(fmt.Sprintf("%[1]s.%[2]s.connection_wait_time", adapterOrAccount, exchange), registry) - am.TLSHandshakeTimer = metrics.GetOrRegisterTimer(fmt.Sprintf("%[1]s.%[2]s.connection_wait_time", adapterOrAccount, exchange), registry) + am.TLSHandshakeTimer = metrics.GetOrRegisterTimer(fmt.Sprintf("%[1]s.%[2]s.tls_handshake_time", adapterOrAccount, exchange), registry) for err := range am.ErrorMeters { am.ErrorMeters[err] = metrics.GetOrRegisterMeter(fmt.Sprintf("%s.%s.requests.%s", adapterOrAccount, exchange, err), registry) }