rohc team mailing list archive

[Manuel Iglesias <Manuel.Iglesias@xxxxxxxxxxxx>]

Hello Didier, 

Hope this find you well,

I would like to know your thoughts about an issue I am having, 

Every time I started a rohc decompressor instance, after exactly 1246 RTP packets (G.711a) received, the decompressor does the job but with huge latency, around 170 ms, after that it seems to work correctly but I cannot be totally sure since I haven't let it long time receiving compressed packets.
The exact number of packet at where it fails make me think of some bug.

I have a couple of logs, one in which I start sending the RTP packets for more than 45 seconds, in that test at packet #1246 it shows the latency in wireshark, but I also have a ms counter in code that confirm the latency during decompressor function call. 
The second test I send packets for 10 seconds at a time, during them I never restart decompressor but compressor get restarted by calling force_contexts_reinit(), this test show same result of latency at packet #1246.

I know the RTP stream is Ok since I have inspected under wireshark. I know the decompressor get packets on time and produce a latency after inspecting receiving end tcpdump capture (see attached image please)

This is a extract of the log that rohc decompressor shows at packet of latency.

[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:780 rohc_decompress3()] decompress the 163-byte packet #1246
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:3645 rohc_decomp_parse_padding()] skip 0 byte(s) of padding
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1024 d_decode_header()] decompressor received 0 bytes of feedback for the same-side associated compressor
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:3582 rohc_decomp_decode_cid()] no add-CID found, CID defaults to 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:3762 rohc_decomp_find_context()] context with CID 0 found
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1180 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1199 d_decode_header()] decode packet as 'UO-0'
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1370 rohc_decomp_decode_pkt()] parse packet type 'UO-0' (2)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:1467 parse_uo0()] 4 SN bits = 0xb
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:1472 parse_uo0()] CRC-3 found in packet = 0x00
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1518 rtp_parse_uo_remainder()] UDP checksum = 0xe319
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1388 rohc_decomp_decode_pkt()] ROHC payload (length = 160 bytes) starts at offset 3
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5630 rfc3095_decomp_decode_bits()] decoded SN = 22955 / 0x59ab (nr bits = 4, bits = 11 / 0xb)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5722 decode_ip_values_from_bits()] decoded outer TOS/TC = 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5735 decode_ip_values_from_bits()] decoded outer TTL/HL = 63
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5749 decode_ip_values_from_bits()] decoded outer protocol/NH = 17
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5765 decode_ip_values_from_bits()] decoded outer NBO = 1
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5778 decode_ip_values_from_bits()] decoded outer RND = 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5791 decode_ip_values_from_bits()] decoded outer SID = 1
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5850 decode_ip_values_from_bits()] decoded outer IP-ID = 0x0000 (rnd = 0, nbo = 1, sid = 1, nr bits = 0, bits = 0x0)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5863 decode_ip_values_from_bits()] decoded outer DF = 1
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5879 decode_ip_values_from_bits()] decoded outer src address = c0a80314 (192.168.3.20)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5895 decode_ip_values_from_bits()] decoded outer dst address = c0a81e16 (192.168.30.22)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1577 rtp_decode_values_from_bits()] decoded UDP source port = 0x2724
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1592 rtp_decode_values_from_bits()] decoded UDP destination port = 0x2724
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1627 rtp_decode_values_from_bits()] decoded UDP checksum = 0xe319 (checksum present = 1)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1641 rtp_decode_values_from_bits()] decoded RTP version = 2
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1655 rtp_decode_values_from_bits()] decoded R-P flag = 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1669 rtp_decode_values_from_bits()] decoded R-X flag = 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1683 rtp_decode_values_from_bits()] decoded CC = 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1699 rtp_decode_values_from_bits()] decoded RTP M flag = 0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1713 rtp_decode_values_from_bits()] decoded R-PT = 8
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1716 rtp_decode_values_from_bits()] 0-bit TS delta = 0x0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1753 rtp_decode_values_from_bits()] TS is deducted from SN
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:444 ts_deduce_from_sn()] new TS_SCALED = 1246 (ref TS_SCALED = 1245, new SN = 22955, ref SN = 22954)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:450 ts_deduce_from_sn()] new TS = 199360 (TS_SCALED = 1246, TS_STRIDE = 160, TS_OFFSET = 0)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1776 rtp_decode_values_from_bits()] decoded timestamp = 199360 / 0x30ac0 (nr bits = 0, bits = 0 / 0x0)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1790 rtp_decode_values_from_bits()] decoded SSRC = 4077531918
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5046 rfc3095_decomp_build_hdrs()] length of transport header = 20 bytes
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5208 build_uncomp_ipv4()] Total Length = 0x00c8 (IHL * 4 + 180)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5212 build_uncomp_ipv4()] IP checksum = 0x98aa
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/d_rtp.c:1833 rtp_build_uncomp_rtp()] UDP + RTP length = 0x00b4
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp_rfc3095.c:5366 check_uncomp_crc()] CRC-3 on uncompressed header = 0x0
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1472 rohc_decomp_decode_pkt()] CRC is correct
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1604 rohc_decomp_decode_pkt()] uncompressed packet length = 200 bytes
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:187 ts_update_context()] old SN 22954 replaced by new SN 22955
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:188 ts_update_context()] old TS 199200 replaced by new TS 199360
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:195 ts_update_context()] old TS_SCALED 1245 replaced by new TS_SCALED 1246
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:210 ts_update_context()] old TS_STRIDE 160 kept unchanged
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/schemes/decomp_scaled_rtp_ts.c:220 ts_update_context()] old TS_OFFSET 0 kept unchanged
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1278 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:802 rohc_decompress3()] stay in U-mode as requested by user
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:855 rohc_decompress3()] packet decompression succeeded
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:863 rohc_decompress3()] update decompressor and context statistics
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1775 rohc_decomp_feedback_ack()] CID 0: U-mode: Full Context state: UO-0 packet successfully decompressed
[DEBUG] [/home/mhanuel/Devel/Networking/rohc/src/decomp/rohc_decomp.c:1860 rohc_decomp_feedback_ack()] do not send a positive ACK because of rate-limiting (100 of 3200 with threshold 64)


DEBUG:New Decompressor Max Delta = 0.180944 at pkt #1246
DEBUG:Pipe recv time: 0.000081
DEBUG:Rohc decompressor took: 0.164379 seconds
INFO:Decompressor Sent Time = 0.000141


Notice that last four lines are my program debug timing information, 
Also, here is a extract of second test

[DEBUG] [rohc_decomp.c:780 rohc_decompress3()] decompress the 164-byte packet #1246
[DEBUG] [rohc_decomp.c:3773 rohc_decomp_parse_padding()] skip 0 byte(s) of padding
[DEBUG] [rohc_decomp.c:1025 d_decode_header()] decompressor received 0 bytes of feedback for the same-side associated compressor
[DEBUG] [rohc_decomp.c:3736 rohc_decomp_decode_cid()] 1-byte large CID = 0
[DEBUG] [rohc_decomp.c:3890 rohc_decomp_find_context()] context with CID 0 found
[DEBUG] [rohc_decomp.c:1181 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[DEBUG] [rohc_decomp.c:1200 d_decode_header()] decode packet as 'UO-0'
[DEBUG] [rohc_decomp.c:1371 rohc_decomp_decode_pkt()] parse packet type 'UO-0' (2)
[DEBUG] [rohc_decomp_rfc3095.c:1490 parse_uo0()] 4 SN bits = 0xf
[DEBUG] [rohc_decomp_rfc3095.c:1495 parse_uo0()] CRC-3 found in packet = 0x06
[DEBUG] [d_rtp.c:1518 rtp_parse_uo_remainder()] UDP checksum = 0xab7b
[DEBUG] [rohc_decomp.c:1389 rohc_decomp_decode_pkt()] ROHC payload (length = 160 bytes) starts at offset 4
[DEBUG] [rohc_decomp_rfc3095.c:5661 rfc3095_decomp_decode_bits()] decoded SN = 21951 / 0x55bf (nr bits = 4, bits = 15 / 0xf)
[DEBUG] [rohc_decomp_rfc3095.c:5754 decode_ip_values_from_bits()] decode outer IPv4 header
[DEBUG] [rohc_decomp_rfc3095.c:5773 decode_ip_values_from_bits()] decoded outer TOS/TC = 0
[DEBUG] [rohc_decomp_rfc3095.c:5792 decode_ip_values_from_bits()] decoded outer TTL/HL = 63
[DEBUG] [rohc_decomp_rfc3095.c:5812 decode_ip_values_from_bits()] decoded outer protocol/NH = 17
[DEBUG] [rohc_decomp_rfc3095.c:5834 decode_ip_values_from_bits()] decoded outer NBO = 1
[DEBUG] [rohc_decomp_rfc3095.c:5853 decode_ip_values_from_bits()] decoded outer RND = 0
[DEBUG] [rohc_decomp_rfc3095.c:5872 decode_ip_values_from_bits()] decoded outer SID = 1
[DEBUG] [rohc_decomp_rfc3095.c:5948 decode_ip_values_from_bits()] decoded outer IP-ID = 0x0000 (rnd = 0, nbo = 1, sid = 1, nr bits = 0, bits = 0x0)
[DEBUG] [rohc_decomp_rfc3095.c:5967 decode_ip_values_from_bits()] decoded outer DF = 1
[DEBUG] [rohc_decomp_rfc3095.c:5990 decode_ip_values_from_bits()] decoded outer src address = c0a80314 (192.168.3.20)
[DEBUG] [rohc_decomp_rfc3095.c:6013 decode_ip_values_from_bits()] decoded outer dst address = c0a81e16 (192.168.30.22)
[DEBUG] [d_rtp.c:1577 rtp_decode_values_from_bits()] decoded UDP source port = 0x2724
[DEBUG] [d_rtp.c:1592 rtp_decode_values_from_bits()] decoded UDP destination port = 0x2724
[DEBUG] [d_rtp.c:1633 rtp_decode_values_from_bits()] decoded UDP checksum = 0xab7b (checksum present = 1)
[DEBUG] [d_rtp.c:1647 rtp_decode_values_from_bits()] decoded RTP version = 2
[DEBUG] [d_rtp.c:1661 rtp_decode_values_from_bits()] decoded R-P flag = 0
[DEBUG] [d_rtp.c:1675 rtp_decode_values_from_bits()] decoded R-X flag = 0
[DEBUG] [d_rtp.c:1689 rtp_decode_values_from_bits()] decoded CC = 0
[DEBUG] [d_rtp.c:1705 rtp_decode_values_from_bits()] decoded RTP M flag = 0
[DEBUG] [d_rtp.c:1719 rtp_decode_values_from_bits()] decoded R-PT = 8
[DEBUG] [d_rtp.c:1722 rtp_decode_values_from_bits()] 0-bit TS delta = 0x0
[DEBUG] [d_rtp.c:1759 rtp_decode_values_from_bits()] TS is deducted from SN
[DEBUG] [decomp_scaled_rtp_ts.c:444 ts_deduce_from_sn()] new TS_SCALED = 242 (ref TS_SCALED = 241, new SN = 21951, ref SN = 21950)
[DEBUG] [decomp_scaled_rtp_ts.c:450 ts_deduce_from_sn()] new TS = 38720 (TS_SCALED = 242, TS_STRIDE = 160, TS_OFFSET = 0)
[DEBUG] [d_rtp.c:1782 rtp_decode_values_from_bits()] decoded timestamp = 38720 / 0x9740 (nr bits = 0, bits = 0 / 0x0)
[DEBUG] [d_rtp.c:1796 rtp_decode_values_from_bits()] decoded SSRC = 4077531918
[DEBUG] [rohc_decomp_rfc3095.c:5057 rfc3095_decomp_build_hdrs()] length of transport header = 20 bytes
[DEBUG] [rohc_decomp_rfc3095.c:5220 build_uncomp_ipv4()] Total Length = 0x00c8 (IHL * 4 + 180)
[DEBUG] [rohc_decomp_rfc3095.c:5224 build_uncomp_ipv4()] IP checksum = 0x98aa
[DEBUG] [d_rtp.c:1839 rtp_build_uncomp_rtp()] UDP + RTP length = 0x00b4
[DEBUG] [rohc_decomp_rfc3095.c:5378 check_uncomp_crc()] CRC-3 on uncompressed header = 0x6
[DEBUG] [rohc_decomp.c:1476 rohc_decomp_decode_pkt()] CRC is correct
[DEBUG] [rohc_decomp.c:1619 rohc_decomp_decode_pkt()] uncompressed packet length = 200 bytes
[DEBUG] [decomp_scaled_rtp_ts.c:187 ts_update_context()] old SN 21950 replaced by new SN 21951
[DEBUG] [decomp_scaled_rtp_ts.c:188 ts_update_context()] old TS 38560 replaced by new TS 38720
[DEBUG] [decomp_scaled_rtp_ts.c:195 ts_update_context()] old TS_SCALED 241 replaced by new TS_SCALED 242
[DEBUG] [decomp_scaled_rtp_ts.c:210 ts_update_context()] old TS_STRIDE 160 kept unchanged
[DEBUG] [decomp_scaled_rtp_ts.c:220 ts_update_context()] old TS_OFFSET 0 kept unchanged
[DEBUG] [rohc_decomp.c:1279 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[DEBUG] [rohc_decomp.c:803 rohc_decompress3()] stay in U-mode as requested by user
[DEBUG] [rohc_decomp.c:856 rohc_decompress3()] packet decompression succeeded
[DEBUG] [rohc_decomp.c:864 rohc_decompress3()] update decompressor and context statistics
[DEBUG] [rohc_decomp.c:1790 rohc_decomp_feedback_ack()] CID 0: U-mode: Full Context state: UO-0 packet successfully decompressed
[DEBUG] [rohc_decomp.c:1875 rohc_decomp_feedback_ack()] do not send a positive ACK because of rate-limiting (100 of 3200 with threshold 64)




DEBUG:New Decompressor Max Delta = 0.178596 at pkt #242
DEBUG:Pipe recv time: 0.000004
DEBUG:Rohc decompressor took: 0.161070 seconds
DEBUG:Scapy decode took: 0.000816 seconds
INFO:Decompressor Sent Time = 0.000110


I am not sure how to further debug the issue or if there is a tweek I might try to avoid this latency, it concerns me somehow since I not positive if the latency repeat over time.

I have also noticed that compressor also produces a packet with high latency, after it it seems to work normally, I have not log the compressor yet.

I would really appreciate your comments,


Manuel Iglesias

Attachment: rohc_latency.png
Description: rohc_latency.png