diff --git a/src/include/private/switch_core_pvt.h b/src/include/private/switch_core_pvt.h index fafaae3cba..321d4ab4ee 100644 --- a/src/include/private/switch_core_pvt.h +++ b/src/include/private/switch_core_pvt.h @@ -170,6 +170,8 @@ struct switch_core_session { switch_buffer_t *text_line_buffer; switch_mutex_t *text_mutex; const char *external_id; + + packet_stats_t stats; }; struct switch_media_bug { diff --git a/src/include/switch_core.h b/src/include/switch_core.h index ff04fa0954..5c508059e4 100644 --- a/src/include/switch_core.h +++ b/src/include/switch_core.h @@ -90,6 +90,30 @@ typedef struct device_uuid_node_s { struct device_uuid_node_s *next; } switch_device_node_t; +typedef struct packet_stats_io_info { + const char* in_callid; + char* in_codec; + uint32_t in_ssrc; + switch_sockaddr_t *in_remote_addr; + switch_sockaddr_t *in_local_addr; + const char* out_callid; + char* out_codec; + uint32_t out_ssrc; + switch_sockaddr_t *out_remote_addr; + switch_sockaddr_t *out_local_addr; + uint32_t count; // count of packets going out +} packet_stats_io_info_t; + +typedef struct packet_stats { + int max; + float average; + uint32_t in_count; + uint32_t in_plc; + uint32_t count; + packet_stats_io_info_t io_info; + switch_bool_t reported; +} packet_stats_t; + typedef struct switch_device_stats_s { uint32_t total; uint32_t total_in; @@ -255,6 +279,10 @@ static inline void *switch_must_realloc(void *_b, size_t _z) ///\{ +SWITCH_DECLARE(void) switch_core_session_increment_read(switch_core_session_t *session); +SWITCH_DECLARE(void) switch_core_session_increment_plc(switch_core_session_t *session); +SWITCH_DECLARE(void) packet_stats_print(switch_core_session_t *session); +SWITCH_DECLARE(void) switch_core_session_set_io_stats(switch_core_session_t *session, packet_stats_io_info_t *packet_stats_io_info); SWITCH_DECLARE(void) switch_core_screen_size(int *x, int *y); SWITCH_DECLARE(void) switch_core_session_sched_heartbeat(switch_core_session_t *session, uint32_t seconds); SWITCH_DECLARE(void) switch_core_session_unsched_heartbeat(switch_core_session_t *session); diff --git a/src/include/switch_frame.h b/src/include/switch_frame.h index 15c02f7839..696f5b1733 100644 --- a/src/include/switch_frame.h +++ b/src/include/switch_frame.h @@ -87,6 +87,7 @@ typedef struct switch_frame_geometry { payload_map_t *pmap; switch_image_t *img; struct switch_frame_geometry geometry; + switch_time_t received_ts; }; SWITCH_END_EXTERN_C diff --git a/src/include/switch_rtp.h b/src/include/switch_rtp.h index 7986bdb622..10aa7f97bf 100644 --- a/src/include/switch_rtp.h +++ b/src/include/switch_rtp.h @@ -57,6 +57,7 @@ typedef struct { char body[SWITCH_RTP_MAX_BUF_LEN+4+sizeof(char *)]; switch_rtp_hdr_ext_t *ext; char *ebody; + switch_time_t received_ts; } switch_rtp_packet_t; typedef enum { diff --git a/src/mod/languages/mod_lua/mod_lua_wrap.cpp b/src/mod/languages/mod_lua/mod_lua_wrap.cpp index e40b50a348..39279fce04 100644 --- a/src/mod/languages/mod_lua/mod_lua_wrap.cpp +++ b/src/mod/languages/mod_lua/mod_lua_wrap.cpp @@ -10744,6 +10744,9 @@ SWIG_PropagateClientData(void) { if (equiv->type && !equiv->type->clientdata) SWIG_TypeClientData(equiv->type, swig_module.types[i]->clientdata); } + if (equiv == equiv->next) { + break; + } equiv = equiv->next; } } diff --git a/src/switch_core_media.c b/src/switch_core_media.c index de5d0eff74..69dc80b2fa 100644 --- a/src/switch_core_media.c +++ b/src/switch_core_media.c @@ -35,6 +35,7 @@ #include #include #include "private/switch_core_pvt.h" +#include #include #include #include @@ -274,6 +275,71 @@ struct switch_media_handle_s { }; +void packet_stats_init(packet_stats_t *stats, int latency, int count) { + stats->max = latency; + stats->average = latency; + stats->count = count; +} +#define _VOR1(v) ((v)?(v):1) +void packet_stats_update(packet_stats_t *stats, int latency) +{ + if (stats->count >= UINT32_MAX) + return; + stats->count++; + + if (stats->count == 1) + packet_stats_init(stats, latency, 1); + if (stats->max < latency) + stats->max = latency; + + if (stats->count > 1) { + float delta; + delta = latency - stats->average; + stats->average += delta/_VOR1(stats->count); + } +} + +void packet_stats_print(switch_core_session_t *session) { + if (session->stats.io_info.in_remote_addr && session->stats.io_info.out_local_addr + && !session->stats.reported) { + char in_ipbuf[48]; + char in_l_ipbuf[48]; + char out_ipbuf[48]; + char out_l_ipbuf[48]; + const char *v=NULL; + + switch_channel_set_variable_printf(session->channel, "packet_stats_report", + "{" + "\"in\" : { \"ssrc\": \"0x%08X\", \"remote_socket\": \"%s:%u\", \"local_socket\": \"%s:%u\"" + ", \"codec\": \"%s\", \"count\": %u, \"plc\": %u}" + "," + "\"out\" : { \"ssrc\": \"0x%08X\", \"remote_socket\": \"%s:%u\", \"local_socket\": \"%s:%u\"" + ", \"codec\": \"%s\", \"count\": %u, \"max\": %d, \"avg\": %.2f }}", + session->stats.io_info.in_ssrc, + switch_get_addr(in_ipbuf, sizeof(in_ipbuf), session->stats.io_info.in_remote_addr), + session->stats.io_info.in_remote_addr->port, + switch_get_addr(in_l_ipbuf, sizeof(in_ipbuf), session->stats.io_info.in_local_addr), + session->stats.io_info.in_local_addr->port, + session->stats.io_info.in_codec, + session->stats.in_count, + session->stats.in_plc, + session->stats.io_info.out_ssrc, + switch_get_addr(out_ipbuf, sizeof(out_ipbuf), session->stats.io_info.out_remote_addr), + session->stats.io_info.out_local_addr->port, + switch_get_addr(out_l_ipbuf, sizeof(out_ipbuf), session->stats.io_info.out_local_addr), + session->stats.io_info.out_remote_addr->port, + session->stats.io_info.out_codec, + session->stats.count, + session->stats.max, + session->stats.average + ); + v = switch_channel_get_variable_dup(session->channel,"packet_stats_report", SWITCH_FALSE, -1); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "[packet_stats_report] %s\n", v); + session->stats.reported = true; + + } +} + switch_srtp_crypto_suite_t SUITES[CRYPTO_INVALID] = { { "AEAD_AES_256_GCM_8", "", AEAD_AES_256_GCM_8, 44, 12}, { "AEAD_AES_256_GCM", "", AEAD_AES_256_GCM, 44, 12}, @@ -15800,7 +15866,6 @@ SWITCH_DECLARE(switch_msrp_session_t *) switch_core_media_get_msrp_session(switc return session->media_handle->msrp_session; } - SWITCH_DECLARE(switch_status_t) switch_core_session_write_frame(switch_core_session_t *session, switch_frame_t *frame, switch_io_flag_t flags, int stream_id) { @@ -16159,6 +16224,7 @@ SWITCH_DECLARE(switch_status_t) switch_core_session_write_frame(switch_core_sess goto done; } + write_frame->received_ts = frame->received_ts; if (session->write_codec) { if (!ptime_mismatch && write_frame->codec && write_frame->codec->implementation && write_frame->codec->implementation->decoded_bytes_per_packet == session->write_impl.decoded_bytes_per_packet) { @@ -16434,6 +16500,16 @@ SWITCH_DECLARE(switch_status_t) switch_core_session_write_frame(switch_core_sess } error: + if (frame->received_ts > 0) { + int64_t d = (switch_micro_time_now() - frame->received_ts)/1000; + if (d > 2000) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "excessive delay[%ld]-[%ld]=[%ldms] seq[%u]ssrc[0x%08X]\n", + (int64_t)(switch_micro_time_now()/1000), (int64_t)(frame->received_ts/1000), d, ntohs(frame->seq), frame->ssrc); + } + packet_stats_update(&session->stats, d); + } + session->stats.io_info.out_codec = write_frame->codec->implementation->iananame; + session->stats.io_info.in_codec = frame->codec->implementation->iananame; switch_mutex_unlock(session->write_codec->mutex); switch_mutex_unlock(frame->codec->mutex); diff --git a/src/switch_core_session.c b/src/switch_core_session.c index 94944faa2f..05b6121a99 100644 --- a/src/switch_core_session.c +++ b/src/switch_core_session.c @@ -36,11 +36,43 @@ #include "switch.h" #include "switch_core.h" #include "private/switch_core_pvt.h" +#include #define DEBUG_THREAD_POOL struct switch_session_manager session_manager; +SWITCH_DECLARE(void) switch_core_session_increment_plc(switch_core_session_t *session) +{ + session->stats.in_plc++; +} + +SWITCH_DECLARE(void) switch_core_session_increment_read(switch_core_session_t *session) +{ + session->stats.in_count++; +} + +SWITCH_DECLARE(void) switch_core_session_set_io_stats(switch_core_session_t *session, packet_stats_io_info_t *packet_stats_io_info) +{ + if ((session->stats.io_info.out_ssrc != 0 && session->stats.io_info.out_ssrc != packet_stats_io_info->out_ssrc) + || (session->stats.io_info.in_ssrc != 0 && session->stats.io_info.in_ssrc != packet_stats_io_info->in_ssrc)) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "SSRC change[%u][%u] [%u][%u]\n", + session->stats.io_info.out_ssrc, packet_stats_io_info->out_ssrc, + session->stats.io_info.in_ssrc, packet_stats_io_info->in_ssrc + ); + packet_stats_print(session); + memset(&session->stats, '\0', sizeof(packet_stats_t)); + } + session->stats.io_info.out_remote_addr = packet_stats_io_info->out_remote_addr; + session->stats.io_info.out_local_addr = packet_stats_io_info->out_local_addr; + session->stats.io_info.out_ssrc = packet_stats_io_info->out_ssrc; + session->stats.io_info.out_callid = packet_stats_io_info->out_callid; + session->stats.io_info.in_remote_addr = packet_stats_io_info->in_remote_addr; + session->stats.io_info.in_local_addr = packet_stats_io_info->in_local_addr; + session->stats.io_info.in_ssrc = packet_stats_io_info->in_ssrc; + session->stats.io_info.in_callid = packet_stats_io_info->in_callid; +} + SWITCH_DECLARE(void) switch_core_session_set_dmachine(switch_core_session_t *session, switch_ivr_dmachine_t *dmachine, switch_digit_action_target_t target) { int i = (int) target; @@ -1497,6 +1529,7 @@ SWITCH_DECLARE(void) switch_core_session_signal_state_change(switch_core_session } } } + packet_stats_print(session); switch_core_session_kill_channel(session, SWITCH_SIG_BREAK); } diff --git a/src/switch_ivr_bridge.c b/src/switch_ivr_bridge.c index 527058f70c..62f59126a3 100644 --- a/src/switch_ivr_bridge.c +++ b/src/switch_ivr_bridge.c @@ -814,6 +814,14 @@ static void *audio_bridge_thread(switch_thread_t *thread, void *obj) continue; } + if (switch_test_flag((read_frame), SFF_PLC)) { + read_frame->received_ts = 0; + switch_core_session_increment_plc(session_b); + } else { + if (read_frame->packetlen > 0) + switch_core_session_increment_read(session_b); + } + if (status != SWITCH_STATUS_BREAK && !switch_channel_test_flag(chan_a, CF_HOLD) && !switch_channel_test_flag(chan_b, CF_LEG_HOLDING)) { if (switch_core_session_write_frame(session_b, read_frame, SWITCH_IO_FLAG_NONE, stream_id) != SWITCH_STATUS_SUCCESS) { switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session_a), SWITCH_LOG_DEBUG, diff --git a/src/switch_jitterbuffer.c b/src/switch_jitterbuffer.c index 655fa022c2..52c8251c50 100644 --- a/src/switch_jitterbuffer.c +++ b/src/switch_jitterbuffer.c @@ -60,6 +60,7 @@ typedef struct switch_jb_node_s { typedef struct switch_jb_stats_s { uint32_t reset_too_big; + uint32_t reset_too_expanded; uint32_t reset_missing_frames; uint32_t reset_ts_jump; uint32_t reset_error; @@ -67,8 +68,13 @@ typedef struct switch_jb_stats_s { uint32_t size_max; uint32_t size_est; uint32_t acceleration; + uint32_t fast_acceleration; + uint32_t forced_acceleration; uint32_t expand; + uint32_t consecutive_miss; + int32_t expand_frame_len; uint32_t jitter_max_ms; + uint32_t buffering_skip; int estimate_ms; int buffer_size_ms; } switch_jb_stats_t; @@ -134,6 +140,7 @@ struct switch_jb_s { uint32_t buffer_lag; uint32_t flush; uint32_t packet_count; + int32_t packets_in_buffer; uint32_t max_packet_len; uint32_t period_len; uint32_t nack_saved_the_day; @@ -784,8 +791,8 @@ static inline void increment_seq(switch_jb_t *jb) static inline void decrement_seq(switch_jb_t *jb) { - jb->last_target_seq = jb->target_seq; jb->target_seq = htons((ntohs(jb->target_seq) - 1)); + jb->last_target_seq = htons((ntohs(jb->target_seq) - 1)); } static inline void set_read_seq(switch_jb_t *jb, uint16_t seq) @@ -930,9 +937,14 @@ static inline int check_jb_size(switch_jb_t *jb) seq_hs = ntohs(np->packet.header.seq); if (target_seq_hs > seq_hs) { - hide_node(np, SWITCH_FALSE); - old++; - continue; + const int MAX_DROPOUT = 3000; + uint16_t udelta = target_seq_hs - seq_hs; + if (udelta > 1 && udelta < MAX_DROPOUT) { + // not a sequence id roll-over, this is an old packet, we can hide it + hide_node(np, SWITCH_FALSE); + old++; + continue; + } } if (count == 0) { @@ -969,6 +981,9 @@ static inline int check_jb_size(switch_jb_t *jb) switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_max_ms", "%u", jb->jitter.stats.size_max * packet_ms); switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_est_ms", "%u", jb->jitter.stats.size_est * packet_ms); switch_channel_set_variable_printf(jb->channel, "rtp_jb_acceleration_ms", "%u", jb->jitter.stats.acceleration * packet_ms); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_fast_acceleration_ms", "%u", jb->jitter.stats.fast_acceleration * packet_ms); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_forced_acceleration_ms", "%u", jb->jitter.stats.forced_acceleration * packet_ms); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", jb->jitter.stats.buffering_skip); switch_channel_set_variable_printf(jb->channel, "rtp_jb_expand_ms", "%u", jb->jitter.stats.expand * packet_ms); } @@ -1004,10 +1019,33 @@ static inline switch_status_t jb_next_packet_by_seq_with_acceleration(switch_jb_ select packet to drop/accelerate. */ if (jb->elastic && jb->jitter.estimate && (jb->visible_nodes * jb->jitter.samples_per_frame) > 0 && jb->jitter.samples_per_second) { - int visible_not_old = check_jb_size(jb); + jb->packets_in_buffer = check_jb_size(jb); jb->jitter.stats.estimate_ms = (int)((*jb->jitter.estimate) / ((jb->jitter.samples_per_second)) * 1000); - jb->jitter.stats.buffer_size_ms = (int)((visible_not_old * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000)); + jb->jitter.stats.buffer_size_ms = (int)((jb->packets_in_buffer * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000)); + + /* If the jitter buffer size is above the its max size, we force accelerate */ + if (jb->packets_in_buffer >= jb->max_frame_len) { + if (packet_vad(jb, packet, len) == SWITCH_FALSE) { + jb_debug(jb, SWITCH_LOG_ALERT, "JITTER_BUFFER above max size: [%d>%d] inactive fast acceleration\n", jb->packets_in_buffer, jb->max_frame_len); + jb->jitter.drop_gap = 3; + jb->jitter.stats.acceleration++; + jb->jitter.stats.expand_frame_len--; + jb->jitter.stats.fast_acceleration++; + return jb_next_packet_by_seq(jb, nodep); + } else { + if (jb->jitter.drop_gap > 0) { + jb->jitter.drop_gap--; + } else { + jb_debug(jb, SWITCH_LOG_ALERT, "JITTER_BUFFER above max size: [%d>%d] forced acceleration\n", jb->packets_in_buffer, jb->max_frame_len); + jb->jitter.drop_gap = 10; + jb->jitter.stats.acceleration++; + jb->jitter.stats.expand_frame_len--; + jb->jitter.stats.forced_acceleration++; + return jb_next_packet_by_seq(jb, nodep); + } + } + } /* We try to accelerate in order to remove delay when the jitter buffer is 3x larger than the estimation. */ if (jb->jitter.stats.buffer_size_ms > (3 * jb->jitter.stats.estimate_ms) && jb->jitter.stats.buffer_size_ms > 60) { @@ -1025,14 +1063,15 @@ static inline switch_status_t jb_next_packet_by_seq_with_acceleration(switch_jb_ if (status != SWITCH_STATUS_SUCCESS || packet_vad(jb, packet, len) == SWITCH_FALSE) { jb->jitter.drop_gap = 3; if (status != SWITCH_STATUS_SUCCESS) { - jb_debug(jb, SWITCH_LOG_INFO, "JITTER estimation n/a buffersize %d/%d %dms seq:%u [drop-missing/no-plc]\n", + jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation n/a buffersize %d/%d %dms seq:%u [drop-missing/no-plc]\n", jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms, seq); } else { - jb_debug(jb, SWITCH_LOG_INFO, "JITTER estimation %dms buffersize %d/%d %dms seq:%u ACCELERATE [drop]\n", + jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation %dms buffersize %d/%d %dms seq:%u ACCELERATE [drop]\n", jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms, seq); } jb->jitter.stats.acceleration++; + jb->jitter.stats.expand_frame_len--; return jb_next_packet_by_seq(jb, nodep); } else { @@ -1084,6 +1123,9 @@ SWITCH_DECLARE(void) switch_jb_set_jitter_estimator(switch_jb_t *jb, double *jit switch_channel_set_variable_printf(jb->channel, "rtp_jb_max_ms", "%u", 0); switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_ms", "%u", 0); switch_channel_set_variable_printf(jb->channel, "rtp_jb_acceleration_ms", "%u", 0); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_fast_acceleration_ms", "%u", 0); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_forced_acceleration_ms", "%u", 0); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", 0); switch_channel_set_variable_printf(jb->channel, "rtp_jb_expand_ms", "%u", 0); switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_max_ms", "%u", 0); switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_ms", "%u", 0); @@ -1174,12 +1216,15 @@ SWITCH_DECLARE(void) switch_jb_debug_level(switch_jb_t *jb, uint8_t level) SWITCH_DECLARE(void) switch_jb_reset(switch_jb_t *jb) { jb->jitter.stats.reset++; + jb->jitter.stats.expand_frame_len = 0; if (jb->channel) { switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_count", "%u", jb->jitter.stats.reset); switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_big", "%u", jb->jitter.stats.reset_too_big); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_expanded", "%u", jb->jitter.stats.reset_too_expanded); switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_missing_frames", "%u", jb->jitter.stats.reset_missing_frames); switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_ts_jump", "%u", jb->jitter.stats.reset_ts_jump); switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_error", "%u", jb->jitter.stats.reset_error); + switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", jb->jitter.stats.buffering_skip); } if (jb->type == SJB_VIDEO) { @@ -1582,12 +1627,14 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp switch_goto_status(SWITCH_STATUS_BREAK, end); } - if (jb->complete_frames < jb->frame_len) { + if (!jb->elastic && (jb->complete_frames < jb->frame_len)) { switch_jb_poll(jb); if (!jb->flush) { jb_debug(jb, 2, "BUFFERING %u/%u\n", jb->complete_frames , jb->frame_len); + jb->jitter.stats.buffering_skip++; + switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", jb->jitter.stats.buffering_skip); switch_goto_status(SWITCH_STATUS_MORE_DATA, end); } } @@ -1695,16 +1742,31 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp switch_goto_status(SWITCH_STATUS_RESTART, end); } else { if (jb->elastic) { - int visible_not_old = check_jb_size(jb); - jb->jitter.stats.estimate_ms = (int)((*jb->jitter.estimate) / ((jb->jitter.samples_per_second)) * 1000); - jb->jitter.stats.buffer_size_ms = (int)((visible_not_old * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000)); + jb->jitter.stats.buffer_size_ms = (int)((jb->packets_in_buffer * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000)); /* When playing PLC, we take the oportunity to expand the buffer if the jitter buffer is smaller than the 3x the estimated jitter. */ - if (jb->jitter.stats.buffer_size_ms < (3 * jb->jitter.stats.estimate_ms)) { - jb_debug(jb, SWITCH_LOG_INFO, "JITTER estimation %dms buffersize %d/%d %dms EXPAND [plc]\n", - jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms); + if (jb->jitter.stats.expand_frame_len < 0) jb->jitter.stats.expand_frame_len = 0; + + if (jb->jitter.stats.expand_frame_len > jb->max_frame_len) { + jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation %dms buffersize %d/%d %dms RESET TOO BIG [%d>%d] target seq[%u]\n", + jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms, + jb->jitter.stats.expand_frame_len, jb->max_frame_len, ntohs(jb->target_seq)); + jb->jitter.stats.reset_too_expanded++; + jb->jitter.stats.expand_frame_len=0; + switch_jb_reset(jb); + switch_goto_status(SWITCH_STATUS_RESTART, end); + } else if (jb->jitter.stats.buffer_size_ms < (3 * jb->jitter.stats.estimate_ms)) { + jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation %dms buffersize %d/%d %dms EXPAND [plc] target_seq[%u] expand[%d] now[%ld]\n", + jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms, + ntohs(jb->target_seq), jb->jitter.stats.expand_frame_len, (int64_t)(switch_micro_time_now()/1000)); jb->jitter.stats.expand++; + jb->jitter.stats.expand_frame_len++; decrement_seq(jb); + } else if (jb->jitter.stats.expand_frame_len >= jb->max_frame_len) { + jb->jitter.stats.reset_error++; + jb->jitter.stats.expand_frame_len=0; + switch_jb_reset(jb); + switch_goto_status(SWITCH_STATUS_RESTART, end); } else { jb_debug(jb, 2, "%s", "Frame not found suggest PLC\n"); } @@ -1712,6 +1774,16 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp jb_debug(jb, 2, "%s", "Frame not found suggest PLC\n"); } + if (jb->elastic) { + jb->jitter.stats.consecutive_miss++; + if (jb->jitter.stats.consecutive_miss > 100) { + jb->jitter.stats.reset_missing_frames++; + jb->jitter.stats.consecutive_miss=0; + jb->elastic = SWITCH_FALSE; + switch_jb_reset(jb); + switch_goto_status(SWITCH_STATUS_RESTART, end); + } + } plc = 1; switch_goto_status(SWITCH_STATUS_NOTFOUND, end); } @@ -1742,6 +1814,8 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp packet->header.seq = seq; packet->header.ts = ts; + } else { + jb->jitter.stats.consecutive_miss=0; } switch_mutex_unlock(jb->mutex); diff --git a/src/switch_rtp.c b/src/switch_rtp.c index 46e13253b7..775db1db50 100644 --- a/src/switch_rtp.c +++ b/src/switch_rtp.c @@ -113,6 +113,7 @@ typedef struct { char body[SWITCH_RTP_MAX_BUF_LEN+4+sizeof(char *)]; switch_rtp_hdr_ext_t *ext; char *ebody; + switch_time_t received_ts; } rtp_msg_t; #define RTP_BODY(_s) (char *) (_s->recv_msg.ebody ? _s->recv_msg.ebody : _s->recv_msg.body) @@ -491,6 +492,7 @@ struct switch_rtp { uint32_t last_max_vb_frames; int skip_timer; uint32_t prev_nacks_inflight; + switch_bool_t packet_stats_io_info_set; }; struct switch_rtcp_report_block { @@ -706,6 +708,7 @@ static handle_rfc2833_result_t handle_rfc2833(switch_rtp_t *rtp_session, switch_ } if (rtp_session->jb && (rtp_session->rtp_bugs & RTP_BUG_FLUSH_JB_ON_DTMF)) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "jb_reset : RTP_BUG_FLUSH_JB_ON_DTMF - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->jb); } @@ -2983,6 +2986,7 @@ SWITCH_DECLARE(void) switch_rtp_reset_jb(switch_rtp_t *rtp_session) { if (switch_rtp_ready(rtp_session)) { if (rtp_session->jb) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset SWITCH RESET - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->jb); } } @@ -4454,11 +4458,32 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_change_interval(switch_rtp_t *rtp_ses return status; } +static void reset_packet_stats_io_info(switch_rtp_t *rtp_session) { + switch_channel_t *channel = switch_core_session_get_channel(rtp_session->session); + const char *uuid=NULL; + switch_core_session_t *b_session=NULL; + switch_rtp_t *b_rtp_session=NULL; + + rtp_session->packet_stats_io_info_set = SWITCH_FALSE; + if (channel) { + uuid = switch_channel_get_variable_dup(channel,"bridge_uuid", SWITCH_FALSE, -1); + } + if (uuid) { + b_session = switch_core_session_locate(uuid); + } + if (b_session) { + b_rtp_session = switch_core_media_get_rtp_session(b_session, SWITCH_MEDIA_TYPE_AUDIO); + b_rtp_session->packet_stats_io_info_set = SWITCH_FALSE; + switch_core_session_rwunlock(b_session); + } + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_INFO, ">>>> PACKET STATS IO INFO UNSET <<<<\n"); +} + SWITCH_DECLARE(switch_status_t) switch_rtp_set_ssrc(switch_rtp_t *rtp_session, uint32_t ssrc) { rtp_session->ssrc = ssrc; rtp_session->send_msg.header.ssrc = htonl(rtp_session->ssrc); - + reset_packet_stats_io_info(rtp_session); return SWITCH_STATUS_SUCCESS; } @@ -4466,6 +4491,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_set_remote_ssrc(switch_rtp_t *rtp_ses { rtp_session->remote_ssrc = ssrc; rtp_session->flags[SWITCH_RTP_FLAG_DETECT_SSRC] = 0; + reset_packet_stats_io_info(rtp_session); return SWITCH_STATUS_SUCCESS; } @@ -4737,10 +4763,12 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_pause_jitter_buffer(switch_rtp_t *rtp if (rtp_session->pause_jb && !pause) { if (rtp_session->jb) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset PAUSE - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->jb); } if (rtp_session->vb) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset PAUSE VB - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->vb); } } @@ -5414,6 +5442,7 @@ SWITCH_DECLARE(void) switch_rtp_set_flag(switch_rtp_t *rtp_session, switch_rtp_f if (rtp_session->jb) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset SET FLAG - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->jb); } } else if (flag == SWITCH_RTP_FLAG_NOBLOCK && rtp_session->sock_input) { @@ -5707,6 +5736,7 @@ static switch_size_t do_flush(switch_rtp_t *rtp_session, int force, switch_size_ } if (rtp_session->vbw) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset VBW - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->vbw); } @@ -5841,6 +5871,46 @@ static int get_recv_payload(switch_rtp_t *rtp_session) return r; } + + +static void set_packet_stats_io_info(switch_rtp_t *rtp_session) { + switch_channel_t *channel = switch_core_session_get_channel(rtp_session->session); + const char *uuid=NULL; + switch_core_session_t *b_session=NULL; + switch_rtp_t *b_rtp_session=NULL; + switch_channel_t *b_channel=NULL; + if (rtp_session->packet_stats_io_info_set) + return; + if (channel) { + uuid = switch_channel_get_variable_dup(channel,"bridge_uuid", SWITCH_FALSE, -1); + } + if (uuid) { + b_session = switch_core_session_locate(uuid); + } + if (b_session) { + b_rtp_session = switch_core_media_get_rtp_session(b_session, SWITCH_MEDIA_TYPE_AUDIO); + b_channel = switch_core_session_get_channel(b_session); + switch_core_session_rwunlock(b_session); + + if (b_rtp_session && b_channel) { + packet_stats_io_info_t packet_stats_io_info; + packet_stats_io_info.out_ssrc = b_rtp_session->ssrc; + packet_stats_io_info.out_codec = '\0'; + packet_stats_io_info.out_remote_addr = b_rtp_session->remote_addr; + packet_stats_io_info.out_local_addr = b_rtp_session->local_addr; + + packet_stats_io_info.in_ssrc = rtp_session->remote_ssrc; + packet_stats_io_info.in_codec = '\0'; + packet_stats_io_info.in_remote_addr = rtp_session->remote_addr; + packet_stats_io_info.in_local_addr = rtp_session->local_addr; + if (rtp_session->remote_ssrc && b_rtp_session->ssrc) + rtp_session->packet_stats_io_info_set = SWITCH_TRUE; + switch_core_session_set_io_stats(b_rtp_session->session, &packet_stats_io_info); + } + } + +} + #define return_cng_frame() do_cng = 1; goto timer_check static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t *bytes, switch_frame_flag_t *flags, @@ -5860,8 +5930,9 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t tries++; - if (tries > 20) { + if (tries > 20 && !(switch_channel_var_true(switch_core_session_get_channel(rtp_session->session), "rtp_jitter_buffer_accelerate"))) { if (rtp_session->jb && !rtp_session->pause_jb && jb_valid(rtp_session)) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset TRIES > 20 ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->jb); } rtp_session->punts++; @@ -5909,6 +5980,9 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t if (poll_status == SWITCH_STATUS_SUCCESS) { status = switch_socket_recvfrom(rtp_session->from_addr, rtp_session->sock_input, 0, (void *) &rtp_session->recv_msg, bytes); + if (*bytes) { + rtp_session->recv_msg.received_ts = switch_micro_time_now(); + } } else { *bytes = 0; } @@ -6431,6 +6505,7 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t if (rtp_session->jb && jb_valid(rtp_session)) { if (rtp_session->last_jb_read_ssrc && rtp_session->last_jb_read_ssrc != read_ssrc) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset SSRC change - ssrc[0x%.8X]\n", rtp_session->ssrc); switch_jb_reset(rtp_session->jb); } @@ -6547,7 +6622,7 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t } } } - + set_packet_stats_io_info(rtp_session); return status; } @@ -8081,6 +8156,8 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_zerocopy_read_frame(switch_rtp_t *rtp switch_set_flag(frame, SFF_RFC2833); } frame->timestamp = ntohl(rtp_session->last_rtp_hdr.ts); + + frame->received_ts = rtp_session->recv_msg.received_ts; frame->seq = (uint16_t) ntohs((uint16_t) rtp_session->last_rtp_hdr.seq); frame->ssrc = ntohl(rtp_session->last_rtp_hdr.ssrc); frame->m = rtp_session->last_rtp_hdr.m ? SWITCH_TRUE : SWITCH_FALSE; @@ -8488,7 +8565,7 @@ static int rtp_common_write(switch_rtp_t *rtp_session, rtp_session->seq += delta; send_msg->header.seq = htons(rtp_session->seq); - + if (rtp_session->flags[SWITCH_RTP_FLAG_BYTESWAP] && send_msg->header.pt == rtp_session->payload) { switch_swap_linear((int16_t *)send_msg->body, (int) datalen); }