From 7e3de20962912510af231cef85a90e359e94f734 Mon Sep 17 00:00:00 2001 From: Wang Xingchao Date: Fri, 5 Jul 2013 13:08:20 +0800 Subject: [PATCH] http-protocol: Add debug function to track latency issue This patch intended to track latency between push_cb and do_work. Also we can enlarge the idea to track latency between different threads and callbacks. Signed-off-by: Wang Xingchao --- src/pulsecore/protocol-http.c | 79 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 79 insertions(+) diff --git a/src/pulsecore/protocol-http.c b/src/pulsecore/protocol-http.c index 7d49bf8..ca0109a 100644 --- a/src/pulsecore/protocol-http.c +++ b/src/pulsecore/protocol-http.c @@ -27,6 +27,7 @@ #include #include #include +#include #include #include @@ -86,6 +87,19 @@ enum method { METHOD_HEAD }; +/* start_us: the starting time of copy memchunk + * now_us: current time + * push_us: timestamp when push chunk into memblockq + * cnt_start: calling counters of push_cb + * cnt_now: calling counters of do_write + * initial: initialzie start_us only once + * */ +struct pa_http_time { + uint64_t start_us, now_us, push_us; + int cnt_start, cnt_now; + int initial; +}; + struct connection { pa_http_protocol *protocol; pa_iochannel *io; @@ -97,6 +111,7 @@ struct connection { char *url; enum method method; pa_module *module; + struct pa_http_time time; }; struct pa_http_protocol { @@ -112,6 +127,48 @@ enum { SOURCE_OUTPUT_MESSAGE_POST_DATA = PA_SOURCE_OUTPUT_MESSAGE_MAX }; +static uint64_t timespec_us(const struct timespec *ts) { + return + ts->tv_sec * 1000000LLU + + ts->tv_nsec / 1000LLU; +} + +static void get_time(uint64_t *time) { + int r = -1; + struct timespec now; + + r = clock_gettime(CLOCK_MONOTONIC, &now); + assert(r == 0); + + *time = timespec_us(&now); +} + +//TODO: start_us maybe refreshed very fast while now_us is latest. +// Add array to store the same pipeline timestamp, like: +// push count =0; work count = 0; +// consume time = time-between-above two counts. +// Avoid: +// push count = 100; work-count = 10; +// then the consume time is not accurate +// +static void debug_timestamp(struct connection *c, + const char *msg) { + unsigned long long delta_push, delta_start; + struct pa_http_time *time; + uint64_t now_us; + + time = &c->time; + get_time(&now_us); + time->now_us = now_us; + pa_log_debug("Stage %s", msg); + + pa_log_debug(" push cnt[%d]:work cnt[%d]", time->cnt_start, + time->cnt_now); + delta_push = time->now_us - time->push_us; + delta_start = time->now_us - time->start_us; + pa_log_debug(" consume %llu us since last push, %llu us since start\n", delta_push, delta_start); +} + /* Called from main context */ static void connection_unlink(struct connection *c) { pa_assert(c); @@ -186,6 +243,7 @@ static void do_work(struct connection *c) { break; } + debug_timestamp(c, "do write"); return; fail: @@ -196,18 +254,23 @@ fail: static int source_output_process_msg(pa_msgobject *m, int code, void *userdata, int64_t offset, pa_memchunk *chunk) { pa_source_output *o = PA_SOURCE_OUTPUT(m); struct connection *c; + struct pa_http_time *time; pa_source_output_assert_ref(o); if (!(c = o->userdata)) return -1; + time = &c->time; + switch (code) { case SOURCE_OUTPUT_MESSAGE_POST_DATA: /* While this function is usually called from IO thread * context, this specific command is not! */ pa_memblockq_push_align(c->output_memblockq, chunk); + time->cnt_now++; + debug_timestamp(c, "do work"); do_work(c); break; @@ -222,10 +285,21 @@ static int source_output_process_msg(pa_msgobject *m, int code, void *userdata, static void source_output_push_cb(pa_source_output *o, const pa_memchunk *chunk) { struct connection *c; + struct pa_http_time *time; + uint64_t start_us, push_us; pa_source_output_assert_ref(o); pa_assert_se(c = o->userdata); pa_assert(chunk); + time = &c->time; + if (!time->initial) { + get_time(&start_us); + time->start_us = start_us; + time->initial = 1; + } + get_time(&push_us); + time->push_us = push_us; + time->cnt_start++; pa_asyncmsgq_post(pa_thread_mq_get()->outq, PA_MSGOBJECT(o), SOURCE_OUTPUT_MESSAGE_POST_DATA, NULL, 0, chunk, NULL); } @@ -685,6 +759,7 @@ fail: void pa_http_protocol_connect(pa_http_protocol *p, pa_iochannel *io, pa_module *m) { struct connection *c; pa_client_new_data client_data; + struct pa_http_time *time; char pname[128]; pa_assert(p); @@ -701,6 +776,10 @@ void pa_http_protocol_connect(pa_http_protocol *p, pa_iochannel *io, pa_module * c->protocol = p; c->state = STATE_REQUEST_LINE; c->module = m; + time = &c->time; + time->cnt_start=0; + time->cnt_now=0; + time->initial = 0; c->line = pa_ioline_new(io); pa_ioline_set_callback(c->line, line_callback, c); -- 1.7.9.5