Skip to content

Commit

Permalink
More granular adapter error metrics (#550)
Browse files Browse the repository at this point in the history 
* Split the adapter error metrics up by purpose. Fixed some bugs.

* Renamed some more metrics, and fixed some issues.

* Split the openrtb2 request type into web and app.
  • Loading branch information
@dbemiller
dbemiller authored Jun 26, 2018
1 parent 6ac68bf commit b91c7f8
Show file tree
Hide file tree
Showing 10 changed files with 186 additions and 106 deletions.
9 changes: 6 additions & 3 deletions endpoints/openrtb2/auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,7 +65,7 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
start := time.Now()
labels := pbsmetrics.Labels{
Source: pbsmetrics.DemandUnknown,
RType: pbsmetrics.ReqTypeORTB2,
RType: pbsmetrics.ReqTypeORTB2Web,
PubID: "",
Browser: pbsmetrics.BrowserOther,
CookieFlag: pbsmetrics.CookieFlagUnknown,
Expand Down Expand Up @@ -94,8 +94,11 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
if req.Site != nil && req.Site.Publisher != nil {
labels.PubID = req.Site.Publisher.ID
}
if req.App != nil && req.App.Publisher != nil {
labels.PubID = req.App.Publisher.ID
if req.App != nil {
labels.RType = pbsmetrics.ReqTypeORTB2App
if req.App.Publisher != nil {
labels.PubID = req.App.Publisher.ID
}
}

ctx := context.Background()
Expand Down
4 changes: 3 additions & 1 deletion exchange/bidder.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -186,7 +186,9 @@ func (bidder *bidderAdapter) doRequest(ctx context.Context, req *adapters.Reques
defer httpResp.Body.Close()

if httpResp.StatusCode < 200 || httpResp.StatusCode >= 400 {
err = fmt.Errorf("Server responded with failure status: %d. Set request.test = 1 for debugging info.", httpResp.StatusCode)
err = &adapters.BadServerResponseError{
Message: fmt.Sprintf("Server responded with failure status: %d. Set request.test = 1 for debugging info.", httpResp.StatusCode),
}
}

return &httpCallInfo{
Expand Down
70 changes: 48 additions & 22 deletions exchange/exchange.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@ import (
"net/http"
"time"

"github.com/prebid/prebid-server/adapters"

"github.com/golang/glog"

"github.com/mxmCherry/openrtb"
Expand Down Expand Up @@ -176,31 +178,17 @@ func (e *exchange) getAllBids(ctx context.Context, cleanRequests map[openrtb_ext
ae.ResponseTimeMillis = int(elapsed / time.Millisecond)
// Timing statistics
e.me.RecordAdapterTime(*bidlabels, time.Since(start))
serr := make([]string, len(err))
for i := 0; i < len(err); i++ {
serr[i] = err[i].Error()
// TODO: #142: for a bidder that return multiple errors, we will log multiple errors for that request
// in the metrics. Need to remember that in analyzing the data.
switch err[i] {
case context.DeadlineExceeded:
bidlabels.AdapterStatus = pbsmetrics.AdapterStatusTimeout
default:
bidlabels.AdapterStatus = pbsmetrics.AdapterStatusErr
}
}
serr := errsToStrings(err)
bidlabels.AdapterBids = bidsToMetric(bids)
bidlabels.AdapterErrors = errorsToMetric(err)
// Append any bid validation errors to the error list
ae.Errors = serr
brw.adapterExtra = ae
if len(err) == 0 {
if bids == nil || len(bids.bids) == 0 {
// Don't want to mark no bids on error topreserve legacy behavior.
bidlabels.AdapterStatus = pbsmetrics.AdapterStatusNoBid
} else {
for _, bid := range bids.bids {
var cpm = float64(bid.bid.Price * 1000)
e.me.RecordAdapterPrice(*bidlabels, cpm)
e.me.RecordAdapterBidReceived(*bidlabels, bid.bidType, bid.bid.AdM != "")
}
if bids != nil {
for _, bid := range bids.bids {
var cpm = float64(bid.bid.Price * 1000)
e.me.RecordAdapterPrice(*bidlabels, cpm)
e.me.RecordAdapterBidReceived(*bidlabels, bid.bidType, bid.bid.AdM != "")
}
}
chBids <- brw
Expand All @@ -216,6 +204,44 @@ func (e *exchange) getAllBids(ctx context.Context, cleanRequests map[openrtb_ext
return adapterBids, adapterExtra
}

func bidsToMetric(bids *pbsOrtbSeatBid) pbsmetrics.AdapterBid {
if bids == nil || len(bids.bids) == 0 {
return pbsmetrics.AdapterBidNone
}
return pbsmetrics.AdapterBidPresent
}

func errorsToMetric(errs []error) map[pbsmetrics.AdapterError]struct{} {
if len(errs) == 0 {
return nil
}
ret := make(map[pbsmetrics.AdapterError]struct{}, len(errs))
var s struct{}
for _, err := range errs {
if err == context.DeadlineExceeded {
ret[pbsmetrics.AdapterErrorTimeout] = s
} else {
switch err.(type) {
case *adapters.BadInputError:
ret[pbsmetrics.AdapterErrorBadInput] = s
case *adapters.BadServerResponseError:
ret[pbsmetrics.AdapterErrorBadServerResponse] = s
default:
ret[pbsmetrics.AdapterErrorUnknown] = s
}
}
}
return ret
}

func errsToStrings(errs []error) []string {
serr := make([]string, len(errs))
for i := 0; i < len(errs); i++ {
serr[i] = errs[i].Error()
}
return serr
}

// This piece takes all the bids supplied by the adapters and crafts an openRTB response to send back to the requester
func (e *exchange) buildBidResponse(ctx context.Context, liveAdapters []openrtb_ext.BidderName, adapterBids map[openrtb_ext.BidderName]*pbsOrtbSeatBid, bidRequest *openrtb.BidRequest, resolvedRequest json.RawMessage, adapterExtra map[openrtb_ext.BidderName]*seatResponseExtra, errList []error) (*openrtb.BidResponse, error) {
bidResponse := new(openrtb.BidResponse)
Expand Down
14 changes: 7 additions & 7 deletions exchange/utils.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,13 +41,13 @@ func splitBidRequest(req *openrtb.BidRequest, impsByBidder map[string][]openrtb.
reqCopy := *req
coreBidder := resolveBidder(bidder, aliases)
newLabel := pbsmetrics.AdapterLabels{
Source: labels.Source,
RType: labels.RType,
Adapter: coreBidder,
PubID: labels.PubID,
Browser: labels.Browser,
CookieFlag: labels.CookieFlag,
AdapterStatus: pbsmetrics.AdapterStatusOK,
Source: labels.Source,
RType: labels.RType,
Adapter: coreBidder,
PubID: labels.PubID,
Browser: labels.Browser,
CookieFlag: labels.CookieFlag,
AdapterBids: pbsmetrics.AdapterBidPresent,
}
blabels[coreBidder] = &newLabel
if hadSync := prepareUser(&reqCopy, bidder, coreBidder, explicitBuyerUIDs, usersyncs); !hadSync && req.App == nil {
Expand Down
32 changes: 18 additions & 14 deletions pbs_light.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -204,13 +204,13 @@ func (deps *auctionDeps) auction(w http.ResponseWriter, r *http.Request, _ httpr
if ex, ok := exchanges[bidder.BidderCode]; ok {
// Make sure we have an independent label struct for each bidder. We don't want to run into issues with the goroutine below.
blabels := pbsmetrics.AdapterLabels{
Source: labels.Source,
RType: labels.RType,
Adapter: openrtb_ext.BidderMap[bidder.BidderCode],
PubID: labels.PubID,
Browser: labels.Browser,
CookieFlag: labels.CookieFlag,
AdapterStatus: pbsmetrics.AdapterStatusOK,
Source: labels.Source,
RType: labels.RType,
Adapter: openrtb_ext.BidderMap[bidder.BidderCode],
PubID: labels.PubID,
Browser: labels.Browser,
CookieFlag: labels.CookieFlag,
AdapterBids: pbsmetrics.AdapterBidPresent,
}
if blabels.Adapter == "" {
// "districtm" is legal, but not in BidderMap. Other values will log errors in the go_metrics code
Expand Down Expand Up @@ -249,19 +249,23 @@ func (deps *auctionDeps) auction(w http.ResponseWriter, r *http.Request, _ httpr
deps.metricsEngine.RecordAdapterTime(blabels, time.Since(start))
bidder.ResponseTime = int(time.Since(start) / time.Millisecond)
if err != nil {
var s struct{}
switch err {
case context.DeadlineExceeded:
blabels.AdapterStatus = pbsmetrics.AdapterStatusTimeout
blabels.AdapterErrors = map[pbsmetrics.AdapterError]struct{}{pbsmetrics.AdapterErrorTimeout: s}
bidder.Error = "Timed out"
case context.Canceled:
fallthrough
default:
blabels.AdapterStatus = pbsmetrics.AdapterStatusErr
bidder.Error = err.Error()
if _, isBadInput := err.(*adapters.BadInputError); !isBadInput {
if _, isBadServer := err.(*adapters.BadServerResponseError); !isBadServer {
glog.Warningf("Error from bidder %v. Ignoring all bids: %v", bidder.BidderCode, err)
}
switch err.(type) {
case *adapters.BadInputError:
blabels.AdapterErrors = map[pbsmetrics.AdapterError]struct{}{pbsmetrics.AdapterErrorBadInput: s}
case *adapters.BadServerResponseError:
blabels.AdapterErrors = map[pbsmetrics.AdapterError]struct{}{pbsmetrics.AdapterErrorBadServerResponse: s}
default:
glog.Warningf("Error from bidder %v. Ignoring all bids: %v", bidder.BidderCode, err)
blabels.AdapterErrors = map[pbsmetrics.AdapterError]struct{}{pbsmetrics.AdapterErrorUnknown: s}
}
}
} else if bid_list != nil {
Expand All @@ -280,7 +284,7 @@ func (deps *auctionDeps) auction(w http.ResponseWriter, r *http.Request, _ httpr
}
} else {
bidder.NoBid = true
blabels.AdapterStatus = pbsmetrics.AdapterStatusNoBid
blabels.AdapterBids = pbsmetrics.AdapterBidNone
}

ch <- bidResult{
Expand Down
53 changes: 34 additions & 19 deletions pbsmetrics/config/metrics_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -45,42 +45,57 @@ func TestMultiMetricsEngine(t *testing.T) {
metricsEngine = &engineList
labels := pbsmetrics.Labels{
Source: pbsmetrics.DemandWeb,
RType: pbsmetrics.ReqTypeORTB2,
RType: pbsmetrics.ReqTypeORTB2Web,
PubID: "test1",
Browser: pbsmetrics.BrowserSafari,
CookieFlag: pbsmetrics.CookieFlagYes,
RequestStatus: pbsmetrics.RequestStatusOK,
}
blabels := pbsmetrics.AdapterLabels{
Source: pbsmetrics.DemandWeb,
RType: pbsmetrics.ReqTypeORTB2,
Adapter: openrtb_ext.BidderPubmatic,
PubID: "test1",
Browser: pbsmetrics.BrowserSafari,
CookieFlag: pbsmetrics.CookieFlagYes,
AdapterStatus: pbsmetrics.AdapterStatusOK,
apnLabels := pbsmetrics.AdapterLabels{
Source: pbsmetrics.DemandWeb,
RType: pbsmetrics.ReqTypeORTB2Web,
Adapter: openrtb_ext.BidderAppnexus,
PubID: "test1",
Browser: pbsmetrics.BrowserSafari,
CookieFlag: pbsmetrics.CookieFlagYes,
AdapterBids: pbsmetrics.AdapterBidNone,
}
pubLabels := pbsmetrics.AdapterLabels{
Source: pbsmetrics.DemandWeb,
RType: pbsmetrics.ReqTypeORTB2Web,
Adapter: openrtb_ext.BidderPubmatic,
PubID: "test1",
Browser: pbsmetrics.BrowserSafari,
CookieFlag: pbsmetrics.CookieFlagYes,
AdapterBids: pbsmetrics.AdapterBidPresent,
}
for i := 0; i < 5; i++ {
metricsEngine.RecordRequest(labels)
metricsEngine.RecordImps(labels, 2)
metricsEngine.RecordRequestTime(labels, time.Millisecond*20)
metricsEngine.RecordAdapterRequest(blabels)
metricsEngine.RecordAdapterPrice(blabels, 1.34)
metricsEngine.RecordAdapterTime(blabels, time.Millisecond*20)
metricsEngine.RecordAdapterRequest(pubLabels)
metricsEngine.RecordAdapterRequest(apnLabels)
metricsEngine.RecordAdapterPrice(pubLabels, 1.34)
metricsEngine.RecordAdapterBidReceived(pubLabels, openrtb_ext.BidTypeBanner, true)
metricsEngine.RecordAdapterTime(pubLabels, time.Millisecond*20)
}
VerifyMetrics(t, "RequestStatuses.OpenRTB2.OK", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2][pbsmetrics.RequestStatusOK].Count(), 5)
VerifyMetrics(t, "RequestStatuses.OpenRTB2.OK", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2Web][pbsmetrics.RequestStatusOK].Count(), 5)
VerifyMetrics(t, "RequestStatuses.Legacy.OK", goEngine.RequestStatuses[pbsmetrics.ReqTypeLegacy][pbsmetrics.RequestStatusOK].Count(), 0)
VerifyMetrics(t, "RequestStatuses.AMP.OK", goEngine.RequestStatuses[pbsmetrics.ReqTypeAMP][pbsmetrics.RequestStatusOK].Count(), 0)
VerifyMetrics(t, "RequestStatuses.OpenRTB2.Error", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2][pbsmetrics.RequestStatusErr].Count(), 0)
VerifyMetrics(t, "RequestStatuses.OpenRTB2.BadInput", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2][pbsmetrics.RequestStatusBadInput].Count(), 0)
VerifyMetrics(t, "Request", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2][pbsmetrics.RequestStatusOK].Count(), 5)
VerifyMetrics(t, "RequestStatuses.OpenRTB2.Error", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2Web][pbsmetrics.RequestStatusErr].Count(), 0)
VerifyMetrics(t, "RequestStatuses.OpenRTB2.BadInput", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2Web][pbsmetrics.RequestStatusBadInput].Count(), 0)
VerifyMetrics(t, "Request", goEngine.RequestStatuses[pbsmetrics.ReqTypeORTB2Web][pbsmetrics.RequestStatusOK].Count(), 5)
VerifyMetrics(t, "ImpMeter", goEngine.ImpMeter.Count(), 10)
VerifyMetrics(t, "NoCookieMeter", goEngine.NoCookieMeter.Count(), 0)
VerifyMetrics(t, "SafariRequestMeter", goEngine.SafariRequestMeter.Count(), 5)
VerifyMetrics(t, "SafariNoCookieMeter", goEngine.SafariNoCookieMeter.Count(), 0)
VerifyMetrics(t, "AdapterMetrics.Pubmatic.RequestMeter", goEngine.AdapterMetrics[openrtb_ext.BidderPubmatic].RequestMeter.Count(), 5)
VerifyMetrics(t, "AdapterMetrics.Pubmatic.ErrorMeter", goEngine.AdapterMetrics[openrtb_ext.BidderPubmatic].ErrorMeter.Count(), 0)
VerifyMetrics(t, "AdapterMetrics.AppNexus.RequestMeter", goEngine.AdapterMetrics[openrtb_ext.BidderAppnexus].RequestMeter.Count(), 0)
VerifyMetrics(t, "AdapterMetrics.Pubmatic.GotBidsMeter", goEngine.AdapterMetrics[openrtb_ext.BidderPubmatic].GotBidsMeter.Count(), 5)
VerifyMetrics(t, "AdapterMetrics.Pubmatic.NoBidMeter", goEngine.AdapterMetrics[openrtb_ext.BidderPubmatic].NoBidMeter.Count(), 0)
for _, err := range pbsmetrics.AdapterErrors() {
VerifyMetrics(t, "AdapterMetrics.Pubmatic.Request.ErrorMeter."+string(err), goEngine.AdapterMetrics[openrtb_ext.BidderPubmatic].ErrorMeters[err].Count(), 0)
}
VerifyMetrics(t, "AdapterMetrics.AppNexus.GotBidsMeter", goEngine.AdapterMetrics[openrtb_ext.BidderAppnexus].GotBidsMeter.Count(), 0)
VerifyMetrics(t, "AdapterMetrics.AppNexus.NoBidMeter", goEngine.AdapterMetrics[openrtb_ext.BidderAppnexus].NoBidMeter.Count(), 5)
}

func VerifyMetrics(t *testing.T, name string, expected int64, actual int64) {
Expand Down
46 changes: 25 additions & 21 deletions pbsmetrics/go_metrics.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,10 +44,9 @@ type Metrics struct {
// AdapterMetrics houses the metrics for a particular adapter
type AdapterMetrics struct {
NoCookieMeter metrics.Meter
ErrorMeter metrics.Meter
ErrorMeters map[AdapterError]metrics.Meter
NoBidMeter metrics.Meter
TimeoutMeter metrics.Meter
RequestMeter metrics.Meter
GotBidsMeter metrics.Meter
RequestTimer metrics.Timer
PriceHistogram metrics.Histogram
BidsReceivedMeter metrics.Meter
Expand Down Expand Up @@ -157,15 +156,17 @@ func makeBlankAdapterMetrics() *AdapterMetrics {
blankMeter := &metrics.NilMeter{}
newAdapter := &AdapterMetrics{
NoCookieMeter: blankMeter,
ErrorMeter: blankMeter,
ErrorMeters: make(map[AdapterError]metrics.Meter),
NoBidMeter: blankMeter,
TimeoutMeter: blankMeter,
RequestMeter: blankMeter,
GotBidsMeter: blankMeter,
RequestTimer: &metrics.NilTimer{},
PriceHistogram: &metrics.NilHistogram{},
BidsReceivedMeter: blankMeter,
MarkupMetrics: makeBlankBidMarkupMetrics(),
}
for _, err := range AdapterErrors() {
newAdapter.ErrorMeters[err] = blankMeter
}
return newAdapter
}

Expand All @@ -187,10 +188,8 @@ func makeBlankMarkupDeliveryMetrics() *MarkupDeliveryMetrics {

func registerAdapterMetrics(registry metrics.Registry, adapterOrAccount string, exchange string, am *AdapterMetrics) {
am.NoCookieMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.no_cookie_requests", adapterOrAccount, exchange), registry)
am.ErrorMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.error_requests", adapterOrAccount, exchange), registry)
am.NoBidMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.no_bid_requests", adapterOrAccount, exchange), registry)
am.TimeoutMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.timeout_requests", adapterOrAccount, exchange), registry)
am.RequestMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.requests", adapterOrAccount, exchange), registry)
am.NoBidMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.requests.nobid", adapterOrAccount, exchange), registry)
am.GotBidsMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.requests.gotbids", adapterOrAccount, exchange), registry)
am.RequestTimer = metrics.GetOrRegisterTimer(fmt.Sprintf("%[1]s.%[2]s.request_time", adapterOrAccount, exchange), registry)
am.PriceHistogram = metrics.GetOrRegisterHistogram(fmt.Sprintf("%[1]s.%[2]s.prices", adapterOrAccount, exchange), registry, metrics.NewExpDecaySample(1028, 0.015))
am.MarkupMetrics = map[openrtb_ext.BidType]*MarkupDeliveryMetrics{
Expand All @@ -199,6 +198,9 @@ func registerAdapterMetrics(registry metrics.Registry, adapterOrAccount string,
openrtb_ext.BidTypeAudio: makeDeliveryMetrics(registry, adapterOrAccount+"."+exchange, openrtb_ext.BidTypeAudio),
openrtb_ext.BidTypeNative: makeDeliveryMetrics(registry, adapterOrAccount+"."+exchange, openrtb_ext.BidTypeNative),
}
for err := range am.ErrorMeters {
am.ErrorMeters[err] = metrics.GetOrRegisterMeter(fmt.Sprintf("%s.%s.requests.%s", adapterOrAccount, exchange, err), registry)
}
if adapterOrAccount != "adapter" {
am.BidsReceivedMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("%[1]s.%[2]s.bids_received", adapterOrAccount, exchange), registry)
}
Expand Down Expand Up @@ -312,20 +314,22 @@ func (me *Metrics) RecordAdapterRequest(labels AdapterLabels) {
glog.Errorf("Trying to run adapter metrics on %s: adapter metrics not found", string(labels.Adapter))
return
}
// Adapter metrics
am.RequestMeter.Mark(1)
// Account-Adapter metrics
aam := me.getAccountMetrics(labels.PubID).adapterMetrics[labels.Adapter]
aam.RequestMeter.Mark(1)

switch labels.AdapterStatus {
case AdapterStatusErr:
am.ErrorMeter.Mark(1)
case AdapterStatusNoBid:
aam := me.getAccountMetrics(labels.PubID).adapterMetrics[labels.Adapter]
switch labels.AdapterBids {
case AdapterBidNone:
am.NoBidMeter.Mark(1)
case AdapterStatusTimeout:
am.TimeoutMeter.Mark(1)
aam.NoBidMeter.Mark(1)
case AdapterBidPresent:
am.GotBidsMeter.Mark(1)
aam.GotBidsMeter.Mark(1)
default:
glog.Warningf("No go-metrics logged for AdapterBids value: %s", labels.AdapterBids)
}
for errType := range labels.AdapterErrors {
am.ErrorMeters[errType].Mark(1)
}

if labels.CookieFlag == CookieFlagNo {
am.NoCookieMeter.Mark(1)
}
Expand Down
Loading

0 comments on commit b91c7f8

Please sign in to comment.