[pulseaudio-discuss] [PATCH] proof of concept: use pactl log to get the buffer log

Deng Zhenrong dzrongg at gmail.com
Sat Mar 31 20:12:18 PDT 2012


This is just a proof of concept for me to see how the overall
communication works. From this patch, I learnt a lot about the
importances of callback, the tag struct etc. It's a nice start for me to
dive into pulseaudio.  :)

However, there's still a lot to improve:
1. Add thread protection to log facilities. To make it simple at first,
   I haven't added that yet, but in real cases, different threads would
   call the log function, and if protection is not there, all would be
   messed up.
2. reduce the overhead of copying the data buffer. Now, `get_log_buffer'
   allocates a new buffer and pass it to tag struct. But this kind of
   operation can be reduced to keep the overhead at minimal.

Signed-off-by: Deng Zhenrong <dzrongg at gmail.com>
---
 src/map-file                    |    1 +
 src/pulse/introspect.c          |   34 +++++++++++++++++++++++
 src/pulse/introspect.h          |    3 ++
 src/pulsecore/log.c             |   58 +++++++++++++++++++++++++++++++++++++++
 src/pulsecore/log.h             |    2 +
 src/pulsecore/native-common.h   |    1 +
 src/pulsecore/pdispatch.c       |    1 +
 src/pulsecore/protocol-native.c |   26 +++++++++++++++++
 src/utils/pactl.c               |   14 +++++++++
 9 files changed, 140 insertions(+), 0 deletions(-)

diff --git a/src/map-file b/src/map-file
index 69cf25b..812875a 100644
--- a/src/map-file
+++ b/src/map-file
@@ -46,6 +46,7 @@ pa_context_get_protocol_version;
 pa_context_get_sample_info_by_index;
 pa_context_get_sample_info_by_name;
 pa_context_get_sample_info_list;
+pa_context_get_log;
 pa_context_get_server;
 pa_context_get_server_info;
 pa_context_get_server_protocol_version;
diff --git a/src/pulse/introspect.c b/src/pulse/introspect.c
index 38a9d1c..2f2ef98 100644
--- a/src/pulse/introspect.c
+++ b/src/pulse/introspect.c
@@ -79,6 +79,40 @@ pa_operation* pa_context_stat(pa_context *c, pa_stat_info_cb_t cb, void *userdat
     return pa_context_send_simple_command(c, PA_COMMAND_STAT, context_stat_callback, (pa_operation_cb_t) cb, userdata);
 }
 
+/*** Logs ***/
+static void context_get_log_callback(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) {
+    pa_operation *o = userdata;
+    const char *p = NULL;
+
+    pa_assert(pd);
+    pa_assert(o);
+    pa_assert(PA_REFCNT_VALUE(o) >= 1);
+
+    if (!o->context)
+        goto finish;
+
+    if (command != PA_COMMAND_REPLY) {
+        if (pa_context_handle_error(o->context, command, t, FALSE) < 0)
+            goto finish;
+    } else if (pa_tagstruct_gets(t, &p) < 0) {
+        pa_context_fail(o->context, PA_ERR_PROTOCOL);
+        goto finish;
+    }
+
+    if (o->callback) {
+        pa_log_info_cb_t cb = (pa_log_info_cb_t) o->callback;
+        cb(o->context, p, o->userdata);
+    }
+
+finish:
+    pa_operation_done(o);
+    pa_operation_unref(o);
+}
+
+pa_operation* pa_context_get_log(pa_context *c, pa_log_info_cb_t cb, void *userdata) {
+    return pa_context_send_simple_command(c, PA_COMMAND_GET_LOG, context_get_log_callback, (pa_operation_cb_t) cb, userdata);
+}
+
 /*** Server Info ***/
 
 static void context_get_server_info_callback(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) {
diff --git a/src/pulse/introspect.h b/src/pulse/introspect.h
index 224432c..e6e1577 100644
--- a/src/pulse/introspect.h
+++ b/src/pulse/introspect.h
@@ -629,6 +629,9 @@ pa_operation* pa_context_stat(pa_context *c, pa_stat_info_cb_t cb, void *userdat
 
 /** @} */
 
+typedef void (*pa_log_info_cb_t) (pa_context *c, const char *buffer, void *userdata);
+pa_operation* pa_context_get_log(pa_context *c, pa_log_info_cb_t cb, void *userdata);
+
 /** @{ \name Cached Samples */
 
 /** Stores information about sample cache entries. Please note that this structure
diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c
index 8eaef54..1a4dbf4 100644
--- a/src/pulsecore/log.c
+++ b/src/pulsecore/log.c
@@ -107,6 +107,55 @@ static void ident_destructor(void) {
     pa_xfree(ident);
 }
 
+#define BUFFER_LENGTH (1024 * 1024)
+static char log_buffer[BUFFER_LENGTH];
+static int log_start_index = 0;
+static int log_end_index = 0;
+static size_t log_used_length = 0;
+
+char *get_log_buffer() {
+    char *result = pa_xnew0(char, BUFFER_LENGTH+1);
+    memcpy(result, &log_buffer[log_start_index], log_used_length);
+    result[log_used_length] = '\0';
+
+    return result;
+}
+
+static void write_to_circular_buffer(const char *p, size_t len) {
+    const char *base = p;
+
+    while (len > 0) {
+        size_t first_chunk;
+        size_t min = len;
+        if (min > BUFFER_LENGTH)
+            min = BUFFER_LENGTH;
+
+        first_chunk = BUFFER_LENGTH - log_end_index;
+        if (min <= first_chunk) {
+            // it can be put into the first part, don't need to wrap up.
+            memcpy(&log_buffer[log_end_index], base, min);
+        } else {
+           // copy the first chunk
+           memcpy(&log_buffer[log_end_index], base, first_chunk);
+           // copy the left data
+           memcpy(&log_buffer[0], base + first_chunk, min - first_chunk);
+        }
+
+        log_end_index += min;
+        if (log_end_index >= BUFFER_LENGTH) {
+            log_end_index -= BUFFER_LENGTH;
+        }
+        log_used_length += min;
+        if (log_used_length >= BUFFER_LENGTH) {
+            log_start_index = log_end_index;
+            log_used_length = BUFFER_LENGTH;
+        }
+
+        base += min;
+        len -= min;
+    }
+}
+
 void pa_log_set_level(pa_log_level_t l) {
     pa_assert(l < PA_LOG_LEVEL_MAX);
 
@@ -358,6 +407,7 @@ void pa_log_levelv_meta(
 
             case PA_LOG_STDERR: {
                 const char *prefix = "", *suffix = "", *grey = "";
+                char metadata[256];
                 char *local_t;
 
 #ifndef OS_IS_WIN32
@@ -381,10 +431,18 @@ void pa_log_levelv_meta(
                 if ((local_t = pa_utf8_to_locale(t)))
                     t = local_t;
 
+
+                pa_snprintf(metadata, sizeof(metadata), "\n%c %s %s", level_to_char[level], timestamp, location);
+
+                // write metadata first and then t into circular buffer, as a first try, we write log to both log buffer and stderr.
+                write_to_circular_buffer(metadata, strlen(metadata));
+                write_to_circular_buffer(t, strlen(t));
+
                 if (_flags & PA_LOG_PRINT_LEVEL)
                     fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix);
                 else
                     fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix);
+
 #ifdef OS_IS_WIN32
                 fflush(stderr);
 #endif
diff --git a/src/pulsecore/log.h b/src/pulsecore/log.h
index 8dd056b..21a599f 100644
--- a/src/pulsecore/log.h
+++ b/src/pulsecore/log.h
@@ -63,6 +63,8 @@ typedef enum pa_log_merge {
     PA_LOG_RESET
 } pa_log_merge_t;
 
+char *get_log_buffer();
+
 /* Set an identification for the current daemon. Used when logging to syslog. */
 void pa_log_set_ident(const char *p);
 
diff --git a/src/pulsecore/native-common.h b/src/pulsecore/native-common.h
index 5d1ba6a..34d4ccf 100644
--- a/src/pulsecore/native-common.h
+++ b/src/pulsecore/native-common.h
@@ -46,6 +46,7 @@ enum {
     PA_COMMAND_LOOKUP_SOURCE,
     PA_COMMAND_DRAIN_PLAYBACK_STREAM,
     PA_COMMAND_STAT,
+    PA_COMMAND_GET_LOG,
     PA_COMMAND_GET_PLAYBACK_LATENCY,
     PA_COMMAND_CREATE_UPLOAD_STREAM,
     PA_COMMAND_DELETE_UPLOAD_STREAM,
diff --git a/src/pulsecore/pdispatch.c b/src/pulsecore/pdispatch.c
index 9a9ef4e..ed88f73 100644
--- a/src/pulsecore/pdispatch.c
+++ b/src/pulsecore/pdispatch.c
@@ -64,6 +64,7 @@ static const char *command_names[PA_COMMAND_MAX] = {
     [PA_COMMAND_LOOKUP_SOURCE] = "LOOKUP_SOURCE",
     [PA_COMMAND_DRAIN_PLAYBACK_STREAM] = "DRAIN_PLAYBACK_STREAM",
     [PA_COMMAND_STAT] = "STAT",
+    [PA_COMMAND_GET_LOG] = "GET_LOG",
     [PA_COMMAND_GET_PLAYBACK_LATENCY] = "GET_PLAYBACK_LATENCY",
     [PA_COMMAND_CREATE_UPLOAD_STREAM] = "CREATE_UPLOAD_STREAM",
     [PA_COMMAND_DELETE_UPLOAD_STREAM] = "DELETE_UPLOAD_STREAM",
diff --git a/src/pulsecore/protocol-native.c b/src/pulsecore/protocol-native.c
index 41fc0a0..468d566 100644
--- a/src/pulsecore/protocol-native.c
+++ b/src/pulsecore/protocol-native.c
@@ -262,6 +262,7 @@ static void command_auth(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_ta
 static void command_set_client_name(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
 static void command_lookup(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
 static void command_stat(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
+static void command_get_log(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
 static void command_get_playback_latency(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
 static void command_get_record_latency(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
 static void command_create_upload_stream(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata);
@@ -309,6 +310,7 @@ static const pa_pdispatch_cb_t command_table[PA_COMMAND_MAX] = {
     [PA_COMMAND_LOOKUP_SINK] = command_lookup,
     [PA_COMMAND_LOOKUP_SOURCE] = command_lookup,
     [PA_COMMAND_STAT] = command_stat,
+    [PA_COMMAND_GET_LOG] = command_get_log,
     [PA_COMMAND_GET_PLAYBACK_LATENCY] = command_get_playback_latency,
     [PA_COMMAND_GET_RECORD_LATENCY] = command_get_record_latency,
     [PA_COMMAND_CREATE_UPLOAD_STREAM] = command_create_upload_stream,
@@ -2786,6 +2788,30 @@ static void command_stat(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_ta
     pa_pstream_send_tagstruct(c->pstream, reply);
 }
 
+static void command_get_log(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) {
+    pa_native_connection *c = PA_NATIVE_CONNECTION(userdata);
+    pa_tagstruct *reply;
+    char *buffer;
+
+    pa_native_connection_assert_ref(c);
+    pa_assert(t);
+
+    if (!pa_tagstruct_eof(t)) {
+        protocol_error(c);
+        return;
+    }
+
+    CHECK_VALIDITY(c->pstream, c->authorized, tag, PA_ERR_ACCESS);
+
+    reply = reply_new(tag);
+
+    buffer = get_log_buffer();
+    pa_tagstruct_puts(reply, buffer);
+    pa_xfree(buffer);
+
+    pa_pstream_send_tagstruct(c->pstream, reply);
+}
+
 static void command_get_playback_latency(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) {
     pa_native_connection *c = PA_NATIVE_CONNECTION(userdata);
     pa_tagstruct *reply;
diff --git a/src/utils/pactl.c b/src/utils/pactl.c
index 05a1519..6a8d680 100644
--- a/src/utils/pactl.c
+++ b/src/utils/pactl.c
@@ -93,6 +93,7 @@ static enum {
     NONE,
     EXIT,
     STAT,
+    LOG,
     INFO,
     UPLOAD_SAMPLE,
     PLAY_SAMPLE,
@@ -164,6 +165,12 @@ static void stat_callback(pa_context *c, const pa_stat_info *i, void *userdata)
     complete_action();
 }
 
+static void get_log_callback(pa_context *c, const char *buf, void *userdata) {
+    if (buf != NULL)
+        printf("%s\n", buf);
+    complete_action();
+}
+
 static void get_server_info_callback(pa_context *c, const pa_server_info *i, void *useerdata) {
     char ss[PA_SAMPLE_SPEC_SNPRINT_MAX], cm[PA_CHANNEL_MAP_SNPRINT_MAX];
 
@@ -1081,6 +1088,10 @@ static void context_state_callback(pa_context *c, void *userdata) {
                         break;
                     actions++;
 
+                case LOG:
+                    pa_operation_unref(pa_context_get_log(c, get_log_callback, NULL));
+                    break;
+
                 case INFO:
                     pa_operation_unref(pa_context_get_server_info(c, get_server_info_callback, NULL));
                     break;
@@ -1439,6 +1450,9 @@ int main(int argc, char *argv[]) {
             if (optind+1 < argc && pa_streq(argv[optind+1], "short"))
                 short_list_format = TRUE;
 
+        } else if (pa_streq(argv[optind], "log")) {
+            action = LOG;
+
         } else if (pa_streq(argv[optind], "info"))
             action = INFO;
 
-- 
1.7.6.5



More information about the pulseaudio-discuss mailing list