Track time taken for XML fetch responses/timeouts

git-svn-id: http://svn.freeswitch.org/svn/freeswitch/trunk@16704 d0543943-73ff-0310-b7d9-9358b9ac24b2

diff --git a/src/mod/event_handlers/mod_erlang_event/mod_erlang_event.c b/src/mod/event_handlers/mod_erlang_event/mod_erlang_event.c
index 442ce1c2745ee335299802199966973d539c4d99..1b9999156f1890a363714d6621d9959b0b08f01f 100644 (file)
--- a/src/mod/event_handlers/mod_erlang_event/mod_erlang_event.c
+++ b/src/mod/event_handlers/mod_erlang_event/mod_erlang_event.c
@@ -378,8 +378,8 @@ static switch_xml_t erlang_fetch(const char *sectionstr, const char *tag_name, c
 {
        char uuid_str[SWITCH_UUID_FORMATTED_LENGTH + 1];
        int type, size;
-       int i = 0;
        fetch_reply_t *p = NULL;
+       switch_time_t now = 0;
        char *xmlstr;
        struct erlang_binding *ptr;
        switch_uuid_t uuid;
@@ -428,6 +428,7 @@ static switch_xml_t erlang_fetch(const char *sectionstr, const char *tag_name, c
                        p->state = reply_not_ready;
                        p->reply = NULL;
                        switch_core_hash_insert_locked(globals.fetch_reply_hash, uuid_str, p, globals.fetch_reply_mutex);
+                       now = switch_micro_time_now();
                }
                /* We don't need to lock here because everybody is waiting
                   on our condition before the action starts. */
@@ -452,7 +453,7 @@ static switch_xml_t erlang_fetch(const char *sectionstr, const char *tag_name, c
        if (!p->reply) {
                p->state = reply_timeout;
                switch_mutex_unlock(globals.fetch_reply_mutex);
-               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Timed out when waiting for XML fetch response\n");
+               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Timed out after %d milliseconds when waiting for XML fetch response\n", (int) (switch_micro_time_now() - now) / 1000);
                goto cleanup;
        }
 
@@ -475,7 +476,7 @@ static switch_xml_t erlang_fetch(const char *sectionstr, const char *tag_name, c
 
        ei_decode_string_or_binary(rep->buff, &rep->index, size, xmlstr);
 
-       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "got data %s after %d milliseconds from %s!\n", xmlstr, i * 10, p->winner);
+       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "got data %s after %d milliseconds from %s!\n", xmlstr, (int) (switch_micro_time_now() - now) / 1000, p->winner);
 
        if (zstr(xmlstr)) {
                switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "No Result\n");