UOE-5440: Changes for capturing Pod algorithm execution time using pbmetrics

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
 }

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"
+)

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

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 {

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

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 {

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