Attachment 82062 Details for Bug 65703 – patch to debug http latency issue

[patch] patch to debug http latency issue

0001-http-protocol-Add-debug-function-to-track-latency-is.patch (text/plain), 5.12 KB, created by Wang Xingchao on 2013-07-05 05:41:44 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Wang Xingchao

Created: 2013-07-05 05:41:44 UTC

Size: 5.12 KB

patch

obsolete

>From 7e3de20962912510af231cef85a90e359e94f734 Mon Sep 17 00:00:00 2001
>From: Wang Xingchao <xingchao.wang@linux.intel.com>
>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 <xingchao.wang@linux.intel.com>
>---
> 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 <stdio.h>
> #include <string.h>
> #include <errno.h>
>+#include <time.h>
> 
> #include <pulse/util.h>
> #include <pulse/xmalloc.h>
>@@ -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
>

Actions: View | Splinter Review

Attachments on bug 65703: 82062 | 82081 | 82082 | 82117 | 82132 | 82133

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.