diff --git a/endpoints/openrtb2/ctv/adpod_generator.go b/endpoints/openrtb2/ctv/adpod_generator.go index 10f4cc4427d..bec01ee069a 100644 --- a/endpoints/openrtb2/ctv/adpod_generator.go +++ b/endpoints/openrtb2/ctv/adpod_generator.go @@ -7,6 +7,7 @@ import ( "github.com/PubMatic-OpenWrap/openrtb" "github.com/PubMatic-OpenWrap/prebid-server/openrtb_ext" + "github.com/PubMatic-OpenWrap/prebid-server/pbsmetrics" ) /********************* AdPodGenerator Functions *********************/ @@ -20,14 +21,15 @@ type filteredBid struct { reasonCode FilterReasonCode } type highestCombination struct { - bids []*Bid - bidIDs []string - durations []int - price float64 - categoryScore map[string]int - domainScore map[string]int - filteredBids map[string]*filteredBid - timeTaken time.Duration + bids []*Bid + bidIDs []string + durations []int + price float64 + categoryScore map[string]int + domainScore map[string]int + filteredBids map[string]*filteredBid + timeTakenCompExcl time.Duration // time taken by comp excl + timeTakenCombGen time.Duration // time taken by combination generator } //AdPodGenerator AdPodGenerator @@ -38,16 +40,18 @@ type AdPodGenerator struct { buckets BidsBuckets comb ICombination adpod *openrtb_ext.VideoAdPod + met pbsmetrics.MetricsEngine } //NewAdPodGenerator will generate adpod based on configuration -func NewAdPodGenerator(request *openrtb.BidRequest, impIndex int, buckets BidsBuckets, comb ICombination, adpod *openrtb_ext.VideoAdPod) *AdPodGenerator { +func NewAdPodGenerator(request *openrtb.BidRequest, impIndex int, buckets BidsBuckets, comb ICombination, adpod *openrtb_ext.VideoAdPod, met pbsmetrics.MetricsEngine) *AdPodGenerator { return &AdPodGenerator{ request: request, impIndex: impIndex, buckets: buckets, comb: comb, adpod: adpod, + met: met, } } @@ -74,7 +78,8 @@ func (o *AdPodGenerator) cleanup(wg *sync.WaitGroup, responseCh chan *highestCom } func (o *AdPodGenerator) getAdPodBids(timeout time.Duration) []*highestCombination { - defer TimeTrack(time.Now(), fmt.Sprintf("Tid:%v ImpId:%v getAdPodBids", o.request.ID, o.request.Imp[o.impIndex].ID)) + start := time.Now() + defer TimeTrack(start, fmt.Sprintf("Tid:%v ImpId:%v getAdPodBids", o.request.ID, o.request.Imp[o.impIndex].ID)) maxRoutines := 3 isTimedOutORReceivedAllResponses := false @@ -84,20 +89,24 @@ func (o *AdPodGenerator) getAdPodBids(timeout time.Duration) []*highestCombinati lock := sync.Mutex{} ticker := time.NewTicker(timeout) + combinationCount := 0 for i := 0; i < maxRoutines; i++ { wg.Add(1) go func() { for !isTimedOutORReceivedAllResponses { + combGenStartTime := time.Now() lock.Lock() durations := o.comb.Get() lock.Unlock() + combGenElapsedTime := time.Since(combGenStartTime) if len(durations) == 0 { break } hbc := o.getUniqueBids(durations) + hbc.timeTakenCombGen = combGenElapsedTime responseCh <- hbc - Logf("Tid:%v GetUniqueBids Durations:%v Price:%v Time:%v Bids:%v", o.request.ID, hbc.durations[:], hbc.price, hbc.timeTaken, hbc.bidIDs[:]) + Logf("Tid:%v GetUniqueBids Durations:%v Price:%v Time:%v Bids:%v", o.request.ID, hbc.durations[:], hbc.price, hbc.timeTakenCompExcl, hbc.bidIDs[:]) } wg.Done() }() @@ -107,14 +116,20 @@ func (o *AdPodGenerator) getAdPodBids(timeout time.Duration) []*highestCombinati // when all go routines are executed go o.cleanup(wg, responseCh) + totalTimeByCombGen := int64(0) + totalTimeByCompExcl := int64(0) for !isTimedOutORReceivedAllResponses { select { case hbc, ok := <-responseCh: + if false == ok { isTimedOutORReceivedAllResponses = true break } if nil != hbc { + combinationCount++ + totalTimeByCombGen += int64(hbc.timeTakenCombGen) + totalTimeByCompExcl += int64(hbc.timeTakenCompExcl) results = append(results, hbc) } case <-ticker.C: @@ -124,6 +139,24 @@ func (o *AdPodGenerator) getAdPodBids(timeout time.Duration) []*highestCombinati } defer ticker.Stop() + + labels := pbsmetrics.PodLabels{ + AlgorithmName: string(CombinationGeneratorV1), + NoOfCombinations: new(int), + } + *labels.NoOfCombinations = combinationCount + o.met.RecordPodCombGenTime(labels, time.Duration(totalTimeByCombGen)) + + compExclLabels := pbsmetrics.PodLabels{ + AlgorithmName: string(CompetitiveExclusionV1), + NoOfResponseBids: new(int), + } + *compExclLabels.NoOfResponseBids = 0 + for _, ads := range o.buckets { + *compExclLabels.NoOfResponseBids += len(ads) + } + o.met.RecordPodCompititveExclusionTime(compExclLabels, time.Duration(totalTimeByCompExcl)) + return results[:] } @@ -193,7 +226,7 @@ func (o *AdPodGenerator) getUniqueBids(durationSequence []int) *highestCombinati } hbc := findUniqueCombinations(data[:], combinations[:], *o.adpod.IABCategoryExclusionPercent, *o.adpod.AdvertiserExclusionPercent) hbc.durations = durationSequence[:] - hbc.timeTaken = time.Since(startTime) + hbc.timeTakenCompExcl = time.Since(startTime) return hbc } diff --git a/endpoints/openrtb2/ctv/constant.go b/endpoints/openrtb2/ctv/constant.go index fd7beebc6fc..e3b7af8ad3e 100644 --- a/endpoints/openrtb2/ctv/constant.go +++ b/endpoints/openrtb2/ctv/constant.go @@ -39,3 +39,13 @@ const ( CTVRCCategoryExclusion FilterReasonCode = 2 CTVRCDomainExclusion FilterReasonCode = 3 ) + +// MonitorKey provides the unique key for moniroting the algorithms +type MonitorKey string + +const ( + // CombinationGeneratorV1 ... + CombinationGeneratorV1 MonitorKey = "comp_exclusion_v1" + // CompetitiveExclusionV1 ... + CompetitiveExclusionV1 MonitorKey = "comp_exclusion_v1" +) diff --git a/endpoints/openrtb2/ctv/impressions/impressions.go b/endpoints/openrtb2/ctv/impressions/impressions.go index 1131e05f927..9338e6ece94 100644 --- a/endpoints/openrtb2/ctv/impressions/impressions.go +++ b/endpoints/openrtb2/ctv/impressions/impressions.go @@ -29,6 +29,12 @@ const ( MinMaxAlgorithm ) +// MonitorKey provides the unique key for moniroting the impressions algorithm +var MonitorKey = map[Algorithm]string{ + MaximizeForDuration: `a1_max`, + MinMaxAlgorithm: `a2_min_max`, +} + // Value use to compute Ad Slot Durations and Pod Durations for internal computation // Right now this value is set to 5, based on passed data observations // Observed that typically video impression contains contains minimum and maximum duration in multiples of 5 diff --git a/endpoints/openrtb2/ctv_auction.go b/endpoints/openrtb2/ctv_auction.go index df8835af10d..4754ad06c40 100644 --- a/endpoints/openrtb2/ctv_auction.go +++ b/endpoints/openrtb2/ctv_auction.go @@ -407,7 +407,7 @@ func (deps *ctvEndpointDeps) getAllAdPodImpsConfigs() { if nil == imp.Video || nil == deps.impData[index].VideoExt || nil == deps.impData[index].VideoExt.AdPod { continue } - deps.impData[index].Config = getAdPodImpsConfigs(&imp, deps.impData[index].VideoExt.AdPod) + deps.impData[index].Config = deps.getAdPodImpsConfigs(&imp, deps.impData[index].VideoExt.AdPod) if 0 == len(deps.impData[index].Config) { errorCode := new(int) *errorCode = 101 @@ -417,9 +417,17 @@ func (deps *ctvEndpointDeps) getAllAdPodImpsConfigs() { } //getAdPodImpsConfigs will return number of impressions configurations within adpod -func getAdPodImpsConfigs(imp *openrtb.Imp, adpod *openrtb_ext.VideoAdPod) []*ctv.ImpAdPodConfig { - impGen := impressions.NewImpressions(imp.Video.MinDuration, imp.Video.MaxDuration, adpod, impressions.MinMaxAlgorithm) +func (deps *ctvEndpointDeps) getAdPodImpsConfigs(imp *openrtb.Imp, adpod *openrtb_ext.VideoAdPod) []*ctv.ImpAdPodConfig { + selectedAlgorithm := impressions.MinMaxAlgorithm + labels := pbsmetrics.PodLabels{AlgorithmName: impressions.MonitorKey[selectedAlgorithm], NoOfImpressions: new(int)} + + // monitor + start := time.Now() + impGen := impressions.NewImpressions(imp.Video.MinDuration, imp.Video.MaxDuration, adpod, selectedAlgorithm) impRanges := impGen.Get() + *labels.NoOfImpressions = len(impRanges) + deps.metricsEngine.RecordPodImpGenTime(labels, start) + config := make([]*ctv.ImpAdPodConfig, len(impRanges)) for i, value := range impRanges { config[i] = &ctv.ImpAdPodConfig{ @@ -610,7 +618,7 @@ func (deps *ctvEndpointDeps) doAdPodExclusions() ctv.AdPodBids { deps.impData[index].VideoExt.AdPod) //adpod generator - adpodGenerator := ctv.NewAdPodGenerator(deps.request, index, buckets, comb, deps.impData[index].VideoExt.AdPod) + adpodGenerator := ctv.NewAdPodGenerator(deps.request, index, buckets, comb, deps.impData[index].VideoExt.AdPod, deps.metricsEngine) adpodBids := adpodGenerator.GetAdPodBids() if adpodBids != nil { diff --git a/pbsmetrics/config/metrics.go b/pbsmetrics/config/metrics.go index ce6c0f5a707..edc0d1c1192 100644 --- a/pbsmetrics/config/metrics.go +++ b/pbsmetrics/config/metrics.go @@ -195,6 +195,27 @@ func (me *MultiMetricsEngine) RecordTimeoutNotice(success bool) { } } +// RecordPodImpGenTime across all engines +func (me *MultiMetricsEngine) RecordPodImpGenTime(labels pbsmetrics.PodLabels, startTime time.Time) { + for _, thisME := range *me { + thisME.RecordPodImpGenTime(labels, startTime) + } +} + +// RecordPodCombGenTime as a noop +func (me *MultiMetricsEngine) RecordPodCombGenTime(labels pbsmetrics.PodLabels, elapsedTime time.Duration) { + for _, thisME := range *me { + thisME.RecordPodCombGenTime(labels, elapsedTime) + } +} + +// RecordPodCompititveExclusionTime as a noop +func (me *MultiMetricsEngine) RecordPodCompititveExclusionTime(labels pbsmetrics.PodLabels, elapsedTime time.Duration) { + for _, thisME := range *me { + thisME.RecordPodCompititveExclusionTime(labels, elapsedTime) + } +} + // DummyMetricsEngine is a Noop metrics engine in case no metrics are configured. (may also be useful for tests) type DummyMetricsEngine struct{} @@ -273,3 +294,15 @@ func (me *DummyMetricsEngine) RecordRequestQueueTime(success bool, requestType p // RecordTimeoutNotice as a noop func (me *DummyMetricsEngine) RecordTimeoutNotice(success bool) { } + +// RecordPodImpGenTime as a noop +func (me *DummyMetricsEngine) RecordPodImpGenTime(labels pbsmetrics.PodLabels, start time.Time) { +} + +// RecordPodCombGenTime as a noop +func (me *DummyMetricsEngine) RecordPodCombGenTime(labels pbsmetrics.PodLabels, elapsedTime time.Duration) { +} + +// RecordPodCompititveExclusionTime as a noop +func (me *DummyMetricsEngine) RecordPodCompititveExclusionTime(labels pbsmetrics.PodLabels, elapsedTime time.Duration) { +} diff --git a/pbsmetrics/go_metrics.go b/pbsmetrics/go_metrics.go index cf634cc5ae1..01305fb46f3 100644 --- a/pbsmetrics/go_metrics.go +++ b/pbsmetrics/go_metrics.go @@ -562,6 +562,18 @@ func (me *Metrics) RecordTimeoutNotice(success bool) { return } +// RecordPodImpGenTime as a noop +func (me *Metrics) RecordPodImpGenTime(labels PodLabels, startTime time.Time) { +} + +// RecordPodCombGenTime as a noop +func (me *Metrics) RecordPodCombGenTime(labels PodLabels, elapsedTime time.Duration) { +} + +// RecordPodCompititveExclusionTime as a noop +func (me *Metrics) RecordPodCompititveExclusionTime(labels PodLabels, elapsedTime time.Duration) { +} + func doMark(bidder openrtb_ext.BidderName, meters map[openrtb_ext.BidderName]metrics.Meter) { met, ok := meters[bidder] if ok { diff --git a/pbsmetrics/metrics.go b/pbsmetrics/metrics.go index 770f5750335..430849deca0 100644 --- a/pbsmetrics/metrics.go +++ b/pbsmetrics/metrics.go @@ -36,6 +36,15 @@ type ImpLabels struct { NativeImps bool } +// PodLabels defines metric labels describing algorithm type +// and other labels as per scenario +type PodLabels struct { + AlgorithmName string // AlgorithmName which is used for generating impressions + NoOfImpressions *int // NoOfImpressions represents number of impressions generated + NoOfCombinations *int // NoOfCombinations represents number of combinations generated + NoOfResponseBids *int // NoOfResponseBids represents number of bids responded (including bids with similar duration) +} + // RequestLabels defines metric labels describing the result of a network request. type RequestLabels struct { RequestStatus RequestStatus @@ -276,4 +285,26 @@ type MetricsEngine interface { RecordPrebidCacheRequestTime(success bool, length time.Duration) RecordRequestQueueTime(success bool, requestType RequestType, length time.Duration) RecordTimeoutNotice(sucess bool) + // ad pod specific metrics + + // RecordPodImpGenTime records number of impressions generated and time taken + // by underneath algorithm to generate them + // labels accept name of the algorithm and no of impressions generated + // startTime indicates the time at which algorithm started + // This function will take care of computing the elpased time + RecordPodImpGenTime(labels PodLabels, startTime time.Time) + + // RecordPodCombGenTime records number of combinations generated and time taken + // by underneath algorithm to generate them + // labels accept name of the algorithm and no of combinations generated + // elapsedTime indicates the time taken by combination generator to compute all requested combinations + // This function will take care of computing the elpased time + RecordPodCombGenTime(labels PodLabels, elapsedTime time.Duration) + + // RecordPodCompititveExclusionTime records time take by competitive exclusion + // to compute the final Ad pod Response. + // labels accept name of the algorithm and no of combinations evaluated, total bids + // elapsedTime indicates the time taken by competitive exclusion to form final ad pod response using combinations and exclusion algorithm + // This function will take care of computing the elpased time + RecordPodCompititveExclusionTime(labels PodLabels, elapsedTime time.Duration) } diff --git a/pbsmetrics/prometheus/prometheus.go b/pbsmetrics/prometheus/prometheus.go index 9c06d6032f4..cde0cab0283 100644 --- a/pbsmetrics/prometheus/prometheus.go +++ b/pbsmetrics/prometheus/prometheus.go @@ -42,6 +42,20 @@ type Metrics struct { // Account Metrics accountRequests *prometheus.CounterVec + + // Ad Pod Metrics + + // podImpGenTimer indicates time taken by impression generator + // algorithm to generate impressions for given ad pod request + podImpGenTimer *prometheus.HistogramVec + + // podImpGenTimer indicates time taken by combination generator + // algorithm to generate combination based on bid response and ad pod request + podCombGenTimer *prometheus.HistogramVec + + // podCompExclTimer indicates time taken by compititve exclusion + // algorithm to generate final pod response based on bid response and ad pod request + podCompExclTimer *prometheus.HistogramVec } const ( @@ -85,6 +99,14 @@ const ( requestFailed = "failed" ) +// pod specific constants +const ( + podAlgorithm = "algorithm" + podNoOfImpressions = "no_of_impressions" + podTotalCombinations = "total_combinations" + podNoOfResponseBids = "no_of_response_bids" +) + // NewMetrics initializes a new Prometheus metrics instance with preloaded label values. func NewMetrics(cfg config.PrometheusMetrics) *Metrics { requestTimeBuckets := []float64{0.05, 0.1, 0.15, 0.20, 0.25, 0.3, 0.4, 0.5, 0.75, 1} @@ -211,6 +233,28 @@ func NewMetrics(cfg config.PrometheusMetrics) *Metrics { []string{requestTypeLabel, requestStatusLabel}, queuedRequestTimeBuckets) + // adpod specific metrics + metrics.podImpGenTimer = newHistogram(cfg, metrics.Registry, + "impr_gen", + "Time taken by Ad Pod Impression Generator in seconds", []string{podAlgorithm, podNoOfImpressions}, + // 200 µS, 250 µS, 275 µS, 300 µS + //[]float64{0.000200000, 0.000250000, 0.000275000, 0.000300000}) + // 100 µS, 200 µS, 300 µS, 400 µS, 500 µS, 600 µS, + []float64{0.000100000, 0.000200000, 0.000300000, 0.000400000, 0.000500000, 0.000600000}) + + metrics.podCombGenTimer = newHistogram(cfg, metrics.Registry, + "comb_gen", + "Time taken by Ad Pod Combination Generator in seconds", []string{podAlgorithm, podTotalCombinations}, + // 200 µS, 250 µS, 275 µS, 300 µS + //[]float64{0.000200000, 0.000250000, 0.000275000, 0.000300000}) + []float64{0.000100000, 0.000200000, 0.000300000, 0.000400000, 0.000500000, 0.000600000}) + + metrics.podCompExclTimer = newHistogram(cfg, metrics.Registry, + "comp_excl", + "Time taken by Ad Pod Compititve Exclusion in seconds", []string{podAlgorithm, podNoOfResponseBids}, + // 200 µS, 250 µS, 275 µS, 300 µS + //[]float64{0.000200000, 0.000250000, 0.000275000, 0.000300000}) + []float64{0.000100000, 0.000200000, 0.000300000, 0.000400000, 0.000500000, 0.000600000}) preloadLabelValues(&metrics) return &metrics @@ -421,3 +465,44 @@ func (m *Metrics) RecordTimeoutNotice(success bool) { }).Inc() } } + +// pod specific metrics + +// recordAlgoTime is common method which handles algorithm time performance +func recordAlgoTime(timer *prometheus.HistogramVec, labels pbsmetrics.PodLabels, elapsedTime time.Duration) { + + pmLabels := prometheus.Labels{ + podAlgorithm: labels.AlgorithmName, + } + + if labels.NoOfImpressions != nil { + pmLabels[podNoOfImpressions] = strconv.Itoa(*labels.NoOfImpressions) + } + if labels.NoOfCombinations != nil { + pmLabels[podTotalCombinations] = strconv.Itoa(*labels.NoOfCombinations) + } + if labels.NoOfResponseBids != nil { + pmLabels[podNoOfResponseBids] = strconv.Itoa(*labels.NoOfResponseBids) + } + + timer.With(pmLabels).Observe(elapsedTime.Seconds()) +} + +// RecordPodImpGenTime records number of impressions generated and time taken +// by underneath algorithm to generate them +func (m *Metrics) RecordPodImpGenTime(labels pbsmetrics.PodLabels, start time.Time) { + elapsedTime := time.Since(start) + recordAlgoTime(m.podImpGenTimer, labels, elapsedTime) +} + +// RecordPodCombGenTime records number of combinations generated and time taken +// by underneath algorithm to generate them +func (m *Metrics) RecordPodCombGenTime(labels pbsmetrics.PodLabels, elapsedTime time.Duration) { + recordAlgoTime(m.podCombGenTimer, labels, elapsedTime) +} + +// RecordPodCompititveExclusionTime records number of combinations comsumed for forming +// final ad pod response and time taken by underneath algorithm to generate them +func (m *Metrics) RecordPodCompititveExclusionTime(labels pbsmetrics.PodLabels, elapsedTime time.Duration) { + recordAlgoTime(m.podCompExclTimer, labels, elapsedTime) +} diff --git a/pbsmetrics/prometheus/prometheus_test.go b/pbsmetrics/prometheus/prometheus_test.go index 21f182e2094..ba187603b60 100644 --- a/pbsmetrics/prometheus/prometheus_test.go +++ b/pbsmetrics/prometheus/prometheus_test.go @@ -1,6 +1,7 @@ package prometheusmetrics import ( + "strconv" "testing" "time" @@ -944,6 +945,46 @@ func TestTimeoutNotifications(t *testing.T) { } +func TestRecordPodImpGenTime(t *testing.T) { + impressions := 4 + testAlgorithmMetrics(t, impressions, func(m *Metrics) dto.Histogram { + m.RecordPodImpGenTime(pbsmetrics.PodLabels{AlgorithmName: "sample_imp_algo", NoOfImpressions: &impressions}, time.Now()) + return getHistogramFromHistogramVec(m.podImpGenTimer, podNoOfImpressions, strconv.Itoa(impressions)) + }) +} + +func TestRecordPodCombGenTime(t *testing.T) { + combinations := 5 + testAlgorithmMetrics(t, combinations, func(m *Metrics) dto.Histogram { + m.RecordPodCombGenTime(pbsmetrics.PodLabels{AlgorithmName: "sample_comb_algo", NoOfCombinations: &combinations}, time.Now()) + return getHistogramFromHistogramVec(m.podCombGenTimer, podTotalCombinations, strconv.Itoa(combinations)) + }) +} + +func TestRecordPodCompetitiveExclusionTime(t *testing.T) { + totalBids := 8 + testAlgorithmMetrics(t, totalBids, func(m *Metrics) dto.Histogram { + m.RecordPodCompititveExclusionTime(pbsmetrics.PodLabels{AlgorithmName: "sample_comt_excl_algo", NoOfResponseBids: &totalBids}, time.Now()) + return getHistogramFromHistogramVec(m.podCompExclTimer, podNoOfResponseBids, strconv.Itoa(totalBids)) + }) +} + +func testAlgorithmMetrics(t *testing.T, input int, f func(m *Metrics) dto.Histogram) { + // test input + adRequests := 2 + m := createMetricsForTesting() + var result dto.Histogram + for req := 1; req <= adRequests; req++ { + result = f(m) + } + + // assert observations + assert.Equal(t, uint64(adRequests), result.GetSampleCount(), "ad requests : count") + for _, bucket := range result.Bucket { + assert.Equal(t, uint64(adRequests), bucket.GetCumulativeCount(), "total observations") + } +} + func assertCounterValue(t *testing.T, description, name string, counter prometheus.Counter, expected float64) { m := dto.Metric{} counter.Write(&m) diff --git a/router/router.go b/router/router.go index 6da9800ba43..843fda9ab25 100644 --- a/router/router.go +++ b/router/router.go @@ -6,6 +6,7 @@ import ( "database/sql" "encoding/json" "fmt" + "github.com/prometheus/client_golang/prometheus" "io/ioutil" "net/http" "path/filepath" @@ -422,3 +423,12 @@ func readDefaultRequest(defReqConfig config.DefReqConfig) (map[string]string, [] } return aliases, []byte{} } + +func GetPrometheusRegistry() *prometheus.Registry { + mEngine, ok := g_metrics.(*metricsConf.DetailedMetricsEngine) + if !ok || mEngine == nil || mEngine.PrometheusMetrics == nil { + return nil + } + + return mEngine.PrometheusMetrics.Registry +}