FS-11446: [freeswitch-core] Improve video JB scaling and fix misreported rtp stats #resolve

This commit is contained in:
Anthony Minessale 2018-10-09 20:15:50 +00:00 committed by Andrey Volk
parent e06ed5ad19
commit 878565e4b3
2 changed files with 72 additions and 69 deletions

View File

@ -34,7 +34,6 @@
#define NACK_TIME 80000
#define RENACK_TIME 100000
#define PERIOD_LEN 250
#define MAX_FRAME_PADDING 2
#define MAX_MISSING_SEQ 20
#define jb_debug(_jb, _level, _format, ...) if (_jb->debug_level >= _level) switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(_jb->session), SWITCH_LOG_ALERT, "JB:%p:%s:%d/%d lv:%d ln:%.4d sz:%.3u/%.3u/%.3u/%.3u c:%.3u %.3u/%.3u/%.3u/%.3u %.2f%% ->" _format, (void *) _jb, (jb->type == SJB_TEXT ? "txt" : (jb->type == SJB_AUDIO ? "aud" : "vid")), _jb->allocated_nodes, _jb->visible_nodes, _level, __LINE__, _jb->min_frame_len, _jb->max_frame_len, _jb->frame_len, _jb->complete_frames, _jb->period_count, _jb->consec_good_count, _jb->period_good_count, _jb->consec_miss_count, _jb->period_miss_count, _jb->period_miss_pct, __VA_ARGS__)
@ -107,6 +106,7 @@ struct switch_jb_s {
uint32_t flush;
uint32_t packet_count;
uint32_t max_packet_len;
uint32_t period_len;
};
@ -516,7 +516,8 @@ static void jb_frame_inc_line(switch_jb_t *jb, int i, int line)
}
if (old_frame_len != jb->frame_len) {
jb_debug(jb, 2, "%d Change framelen from %u to %u\n", line, old_frame_len, jb->frame_len);
jb_debug(jb, 1, "%d Change framelen from %u to %u\n", line, old_frame_len, jb->frame_len);
//if (jb->session) {
// switch_core_session_request_video_refresh(jb->session);
//}
@ -641,7 +642,7 @@ static inline void add_node(switch_jb_t *jb, switch_rtp_packet_t *packet, switch
switch_core_inthash_insert(jb->node_hash_ts, node->packet.header.ts, node);
}
jb_debug(jb, (packet->header.m ? 1 : 2), "PUT packet last_ts:%u ts:%u seq:%u%s\n",
jb_debug(jb, (packet->header.m ? 2 : 3), "PUT packet last_ts:%u ts:%u seq:%u%s\n",
ntohl(jb->highest_wrote_ts), ntohl(node->packet.header.ts), ntohs(node->packet.header.seq), packet->header.m ? " <MARK>" : "");
if (jb->write_init && jb->type == SJB_VIDEO) {
@ -773,11 +774,6 @@ static inline switch_status_t jb_next_packet_by_seq(switch_jb_t *jb, switch_jb_n
if (jb->type == SJB_VIDEO) {
int x;
if (jb->period_miss_count > 1 && !jb->period_miss_inc) {
jb->period_miss_inc++;
jb_frame_inc(jb, 1);
}
if (jb->session) {
switch_core_session_request_video_refresh(jb->session);
}
@ -792,6 +788,13 @@ static inline switch_status_t jb_next_packet_by_seq(switch_jb_t *jb, switch_jb_n
jb->dropped++;
drop_ts(jb, node->packet.header.ts);
jb->highest_dropped_ts = ntohl(node->packet.header.ts);
if (jb->period_miss_count > 2 && jb->period_miss_inc < 1) {
jb->period_miss_inc++;
jb_frame_inc(jb, 1);
}
node = NULL;
goto top;
}
@ -1070,7 +1073,11 @@ SWITCH_DECLARE(switch_status_t) switch_jb_create(switch_jb_t **jbp, switch_jb_ty
if (jb->type == SJB_VIDEO) {
switch_core_inthash_init(&jb->missing_seq_hash);
jb->period_len = 2500;
} else {
jb->period_len = 250;
}
switch_core_inthash_init(&jb->node_hash);
switch_mutex_init(&jb->mutex, SWITCH_MUTEX_NESTED, pool);
switch_mutex_init(&jb->list_mutex, SWITCH_MUTEX_NESTED, pool);
@ -1228,7 +1235,7 @@ SWITCH_DECLARE(switch_status_t) switch_jb_put_packet(switch_jb_t *jb, switch_rtp
switch_jb_reset(jb);
} else {
if (jb->frame_len < got - want) {
if (jb->type != SJB_VIDEO && jb->frame_len < got - want) {
jb_frame_inc(jb, 1);
}
@ -1312,9 +1319,9 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp
jb_debug(jb, 2, "GET PACKET %u/%u n:%d\n", jb->complete_frames , jb->frame_len, jb->visible_nodes);
if (++jb->period_count >= PERIOD_LEN) {
if (++jb->period_count >= jb->period_len) {
if (jb->consec_good_count >= (PERIOD_LEN - 5)) {
if (jb->consec_good_count >= (jb->period_len - 5)) {
jb_frame_inc(jb, -1);
}
@ -1429,7 +1436,7 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp
packet->header.version = 2;
hide_node(node, SWITCH_TRUE);
jb_debug(jb, 1, "GET packet ts:%u seq:%u %s\n", ntohl(packet->header.ts), ntohs(packet->header.seq), packet->header.m ? " <MARK>" : "");
jb_debug(jb, 2, "GET packet ts:%u seq:%u %s\n", ntohl(packet->header.ts), ntohs(packet->header.seq), packet->header.m ? " <MARK>" : "");
} else {
status = SWITCH_STATUS_MORE_DATA;

View File

@ -1550,58 +1550,54 @@ static uint8_t get_next_write_ts(switch_rtp_t *rtp_session, uint32_t timestamp)
return m;
}
static void do_mos(switch_rtp_t *rtp_session, int force) {
static void do_mos(switch_rtp_t *rtp_session) {
int R;
if ((switch_size_t)rtp_session->stats.inbound.recved < rtp_session->stats.inbound.flaws) {
rtp_session->stats.inbound.flaws = 0;
}
if (rtp_session->stats.inbound.recved > 0 &&
rtp_session->stats.inbound.flaws && (force || rtp_session->stats.inbound.last_flaw != rtp_session->stats.inbound.flaws)) {
int R;
rtp_session->stats.inbound.flaws && (rtp_session->stats.inbound.last_flaw != rtp_session->stats.inbound.flaws)) {
if (rtp_session->consecutive_flaws++) {
int diff, penalty;
int penalty = rtp_session->consecutive_flaws;
diff = (rtp_session->stats.inbound.flaws - rtp_session->stats.inbound.last_flaw);
if (diff < 1) diff = 1;
penalty = diff * 2;
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG3, "%s %s %d consecutive flaws, adding %d flaw penalty\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s %s %d consecutive flaws, adding %d flaw penalty\n",
rtp_session_name(rtp_session), rtp_type(rtp_session),
rtp_session->consecutive_flaws, penalty);
rtp_session->bad_stream++;
rtp_session->stats.inbound.flaws += penalty;
rtp_session->stats.inbound.last_flaw = rtp_session->stats.inbound.flaws;
if (rtp_session->stats.inbound.error_log) {
rtp_session->stats.inbound.error_log->flaws += penalty;
rtp_session->stats.inbound.error_log->consecutive_flaws++;
}
}
R = (int)((double)((double)(rtp_session->stats.inbound.recved - rtp_session->stats.inbound.flaws) / (double)rtp_session->stats.inbound.recved) * 100.0);
if (R < 0 || R > 100) R = 100;
rtp_session->stats.inbound.R = R;
rtp_session->stats.inbound.mos = 1 + (0.035) * R + (.000007) * R * (R-60) * (100-R);
rtp_session->stats.inbound.last_flaw = rtp_session->stats.inbound.flaws;
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG3, "%s %s stat %0.2f %ld/%d flaws: %ld mos: %0.2f v: %0.2f %0.2f/%0.2f\n",
rtp_session_name(rtp_session),
rtp_type(rtp_session),
rtp_session->stats.inbound.R,
(long int)(rtp_session->stats.inbound.recved - rtp_session->stats.inbound.flaws), rtp_session->stats.inbound.recved,
(long int)rtp_session->stats.inbound.flaws,
rtp_session->stats.inbound.mos,
rtp_session->stats.inbound.variance,
rtp_session->stats.inbound.min_variance,
rtp_session->stats.inbound.max_variance
);
} else {
rtp_session->consecutive_flaws = 0;
}
R = (int)((double)((double)(rtp_session->stats.inbound.recved - rtp_session->stats.inbound.flaws) / (double)rtp_session->stats.inbound.recved) * 100.0);
if (R < 0 || R > 100) R = 100;
rtp_session->stats.inbound.R = R;
rtp_session->stats.inbound.mos = 1 + (0.035) * R + (.000007) * R * (R-60) * (100-R);
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG3, "%s %s stat %0.2f %ld/%d flaws: %ld mos: %0.2f v: %0.2f %0.2f/%0.2f\n",
rtp_session_name(rtp_session),
rtp_type(rtp_session),
rtp_session->stats.inbound.R,
(long int)(rtp_session->stats.inbound.recved - rtp_session->stats.inbound.flaws), rtp_session->stats.inbound.recved,
(long int)rtp_session->stats.inbound.flaws,
rtp_session->stats.inbound.mos,
rtp_session->stats.inbound.variance,
rtp_session->stats.inbound.min_variance,
rtp_session->stats.inbound.max_variance
);
}
void burstr_calculate ( int loss[], int received, double *burstr, double *lossr )
@ -1699,9 +1695,9 @@ static void check_jitter(switch_rtp_t *rtp_session)
rtp_session->next_stat_check_time = current_time + 5000;
burstr_calculate(rtp_session->stats.inbound.loss, rtp_session->stats.inbound.recved,
&(rtp_session->stats.inbound.burstrate), &(rtp_session->stats.inbound.lossrate));
do_mos(rtp_session, SWITCH_TRUE);
do_mos(rtp_session);
} else {
do_mos(rtp_session, SWITCH_FALSE);
do_mos(rtp_session);
}
if (rtp_session->stats.inbound.last_loss || rtp_session->bad_stream) {
@ -2226,7 +2222,7 @@ static int check_rtcp_and_ice(switch_rtp_t *rtp_session)
nack = (uint32_t *) p;
*nack = cur_nack[n];
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "Sending RTCP NACK %u [%d]\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "Sending RTCP NACK %u [%d]\n",
ntohs(*nack & 0xFFFF), rtp_session->rtcp_vstats.video_in.nack_count);
rtcp_bytes += sizeof(switch_rtcp_ext_hdr_t) + sizeof(cur_nack[n]);
@ -2269,7 +2265,7 @@ static int check_rtcp_and_ice(switch_rtp_t *rtp_session)
fir->r1 = fir->r2 = fir->r3 = 0;
rtp_session->rtcp_vstats.video_in.fir_count++;
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "Sending RTCP FIR SEQ %d [%u]\n", rtp_session->fir_seq, rtp_session->rtcp_vstats.video_in.fir_count);
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "Sending RTCP FIR SEQ %d [%u]\n", rtp_session->fir_seq, rtp_session->rtcp_vstats.video_in.fir_count);
rtp_session->fir_seq++;
@ -2299,12 +2295,12 @@ static int check_rtcp_and_ice(switch_rtp_t *rtp_session)
ext_hdr->recv_ssrc = 0;
if (rtp_session->tmmbr) {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "Sending RTCP TMMBR %u\n", rtp_session->tmmbr);
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "Sending RTCP TMMBR %u\n", rtp_session->tmmbr);
ext_hdr->fmt = _RTCP_RTPFB_TMMBR;
bps = rtp_session->tmmbr;
rtp_session->tmmbr = 0;
} else {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "Sending RTCP TMMBN %u\n", rtp_session->tmmbr);
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "Sending RTCP TMMBN %u\n", rtp_session->tmmbr);
ext_hdr->fmt = _RTCP_RTPFB_TMMBN;
bps = rtp_session->tmmbn;
rtp_session->tmmbn = 0;
@ -2762,10 +2758,10 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_set_local_address(switch_rtp_t *rtp_s
goto done;
}
//if (rtp_session->flags[SWITCH_RTP_FLAG_VIDEO]) {
//switch_socket_opt_set(new_sock, SWITCH_SO_RCVBUF, 1572864);
//switch_socket_opt_set(new_sock, SWITCH_SO_SNDBUF, 1572864);
//}
if (rtp_session->flags[SWITCH_RTP_FLAG_VIDEO]) {
switch_socket_opt_set(new_sock, SWITCH_SO_RCVBUF, 1572864);
switch_socket_opt_set(new_sock, SWITCH_SO_SNDBUF, 1572864);
}
if (switch_socket_bind(new_sock, rtp_session->local_addr) != SWITCH_STATUS_SUCCESS) {
char *em = switch_core_sprintf(rtp_session->pool, "Bind Error! %s:%d", host, port);
@ -5014,7 +5010,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_sync_stats(switch_rtp_t *rtp_session)
switch_channel_set_variable_printf(channel, "vad_total_talk_time_sec", "%u", (uint32_t)rtp_session->vad_data.total_talk_time / 1000000);
}
do_mos(rtp_session, SWITCH_TRUE);
do_mos(rtp_session);
if (rtp_session->stats.inbound.error_log && !rtp_session->stats.inbound.error_log->stop) {
rtp_session->stats.inbound.error_log->stop = switch_micro_time_now();
@ -6453,7 +6449,7 @@ static void handle_nack(switch_rtp_t *rtp_session, uint32_t nack)
my_host = switch_get_addr(bufc, sizeof(bufc), rtp_session->local_addr);
}
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s Got NACK [%u][0x%x] for seq %u\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "%s Got NACK [%u][0x%x] for seq %u\n",
switch_core_session_get_name(rtp_session->session), nack, nack, ntohs(seq));
if (switch_jb_get_packet_by_seq(rtp_session->vbw, seq, (switch_rtp_packet_t *) send_msg, &bytes) == SWITCH_STATUS_SUCCESS) {
@ -6469,16 +6465,16 @@ static void handle_nack(switch_rtp_t *rtp_session, uint32_t nack)
send_msg->header.pt, ntohl(send_msg->header.ts), ntohs(send_msg->header.seq), send_msg->header.m);
}
//switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG1, "RE----SEND %u\n", ntohs(send_msg->header.seq));
//switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG2, "RE----SEND %u\n", ntohs(send_msg->header.seq));
switch_rtp_write_raw(rtp_session, (void *) send_msg, &bytes, SWITCH_FALSE);
} else {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "Cannot send NACK for seq %u\n", ntohs(seq));
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "Cannot send NACK for seq %u\n", ntohs(seq));
}
blp = ntohs(blp);
for (i = 0; i < 16; i++) {
if (blp & (1 << i)) {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s Also Got NACK for seq %u\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "%s Also Got NACK for seq %u\n",
switch_core_session_get_name(rtp_session->session), ntohs(seq) + i + 1);
/* If they are missing more than one, may as well gen a key frame for good measure */
//switch_core_media_gen_key_frame(rtp_session->session);
@ -6498,7 +6494,7 @@ static void handle_nack(switch_rtp_t *rtp_session, uint32_t nack)
switch_rtp_write_raw(rtp_session, (void *) &send_msg, &bytes, SWITCH_FALSE);
} else {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "Cannot send NACK for seq %u\n", ntohs(seq) + i);
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "Cannot send NACK for seq %u\n", ntohs(seq) + i);
}
}
}
@ -6516,7 +6512,7 @@ static switch_status_t process_rtcp_report(switch_rtp_t *rtp_session, rtcp_msg_t
rtcp_ext_msg_t *extp = (rtcp_ext_msg_t *) msg;
if (extp->header.fmt != 15) { // <---- REMOVE WHEN BRIA STOPS SENDING UNSOLICITED REMB
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s PICKED UP %s XRTCP type: %d fmt: %d\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "%s PICKED UP %s XRTCP type: %d fmt: %d\n",
switch_core_session_get_name(rtp_session->session), rtp_type(rtp_session), msg->header.type, extp->header.fmt);
}
@ -6534,14 +6530,14 @@ static switch_status_t process_rtcp_report(switch_rtp_t *rtp_session, rtcp_msg_t
#endif
if (switch_core_session_media_flow(rtp_session->session, SWITCH_MEDIA_TYPE_VIDEO) == SWITCH_MEDIA_FLOW_RECVONLY) {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s Ignoring FIR/PLI from a sendonly stream.\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "%s Ignoring FIR/PLI from a sendonly stream.\n",
switch_core_session_get_name(rtp_session->session));
} else {
switch_core_media_gen_key_frame(rtp_session->session);
if (rtp_session->vbw) {
switch_jb_reset(rtp_session->vbw);
}
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s Got FIR/PLI\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "%s Got FIR/PLI\n",
switch_core_session_get_name(rtp_session->session));
switch_channel_set_flag(switch_core_session_get_channel(rtp_session->session), CF_VIDEO_REFRESH_REQ);
}
@ -6551,7 +6547,7 @@ static switch_status_t process_rtcp_report(switch_rtp_t *rtp_session, rtcp_msg_t
uint32_t *nack = (uint32_t *) extp->body;
int i;
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s Got NACK count %d\n",
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, "%s Got NACK count %d\n",
switch_core_session_get_name(rtp_session->session), ntohs(extp->header.length) - 2);
@ -6586,8 +6582,8 @@ static switch_status_t process_rtcp_report(switch_rtp_t *rtp_session, rtcp_msg_t
if (msg->header.type == _RTCP_PT_SR) { /* Sender report */
struct switch_rtcp_sender_report* sr = (struct switch_rtcp_sender_report*)msg->body;
rtp_session->stats.rtcp.packet_count += ntohl(sr->sender_info.pc);
rtp_session->stats.rtcp.octet_count += ntohl(sr->sender_info.oc);
rtp_session->stats.rtcp.packet_count = ntohl(sr->sender_info.pc);
rtp_session->stats.rtcp.octet_count = ntohl(sr->sender_info.oc);
packet_ssrc = sr->ssrc;
/* Extracting LSR from NTP timestamp and save it */
lsr = (ntohl(sr->sender_info.ntp_lsw)&0xffff0000)>>16 | (ntohl(sr->sender_info.ntp_msw)&0x0000ffff)<<16; /* The middle 32 bits out of 64 in the NTP timestamp */
@ -7753,7 +7749,7 @@ static int rtp_common_read(switch_rtp_t *rtp_session, switch_payload_t *payload_
rtp_session->stats.inbound.error_log->flaws++;
}
rtp_session->stats.inbound.flaws++;
do_mos(rtp_session, SWITCH_FALSE);
do_mos(rtp_session);
}
rtp_session->cng_count++;
@ -8958,7 +8954,7 @@ SWITCH_DECLARE(switch_rtp_stats_t *) switch_rtp_get_stats(switch_rtp_t *rtp_sess
switch_jb_get_frames(rtp_session->jb, NULL, NULL, NULL, (uint32_t *)&s->inbound.largest_jb_size);
}
do_mos(rtp_session, SWITCH_FALSE);
do_mos(rtp_session);
switch_mutex_unlock(rtp_session->flag_mutex);