Shaka 3.0.1 is not raising DASH timed metadata correctly on a DAI stream

[TheSouryaRoy]

Have you read the FAQ and checked for duplicate open issues?
Yes

What version of Shaka Player are you using?
3.0.1 (issue is not present in Shaka 2.5)

Can you reproduce the issue with our latest release version?
Yes

Can you reproduce the issue with the latest code from master?
Yes

Are you using the demo app or your own custom app?
Own custom app (link below)

If custom app, can you reproduce the issue using our demo app?
Could not extract timed metadata from the demo app

What browser and OS are you using?
Chrome 83, MacOS 10.15.5

What issue are you facing?
We are playing a DAI stream on Shaka Player 3.0.1 with IMA SDK. Instead of incrementally raising the timed metadata events as they are encountered, Shaka Player is raising a bunch of them all at once. As a result, our ad measurement pings are being fired incorrectly.

We tried to reproduce the issue on Shaka 2.5, but were unsuccessful. This seems to us a Shaka 3.x-only issue.

What did you do?

1. Went to demo app: https://storage.googleapis.com/gvabox/sanils/h5/dai/shaka_test/dai_shaka_3.0.1.html
2. Used Asset Key: 0ndl1dJcRmKDUPxTRjvdog
3. Hit "Request Live"

For reference, here is the manifest link: https://dai.google.com/linear/dash/pa/event/0ndl1dJcRmKDUPxTRjvdog/stream/4a68c85b-002d-4a69-b1d6-6eadcbbf32d4:ATL/manifest.mpd

What did you expect to happen?
Timed metadata events are being raised as they are encountered in the stream.

What actually happened?
Timed metadata events are not being raised as they are encountered in the stream, and instead are being raised all at once after some delay.

[TheSouryaRoy]

Quick addition: This is only observed after you have the stream running for 20-30 mins.

[ismena]

Just to confirm:

• when you mention 2.5 doesn't have the issue, do you mean that it's working correctly?
• in 3.0.1, does it work as expected for the first 20-30 minutes?

[karlandersson]

Yes, for 2.5 it looks to be working correctly while for 3.0.1 it works in the beginning but stops working after a an amount of time.

[joeyparrish]

Does that time roughly correspond to the period boundaries (ad boundaries?) in the content?

[karlandersson]

Yes, we believe so

[ismena]

Ok, we made some changes to how we handle periods in 3.0+, sounds like it might've screwed up our timed event parsing/raising. We'll investigate.

[ismena]

@TheSouryaRoy @karlandersson
Starting to look into this! This might be a bit far fetched, but please let us know if you have a piece of content with shorter periods where the issue can be reproduced. We can (and will) definitely work with this one, but a repro cycle of 20-30 minutes means a bit of a long iteration.
I'll try to come up with a test to repro the issue in the meantime, now that we have some idea where the problem might lie.

[joeyparrish]

What if we start playback at a time right before the first period transition? Would that still reproduce the issue, but faster?

[ismena]

@joeyparrish It's a live stream with a limited seek window! :)
There's a fair amount of luck involved in what you get when you load :)
I'll sync with you offline though, for more ideas on how to possibly speed this up.

[TheSouryaRoy]

Thanks @ismena and @joeyparrish for looking into this. We'll try to see if we can reproduce during a shorter time period and get back.

On a related note, we have observed Shaka 2.5 to drop some of the metadata at period boundaries, but interestingly that is not happening on Shaka 3.0.1 (more details: #2723).

[TheSouryaRoy]

Haven't been able to find a way to speed things up, still taking 20-30 mins for the stream to run before the issue appears. Also, we have period transitions (ads) in the stream every 30 or so seconds, so even if you move right before the period transition, it would not be of much help.

Will keep on trying and update the thread if I have luck in reproducing this faster.

[ismena]

SG @TheSouryaRoy. We are also trying to repro it in a test to figure out what exactly might be going on.

I've seen the repro on your demo page, trying to get one on my local build now with added logging.

[ismena]

This (Murphy's law!) doesn't seem to repro on my local build (the latest master). Trying the stable 3.0.1 to check if the problem happened to be fixed with one of the latest changes in master.

[ismena]

Alright, now I'm not seeing the repro anywhere, including the demo provided in the report (ran the stream for ~1h).

@TheSouryaRoy can you please verify that I'm not going mad and tell me if it's still reproing :(

[TheSouryaRoy]

@ismena Try now. I was just able to reproduce the issue on the demo app (stream ran for around 10-15 mins).

However, I did try earlier today and was not able to reproduce it either.

Here is what happened: We usually had only 15 second ad creatives. Earlier today I enabled 10 second ad creative to see if we can speed things up. It seems the issue stopped happening once we enabled the 10 second ad creative and started happening again when I disabled the 10 second ad creative.

Each break is 30 second long. And here is how the ads are being placed (each ad is its own period):

Initial and current setup (i.e. before introducing the 10 second ad creative):
Two types of ad breaks happen:

1. We get two 15 second ad creatives (Ad + Ad) to fill the break, or
2. One 15 second ad and 15 second slate (Ad + Slate).

Setup earlier today (i.e. with 10 second ad creatives)
Two types of ad breaks happened:

1. Two 15 second ad creatives (Ad + Ad), or
2. One 15 second ad creative, one 10 second, and 5 second slate (Ad + Ad + Slate)
   Due to how the ad rules are configured, we never encountered one 15 second ad and a 15 second slate.

For some reason in the second case, this issue is not reproducible. Very strange.

[ismena]

Okay, let me go ahead and leave some investigation notes here from what I discovered looking at this throughout the week:

1. IMA events are coded into DASH timed regions and the specific integration mentioned in the repro listens to our 'timelineregionenter' event to fire their events.
2. We have a timer that's supposed to go off every 0.25 seconds and go through all the timed regions to see of we have entered any of them (or have just passed any, in between the timer calls). If we did, we fire the event.

NOTE: If the stream is running in a non-active window/tab, browsers impose restrictions on the timers, slowing them all done to once a second. That's not the main problem in this case, but it's a good-to-know thing for delays.

3. It's a LIVE stream simulation, so it's effectively endless. Over time, as we get more and more timed metadata regions, going through all of them takes more and more time. That doesn't seem to be the main problem either, but it does become a problem over long periods of time, so it's a good idea to filter timed regions in RegionObserver by availabilty window, so we don't keep computing for regions no one can possibly see anyway.

4. I noticed that even in the active window & tab the timer slows down significantly over time and starts firing every 1->2->3->...-> wooping 30(!) seconds.
   Drilling down into performance shows that the majority of time is spent filtering the manifest. Looking into it further shows that every time the manifest is updated, a few hundred variants get added to our manifest object. Within an hour, it gets to hundreds of thousands variants that are processed(filtered) every manifest update. Performance drain found! (Hopefully that's the main one).
   I think, in 2.5 our variant handling was period-specific, so we didn't get into this situation. Starting with 3.0, there's no more periods, so all the variants for the entire presentation are always computed for.

Next steps:

1. Figure out why the heck we are creating so many variants and if it is specific to a certain type of LIVE content (are ad periods different enough that we're failing to combine them with existing variants or something?).
2. If the content is legit and we're failing to create variants for it appropriately, find where the problem is.
3. Unrelated to the main issue: trim DASH timed regions stored in the RegionObserver by the availability window.

I'm out next week and will sync with the team on Friday to hand this off, if needed.

@TheSouryaRoy and the team, apologies that this is taking awhile. The combination of a lengthy repro + a deeper performance issue makes for a longer debugging cycle. The good news is, I'm pretty sure we're on the right track here and just need to get to the bottom of the problem.

[ismena]

Handing this off to @michellezhuogg for next week while I'm out.

A few additional notes:

1. To get the stream on your the Shaka demo page, run this in the console:

var adM = shakaDemoMain.player_.getAdManager();
var video = shakaDemoMain.video_;
var adContainer = video.ui.getControls().getControlsContainer();
adM.initServerSide(adContainer, video);
var streamRequest = new google.ima.dai.api.LiveStreamRequest();
streamRequest.assetKey = '0ndl1dJcRmKDUPxTRjvdog';
adM.requestServerSideStream(streamRequest).then((uri) => shakaDemoMain.player_.load(uri));

2. The content seems to have duplicated audio streams in every period (same bandwidth, same language, etc, basicallly everything's the same except for an id). It's a good idea to talk to the IMA team about why this content was created this way and if it might make sense for them to tweak their processes to avoid duplication.

[ismena]

Note: the content in #2736 also seems to exhibit the same variant explosion pattern.

[rohitsw-g]

Hey all, Wanted to check if there were any more updates here. Thank you.

[ismena]

Hi Rohit,
I'm back from vacation and will be making this a priority this week.

[rohitsw-g]

Thank you. Please let us know if you would like us to make changes to the content etc to help repro.

The original content is being generated via aws elemental encoder and media packager services

[ismena]

Thanks! Hm, so it's the AWS logic that generates all those duplicated streams? I wonder how and why they end up doing that.

I don't think we need more/new content at the moment. I was finally able to track what exactly is causing a delay, now I just need to figure out why it is happening. The content is packaged in an unusual way, but IMO we should still be able to handle it better than what I see happening now.
My next stop is to try to replicate the problem in a test so I have a ready isolated repro that does not require waiting. If I can do that, everything will go much faster from now on.
The main reason this issue was taking longer is that I had to wait ~30 minutes to get into the repro state each time.

I'll keep you posted as my work progresses!