Response Times in getAllBids() Objects do not match actual times, potentially timed out bid is declared winner.

[mahammer]

Type of issue

Question/Issue

Description

I've setup pbjs with 8 bidders on a heavy page to check out the concurrent connection issues and having bids stuck in the queue and I am running my own analytics, however the response times/timeouts seem to have issues. I don't know if I am missing something or somethings actually going wrong. For an easier overview, I reduced the bidders to 4. I use a setTimeout() to call sendAdserverRequest() with a timeout of 900ms.

Inside sendAdserverRequest() after

pbjs.setTargetingForGPTAsync();
googletag.pubads().refresh();

I output the result of pbjs.getBidResponses() (cropped)

bidder:"openx" | adId:"6984ba929fcbbd" | timeToRespond: 1170
bidder:"sekindo" | adId:"8d5831d61b46df" | timeToRespond: 1197
bidder:"pulsepoint" | adId:"4f396dad7f8911" | timeToRespond: 1479
bidder:"yieldbot" | adId:"11f61b3365b5e92" | timeToRespond: 1761

and pbjs.getAdserverTargeting(). hb_bidder:"sekindo" | hb_adid:"8d5831d61b46df"

Additional Info

Checking Headerbid Expert on the exact auction it tells me: OpenX: no info AppNexus (Sekindo alias): 315ms PulsePoint: 303ms Yieldbot: 363ms

Checking Chrome's network information: AppNexus(Sekindo alias): 665ms - (349ms Queueing) = 315ms PulsePoint: 304ms - (1ms Queueing) = 303ms Yieldbot: 363ms - (0ms Queueing) = 363ms

Expected results

If the timeout is set to 900 I expected pbjs.getBidResponses() to be empty as all of them have a TTR>900. I also expected to have no winner. After all according to the pbjs bid objects they all had a TTR>900.

Actual results

Sekindo is the winner and sent do DFP. According to math {TIMEOUT} - TTR, all of them timed out, although it seems they did not. This would suggest that the GC and HBE numbers are actually the correct response times and that nothing timed out at all.

Elaboration on Issue

Having contracts with 16 bidding partners requires us to collect timeouts and other information properly in order to optimize the setup. However, it's not possible for instance to record if a bid that came in after the timeout would have had a higher CPM, or if the one that times out would not win anyways if the response times in the bid objects are not representing the response time. And in this instance, it is not even possible to properly track a timeout: Timeout is set to 900ms Sekindo is sent as winner to DFP. Sekindo has a response time of 1197ms So all I can do is log that Sekindo timed out 1197-900=297ms although they won as their response seemingly only took 315ms

Questions

1) How am I able to properly check if a bid timed out? 2) Is there a way to get the actual response times? 3) Why are the numbers in the bid objects that much higher?

Platform details

PB 0.21.0, GC 57.0.2987.133

[mahammer]

More Info:

I also got a timestamp now on requestBids and subtracted the bid object's responseTimestamp. This metric matches the timeToRespond +/- 10ms. In this test with a timeout of 900ms a bidder with a TTR of 1090ms won.

[mahammer]

Issue isolated:

Sorry for the monolog but I think I found the culprit. As usual between keyboard and chair. But I am sure this'll help someone else hoping people read the issue tracker :D For what I can tell with some testing:

• the prebid bid object response times are the times from requestBid to pbjs actually could read the response. Those times should be correct.

The culprit is the timeout function:

var timeoutStart = (new Date).getTime();
setTimeout(function() {
    console.log((new Date).getTime() - timeoutStart);
    sendAdserverRequest();     
}, 900);

I could have thought of that first, but it's not actually 900ms until sendAdserverRequest() It varies, on the page I am testing on between 1200-1500ms.

So naturally, a recorded TTR of 1100ms is within the 900ms as they are actually e.g. 1250ms. I guess this is an inherent flaw with JS that this can't be exact. In conclusion, I have to calculate the applied timeout as opposed to the defined one, subtract it from the response times and everything positive is actually timed out.

[mahammer]

More information:

Calling the ad server request within a timeout function is actually a bad idea. I found out it's better to use the timeout: parameter in requestBids() which eliminates the initial delay and offset between calling the timeout function and calling requestBids(). This way at least the timeout starts with requestBids() and the auction begins synchronously so to speak.

The issue persists though that the real timeout, depending on how busy the JS queue is, is delayed. But that's easy to measure and calculate the actual timeouts of the individual bidders if there are any.

[mkendall07]

It's really a preference on the publisher side how to implement this and which timeout works for them. We cannot do anything about time slippage due to a busy JS queue - it's just how JS works.

[mkendall07]

You might also be interested in: https://github.com/prebid/Prebid.js/issues/1046 same type of issue.