Skip to content

Commit

Permalink
Merge pull request #177 from PubMatic-OpenWrap/UOE-6646
Browse files Browse the repository at this point in the history 
UOE-6646: Added label adapter_name for tls_handshake_time stat
  • Loading branch information
@pm-isha-bharti
pm-isha-bharti authored Jul 14, 2021
2 parents 62934aa + b420a11 commit c16692e
Show file tree
Hide file tree
Showing 9 changed files with 153 additions and 86 deletions.
2 changes: 1 addition & 1 deletion exchange/bidder.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
2 changes: 1 addition & 1 deletion exchange/bidder_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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{})
Expand Down
6 changes: 3 additions & 3 deletions metrics/config/metrics.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
}

Expand Down Expand Up @@ -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
Expand Down
44 changes: 28 additions & 16 deletions metrics/go_metrics.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -101,6 +100,7 @@ type AdapterMetrics struct {
ConnCreated metrics.Counter
ConnReused metrics.Counter
ConnWaitTime metrics.Timer
TLSHandshakeTimer metrics.Timer
}

type MarkupDeliveryMetrics struct {
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
}
Expand Down Expand Up @@ -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.
Expand Down
44 changes: 33 additions & 11 deletions metrics/go_metrics_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
}

Expand Down
2 changes: 1 addition & 1 deletion metrics/metrics.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
4 changes: 2 additions & 2 deletions metrics/metrics_mock.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
76 changes: 43 additions & 33 deletions metrics/prometheus/prometheus.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -62,6 +62,7 @@ type Metrics struct {
adapterConnectionWaitTime *prometheus.HistogramVec
adapterDuplicateBidIDCounter *prometheus.CounterVec
adapterVideoBidDuration *prometheus.HistogramVec
tlsHandhakeTimer *prometheus.HistogramVec

// Account Metrics
accountRequests *prometheus.CounterVec
Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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) {
Expand Down
Loading

0 comments on commit c16692e

Please sign in to comment.