6 Replies Latest reply on Nov 8, 2011 1:21 AM by Silviu Vergoti

    InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams

    gr8gib1968

      Can someone tell me why InsufficientBufferRule.as uses the "rtmpMetrics.netStream.bufferLength" as opposed to "rtmpMetrics.netStream.info.videoBufferLength"?

       

      The reason I ask is because the "rtmpMetrics.netStream.bufferLength" returns 10 times(can grow to even more during transitions in quick succesion) what the actuall buffer length is when it switchs to a differnt stream. It will then continually drop until it starts returning the real buffer length(with my current bitrate(100, 300, 500) and bufferTime(10 seconds) setup, its takes about 20 seconds to get back to real buffer length). Durring this time the player is vulnerable to a buffer empty event because of the extremly high(and obviously wrong) buffer length being returned by "rtmpMetrics.netStream.bufferLength". Because of the incorrect buffer length being returned, the "if (_panic || (rtmpMetrics.netStream.bufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))" statement never fires and hence the buffer drains completely without any warning.

       

      I hate the stuttering buffer empty, buffer full, buffer empty, buffer full... crap that happens when this occurs so I've been debugging(more like hacking:)) this issue for quite some time. I tried many different things to try and avoid the buffering empty state. Most of my hacks have been done in the NetStreamSwitchManager file and I have had some limited success in avoiding the buffer empty state but ultimatly it would shows it ugly head no matter what I did.

       

      Last night I found the "rtmpMetrics.netStream.info.videoBufferLength" property and noticed it returns the correct buffer length all the time even during a transition. So I changed "if (_panic || (rtmpMetrics.netStream.bufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))" to "if (_panic || (rtmpMetrics.netStream.info.videoBufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))" and tada!!!! It works like a dream. No matter what I do with my Netlimiter program(simulates bad connections), short of going below the 100kbs setting, the player never reaches the buffer empty state. Yaaaayyyyyyyyy:). I was even able to remove some of my hacks and still get good results. I plan on setting up a totaly new and clean enviroment and try this without any of my previous hacks and see how it works. In the meantime I was hoping someone could enlighten me as to why bufferLength is being used as opposed to videoBufferLength.

       

      I included some browser logs that show what I am describing below. Any insight into this would be greatly appreciated.

       

      100kbs to 300kbs

       

      [LOG] time 10:44:15.967 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 10.102

      [LOG] time 10:44:15.969 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10.1

      [LOG] time 10:44:16.517 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 9.901

      [LOG] time 10:44:16.519 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 9.9

      [LOG] time 10:44:17.49 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 68955.72916666667

      [LOG] time 10:44:17.50 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 9.981

      [LOG] time 10:44:17.57 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 9.95

      [LOG] time 10:44:17.549 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : Move up since avg dropped FPS 0 < 2 and bufferLength > 10

      [LOG] time 10:44:17.551 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : getNewIndex() - about to return: 2, detail=null

      [LOG] time 10:44:17.554 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 68955.72916666667

      [LOG] time 10:44:17.557 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 10.085

      [LOG] time 10:44:17.560 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10.05

      [LOG] time 10:44:17.564 :: org.osmf.net::NetStreamSwitchManager : 10:44:17 GMT-0400>>> NetStreamSwitchManager.----------0

      [LOG] time 10:44:17.567 :: org.osmf.net::NetStreamSwitchManager : 10:44:17 GMT-0400>>> NetStreamSwitchManager.checkRules() - Calling for switch to 1 at 300 kbps

      [LOG] time 10:44:17.570 :: org.osmf.net::NetStreamSwitchManager : 10:44:17 GMT-0400>>> NetStreamSwitchManager.executeSwitch() - Switching to index 1 at 300 kbps

      [LOG] time 10:44:18.165 :: org.osmf.net::NetStreamMetricsBase : onNetStatus() - event.info.code=NetStream.Play.Transition

      [LOG] time 10:44:18.167 :: org.osmf.net::NetStreamSwitchManager : 10:44:18 GMT-0400>>> NetStreamSwitchManager.onNetStatus() - event.info.code=NetStream.Play.Transition

      [LOG] time 10:44:18.599 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : Move up since avg dropped FPS 0 < 2 and bufferLength > 10

      [LOG] time 10:44:18.603 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : getNewIndex() - about to return: 2, detail=null

      [LOG] time 10:44:18.607 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 68955.72916666667

      [LOG] time 10:44:18.610 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 27.508

      [LOG] time 10:44:18.612 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10.1

      [LOG] time 10:44:19.99 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : Move up since avg dropped FPS 0 < 2 and bufferLength > 10

      [LOG] time 10:44:19.101 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : getNewIndex() - about to return: 2, detail=null

      [LOG] time 10:44:19.105 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 68955.72916666667

      [LOG] time 10:44:19.108 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 27.008

      [LOG] time 10:44:19.110 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10

       


      300kbs to 500kbs

      [LOG] time 10:44:47.472 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 10.035

      [LOG] time 10:44:47.480 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10

      [LOG] time 10:44:47.966 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : Move up since avg dropped FPS 0 < 2 and bufferLength > 10

      [LOG] time 10:44:47.968 :: org.osmf.net.rtmpstreaming::SufficientBandwidthRule : getNewIndex() - about to return: 2, detail=null

      [LOG] time 10:44:47.970 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 31764.322916666668

      [LOG] time 10:44:47.972 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 10.135

      [LOG] time 10:44:47.976 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10.1

      [LOG] time 10:44:47.981 :: org.osmf.net::NetStreamSwitchManager : 10:44:47 GMT-0400>>> NetStreamSwitchManager.----------1

      [LOG] time 10:44:47.986 :: org.osmf.net::NetStreamSwitchManager : 10:44:47 GMT-0400>>> NetStreamSwitchManager.checkRules() - Calling for switch to 2 at 500 kbps

      [LOG] time 10:44:47.989 :: org.osmf.net::NetStreamSwitchManager : 10:44:47 GMT-0400>>> NetStreamSwitchManager.executeSwitch() - Switching to index 2 at 500 kbps

      [LOG] time 10:44:48.308 :: org.osmf.net::NetStreamMetricsBase : onNetStatus() - event.info.code=NetStream.Play.Transition

      [LOG] time 10:44:48.309 :: org.osmf.net::NetStreamSwitchManager : 10:44:48 GMT-0400>>> NetStreamSwitchManager.onNetStatus() - event.info.code=NetStream.Play.Transition

      [LOG] time 10:44:48.465 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 23247.514204545456

      [LOG] time 10:44:48.467 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 40

      [LOG] time 10:44:48.469 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 10

      [LOG] time 10:44:48.966 :: org.osmf.net.rtmpstreaming::InsufficientBandwidthRule : -------Average bandwidth of 17793.34677419355

      [LOG] time 10:44:48.967 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : bufferLength reporting Buffer of 39.5

      [LOG] time 10:44:48.970 :: org.osmf.net.rtmpstreaming::InsufficientBufferRule : videoBufferLength reporting Buffer of 9.9

       

       

      Thanks,

      Wayne

       

      P.S.    While wrighting this I realized I need to replace the second part of that if statement to the videoBufferLength as well, so I will do that and make sure it still works. If I don't reply to this you can assume that it works as well.

       


        • 1. Re: InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams
          gr8gib1968 Level 1

          I should have mentioned that my minBufferLength is now set to 9 seconds.

          • 2. Re: InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams
            gr8gib1968 Level 1

            Wow I'm starting to get a little confused here. I need to mention that in my first post I said that I changed/used 

            "if (_panic || (rtmpMetrics.netStream.bufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))".

            That was not the truth, I had actually shortened that statement in one of my earlier hack attempts, not really giving it to much thought at the time. The statement that I ended up changing/using was more like

            "if (_panic || rtmpMetrics.netStream.bufferLength < minBufferLength)" changed to "if (_panic || rtmpMetrics.netStream.info.videoBufferLength < minBufferLength)".

             

            So now that I go back and try using the original code which I had commented out earlier I realize there is somthing very wrong here, I think:) The second part of the statement

            "if (_panic || (rtmpMetrics.netStream.bufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))"

            is checking if the buffer length is greater than the buffer time, but the first part is checking if the buffer length is less than min buffer length. How would that ever be possible?

             

            bufferTime = 10

            minBufferLength = 9

             

            if the bufferLength(no matter which one you use) is less than minBufferLength(9) how is ever going to be greater than bufferTime(10)?

             

            fyi:

            if  I change the statement

            "if (_panic || (rtmpMetrics.netStream.bufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))"

            to

            "if (_panic || (rtmpMetrics.netStream.info.videoBufferLength < minBufferLength && rtmpMetrics.netStream.info.videoBufferLength < rtmpMetrics.netStream.bufferTime))"

            it works like a dream again.

             

            Thanks again,

            Wayne

             

            P.S.   I noticed that there are other places such as SufficientBandwidthRule.as that are referencing rtmpMetrics.netStream.bufferLength. I plan on going through the code and changing these and see how it works. I'm starting to wonder what else could be written like this or am I crazy? 

            • 3. Re: InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams
              gr8gib1968 Level 1

              OK. There is deffinetly something to this. I have setup a brand new enviroment with brand new source code(just downloaded 1.6) to get rid of any previous hacks I may have made. I then applied this change to the InsufficientBufferRule.as and SufficientBandwidthRule.as files and no other changes and it still works pretty well meaning I never see the buffer empty state. I do see that it is back to skiping the middle bandwidth setting when detecting a switch up, however now that the InsufficientBufferRule.as is working correctly it still immediately detects the lowering buffer and switches back down without hitting the buffer empty state.

               

              My next move is to put my one hack back in to make it switch up 1 step at a time instead of skip a step because although it detects the lowering buffer and switches down, I noticed that after a while of this back forth switching the videoBufferLength gets stuck at a low rate(7 or so). I may also play with the bufferTime(is now 10) and the minBufferLength(is now 9) to give the buffer a little more wiggle room, just need to remember that takes away reaction time.

               

              I guess I should also mention that I am using Flowplayer which in all reality is using OSMF when it comes to live RTMP dynamic streaming. I tried using the OSMF/Strobe player never having much luck(I'm sure I could get it, I just get impatient sometimes and already new Flowplayer from years ago). It really is the same code though, in fact you need to have the osmf infrastucture in your flowplayer build enviroment to build the bwcheck plugin.

               

              Any info or insight into this from anybody would be greatly appreciated.

               

              Thanks,

              Wayne

              • 4. Re: InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams
                gr8gib1968 Level 1

                I'm definately sticking with the info.videoBufferLength as it gives me an accurate buffer length that can run through the checks in the InsufficientBufferRule.as file and actually call for a switch(panic code) to the lowest bitrate and make that switch before the buffer gets to an empty buffer state thus avoiding that ugly stuttering. The buffer usually starts recovering around 4 seconds when the panic code is run and that switch is made/complete. There is still an ocasional buffer empty state(very dependent on internet connection quality) but it hasn't stuttered near as bad as it use to, because the panic code fired and the swicth was just about complete. So it will only stutter  buffer for 1 or 2 times instead of the 10, 15 or I've even seen 20 times:(.

                 

                As for the second part of that if statement, I still don't understand how that ever works for anyone.

                 

                                                           lets say its 7       Im using 8                                        remember its 7                                       Im using 10

                                                                             |                     |                                                             |                                                       |

                if (_panic || (rtmpMetrics.netStream.bufferLength < minBufferLength && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime))

                 

                So if the buffer length is 7 which is less than 8, how can buffer length which is 7 be greater than 10?

                 

                It can't be, so this panic code never ever ever fires for anyone that is using this hence the buffer runs empty and that ugly stuttering starts.

                 

                Anyway I changed that greater than sign to a less than sign and now the panic code works. Although I still don't know why we would need to check against the bufferTime, if we already determined that the buffer is below the minBufferLength, just switch down, no other checks are needed in my mind.

                 

                At this point I'm going to leave what I have alone and start enjoying this.

                 

                Thanks,

                Wayne

                 

                Streaming Server = Wowza

                Streams Encoder = VLC encoding 3 streams of 100, 300 and 500 kbs with keyframes set to 15

                Web Video Player = Flowplayer with rtmp and bwcheck plugin

                • 5. Re: InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams
                  gr8gib1968 Level 1

                  Ok, I couldn't leave well enough alone. I think I may have found the heart of the unstable buffer issue. In the SufficientBandwidthRule.as file there is a 1 line condintional statement that is actually assigning crap to the buffer making it abnormaly high. the statement is below.

                   

                  newIndex = (rtmpMetrics.droppedFPS < _minDroppedFrames && rtmpMetrics.netStream.bufferLength > rtmpMetrics.netStream.bufferTime) ? newIndex : -1;

                   

                  Somehow the 2nd part of that statement adds crap to the buffer. It even happens with the .info.videoBufferLength, but no where near as bad as the .bufferLength. However changing the syntax to a more traditional if statement(see below) allieviates that, at least for the .info.videoBufferLength. I haven't changed my code back to using the .bufferLength to try it and I probablly won't as the .info.videoBufferLength works just fine for me.

                   

                  if (rtmpMetrics.netStream.info.videoBufferLength > rtmpMetrics.netStream.bufferTime) {

                       newIndex = newIndex;

                  } else {

                       newIndex = -1;

                  }

                   

                  Using the above if statement instead of the 1 line statement gives me a completly stable buffer that never goes above the .bufferTime value by more than 1.

                   

                  I also made some other changes(theres a bug in the checkRule() function in the NetStreamSwitchManager.as file, it wants to switch to the highest index when it shouldn't). If I get some time I will get into that story. Right now I'm gonna sit back and enjoy

                   

                  Thanks,

                  Wayne

                  • 6. Re: InsufficientBufferRule reporting bogus buffer lengths with live dynamic MBR streams
                    Silviu Vergoti Adobe Employee

                    Hi Wayne,

                     

                    Thank you for the very detailed report!

                     

                    We're tracking your reports at http://bugs.adobe.com/jira/browse/FM-1447 . I really had no time to replicate it.

                     

                    If you find more bugs, please file reports at http://bugs.adobe.com/jira/browse/FM , this will allow us to better prioritize them.

                     

                    Thank you again,

                     

                    S.