mod_sangoma_codec: more timing debug code

diff --git a/src/mod/codecs/mod_sangoma_codec/mod_sangoma_codec.c b/src/mod/codecs/mod_sangoma_codec/mod_sangoma_codec.c
index da8d7fe73d4dc7e1df2a3f5228ad10b4d8e90c61..697134b1c82e5196b7552cc417dab6366d9fda4e 100644 (file)
--- a/src/mod/codecs/mod_sangoma_codec/mod_sangoma_codec.c
+++ b/src/mod/codecs/mod_sangoma_codec/mod_sangoma_codec.c
@@ -137,6 +137,7 @@ struct codec_data {
        /* avg Rx time */
        switch_time_t avgrxus;
        switch_time_t last_rx_time;
+       switch_time_t last_func_call_time;
 
        /* RTP queue. The bigger the queue, the bigger the possible delay */
        struct sangoma_rtp_payload rtp_queue[SANGOMA_RTP_QUEUE_SIZE];
@@ -386,7 +387,7 @@ static switch_status_t switch_sangoma_encode(switch_codec_t *codec, switch_codec
        switch_frame_t encoded_frame;
        switch_status_t sres;
        switch_time_t now_time, difftime;
-       switch_time_t prevread_time, afterread_time;
+       switch_time_t func_start_time, func_end_time;
        unsigned char ebuf_ulaw[decoded_data_len / 2];
        short *dbuf_linear;
        int i = 0;
@@ -394,7 +395,7 @@ static switch_status_t switch_sangoma_encode(switch_codec_t *codec, switch_codec
        struct sangoma_transcoding_session *sess = codec->private_info;
 
        if (sess->encoder.debug_timing) {
-               prevread_time =  switch_micro_time_now();
+               func_start_time =  switch_micro_time_now();
        }
 
        /* start assuming we will not encode anything */
@@ -416,13 +417,10 @@ static switch_status_t switch_sangoma_encode(switch_codec_t *codec, switch_codec
                switch_mutex_unlock(g_sessions_lock);
        }
 
-       if (sess->encoder.debug_timing) {
-               now_time = switch_micro_time_now();
-               if (sess->encoder.last_rx_time) {
-                       difftime = now_time - sess->encoder.last_rx_time;
-                       if (difftime > 25000 || difftime < 15000) {
-                               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "%ldus since last read on encoding session %lu.\n", (long)difftime, sess->sessid);
-                       }
+       if (sess->encoder.debug_timing && sess->encoder.last_func_call_time) {
+               difftime = func_start_time - sess->encoder.last_func_call_time;
+               if (difftime > 25000 || difftime < 15000) {
+                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "%ldus since last read on encoding session %lu\n", (long)difftime, sess->sessid);
                }
        }
 
@@ -551,11 +549,12 @@ static switch_status_t switch_sangoma_encode(switch_codec_t *codec, switch_codec
        }
 
        if (sess->encoder.debug_timing) {
-               afterread_time =  switch_micro_time_now();
-               difftime = afterread_time - prevread_time;
+               func_end_time = switch_micro_time_now();
+               difftime = func_end_time - func_start_time;
                if (difftime > 5000) {
                        switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "%ldus to execute encoding function in session %lu.\n", (long)difftime, sess->sessid);
                }
+               sess->encoder.last_func_call_time = func_end_time;
        }
        return SWITCH_STATUS_SUCCESS;
 }
@@ -576,14 +575,14 @@ static switch_status_t switch_sangoma_decode(switch_codec_t *codec,       /* codec ses
        switch_frame_t ulaw_frame;
        switch_status_t sres;
        switch_time_t now_time, difftime;
-       switch_time_t prevread_time, afterread_time;
+       switch_time_t func_start_time, func_end_time;
        short *dbuf_linear;
        int i = 0;
        int res = 0;
        struct sangoma_transcoding_session *sess = codec->private_info;
 
        if (sess->decoder.debug_timing) {
-               prevread_time =  switch_micro_time_now();
+               func_start_time =  switch_micro_time_now();
        }
 
        dbuf_linear = decoded_data;
@@ -613,13 +612,10 @@ static switch_status_t switch_sangoma_decode(switch_codec_t *codec,       /* codec ses
                switch_mutex_unlock(g_sessions_lock);
        }
 
-       if (sess->decoder.debug_timing) {
-               now_time = switch_micro_time_now();
-               if (sess->decoder.last_rx_time) {
-                       difftime = now_time - sess->decoder.last_rx_time;
-                       if (difftime > 25000 || difftime < 15000) {
-                               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "%ldms since last read on decoding session %lu.\n", (long)difftime, sess->sessid);
-                       }
+       if (sess->decoder.debug_timing && sess->decoder.last_func_call_time) {
+               difftime = func_start_time - sess->decoder.last_func_call_time;
+               if (difftime > 25000 || difftime < 15000) {
+                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "%ldms since last read on decoding session %lu.\n", (long)difftime, sess->sessid);
                }
        }
 
@@ -743,11 +739,12 @@ static switch_status_t switch_sangoma_decode(switch_codec_t *codec,       /* codec ses
        }
 
        if (sess->decoder.debug_timing) {
-               afterread_time =  switch_micro_time_now();
-               difftime = afterread_time - prevread_time;
+               func_end_time = switch_micro_time_now();
+               difftime = func_end_time - func_start_time;
                if (difftime > 5000) {
                        switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "%ldus to execute decoding function in session %lu.\n", (long)difftime, sess->sessid);
                }
+               sess->decoder.last_func_call_time = func_end_time;
        }
 
        return SWITCH_STATUS_SUCCESS;