Understanding RTP Packet Loss Logging

Wowza Streaming Engine
1

I’ve configured RTP Packet Loss Logging. My RTP jitter properties are below.

I’m confused by the logs that are produced though. When streaming over a high quality wifi connection I don’t see any / many logs (as I would expect). When I stream over an LTE connection I see many more lost packet logs. (Again this is as I would expect.)

However some of the logged messages don’t appear to have any lost packets.

Here is a chunk of the logs as an example:

2017-02-07      18:58:28        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27563 curr:27564 -       -       -       1290188.528     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:28        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27565 curr:27566 -       -       -       1290188.569     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:28        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27571 curr:27584 -       -       -       1290188.975     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:28        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27585 curr:27586 -       -       -       1290189.006     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:28        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27587 curr:27588 -       -       -       1290189.077     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:28        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27589 curr:27590 -       -       -       1290189.158     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27591 curr:27604 -       -       -       1290189.482     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27605 curr:27606 -       -       -       1290189.553     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27607 curr:27608 -       -       -       1290189.615     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27609 curr:27610 -       -       -       1290189.777     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27611 curr:27625 -       -       -       1290189.959     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27626 curr:27627 -       -       -       1290189.98      -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27628 curr:27629 -       -       -       1290190.0       -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27630 curr:27631 -       -       -       1290190.051     -       -       -       -       -       -      --       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2017-02-07      18:58:29        UTC     comment server  WARN    200     -       RTPDePacketizerWrapperPacketSorter.packetLoss[webrtc/_definst_/my-stream:track1]: last:27632 curr:27633 -       -       -       1290190.062     -       -       -       -       -       -      -

Some of these log messages seem like what I would expect, like “last:27591 curr:27604”. Clearly there were a number of packets lost there. However many of these messages don’t seem like packet loss like: “last:27563 curr:27564” and “last:27632 curr:27633”. In both of these cases the last number is one less than the curr number, which I would expect means no packets were lost. Am I mis-interpreting this? Are these messages being logged erroneously? Is “last” the expected next packet, not the last received packet?

                        <Properties>
                                <Property>
                                        <Name>rtpDePacketizerPacketSorterLogPacketLoss</Name>
                                        <Value>true</Value>
                                        <Type>Boolean</Type>
                                </Property>
                                <Property>
                                        <Name>mpegtsLogIncompleteVideoFrames</Name>
                                        <Value>true</Value>
                                        <Type>Boolean</Type>
                                </Property>
                                <Property>
                                        <Name>rtpDePacketizerWrapper</Name>
                                        <Value>com.wowza.wms.rtp.depacketizer.RTPDePacketizerWrapperPacketSorter</Value>
                                        <Type>String</Type>
                                </Property>
                                <Property>
                                        <Name>rtpDePacketizerPacketSorterBufferTime</Name>
                                        <Value>500</Value>
                                        <Type>Integer</Type>
                                </Property>
                        </Properties>

Thanks for any clarification!

Aaron

2

Hello,

Thanks for contacting Wowza Forums!

Regarding the packet loss and the log messages, the server logs what happens. So if you are not receiving a lot of log messages on wifi, that means the connection is stable. Since you see packet loss on LTE, that means LTE is not stable and it will log the messages notifying you it is not stable.

The server will log when it detects packet loss, if it does not detect packet loss, nothing will be logged.

Hope this helps. If any further questions, feel free to contact us.

regards,

Jermaine

3

Unfortunately that didn’t really help Jermaine.

I’m trying to understand what the log message means. When it says “last:27591 curr:27604” it’s pretty clear that 15 packets were lost.

However I’m seeing lots of messages that say something like “last:27632 curr:27633”. In this case it’s not clear that any packets were lost. Why do I see a message when the packet sequence number incremented by one.

Aaron

4

I agree, that explanation did not help. I’m seeing a lot of “last:395 curr:396” and I need a better explanation. My Jitter Buffer is set to a low 250ms at the moment, so I suspect the shorter the buffer the closer these packet numbers get.

Aaron, in your case, I suspect even though “last:27632” is at the end of the buffer, the buffer is probably reaching its timeout duration while still waiting for, say, 27631 and the ones before that. So although 27633 would fit in the buffer’s empty space, there’s no slot open after 27632 to put it in until either the “late” packets before it arrive or the buffer timeout is reached.

To use a metaphor, think of a sandwich assembly line. They’re giving you ingredients in a random order to assemble the sandwich. But as soon as you fully assemble one sandwich, you pass it along and open room at your workstation. Now if you’re busy assembling a sandwich and the cheese never arrives, and too many ingredients for the second sandwich arrive, you’re going to have to abandon your cheese-less sandwich because otherwise you’ll run out of room for the second (and third) sandwich. The smaller your workstation area (buffer time length), the more likely it is for the “last” (cheese-less) sandwich to be close in index number to the current sandwich. If you have a larger workstation, they may be allowed to fall 7 sandwiches behind before you finally get the cheese. If it’s too small, you must abandon the immediately previous sandwich.

Another case exists too, in which your workstation is large enough, but the person sending you ingredients has a long hiccup on the cheese once in a while (bad network conditions). That’s less frequently likely, if you have a buffer just long enough.

In both cases, I recommend increasing the buffer size to Goldilocks level (not too big, not too small, just right). I suspect for my use case that 500ms is the happy place.

5

Thanks for the ideas Amin.

I’m sure it’s something along these lines, although I had been assuming that the numbers printed in the logs are RTP Packet sequence numbers. Given that RTP packets are sized such that they should be transported as a single packet I’m not sure the buffering analogy works. If it turns out that the numbers in the logs are frame or NALU numbers then your ideas seem right on.

Sad that we can’t get a better answer from Wowza on what these values actually mean.