Fixed bug in RTT calculation in RTCP and increase RTT resolution to usec

git-svn-id: http://svn.pjsip.org/repos/pjproject/trunk@384 74dad513-b988-da41-8d7b-12977e46ad98

3 files changed, 92 insertions, 54 deletions

diff --git a/pjmedia/include/pjmedia/rtcp.h b/pjmedia/include/pjmedia/rtcp.h
index 1ce8362b..c577556c 100644
--- a/pjmedia/include/pjmedia/rtcp.h
+++ b/pjmedia/include/pjmedia/rtcp.h
@@ -163,10 +163,10 @@ struct pjmedia_rtcp_session
     pj_uint32_t		    jitter;	/**< Scaled jitter		    */
     pj_timestamp	    ts_freq;	/**< System timestamp frequency.    */
 
-    pjmedia_rtcp_ntp_rec    rtcp_lsr;	 /**< NTP ts in last SR received    */
+    pjmedia_rtcp_ntp_rec    rtcp_lsr;	/**< NTP ts in last SR received    */
     pj_timestamp	    rtcp_lsr_time;/**< Time when last SR is received*/
-    pj_uint32_t		    peer_ssrc;	 /**< Peer SSRC			    */
-    unsigned		    ee_delay;	/**< End-to-end delay, in msec.	    */
+    pj_uint32_t		    peer_ssrc;	/**< Peer SSRC			    */
+    unsigned		    rtt_us;	/**< End-to-end delay, in usec.	    */
 };
 
 /**
diff --git a/pjmedia/src/pjmedia/rtcp.c b/pjmedia/src/pjmedia/rtcp.c
index bb5666e9..777aa929 100644
--- a/pjmedia/src/pjmedia/rtcp.c
+++ b/pjmedia/src/pjmedia/rtcp.c
@@ -19,10 +19,12 @@
 #include <pjmedia/rtcp.h>
 #include <pjmedia/errno.h>
 #include <pj/assert.h>
+#include <pj/log.h>
 #include <pj/os.h>
 #include <pj/sock.h>
 #include <pj/string.h>
 
+#define THIS_FILE "rtcp.c"
 
 #define RTCP_SR   200
 #define RTCP_RR   201
@@ -32,6 +34,11 @@
 #   error "High resolution timer needs to be enabled"
 #endif
 
+#if 0
+#   define TRACE_(x)	PJ_LOG(3,x)
+#else
+#   define TRACE_(x)
+#endif
 
 /*
  * Get NTP time.
@@ -182,12 +189,13 @@ PJ_DEF(void) pjmedia_rtcp_rx_rtcp( pjmedia_rtcp_session *session,
     /* Calculate SR arrival time for DLSR */
     pj_get_timestamp(&session->rtcp_lsr_time);
 
-    /* Calculate ee_delay if it has RR */
+    /* Calculate RTT if it has RR */
     if (size >= sizeof(pjmedia_rtcp_pkt)) {
 	
 	/* Can only calculate if LSR and DLSR is present in RR */
 	if (rtcp->rr.lsr && rtcp->rr.dlsr) {
-	    pj_uint32_t lsr, now, dlsr, eedelay;
+	    pj_uint32_t lsr, now, dlsr;
+	    pj_uint64_t eedelay;
 	    pjmedia_rtcp_ntp_rec ntp;
 
 	    /* LSR is the middle 32bit of NTP. It has 1/65536 second 
@@ -206,10 +214,25 @@ PJ_DEF(void) pjmedia_rtcp_rx_rtcp( pjmedia_rtcp_session *session,
 	    /* End-to-end delay is (now-lsr-dlsr) */
 	    eedelay = now - lsr - dlsr;
 
-	    /* Convert end to end delay to msec: 
+	    /* Convert end to end delay to usec (keeping the calculation in
+             * 64bit space)::
 	     *   session->ee_delay = (eedelay * 1000) / 65536;
 	     */
-	    session->ee_delay = (eedelay * 1000) >> 16;
+	    eedelay = (eedelay * 1000000) >> 16;
+
+	    TRACE_((THIS_FILE, "Rx RTCP: lsr=%p, dlsr=%p (%d:%03dms), "
+			       "now=%p, rtt=%p",
+		    lsr, dlsr, dlsr/65536, (dlsr%65536)*1000/65536,
+		    now, (pj_uint32_t)eedelay));
+	    
+	    /* Only save calculation if "now" is greater than lsr, or
+	     * otherwise rtt will be invalid 
+	     */
+	    if (now-dlsr >= lsr) {
+		session->rtt_us = (pj_uint32_t)eedelay;
+	    } else {
+		TRACE_((THIS_FILE, "NTP clock running backwards?"));
+	    }
 	}
     }
 }
@@ -271,7 +294,7 @@ PJ_DEF(void) pjmedia_rtcp_build_rtcp(pjmedia_rtcp_session *session,
     rtcp_pkt->sr.ntp_sec = pj_htonl(ntp.hi);
     rtcp_pkt->sr.ntp_frac = pj_htonl(ntp.lo);
     
-    if (session->rtcp_lsr_time.u64 == 0 || session->rtcp_lsr.lo == 0) {
+    if (session->rtcp_lsr_time.u64 == 0) {
 	rtcp_pkt->rr.lsr = 0;
 	rtcp_pkt->rr.dlsr = 0;
     } else {
@@ -289,6 +312,9 @@ PJ_DEF(void) pjmedia_rtcp_build_rtcp(pjmedia_rtcp_session *session,
 	 */
 	pj_get_timestamp(&ts);
 
+	/* Calculate DLSR */
+	ts.u64 -= session->rtcp_lsr_time.u64;
+
 	/* Convert interval to 1/65536 seconds value */
 	ts.u64 = ((ts.u64 - session->rtcp_lsr_time.u64) << 16) / 
 		    session->ts_freq.u64;
@@ -302,4 +328,4 @@ PJ_DEF(void) pjmedia_rtcp_build_rtcp(pjmedia_rtcp_session *session,
     *len = sizeof(pjmedia_rtcp_pkt);
 }
 
- 
\ No newline at end of file
+ 
diff --git a/pjsip-apps/src/samples/siprtp.c b/pjsip-apps/src/samples/siprtp.c
index c7764499..75b89a25 100644
--- a/pjsip-apps/src/samples/siprtp.c
+++ b/pjsip-apps/src/samples/siprtp.c
@@ -58,7 +58,7 @@ struct stream_stat
     pj_uint32_t	    discard, reorder;
     unsigned	    loss_min, loss_avg, loss_max;
     char	   *loss_type;
-    unsigned	    jitter_min, jitter_avg, jitter_max;
+    unsigned	    jitter_min_us, jitter_avg_us, jitter_max_us;
     unsigned	    rtcp_cnt;
 };
 
@@ -253,15 +253,25 @@ static pj_status_t init_sip()
     /* Add UDP transport. */
     {
 	pj_sockaddr_in addr;
+	pjsip_host_port addrname;
 
+	pj_memset(&addr, 0, sizeof(addr));
 	addr.sin_family = PJ_AF_INET;
 	addr.sin_addr.s_addr = 0;
 	addr.sin_port = pj_htons((pj_uint16_t)app.sip_port);
 
-	status = pjsip_udp_transport_start( app.sip_endpt, &addr, NULL, 
+	if (app.local_addr) {
+	    addrname.host = pj_str(app.local_addr);
+	    addrname.port = app.sip_port;
+	}
+
+	status = pjsip_udp_transport_start( app.sip_endpt, &addr, 
+					    (app.local_addr ? &addrname:NULL), 
 					    1, NULL);
-	if (status != PJ_SUCCESS)
+	if (status != PJ_SUCCESS) {
+	    app_perror(THIS_FILE, "Unable to start UDP transport", status);
 	    return status;
+	}
     }
 
     /* 
@@ -365,7 +375,6 @@ static pj_status_t init_media()
 	return -1;
     }
 
-
     /* RTP port counter */
     rtp_port = (pj_uint16_t)(app.rtp_start_port & 0xFFFE);
 
@@ -1123,14 +1132,15 @@ static int media_thread(void *arg)
 		/* Process RTCP stats */
 		unsigned jitter;
 		
-		jitter = pj_ntohl(strm->rem_rtcp.rr.jitter) * 1000 /
-			 strm->clock_rate;
-		if (jitter < strm->tx_stat.jitter_min)
-		    strm->tx_stat.jitter_min = jitter;
-		if (jitter > strm->tx_stat.jitter_max)
-		    strm->tx_stat.jitter_max = jitter;
-		strm->tx_stat.jitter_avg = (strm->tx_stat.jitter_avg * strm->tx_stat.rtcp_cnt +
-					    jitter) / (strm->tx_stat.rtcp_cnt + 1);
+		jitter = (unsigned)(pj_ntohl(strm->rem_rtcp.rr.jitter) * 
+                                    1000000.0 / strm->clock_rate);
+		if (jitter < strm->tx_stat.jitter_min_us)
+		    strm->tx_stat.jitter_min_us = jitter;
+		if (jitter > strm->tx_stat.jitter_max_us)
+		    strm->tx_stat.jitter_max_us = jitter;
+		strm->tx_stat.jitter_avg_us = 
+			(strm->tx_stat.jitter_avg_us * strm->tx_stat.rtcp_cnt +
+			 jitter) / (strm->tx_stat.rtcp_cnt + 1);
 
 		strm->tx_stat.rtcp_cnt++;
 	    }
@@ -1218,21 +1228,21 @@ static int media_thread(void *arg)
 	    {
 		unsigned jitter;
 		
-		jitter = pj_ntohl(rtcp_pkt->rr.jitter) * 1000 /
-			 strm->clock_rate;
-		if (jitter < strm->rx_stat.jitter_min)
-		    strm->rx_stat.jitter_min = jitter;
-		if (jitter > strm->rx_stat.jitter_max)
-		    strm->rx_stat.jitter_max = jitter;
-		strm->rx_stat.jitter_avg = (strm->rx_stat.jitter_avg * strm->rx_stat.rtcp_cnt +
-					    jitter) / (strm->rx_stat.rtcp_cnt + 1);
+		jitter = (unsigned) (pj_ntohl(rtcp_pkt->rr.jitter) * 
+				     1000000.0 / strm->clock_rate);
+		if (jitter < strm->rx_stat.jitter_min_us)
+		    strm->rx_stat.jitter_min_us = jitter;
+		if (jitter > strm->rx_stat.jitter_max_us)
+		    strm->rx_stat.jitter_max_us = jitter;
+		strm->rx_stat.jitter_avg_us = 
+			(strm->rx_stat.jitter_avg_us * strm->rx_stat.rtcp_cnt +
+			 jitter) / (strm->rx_stat.rtcp_cnt + 1);
 
 		strm->rx_stat.rtcp_cnt++;
 	    }
 
 	    next_rtcp.u64 += (freq.u64 * RTCP_INTERVAL);
 	}
-
     }
 
     return 0;
@@ -1246,7 +1256,7 @@ static void call_on_media_update( pjsip_inv_session *inv,
     struct call *call;
     pj_pool_t *pool;
     struct media_stream *audio;
-    pjmedia_sdp_session *local_sdp, *remote_sdp;
+    const pjmedia_sdp_session *local_sdp, *remote_sdp;
     struct codec *codec_desc = NULL;
     unsigned i;
 
@@ -1407,7 +1417,7 @@ static void print_call(int call_index)
 	pj_gettimeofday(&now);
 	PJ_TIME_VAL_SUB(now, call->connect_time);
 
-	sprintf(duration, " [duration: %02d:%02d:%02d.%03d]",
+	sprintf(duration, " [duration: %02ld:%02ld:%02ld.%03ld]",
 		now.sec / 3600,
 		(now.sec % 3600) / 60,
 		(now.sec % 60),
@@ -1443,7 +1453,7 @@ static void print_call(int call_index)
 	if (call->response_time.sec) {
 	    t = call->response_time;
 	    PJ_TIME_VAL_SUB(t, call->start_time);
-	    sprintf(pdd, "got 1st response in %d ms", PJ_TIME_VAL_MSEC(t));
+	    sprintf(pdd, "got 1st response in %ld ms", PJ_TIME_VAL_MSEC(t));
 	} else {
 	    pdd[0] = '\0';
 	}
@@ -1451,7 +1461,8 @@ static void print_call(int call_index)
 	if (call->connect_time.sec) {
 	    t = call->connect_time;
 	    PJ_TIME_VAL_SUB(t, call->start_time);
-	    sprintf(connectdelay, ", connected after: %d ms", PJ_TIME_VAL_MSEC(t));
+	    sprintf(connectdelay, ", connected after: %ld ms", 
+		    PJ_TIME_VAL_MSEC(t));
 	} else {
 	    connectdelay[0] = '\0';
 	}
@@ -1464,13 +1475,13 @@ static void print_call(int call_index)
 	return;
     }
 
-    printf("   Stream #0: audio %.*s@%dHz, %dms/frame, %sbps (%sbps +IP hdr)\n",
-	   (int)audio->si.fmt.encoding_name.slen,
-	   audio->si.fmt.encoding_name.ptr,
-	   audio->clock_rate,
-	   audio->samples_per_frame * 1000 / audio->clock_rate,
-	   good_number(bps, audio->bytes_per_frame * audio->clock_rate / audio->samples_per_frame),
-	   good_number(ipbps, (audio->bytes_per_frame+32) * audio->clock_rate / audio->samples_per_frame));
+    printf("   Stream #0: audio %.*s@%dHz, %dms/frame, %sB/s (%sB/s +IP hdr)\n",
+   	(int)audio->si.fmt.encoding_name.slen,
+	audio->si.fmt.encoding_name.ptr,
+	audio->clock_rate,
+	audio->samples_per_frame * 1000 / audio->clock_rate,
+	good_number(bps, audio->bytes_per_frame * audio->clock_rate / audio->samples_per_frame),
+	good_number(ipbps, (audio->bytes_per_frame+32) * audio->clock_rate / audio->samples_per_frame));
 
     total_loss = (audio->rtcp.rtcp_pkt.rr.total_lost_2 << 16) +
 	         (audio->rtcp.rtcp_pkt.rr.total_lost_1 << 8) +
@@ -1478,8 +1489,8 @@ static void print_call(int call_index)
 
     printf("              RX total %s packets %sB received (%sB +IP hdr)%s\n"
 	   "                 pkt discards=%d (%3.1f%%), loss=%d (%3.1f%%), reorder=%d (%3.1f%%)%s\n"
-	   "                 loss period min=%d ms, avg=%d ms, max=%d ms%s\n"
-	   "                 jitter min=%d ms, avg=%d ms, max=%d ms, current=%d ms%s\n",
+	   "                 loss period min=%dms, avg=%dms, max=%dms%s\n"
+	   "                 jitter min=%5.3fms, avg=%5.3fms, max=%5.3fms, curr=%5.3f ms%s\n",
 	   good_number(packets, audio->rx_stat.pkt),
 	   good_number(bytes, audio->rx_stat.payload),
 	   good_number(ipbytes, audio->rx_stat.payload + audio->rx_stat.pkt * 32),
@@ -1492,10 +1503,10 @@ static void print_call(int call_index)
 	   "",
 	   -1, -1, -1, 
 	   "",
-	   (audio->rx_stat.rtcp_cnt ? audio->rx_stat.jitter_min : -1), 
-	   (audio->rx_stat.rtcp_cnt ? audio->rx_stat.jitter_avg : -1),
-	   (audio->rx_stat.rtcp_cnt ? audio->rx_stat.jitter_max : -1),
-	   (audio->rx_stat.rtcp_cnt ? pj_ntohl(audio->rtcp.rtcp_pkt.rr.jitter)*1000/audio->clock_rate : -1),
+	   (audio->rx_stat.rtcp_cnt? audio->rx_stat.jitter_min_us/1000.0 : -1.),
+	   (audio->rx_stat.rtcp_cnt? audio->rx_stat.jitter_avg_us/1000.0 : -1.),
+	   (audio->rx_stat.rtcp_cnt? audio->rx_stat.jitter_max_us/1000.0 : -1.),
+	   (audio->rx_stat.rtcp_cnt? pj_ntohl(audio->rtcp.rtcp_pkt.rr.jitter)*1000.0/audio->clock_rate : -1.),
 	   ""
 	   );
 
@@ -1506,8 +1517,8 @@ static void print_call(int call_index)
 
     printf("              TX total %s packets %sB sent (%sB +IP hdr)%s\n"
 	   "                 pkt discards=%d (%3.1f%%), loss=%d (%3.1f%%), reorder=%d (%3.1f%%)%s\n"
-	   "                 loss period min=%d ms, avg=%d ms, max=%d ms%s\n"
-	   "                 jitter min=%d ms, avg=%d ms, max=%d ms, current=%d ms%s\n",
+	   "                 loss period min=%dms, avg=%dms, max=%dms%s\n"
+	   "                 jitter min=%5.3fms, avg=%5.3fms, max=%5.3fms, curr=%5.3f ms%s\n",
 	   good_number(packets, audio->tx_stat.pkt),
 	   good_number(bytes, audio->tx_stat.payload),
 	   good_number(ipbytes, audio->tx_stat.payload + audio->tx_stat.pkt * 32),
@@ -1520,14 +1531,15 @@ static void print_call(int call_index)
 	   "",
 	   -1, -1, -1, 
 	   "",
-	   (audio->tx_stat.rtcp_cnt ? audio->tx_stat.jitter_min : -1), 
-	   (audio->tx_stat.rtcp_cnt ? audio->tx_stat.jitter_avg : -1),
-	   (audio->tx_stat.rtcp_cnt ? audio->tx_stat.jitter_max : -1),
-	   (audio->tx_stat.rtcp_cnt ? pj_ntohl(audio->rem_rtcp.rr.jitter)*1000/audio->clock_rate : -1),
+	   (audio->tx_stat.rtcp_cnt? audio->tx_stat.jitter_min_us/1000.0 : -1.),
+	   (audio->tx_stat.rtcp_cnt? audio->tx_stat.jitter_avg_us/1000.0 : -1.),
+	   (audio->tx_stat.rtcp_cnt? audio->tx_stat.jitter_max_us/1000.0 : -1.),
+	   (audio->tx_stat.rtcp_cnt? pj_ntohl(audio->rem_rtcp.rr.jitter)*1000.0/audio->clock_rate : -1.),
 	   ""
 	   );
 
-    printf("              End to end delay: %u ms\n", audio->rtcp.ee_delay);
+    printf("              End to end delay: %5.3f ms\n", 
+	   audio->rtcp.rtt_us / 1000.0);
 
 }