UOE-6646: Added label adapter_name for tls_handshake_time stat

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)

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{})

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

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.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)
 	}
@@ -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.

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)
 	}
 }
 

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.

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

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) {