Debug Metrics Implementation #2246

AlexBVolcy · 2022-05-13T20:18:58Z

This PR implements the feature/issue #1474

The goal is to add new metrics to PBS related to debug

The first new debug metric, is one that counts the number of requests we receive that has debug enabled.

The second new debug metric, is one that counts the number of requests from an account that has debug enabled.

This second metric is controlled by a config flag "metrics.disabled_metrics.account_debug" because of concerns of high cardinality

These metrics are implemented for both prometheus and influx, by creating/implementing a new record function RecordDebugRequest() within both metrics' frameworks.

This function is then called within HoldAuction() after we receive debug information from the getDebugInfo() call.

For influx, I added two new meters to represent the new metrics in the Metrics and AccountMetrics struct, DebugRequestMeter and accountMetrics.DebugRequestMeter

For prometheus, I added two new metrics to the prometheus specific Metrics struct debugRequests and accountDebugRequests

New tests were included to test these updated metrics

Other metrics engines like nil metrics, multi metrics, and metrics mock, only need to be updated with a simple handling of how they implement/call RecordDebugRequest()

SyntaxNode · 2022-05-16T17:41:56Z

endpoints/openrtb2/auction_test.go

@@ -3702,7 +3702,7 @@ type warningsCheckExchange struct {
 	auctionRequest exchange.AuctionRequest
 }

-func (e *warningsCheckExchange) HoldAuction(ctx context.Context, r exchange.AuctionRequest, debugLog *exchange.DebugLog) (*openrtb2.BidResponse, error) {
+func (e *warningsCheckExchange) HoldAuction(ctx context.Context, r exchange.AuctionRequest, debugLog *exchange.DebugLog, labels *metrics.Labels) (*openrtb2.BidResponse, error) {


It is not necessary to add a new labels argument. The labels are already present in the r exchange.AuctionRequest argument.

Refactored and removed in latest commit

SyntaxNode · 2022-05-16T17:46:10Z

metrics/metrics.go

+	CookieFlag       CookieFlag
+	RequestStatus    RequestStatus
+	DebugFlag        bool
+	AccountDebugFlag bool


I think you'll be fine with a single debug flag, perhaps naming DebugEnabed or DebugRequested or perhaps even Debug. We don't care how debug is enabled, just that it is is enabled. With the implementation of the debug permissions, I can easily see how you arrived at this though. :)

Ah this makes sense! I'll update accordingly.

SyntaxNode · 2022-05-16T17:54:06Z

metrics/prometheus/prometheus.go

+	metrics.requestsDebug = newCounter(cfg, reg,
+		"requests_debug",
+		"Count of total requests to Prebid Server that have debug enabled labled by type, status.",
+		[]string{requestTypeLabel, requestStatusLabel})


I do not believe we need to have any labels on this metric. I personally don't see any value in the status label and only minimal value in the types label. I won't put up a fight it you want to keep the type label, but I'll need convincing on why this is important for the status label.

Yeah I struggled to think of reasons to have the labels, but I initially just matched the format of metrics.requests. But I feel comfortable with removing both

Discussed during stand up, both labels have been removed

SyntaxNode

Looks good. Let's try to improve the flow of the debug flag, or put it off for a future update if we think of a good idea and decide it's too much work to include here.

SyntaxNode · 2022-05-19T04:20:27Z

endpoints/openrtb2/amp_auction.go

@@ -219,6 +220,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		ao.Errors = append(ao.Errors, err)
 		return
 	}
+	labels.DebugEnabled = debugLog.DebugFlag


What is the purpose of this line? ... since it occurs after the HoldAuction call. Wouldn't the metrics for an incoming request have been recorded before hitting this line? Same applies to openrtb/auction.go

If I understand this correctly, metrics will be written at the end of endpoint execution. It's defined in defer section, L122:

defer func() { deps.metricsEngine.RecordRequest(labels) deps.metricsEngine.RecordRequestTime(labels, time.Since(start)) deps.analytics.LogAmpObject(&ao) }()

Auction, video and amp endpoints have this approach.

Yeah exactly like Veronika said above! And when I sent test postman requests, it acted like this as well!

Ah. Got it. This code is a bit too clever IMHO, but I agree it's beyond the scope of this PR to fix. Can you add a comment before these lines to make it clear what's going on to my future self?

SyntaxNode · 2022-05-19T04:27:27Z

endpoints/openrtb2/amp_auction.go

@@ -219,6 +220,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		ao.Errors = append(ao.Errors, err)
 		return
 	}
+	labels.DebugEnabled = debugLog.DebugFlag


I consider it a "code smell" that debugLog is instantiated here just to return the DebugFlag to the outer scope. It would be preferable IMHO to either calculate the debug flag prior to calling HoldAuction or include it as a return argument somehow. I know you didn't create this situation, but I believe it's worth an investigation to try and make this flow a bit nicer now.

Would it be better if labels.DebugEnabled will be passed in auctionRequest downstrem to getDebugInfo and modified there?
I cannot think about better solution...

SyntaxNode · 2022-05-19T04:27:27Z

endpoints/openrtb2/amp_auction.go

@@ -219,6 +220,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		ao.Errors = append(ao.Errors, err)
 		return
 	}
+	labels.DebugEnabled = debugLog.DebugFlag


I consider it a "code smell" that debugLog is instantiated here just to return the DebugFlag to the outer scope. It would be preferable IMHO to either calculate the debug flag prior to calling HoldAuction or include it as a return argument somehow. I know you didn't create this situation, but I believe it's worth an investigation to try and make this flow a bit nicer now.

I agree with Scott here. This definitely seems odd to instantiate the debugLog struct here just to return the DebugFlag to the outer scope. How about making debugLog a part of the AuctionRequest struct? That way you can read and modify it in HoldAuction as needed and you can again access it outside of HoldAuction for setting the metrics label and such

Yeah that code smell call out makes total sense! I wrote up some code just now to put debugLog in the AuctionRequest struct, and that solution worked! I need to run some more tests, but I think that would be a valid solution to this.

That way you can read and modify it in HoldAuction as needed and you can again access it outside of HoldAuction for setting the metrics label and such

A step in the right direction, but modifying it as a way to pass information upstream is still an undesirable design. We might have to tackle that later on.

VeronikaSolovei9

Changes look good to me. Please resolve Scott's comments.

SyntaxNode · 2022-05-19T04:20:27Z

endpoints/openrtb2/amp_auction.go

@@ -219,6 +220,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		ao.Errors = append(ao.Errors, err)
 		return
 	}
+	labels.DebugEnabled = debugLog.DebugFlag


What is the purpose of this line? ... since it occurs after the HoldAuction call. Wouldn't the metrics for an incoming request have been recorded before hitting this line?

SyntaxNode · 2022-05-19T16:30:08Z

endpoints/openrtb2/amp_auction.go

@@ -219,6 +220,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		ao.Errors = append(ao.Errors, err)
 		return
 	}
+	labels.DebugEnabled = debugLog.DebugFlag


Ah. Got it. This code is a bit too clever IMHO, but I agree it's beyond the scope of this PR to fix. Can you add a comment before these lines to make it clear what's going on to my future self?

SyntaxNode · 2022-05-19T16:32:21Z

endpoints/openrtb2/amp_auction.go

@@ -219,6 +220,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		ao.Errors = append(ao.Errors, err)
 		return
 	}
+	labels.DebugEnabled = debugLog.DebugFlag


That way you can read and modify it in HoldAuction as needed and you can again access it outside of HoldAuction for setting the metrics label and such

A step in the right direction, but modifying it as a way to pass information upstream is still an undesirable design. We might have to tackle that later on.

mansinahar · 2022-05-19T16:43:53Z

A step in the right direction, but modifying it as a way to pass information upstream is still an undesirable design. We might have to tackle that later on.

There's one other thing I think we should do here that is perhaps create a new function for recording debug enabled requests rather than using the current record request method. Then you can just call that record method in HoldAuction itself rather than calling it in each of the endpoint handlers. The debug enabled metrics anyway don't care about the source of the request. And this way we wouldn't be modifying it just to be able to pass the information back upstream. Also, debug info is per request so I think it makes sense to add it as part of the AuctionRequest struct.

AlexBVolcy · 2022-05-19T21:25:02Z

The latest commit I pushed is the one where I implemented a function RecordDebugRequest to handle the recording of the new metrics. This function gets called now in HoldAuction so that way we wouldn't have to be concerned with passing the debug information found in HoldAuction upstream, and instead can just pass the debug enabled info directly to RecordDebugRequest.

And as a heads up, I wrongfully titled the name of this commit to be Debug Log Refactoring. The DebugLog object is still a separate parameter in HoldAuction, and hasn't been combined with the AuctionRequest object yet. I discussed this with Mansi, and this will be handled in a future PR.

VeronikaSolovei9

LGTM!

mansinahar · 2022-05-23T16:32:23Z

metrics/go_metrics.go

+	}
+
+	am := me.getAccountMetrics(pubID)
+	if !me.MetricsDisabled.AccountDebug && debugEnabled {


You can simplify this by moving this block of code into the if condition on L438 as well. This will help get rid of the debugEnabled check here. Also, shouldn't we check that the publisher ID isn't unknown here as well like you're doing for Prometheus's record debug function?

Yes I'll refactor this and add the unknown check as well!

endpoints/openrtb2/amp_auction.go

metrics/go_metrics.go

mansinahar · 2022-05-24T18:43:55Z

metrics/prometheus/prometheus.go

@@ -182,6 +184,10 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet
 		"Count of total requests to Prebid Server labeled by type and status.",
 		[]string{requestTypeLabel, requestStatusLabel})

+	metrics.requestsDebug = newCounterWithoutLabels(cfg, reg,
+		"requests_debug",
+		"Count of total requests to Prebid Server that have debug enabled labled by type, status.")


These are not going to be labeled by type and status so please update the description accordingly

mansinahar · 2022-05-24T18:47:06Z

metrics/prometheus/prometheus.go

@@ -370,6 +376,11 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet
 		"Count of total requests to Prebid Server labeled by account.",
 		[]string{accountLabel})

+	metrics.accountDebugRequests = newCounter(cfg, reg,
+		"account_requests_debug",
+		"Count of total requests to Prebid Server where the account has debug enabled labeled by account.",


Can you please update the description here to be something along the lines of:

Count of total requests to Prebid Server that have debug enabled labled by account

mansinahar · 2022-05-24T18:59:09Z

config/config.go

@@ -487,6 +487,9 @@ type DisabledMetrics struct {
 	// True if we want to stop collecting account-to-adapter metrics
 	AccountAdapterDetails bool `mapstructure:"account_adapter_details"`

+	// True if we want to stop collecting account debug request metrics
+	AccountDebug bool `mapstructure:"account_debug"`
+


Please add tests for this new config option in config_test.go

metrics/go_metrics_test.go

metrics/prometheus/prometheus_test.go

mansinahar

I think this is looking pretty close. Thanks for addressing all the feedback. I have one major comment about the different types being used for account vs non-account metric in Prometheus. The other two are quite minor

metrics/prometheus/prometheus.go

mansinahar · 2022-05-25T14:20:35Z

metrics/prometheus/prometheus_test.go

+		expectedDebugCount               float64
+	}{
+		{
+			description:                      "Boolean flags should result in both metrics being updated",


Please specify what the boolean flags are set to in the description. For readability purposes and for when tests fail these descriptions help us easily understand what was passed in and what was expected. I like the descriptions you have for the last two test cases. Could you please update these to have the same format as well?

I noticed the same thing in the go_metrics_test.go file as well

mansinahar · 2022-05-25T14:23:31Z

config/config_test.go

@@ -611,6 +612,7 @@ func TestFullConfig(t *testing.T) {
 	cmpBools(t, "account_required", cfg.AccountRequired, true)
 	cmpBools(t, "auto_gen_source_tid", cfg.AutoGenSourceTID, false)
 	cmpBools(t, "account_adapter_details", cfg.Metrics.Disabled.AccountAdapterDetails, true)
+	cmpBools(t, "account_debug", cfg.Metrics.Disabled.AccountDebug, true)


For the TestFullConfig I would suggest setting the value for account_debug to be false (different from the default value) in the above fullConfig value and assert it here to be false as well. This just helps us test through both the flow with default values and non-default values.

VeronikaSolovei9

LGTM!

Initial Debug metrics

37f6166

mansinahar requested review from VeronikaSolovei9 and mansinahar May 16, 2022 17:29

mansinahar assigned VeronikaSolovei9 and mansinahar May 16, 2022

SyntaxNode reviewed May 16, 2022

View reviewed changes

AlexBVolcy added 4 commits May 17, 2022 10:54

Merge branch 'master' into debug_metrics

e883324

Fix tests

116e4db

Minor update to debug tracking

f390055

Removing unused line of code

64bab43

SyntaxNode reviewed May 19, 2022

View reviewed changes

VeronikaSolovei9 reviewed May 19, 2022

View reviewed changes

SyntaxNode reviewed May 19, 2022

View reviewed changes

Debug log refactoring

2840c89

AlexBVolcy added 2 commits May 19, 2022 14:33

Remove label

7d1fe36

Removing unsued code

8ff0cad

VeronikaSolovei9 previously approved these changes May 20, 2022

View reviewed changes

mansinahar reviewed May 23, 2022

View reviewed changes

Minor refactoring, add pubId to video endpoint

388ba17

AlexBVolcy dismissed VeronikaSolovei9’s stale review via 388ba17 May 23, 2022 23:31

VeronikaSolovei9 previously approved these changes May 24, 2022

View reviewed changes

mansinahar reviewed May 24, 2022

View reviewed changes

Address minor feedback changes

a6b0a71

AlexBVolcy dismissed VeronikaSolovei9’s stale review via a6b0a71 May 24, 2022 21:16

mansinahar reviewed May 25, 2022

View reviewed changes

Config test update, description of tests update

5494664

VeronikaSolovei9 approved these changes May 25, 2022

View reviewed changes

mansinahar approved these changes May 25, 2022

View reviewed changes

mansinahar merged commit ce57f41 into prebid:master May 25, 2022

jorgeluisrocha pushed a commit to jwplayer/prebid-server that referenced this pull request Sep 28, 2022

Debug Metrics Implementation (prebid#2246)

288c6ee

shunj-nb pushed a commit to ParticleMedia/prebid-server that referenced this pull request Nov 8, 2022

Debug Metrics Implementation (prebid#2246)

a4934d0

SyntaxNode mentioned this pull request Dec 12, 2022

Debug Metrics #1474

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Debug Metrics Implementation #2246

Debug Metrics Implementation #2246

AlexBVolcy commented May 13, 2022 •

edited

Loading

SyntaxNode May 16, 2022

AlexBVolcy May 17, 2022

SyntaxNode May 16, 2022

AlexBVolcy May 16, 2022

SyntaxNode May 16, 2022

AlexBVolcy May 16, 2022

AlexBVolcy May 17, 2022

SyntaxNode left a comment

SyntaxNode May 19, 2022

VeronikaSolovei9 May 19, 2022

AlexBVolcy May 19, 2022

SyntaxNode May 19, 2022

SyntaxNode May 19, 2022

VeronikaSolovei9 May 19, 2022

SyntaxNode May 19, 2022

mansinahar May 19, 2022

AlexBVolcy May 19, 2022 •

edited

Loading

SyntaxNode May 19, 2022

VeronikaSolovei9 left a comment

SyntaxNode May 19, 2022

SyntaxNode May 19, 2022

SyntaxNode May 19, 2022

mansinahar commented May 19, 2022

AlexBVolcy commented May 19, 2022 •

edited

Loading

VeronikaSolovei9 left a comment

mansinahar May 23, 2022

AlexBVolcy May 23, 2022 •

edited

Loading

mansinahar May 24, 2022

mansinahar May 24, 2022

mansinahar May 24, 2022

mansinahar left a comment

mansinahar May 25, 2022

mansinahar May 25, 2022

VeronikaSolovei9 left a comment

Debug Metrics Implementation #2246

Debug Metrics Implementation #2246

Conversation

AlexBVolcy commented May 13, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SyntaxNode left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AlexBVolcy May 19, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

VeronikaSolovei9 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mansinahar commented May 19, 2022

AlexBVolcy commented May 19, 2022 • edited Loading

VeronikaSolovei9 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AlexBVolcy May 23, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mansinahar left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

VeronikaSolovei9 left a comment

Choose a reason for hiding this comment

AlexBVolcy commented May 13, 2022 •

edited

Loading

AlexBVolcy May 19, 2022 •

edited

Loading

AlexBVolcy commented May 19, 2022 •

edited

Loading

AlexBVolcy May 23, 2022 •

edited

Loading