Prebid.js: Prebid Timeout Issue

[cwbeck]

We have been looking at the latency of providers and even though we set a timeout of 1500ms (as described in the Prebid.js documentation), it would seem this is not being correctly observed - here is the aggregated view of 10 minutes worth of bid data from our live network.

Has anyone experienced this same issue?

pulsepoint
-- Latency Group: 200ms -> 300ms - Count: 85820
-- Latency Group: 300ms -> 400ms - Count: 77852
-- Latency Group: 400ms -> 500ms - Count: 58977
-- Latency Group: 100ms -> 200ms - Count: 47180
-- Latency Group: 500ms -> 600ms - Count: 44875
-- Latency Group: 600ms -> 700ms - Count: 35399
-- Latency Group: 700ms -> 800ms - Count: 28052
-- Latency Group: 800ms -> 900ms - Count: 22272
-- Latency Group: 900ms -> 1000ms - Count: 18396
-- Latency Group: 1000ms -> 1100ms - Count: 14981
-- Latency Group: 1100ms -> 1200ms - Count: 12823
-- Latency Group: 1200ms -> 1300ms - Count: 10994
-- Latency Group: 1300ms -> 1400ms - Count: 9117
-- Latency Group: 1400ms -> 1500ms - Count: 7719
-- Latency Group: 1500ms -> 1600ms - Count: 4754
-- Latency Group: 0ms -> 100ms - Count: 4515
-- Latency Group: 1600ms -> 1700ms - Count: 3402
-- Latency Group: 1700ms -> 1800ms - Count: 2705
-- Latency Group: 1800ms -> 1900ms - Count: 2111
-- Latency Group: 1900ms -> 2000ms - Count: 1707
-- Latency Group: 2000ms -> 2100ms - Count: 1328
-- Latency Group: 2100ms -> 2200ms - Count: 1120
-- Latency Group: 2200ms -> 2300ms - Count: 843
-- Latency Group: 2300ms -> 2400ms - Count: 716
-- Latency Group: 2400ms -> 2500ms - Count: 590
-- Latency Group: 2500ms -> 2600ms - Count: 529
-- Latency Group: 2600ms -> 2700ms - Count: 447
-- Latency Group: 2700ms -> 2800ms - Count: 371
-- Latency Group: 2800ms -> 2900ms - Count: 320
-- Latency Group: 2900ms -> 3000ms - Count: 295
-- Latency Group: 3000ms -> 3100ms - Count: 235
-- Latency Group: 3100ms -> 3200ms - Count: 214
-- Latency Group: 3200ms -> 3300ms - Count: 176
-- Latency Group: 3300ms -> 3400ms - Count: 146
-- Latency Group: 3400ms -> 3500ms - Count: 132
-- Latency Group: 3500ms -> 3600ms - Count: 127
-- Latency Group: 3700ms -> 3800ms - Count: 94
-- Latency Group: 3800ms -> 3900ms - Count: 87
-- Latency Group: 3600ms -> 3700ms - Count: 87
-- Latency Group: 3900ms -> 4000ms - Count: 85
-- Latency Group: 4000ms -> 4100ms - Count: 78
-- Latency Group: 4100ms -> 4200ms - Count: 52
-- Latency Group: 4300ms -> 4400ms - Count: 52
-- Latency Group: 4400ms -> 4500ms - Count: 47
-- Latency Group: 4200ms -> 4300ms - Count: 47
-- Latency Group: 4500ms -> 4600ms - Count: 42
-- Latency Group: 4800ms -> 4900ms - Count: 31
-- Latency Group: 4900ms -> 5000ms - Count: 31
-- Latency Group: 4700ms -> 4800ms - Count: 30
-- Latency Group: 5200ms -> 5300ms - Count: 30
-- Latency Group: 4600ms -> 4700ms - Count: 28
-- Latency Group: 5100ms -> 5200ms - Count: 25
-- Latency Group: 5300ms -> 5400ms - Count: 25
-- Latency Group: 5000ms -> 5100ms - Count: 24
-- Latency Group: 6600ms -> 6700ms - Count: 20
-- Latency Group: 5400ms -> 5500ms - Count: 16
-- Latency Group: 5800ms -> 5900ms - Count: 16
-- Latency Group: 5500ms -> 5600ms - Count: 14
-- Latency Group: 8300ms -> 8400ms - Count: 13
-- Latency Group: 5600ms -> 5700ms - Count: 13
-- Latency Group: 6400ms -> 6500ms - Count: 13
-- Latency Group: 6800ms -> 6900ms - Count: 12
-- Latency Group: 6700ms -> 6800ms - Count: 12
-- Latency Group: 8500ms -> 8600ms - Count: 11
aol
-- Latency Group: 300ms -> 400ms - Count: 55655
-- Latency Group: 400ms -> 500ms - Count: 55412
-- Latency Group: 500ms -> 600ms - Count: 50143
-- Latency Group: 600ms -> 700ms - Count: 47139
-- Latency Group: 700ms -> 800ms - Count: 41456
-- Latency Group: 200ms -> 300ms - Count: 41001
-- Latency Group: 800ms -> 900ms - Count: 34095
-- Latency Group: 900ms -> 1000ms - Count: 27617
-- Latency Group: 1000ms -> 1100ms - Count: 22766
-- Latency Group: 1100ms -> 1200ms - Count: 19025
-- Latency Group: 1200ms -> 1300ms - Count: 15382
-- Latency Group: 1300ms -> 1400ms - Count: 12696
-- Latency Group: 100ms -> 200ms - Count: 11826
-- Latency Group: 1400ms -> 1500ms - Count: 10676
-- Latency Group: 1500ms -> 1600ms - Count: 6241
-- Latency Group: 1600ms -> 1700ms - Count: 4001
-- Latency Group: 1700ms -> 1800ms - Count: 2744
-- Latency Group: 1800ms -> 1900ms - Count: 2125
-- Latency Group: 1900ms -> 2000ms - Count: 1521
-- Latency Group: 2000ms -> 2100ms - Count: 1026
-- Latency Group: 2100ms -> 2200ms - Count: 762
-- Latency Group: 2200ms -> 2300ms - Count: 604
-- Latency Group: 2300ms -> 2400ms - Count: 472
-- Latency Group: 0ms -> 100ms - Count: 333
-- Latency Group: 2400ms -> 2500ms - Count: 318
-- Latency Group: 2500ms -> 2600ms - Count: 300
-- Latency Group: 2600ms -> 2700ms - Count: 219
-- Latency Group: 2700ms -> 2800ms - Count: 202
-- Latency Group: 2800ms -> 2900ms - Count: 158
-- Latency Group: 2900ms -> 3000ms - Count: 128
-- Latency Group: 3000ms -> 3100ms - Count: 118
-- Latency Group: 3100ms -> 3200ms - Count: 114
-- Latency Group: 3200ms -> 3300ms - Count: 94
-- Latency Group: 3300ms -> 3400ms - Count: 86
-- Latency Group: 3400ms -> 3500ms - Count: 76
-- Latency Group: 3600ms -> 3700ms - Count: 63
-- Latency Group: 3500ms -> 3600ms - Count: 54
-- Latency Group: 3700ms -> 3800ms - Count: 51
-- Latency Group: 3800ms -> 3900ms - Count: 41
-- Latency Group: 4000ms -> 4100ms - Count: 33
-- Latency Group: 3900ms -> 4000ms - Count: 31
-- Latency Group: 4300ms -> 4400ms - Count: 28
-- Latency Group: 4200ms -> 4300ms - Count: 26
-- Latency Group: 4500ms -> 4600ms - Count: 25
-- Latency Group: 4400ms -> 4500ms - Count: 22
-- Latency Group: 4100ms -> 4200ms - Count: 19
-- Latency Group: 4700ms -> 4800ms - Count: 19
-- Latency Group: 5000ms -> 5100ms - Count: 18
-- Latency Group: 4800ms -> 4900ms - Count: 16
-- Latency Group: 4900ms -> 5000ms - Count: 16
-- Latency Group: 4600ms -> 4700ms - Count: 14
-- Latency Group: 5100ms -> 5200ms - Count: 12
-- Latency Group: 5800ms -> 5900ms - Count: 11
-- Latency Group: 5200ms -> 5300ms - Count: 11
appnexus
-- Latency Group: 300ms -> 400ms - Count: 58750
-- Latency Group: 200ms -> 300ms - Count: 53059
-- Latency Group: 400ms -> 500ms - Count: 51087
-- Latency Group: 500ms -> 600ms - Count: 40653
-- Latency Group: 600ms -> 700ms - Count: 30993
-- Latency Group: 100ms -> 200ms - Count: 29864
-- Latency Group: 700ms -> 800ms - Count: 25016
-- Latency Group: 800ms -> 900ms - Count: 20157
-- Latency Group: 900ms -> 1000ms - Count: 16643
-- Latency Group: 1000ms -> 1100ms - Count: 13862
-- Latency Group: 1100ms -> 1200ms - Count: 11698
-- Latency Group: 1200ms -> 1300ms - Count: 10001
-- Latency Group: 1300ms -> 1400ms - Count: 8947
-- Latency Group: 1400ms -> 1500ms - Count: 7568
-- Latency Group: 1500ms -> 1600ms - Count: 4769
-- Latency Group: 0ms -> 100ms - Count: 4013
-- Latency Group: 1600ms -> 1700ms - Count: 3465
-- Latency Group: 1700ms -> 1800ms - Count: 2624
-- Latency Group: 1800ms -> 1900ms - Count: 2023
-- Latency Group: 1900ms -> 2000ms - Count: 1593
-- Latency Group: 2000ms -> 2100ms - Count: 1174
-- Latency Group: 2100ms -> 2200ms - Count: 1007
-- Latency Group: 2200ms -> 2300ms - Count: 786
-- Latency Group: 2300ms -> 2400ms - Count: 637
-- Latency Group: 2400ms -> 2500ms - Count: 506
-- Latency Group: 2500ms -> 2600ms - Count: 467
-- Latency Group: 2600ms -> 2700ms - Count: 412
-- Latency Group: 2700ms -> 2800ms - Count: 298
-- Latency Group: 2800ms -> 2900ms - Count: 279
-- Latency Group: 2900ms -> 3000ms - Count: 236
-- Latency Group: 3000ms -> 3100ms - Count: 191
-- Latency Group: 3100ms -> 3200ms - Count: 174
-- Latency Group: 3200ms -> 3300ms - Count: 145
-- Latency Group: 3300ms -> 3400ms - Count: 131
-- Latency Group: 3500ms -> 3600ms - Count: 96
-- Latency Group: 3700ms -> 3800ms - Count: 90
-- Latency Group: 3400ms -> 3500ms - Count: 89
-- Latency Group: 3600ms -> 3700ms - Count: 70
-- Latency Group: 4000ms -> 4100ms - Count: 59
-- Latency Group: 3800ms -> 3900ms - Count: 56
-- Latency Group: 3900ms -> 4000ms - Count: 53
-- Latency Group: 4200ms -> 4300ms - Count: 42
-- Latency Group: 4100ms -> 4200ms - Count: 42
-- Latency Group: 4300ms -> 4400ms - Count: 32
-- Latency Group: 4600ms -> 4700ms - Count: 26
-- Latency Group: 4700ms -> 4800ms - Count: 25
-- Latency Group: 4800ms -> 4900ms - Count: 24
-- Latency Group: 5200ms -> 5300ms - Count: 23
-- Latency Group: 4400ms -> 4500ms - Count: 20
-- Latency Group: 5300ms -> 5400ms - Count: 16
-- Latency Group: 5500ms -> 5600ms - Count: 16
-- Latency Group: 6700ms -> 6800ms - Count: 16
-- Latency Group: 5400ms -> 5500ms - Count: 15
-- Latency Group: 4500ms -> 4600ms - Count: 13
-- Latency Group: 5100ms -> 5200ms - Count: 12
-- Latency Group: 4900ms -> 5000ms - Count: 12
-- Latency Group: 7800ms -> 7900ms - Count: 11
rubicon
-- Latency Group: 400ms -> 500ms - Count: 56369
-- Latency Group: 300ms -> 400ms - Count: 53925
-- Latency Group: 500ms -> 600ms - Count: 52531
-- Latency Group: 600ms -> 700ms - Count: 44159
-- Latency Group: 1000ms -> 1100ms - Count: 36712
-- Latency Group: 700ms -> 800ms - Count: 35554
-- Latency Group: 800ms -> 900ms - Count: 29799
-- Latency Group: 200ms -> 300ms - Count: 29477
-- Latency Group: 1100ms -> 1200ms - Count: 25974
-- Latency Group: 900ms -> 1000ms - Count: 25547
-- Latency Group: 1200ms -> 1300ms - Count: 19271
-- Latency Group: 1300ms -> 1400ms - Count: 15071
-- Latency Group: 1400ms -> 1500ms - Count: 12209
-- Latency Group: 1500ms -> 1600ms - Count: 7669
-- Latency Group: 1600ms -> 1700ms - Count: 5303
-- Latency Group: 100ms -> 200ms - Count: 4442
-- Latency Group: 1700ms -> 1800ms - Count: 4089
-- Latency Group: 1900ms -> 2000ms - Count: 3372
-- Latency Group: 1800ms -> 1900ms - Count: 3040
-- Latency Group: 2000ms -> 2100ms - Count: 2041
-- Latency Group: 2100ms -> 2200ms - Count: 1347
-- Latency Group: 2200ms -> 2300ms - Count: 1067
-- Latency Group: 2300ms -> 2400ms - Count: 833
-- Latency Group: 0ms -> 100ms - Count: 786
-- Latency Group: 2400ms -> 2500ms - Count: 648
-- Latency Group: 2500ms -> 2600ms - Count: 523
-- Latency Group: 2600ms -> 2700ms - Count: 437
-- Latency Group: 2700ms -> 2800ms - Count: 385
-- Latency Group: 2800ms -> 2900ms - Count: 341
-- Latency Group: 2900ms -> 3000ms - Count: 309
-- Latency Group: 3100ms -> 3200ms - Count: 236
-- Latency Group: 3000ms -> 3100ms - Count: 230
-- Latency Group: 3200ms -> 3300ms - Count: 184
-- Latency Group: 3400ms -> 3500ms - Count: 182
-- Latency Group: 3300ms -> 3400ms - Count: 168
-- Latency Group: 3600ms -> 3700ms - Count: 134
-- Latency Group: 3500ms -> 3600ms - Count: 134
-- Latency Group: 3700ms -> 3800ms - Count: 111
-- Latency Group: 3900ms -> 4000ms - Count: 110
-- Latency Group: 3800ms -> 3900ms - Count: 100
-- Latency Group: 4100ms -> 4200ms - Count: 84
-- Latency Group: 4000ms -> 4100ms - Count: 79
-- Latency Group: 4200ms -> 4300ms - Count: 77
-- Latency Group: 4500ms -> 4600ms - Count: 59
-- Latency Group: 4400ms -> 4500ms - Count: 54
-- Latency Group: 4800ms -> 4900ms - Count: 52
-- Latency Group: 4300ms -> 4400ms - Count: 51
-- Latency Group: 4900ms -> 5000ms - Count: 47
-- Latency Group: 4700ms -> 4800ms - Count: 43
-- Latency Group: 4600ms -> 4700ms - Count: 35
-- Latency Group: 5400ms -> 5500ms - Count: 35
-- Latency Group: 5000ms -> 5100ms - Count: 29
-- Latency Group: 5100ms -> 5200ms - Count: 25
-- Latency Group: 5200ms -> 5300ms - Count: 24
-- Latency Group: 5600ms -> 5700ms - Count: 21
-- Latency Group: 5800ms -> 5900ms - Count: 21
-- Latency Group: 5700ms -> 5800ms - Count: 20
-- Latency Group: 6300ms -> 6400ms - Count: 19
-- Latency Group: 5900ms -> 6000ms - Count: 19
-- Latency Group: 5500ms -> 5600ms - Count: 19
-- Latency Group: 6900ms -> 7000ms - Count: 18
-- Latency Group: 5300ms -> 5400ms - Count: 18
-- Latency Group: 6800ms -> 6900ms - Count: 16
-- Latency Group: 8700ms -> 8800ms - Count: 14
-- Latency Group: 6200ms -> 6300ms - Count: 14
-- Latency Group: 6700ms -> 6800ms - Count: 13
-- Latency Group: 6400ms -> 6500ms - Count: 13
-- Latency Group: 7600ms -> 7700ms - Count: 12
-- Latency Group: 8100ms -> 8200ms - Count: 12
-- Latency Group: 13000ms -> 13100ms - Count: 12
-- Latency Group: 6600ms -> 6700ms - Count: 12
-- Latency Group: 7300ms -> 7400ms - Count: 11
sovrn
-- Latency Group: 400ms -> 500ms - Count: 2284
-- Latency Group: 300ms -> 400ms - Count: 2064
-- Latency Group: 500ms -> 600ms - Count: 1746
-- Latency Group: 200ms -> 300ms - Count: 1665
-- Latency Group: 600ms -> 700ms - Count: 1414
-- Latency Group: 700ms -> 800ms - Count: 1143
-- Latency Group: 800ms -> 900ms - Count: 915
-- Latency Group: 900ms -> 1000ms - Count: 793
-- Latency Group: 1000ms -> 1100ms - Count: 654
-- Latency Group: 1100ms -> 1200ms - Count: 551
-- Latency Group: 100ms -> 200ms - Count: 511
-- Latency Group: 1200ms -> 1300ms - Count: 451
-- Latency Group: 1300ms -> 1400ms - Count: 382
-- Latency Group: 1400ms -> 1500ms - Count: 313
-- Latency Group: 1500ms -> 1600ms - Count: 220
-- Latency Group: 1600ms -> 1700ms - Count: 194
-- Latency Group: 1700ms -> 1800ms - Count: 171
-- Latency Group: 1800ms -> 1900ms - Count: 119
-- Latency Group: 1900ms -> 2000ms - Count: 94
-- Latency Group: 2000ms -> 2100ms - Count: 73
-- Latency Group: 2100ms -> 2200ms - Count: 64
-- Latency Group: 2200ms -> 2300ms - Count: 46
-- Latency Group: 2400ms -> 2500ms - Count: 46
-- Latency Group: 2500ms -> 2600ms - Count: 39
-- Latency Group: 2300ms -> 2400ms - Count: 37
-- Latency Group: 2700ms -> 2800ms - Count: 35
-- Latency Group: 2600ms -> 2700ms - Count: 33
-- Latency Group: 2900ms -> 3000ms - Count: 22
-- Latency Group: 2800ms -> 2900ms - Count: 21
-- Latency Group: 3000ms -> 3100ms - Count: 20
-- Latency Group: 0ms -> 100ms - Count: 18
-- Latency Group: 3200ms -> 3300ms - Count: 17
-- Latency Group: 3100ms -> 3200ms - Count: 16
-- Latency Group: 3400ms -> 3500ms - Count: 16
-- Latency Group: 3500ms -> 3600ms - Count: 13
-- Latency Group: 3900ms -> 4000ms - Count: 11
adform
-- Latency Group: 200ms -> 300ms - Count: 4269
-- Latency Group: 300ms -> 400ms - Count: 3820
-- Latency Group: 400ms -> 500ms - Count: 3058
-- Latency Group: 500ms -> 600ms - Count: 2381
-- Latency Group: 100ms -> 200ms - Count: 2012
-- Latency Group: 600ms -> 700ms - Count: 1819
-- Latency Group: 700ms -> 800ms - Count: 1452
-- Latency Group: 800ms -> 900ms - Count: 1163
-- Latency Group: 900ms -> 1000ms - Count: 902
-- Latency Group: 1000ms -> 1100ms - Count: 733
-- Latency Group: 1100ms -> 1200ms - Count: 538
-- Latency Group: 1200ms -> 1300ms - Count: 434
-- Latency Group: 1300ms -> 1400ms - Count: 389
-- Latency Group: 1400ms -> 1500ms - Count: 326
-- Latency Group: 1500ms -> 1600ms - Count: 192
-- Latency Group: 1600ms -> 1700ms - Count: 161
-- Latency Group: 1700ms -> 1800ms - Count: 125
-- Latency Group: 1800ms -> 1900ms - Count: 100
-- Latency Group: 1900ms -> 2000ms - Count: 68
-- Latency Group: 2100ms -> 2200ms - Count: 50
-- Latency Group: 2000ms -> 2100ms - Count: 47
-- Latency Group: 2200ms -> 2300ms - Count: 43
-- Latency Group: 2500ms -> 2600ms - Count: 38
-- Latency Group: 2300ms -> 2400ms - Count: 29
-- Latency Group: 2400ms -> 2500ms - Count: 26
-- Latency Group: 0ms -> 100ms - Count: 25
-- Latency Group: 2700ms -> 2800ms - Count: 18
-- Latency Group: 2600ms -> 2700ms - Count: 16
-- Latency Group: 3500ms -> 3600ms - Count: 16

[headerbidding]

Yes, I see long timeouts also when I check using the Headerbid Expert Chrome extension.

[mkendall07]

@cwbeck
How is this data being collected? Please note that when you set a timeout, it's still possible for bids to return _after_ the timeout, they just are not included in the auction.

[cwbeck]

Hi @mkendall07, this is how we are currently setup

pbjs.requestBids({
  timeout: 1500,
  bidsBackHandler: function(bidResponses){
    //we collect the bid responses here to form the landscape
    ...
    var bidLandscape = [];
    ...
    for(var i=0;i<bidResponses.bids.length;i++){
      ...
      bidLandscape.push({
        'bidder': adBid.bidder,
        'n_cpm': adBid.cpm,
        'latency': adBid.timeToRespond,
        'bid_width': adBid.width,
        'bid_height': adBid.height
      });
      ...
    }
    ...
    var adTracking = require('project/tracking/tracking');
    adTracking.fire(placementId, winningBid.bidder, winningBid.cpm, winningBid.winType, bidLandscape, winningBid.width, winningBid.height, optional);
    ...
  }
});

All this data is sent back to us for every impression for analysis.

What we see is bidsBackHandler appearing to wait for all bids to return regardless. All figures provided are based on latency provided by PBJS.

[cwbeck]

@mkendall07 - it is worth noting I have been unable to spot an issue with Prebid.js code. We have seen this issue before with setTimeout behaviour on another project (used to draw canvas frames) whereby the single-threaded JS engine loads on a _heavy site_ and the competition for resource means the call is actually ignored and in our case the frame was never drawn due to callback never being triggered.

I'm keen to know your thoughts on this, but I also question if there is some other method to perhaps timeout individual requests instead.

Perhaps dropping some of this logic into a worker that will not be blocked in the main thread?

[mkendall07]

@cwbeck
Thanks for the details. I'm really surprised that your seeing that many bids past the timeout (and that far past the timeout). I've seen timeouts be delayed somewhat, but not to that extent. One possible work around to this would be to keep a hard timer in prebid.js (ms since request started) that is checked after each bid is in. This of course isn't perfect, but possibly could be used in conjunction with timeout to help maintain the integrity of the timeout. The idea with web worker is interesting, I'll look into that as a possibility as well.

[mkendall07]

This has been addressed for awhile.

[doingweb]

Hey @mkendall07, sorry to totally necro this issue, but could you follow up a little on the web worker idea? Did you get around to trying that out, and if so, what were the results? We're finding ourselves having the same event loop queue issue and are considering that as a possible solution.

Thanks! :)

[doingweb]

I did some exploring myself yesterday and found that, while it was easy enough to patch loadScript() to use importScripts() rather than DOM injection to perform the JSONP requests, the exchanges still assume they're in a browser context and may try to use any number of features not available in Web Workers. No go for us :/

[mkendall07]

@doingweb
yeah, we didn't see any performance gain using web workers. I think it's because most of our operations are network bound vs using a lot of processing power.