[pulseaudio-discuss] [PATCH] proof of concept: use pactl log to get the buffer log
Tanu Kaskinen
tanuk at iki.fi
Mon Apr 2 10:07:33 PDT 2012
Hi Deng[1],
Very nice patch, I'm impressed! If it weren't for the threading issues,
it's almost merge-quality; I found only minor things to complain about.
Or well, there seems to be a quite bad bug in get_log_buffer(), but that
should be easy to fix.
Have you tried if it works with a full buffer? One megabyte sounds like
something that the tagstruct system might reject. I didn't find any code
that would limit the tag size, though, except for proplists, so probably
it will work just fine. (Sidenote: if there are no string size
limitations in the protocol, I think that's a bug, because clients can
fool the server, and vice versa, into allocating unlimited amounts of
memory.)
As you say, the code isn't really safe to be used from multiple threads.
It's not obvious to me how this should be solved, because logging from
realtime threads should be lock-free. Needs some thinking...
Please read [2], it contains documentation about the coding style rules.
[1] Do you prefer to be called "Deng" or "Zhengrong" (or something
else)? AFAIK Chinese names have different conventions than western
names, so I don't know if it's correct to just pick the first name...
[2] http://www.freedesktop.org/wiki/Software/PulseAudio/Documentation/Developer/CodingStyle
-- Tanu
PS. The rest of my review comments are written as inline comments below:
On Sun, 2012-04-01 at 11:12 +0800, Deng Zhenrong wrote:
> 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);
Coding style: please add an empty line after variable declarations.
> + memcpy(result, &log_buffer[log_start_index], log_used_length);
> + result[log_used_length] = '\0';
> +
> + return result;
> +}
Shouldn't this copy the buffer in two parts: from log_start_index to the
end of the buffer, and then from the beginning of the buffer to
log_end_index?
> +
> +static void write_to_circular_buffer(const char *p, size_t len) {
> + const char *base = p;
> +
> + while (len > 0) {
Instead of looping, wouldn't it make sense to just write the tail of the
log message if it can't fully fit in the buffer? The end result would
anyway be the same.
> + size_t first_chunk;
I'd prefer "first_chunk_len".
> + size_t min = len;
I don't quite get this variable name. But if you get rid of the looping,
this shouldn't be needed anyway.
> + 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.
Coding style: please use only the /* */ syntax for comments.
> + 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.
Coding style: please wrap comments at 80 chars.
> + 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();
Should have pa_log prefix, i.e. pa_log_get_buffer(). Oh, another thing
came to my mind: I believe it's not a good idea to declare functions
with an empty argument list, because that gets translated (for legacy
reasons) to "...", i.e. any number of arguments. The declaration should
be pa_log_get_buffer(void);
Also, pa_log_get_buffer_copy(void) would make it more obvious that the
function is returning a new string that the caller has to free.
More information about the pulseaudio-discuss
mailing list