There's a bug[1] where memblockq crashes in an assertion, and it seems to be a bug in memblockq code. The assertion might in theory contain enough information for figuring out the bug, but in practice the code is too complex to do that (at least for me). This patch saves a snapshot of the memblockq state to a history buffer whenever the state changes. The history data can then be used to see what the memblockq state was just before the crashing pa_memblockq_push() call, and what has been happening in the queue prior to that. The history logging is disabled by default to ensure that it doesn't cause any performance problems in normal use. [1] https://bugs.freedesktop.org/show_bug.cgi?id=45373 --- src/pulsecore/memblockq.c | 477 +++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 456 insertions(+), 21 deletions(-) diff --git a/src/pulsecore/memblockq.c b/src/pulsecore/memblockq.c index 4eeb4d6..967d5ea 100644 --- a/src/pulsecore/memblockq.c +++ b/src/pulsecore/memblockq.c @@ -38,6 +38,24 @@ /* #define MEMBLOCKQ_DEBUG */ +#ifndef ENABLE_MEMBLOCKQ_HISTORY +#define ENABLE_MEMBLOCKQ_HISTORY 0 +#endif + +/* On my machine with the current implementation (2012-04-28) the size of one + * history item is 1744 bytes, so in total the history memory consumption is + * 50 * 1744 = 87.2 kB per memblockq. One chunk_info struct is 16 bytes, so + * with 100 chunks the chunk list takes 1.6 kB per history item. */ +#define HISTORY_N_ITEMS 50 +#define HISTORY_MAX_N_BLOCKS 100 + +static void prebuf_force_internal(pa_memblockq *bq, pa_bool_t log_to_history); +static void set_maxlength_internal(pa_memblockq *bq, size_t maxlength, pa_bool_t log_to_history); +static void set_tlength_internal(pa_memblockq *bq, size_t tlength, pa_bool_t log_to_history); +static void set_minreq_internal(pa_memblockq *bq, size_t minreq, pa_bool_t log_to_history); +static void set_prebuf_internal(pa_memblockq *bq, size_t prebuf, pa_bool_t log_to_history); +static void set_maxrewind_internal(pa_memblockq *bq, size_t maxrewind, pa_bool_t log_to_history); + struct list_item { struct list_item *next, *prev; int64_t index; @@ -46,6 +64,99 @@ struct list_item { PA_STATIC_FLIST_DECLARE(list_items, 0, pa_xfree); +enum operation { + OPERATION_NEW, + OPERATION_PUSH, + OPERATION_SEEK, + OPERATION_PEEK, + OPERATION_DROP, + OPERATION_REWIND, + OPERATION_POP_MISSING, + OPERATION_FLUSH_WRITE, + OPERATION_FLUSH_READ, + OPERATION_PREBUF_DISABLE, + OPERATION_PREBUF_FORCE, + OPERATION_SET_MAXLENGTH, + OPERATION_SET_TLENGTH, + OPERATION_SET_MINREQ, + OPERATION_SET_PREBUF, + OPERATION_SET_MAXREWIND, + OPERATION_SET_SILENCE, + OPERATION_APPLY_ATTR +}; + +struct chunk_info { + int64_t index; + size_t chunk_length; +}; + +struct memblockq_state { + struct chunk_info chunk_list[HISTORY_MAX_N_BLOCKS]; + struct chunk_info *current_read, *current_write; + unsigned n_blocks; + size_t maxlength, tlength, prebuf, minreq, maxrewind; + int64_t read_index, write_index; + pa_bool_t in_prebuf; + int64_t missing, requested; + pa_bool_t has_silence; +}; + +struct history_item { + enum operation op; + union { + struct { + size_t uchunk_length; + } push_info; + + struct { + int64_t offset; + pa_seek_mode_t seek; + pa_bool_t account; + } seek_info; + + struct { + size_t length; + } drop_info; + + struct { + size_t length; + } rewind_info; + + struct { + pa_bool_t account; + } flush_write_info; + + struct { + size_t maxlength; + } set_maxlength_info; + + struct { + size_t tlength; + } set_tlength_info; + + struct { + size_t prebuf; + } set_prebuf_info; + + struct { + size_t minreq; + } set_minreq_info; + + struct { + size_t maxrewind; + } set_maxrewind_info; + + struct { + pa_memchunk *silence; /* Usually an invalid pointer, don't dereference! */ + } set_silence_info; + + struct { + pa_buffer_attr a; + } apply_attr_info; + }; + struct memblockq_state state; +}; + struct pa_memblockq { struct list_item *blocks, *blocks_tail; struct list_item *current_read, *current_write; @@ -58,8 +169,214 @@ struct pa_memblockq { int64_t missing, requested; char *name; pa_sample_spec sample_spec; + + pa_bool_t history_enabled; + struct history_item *history; + unsigned first_history_item_index; + unsigned last_history_item_index; + pa_bool_t history_is_empty; }; +static void save_state(pa_memblockq *bq, enum operation op) { + struct memblockq_state *state; + struct list_item *item; + unsigned i; + + pa_assert(bq); + pa_assert(bq->history_enabled); + + bq->last_history_item_index++; + + if (bq->last_history_item_index >= HISTORY_N_ITEMS) + bq->last_history_item_index = 0; + + if (bq->last_history_item_index == bq->first_history_item_index && !bq->history_is_empty) + bq->first_history_item_index++; + + if (bq->first_history_item_index >= HISTORY_N_ITEMS) + bq->first_history_item_index = 0; + + bq->history_is_empty = FALSE; + + bq->history[bq->last_history_item_index].op = op; + state = &bq->history[bq->last_history_item_index].state; + + pa_assert_se((state->n_blocks = bq->n_blocks) <= HISTORY_MAX_N_BLOCKS); + + state->current_read = NULL; + state->current_write = NULL; + + for (i = 0, item = bq->blocks; item; item = item->next, i++) { + state->chunk_list[i].index = item->index; + state->chunk_list[i].chunk_length = item->chunk.length; + + if (item == bq->current_read) + state->current_read = &state->chunk_list[i]; + + if (item == bq->current_write) + state->current_write = &state->chunk_list[i]; + } + + state->maxlength = bq->maxlength; + state->tlength = bq->tlength; + state->prebuf = bq->prebuf; + state->minreq = bq->minreq; + state->maxrewind = bq->maxrewind; + state->read_index = bq->read_index; + state->write_index = bq->write_index; + state->in_prebuf = bq->in_prebuf; + state->missing = bq->missing; + state->requested = bq->requested; + state->has_silence = !!bq->silence.memblock; +} + +static const char *seek_mode_to_string(pa_seek_mode_t mode) { + static const char *table[] = { + [PA_SEEK_RELATIVE] = "PA_SEEK_RELATIVE", + [PA_SEEK_ABSOLUTE] = "PA_SEEK_ABSOLUTE", + [PA_SEEK_RELATIVE_ON_READ] = "PA_SEEK_RELATIVE_ON_READ", + [PA_SEEK_RELATIVE_END] = "PA_SEEK_RELATIVE_END" + }; + + return table[mode]; +} + +static void dump_history_item(struct history_item *item) { + unsigned i; + + pa_assert(item); + + switch (item->op) { + case OPERATION_NEW: + pa_log("pa_memblockq_new()"); + break; + + case OPERATION_PUSH: + pa_log("pa_memblockq_push(uchunk->length = %zu)", item->push_info.uchunk_length); + break; + + case OPERATION_SEEK: + pa_log("pa_memblockq_seek(offest = %" PRId64 ", seek = %s, account = %s)", + item->seek_info.offset, seek_mode_to_string(item->seek_info.seek), pa_yes_no(item->seek_info.account)); + break; + + case OPERATION_PEEK: + pa_log("pa_memblockq_peek()"); + break; + + case OPERATION_DROP: + pa_log("pa_memblockq_drop(length = %zu)", item->drop_info.length); + break; + + case OPERATION_REWIND: + pa_log("pa_memblockq_rewind(length = %zu)", item->rewind_info.length); + break; + + case OPERATION_POP_MISSING: + pa_log("pa_memblockq_pop_missing()"); + break; + + case OPERATION_FLUSH_WRITE: + pa_log("pa_memblockq_flush_write(account = %s)", pa_yes_no(item->flush_write_info.account)); + break; + + case OPERATION_FLUSH_READ: + pa_log("pa_memblockq_flush_read()"); + break; + + case OPERATION_PREBUF_DISABLE: + pa_log("pa_memblockq_prebuf_disable()"); + break; + + case OPERATION_PREBUF_FORCE: + pa_log("pa_memblockq_prebuf_force()"); + break; + + case OPERATION_SET_MAXLENGTH: + pa_log("pa_memblockq_set_maxlength(maxlength = %zu)", item->set_maxlength_info.maxlength); + break; + + case OPERATION_SET_TLENGTH: + pa_log("pa_memblockq_set_tlength(tlength = %zu)", item->set_tlength_info.tlength); + break; + + case OPERATION_SET_MINREQ: + pa_log("pa_memblockq_set_minreq(minreq = %zu)", item->set_minreq_info.minreq); + break; + + case OPERATION_SET_PREBUF: + pa_log("pa_memblockq_set_prebuf(prebuf = %zu)", item->set_prebuf_info.prebuf); + break; + + case OPERATION_SET_MAXREWIND: + pa_log("pa_memblockq_set_maxrewind(maxrewind = %zu)", item->set_maxrewind_info.maxrewind); + break; + + case OPERATION_SET_SILENCE: + pa_log("pa_memblockq_set_silence(%p)", item->set_silence_info.silence); + break; + + case OPERATION_APPLY_ATTR: + pa_log("pa_memblockq_apply_attr(a->maxlength = %" PRIu32 ", a->tlength = %" PRIu32 ", a->prebuf = %" PRIu32 ", a->minreq = %" PRIu32 ", a->fragsize = %" PRIu32 ")", + item->apply_attr_info.a.maxlength, + item->apply_attr_info.a.tlength, + item->apply_attr_info.a.prebuf, + item->apply_attr_info.a.minreq, + item->apply_attr_info.a.fragsize); + break; + + default: + pa_assert_not_reached(); + } + + pa_log(" maxlength: %zu", item->state.maxlength); + pa_log(" tlength: %zu", item->state.tlength); + pa_log(" prebuf: %zu", item->state.prebuf); + pa_log(" minreq: %zu", item->state.minreq); + pa_log(" maxrewind: %zu", item->state.maxrewind); + pa_log(" in prebuf: %s", pa_yes_no(item->state.in_prebuf)); + pa_log(" missing: %" PRId64, item->state.missing); + pa_log(" requested: %" PRId64, item->state.requested); + pa_log(" has silence: %s", pa_yes_no(item->state.has_silence)); + pa_log(" read index: %10" PRId64 " write index: %10" PRId64, item->state.read_index, item->state.write_index); + + pa_log("Blocks:"); + + for (i = 0; i < item->state.n_blocks; i++) + pa_log(" index: %10" PRId64 " length: %5zu%s%s", + item->state.chunk_list[i].index, + item->state.chunk_list[i].chunk_length, + &item->state.chunk_list[i] == item->state.current_read ? " (current read)" : "", + &item->state.chunk_list[i] == item->state.current_write ? " (current write)" : ""); + + if (i == 0) + pa_log("(no blocks)"); + + pa_log("---"); +} + +PA_GCC_UNUSED static void dump_history(pa_memblockq *bq) { + unsigned i; + + pa_assert(bq); + pa_assert(bq->history_enabled); + + pa_log("Dumping memblockq history."); + pa_log("General memblockq information:"); + pa_log(" name: \"%s\"", bq->name); + pa_log(" sample spec: format=%s rate=%" PRIu32 " channels=%" PRIu8, pa_sample_format_to_string(bq->sample_spec.format), bq->sample_spec.rate, bq->sample_spec.channels); + pa_log(" base: %zu", bq->base); + pa_log("---"); + + if (bq->first_history_item_index > bq->last_history_item_index) { + for (i = bq->first_history_item_index; i < HISTORY_N_ITEMS; i++) + dump_history_item(&bq->history[i]); + } + + for (i = 0; i <= bq->last_history_item_index; i++) + dump_history_item(&bq->history[i]); +} + pa_memblockq* pa_memblockq_new( const char *name, int64_t idx, @@ -88,11 +405,11 @@ pa_memblockq* pa_memblockq_new( bq->in_prebuf = TRUE; - pa_memblockq_set_maxlength(bq, maxlength); - pa_memblockq_set_tlength(bq, tlength); - pa_memblockq_set_minreq(bq, minreq); - pa_memblockq_set_prebuf(bq, prebuf); - pa_memblockq_set_maxrewind(bq, maxrewind); + set_maxlength_internal(bq, maxlength, FALSE); + set_tlength_internal(bq, tlength, FALSE); + set_minreq_internal(bq, minreq, FALSE); + set_prebuf_internal(bq, prebuf, FALSE); + set_maxrewind_internal(bq, maxrewind, FALSE); pa_log_debug("memblockq sanitized: maxlength=%lu, tlength=%lu, base=%lu, prebuf=%lu, minreq=%lu maxrewind=%lu", (unsigned long) bq->maxlength, (unsigned long) bq->tlength, (unsigned long) bq->base, (unsigned long) bq->prebuf, (unsigned long) bq->minreq, (unsigned long) bq->maxrewind); @@ -104,6 +421,16 @@ pa_memblockq* pa_memblockq_new( bq->mcalign = pa_mcalign_new(bq->base); +#if ENABLE_MEMBLOCKQ_HISTORY + bq->history_enabled = TRUE; + bq->history = pa_xnew0(struct history_item, HISTORY_N_ITEMS); + bq->last_history_item_index = HISTORY_N_ITEMS - 1; +#endif + bq->history_is_empty = TRUE; + + if (bq->history_enabled) + save_state(bq, OPERATION_NEW); + return bq; } @@ -440,6 +767,12 @@ int pa_memblockq_push(pa_memblockq* bq, const pa_memchunk *uchunk) { finish: write_index_changed(bq, old, TRUE); + + if (bq->history_enabled) { + save_state(bq, OPERATION_PUSH); + bq->history[bq->last_history_item_index].push_info.uchunk_length = uchunk->length; + } + return 0; } @@ -528,6 +861,9 @@ int pa_memblockq_peek(pa_memblockq* bq, pa_memchunk *chunk) { chunk->index += (size_t) d; chunk->length -= (size_t) d; + if (bq->history_enabled) + save_state(bq, OPERATION_PEEK); + return 0; } @@ -603,6 +939,8 @@ int pa_memblockq_peek_fixed_size(pa_memblockq *bq, size_t block_size, pa_memchun void pa_memblockq_drop(pa_memblockq *bq, size_t length) { int64_t old; + size_t original_length = length; + pa_assert(bq); pa_assert(length % bq->base == 0); @@ -642,6 +980,11 @@ void pa_memblockq_drop(pa_memblockq *bq, size_t length) { drop_backlog(bq); read_index_changed(bq, old); + + if (bq->history_enabled) { + save_state(bq, OPERATION_DROP); + bq->history[bq->last_history_item_index].drop_info.length = original_length; + } } void pa_memblockq_rewind(pa_memblockq *bq, size_t length) { @@ -656,6 +999,11 @@ void pa_memblockq_rewind(pa_memblockq *bq, size_t length) { bq->read_index -= (int64_t) length; read_index_changed(bq, old); + + if (bq->history_enabled) { + save_state(bq, OPERATION_REWIND); + bq->history[bq->last_history_item_index].rewind_info.length = length; + } } pa_bool_t pa_memblockq_is_readable(pa_memblockq *bq) { @@ -716,6 +1064,13 @@ void pa_memblockq_seek(pa_memblockq *bq, int64_t offset, pa_seek_mode_t seek, pa drop_backlog(bq); write_index_changed(bq, old, account); + + if (bq->history_enabled) { + save_state(bq, OPERATION_SEEK); + bq->history[bq->last_history_item_index].seek_info.offset = offset; + bq->history[bq->last_history_item_index].seek_info.seek = seek; + bq->history[bq->last_history_item_index].seek_info.account = account; + } } void pa_memblockq_flush_write(pa_memblockq *bq, pa_bool_t account) { @@ -727,8 +1082,13 @@ void pa_memblockq_flush_write(pa_memblockq *bq, pa_bool_t account) { old = bq->write_index; bq->write_index = bq->read_index; - pa_memblockq_prebuf_force(bq); + prebuf_force_internal(bq, FALSE); write_index_changed(bq, old, account); + + if (bq->history_enabled) { + save_state(bq, OPERATION_FLUSH_WRITE); + bq->history[bq->last_history_item_index].flush_write_info.account = account; + } } void pa_memblockq_flush_read(pa_memblockq *bq) { @@ -740,8 +1100,11 @@ void pa_memblockq_flush_read(pa_memblockq *bq) { old = bq->read_index; bq->read_index = bq->write_index; - pa_memblockq_prebuf_force(bq); + prebuf_force_internal(bq, FALSE); read_index_changed(bq, old); + + if (bq->history_enabled) + save_state(bq, OPERATION_FLUSH_READ); } size_t pa_memblockq_get_tlength(pa_memblockq *bq) { @@ -806,13 +1169,23 @@ void pa_memblockq_prebuf_disable(pa_memblockq *bq) { pa_assert(bq); bq->in_prebuf = FALSE; + + if (bq->history_enabled) + save_state(bq, OPERATION_PREBUF_DISABLE); } -void pa_memblockq_prebuf_force(pa_memblockq *bq) { +static void prebuf_force_internal(pa_memblockq *bq, pa_bool_t log_to_history) { pa_assert(bq); if (bq->prebuf > 0) bq->in_prebuf = TRUE; + + if (log_to_history && bq->history_enabled) + save_state(bq, OPERATION_PREBUF_FORCE); +} + +void pa_memblockq_prebuf_force(pa_memblockq *bq) { + prebuf_force_internal(bq, TRUE); } size_t pa_memblockq_get_maxlength(pa_memblockq *bq) { @@ -848,10 +1221,13 @@ size_t pa_memblockq_pop_missing(pa_memblockq *bq) { pa_log("[%s] sent %lli: request counter is at %lli", bq->name, (long long) l, (long long) bq->requested); #endif + if (bq->history_enabled) + save_state(bq, OPERATION_POP_MISSING); + return l; } -void pa_memblockq_set_maxlength(pa_memblockq *bq, size_t maxlength) { +static void set_maxlength_internal(pa_memblockq *bq, size_t maxlength, pa_bool_t log_to_history) { pa_assert(bq); bq->maxlength = ((maxlength+bq->base-1)/bq->base)*bq->base; @@ -860,11 +1236,22 @@ void pa_memblockq_set_maxlength(pa_memblockq *bq, size_t maxlength) { bq->maxlength = bq->base; if (bq->tlength > bq->maxlength) - pa_memblockq_set_tlength(bq, bq->maxlength); + set_tlength_internal(bq, bq->maxlength, FALSE); + + if (log_to_history && bq->history_enabled) { + save_state(bq, OPERATION_SET_MAXLENGTH); + bq->history[bq->last_history_item_index].set_maxlength_info.maxlength = maxlength; + } } -void pa_memblockq_set_tlength(pa_memblockq *bq, size_t tlength) { +void pa_memblockq_set_maxlength(pa_memblockq *bq, size_t maxlength) { + set_maxlength_internal(bq, maxlength, TRUE); +} + +static void set_tlength_internal(pa_memblockq *bq, size_t tlength, pa_bool_t log_to_history) { size_t old_tlength; + size_t original_tlength = tlength; + pa_assert(bq); if (tlength <= 0 || tlength == (size_t) -1) @@ -877,15 +1264,24 @@ void pa_memblockq_set_tlength(pa_memblockq *bq, size_t tlength) { bq->tlength = bq->maxlength; if (bq->minreq > bq->tlength) - pa_memblockq_set_minreq(bq, bq->tlength); + set_minreq_internal(bq, bq->tlength, FALSE); if (bq->prebuf > bq->tlength+bq->base-bq->minreq) - pa_memblockq_set_prebuf(bq, bq->tlength+bq->base-bq->minreq); + set_prebuf_internal(bq, bq->tlength + bq->base-bq->minreq, FALSE); bq->missing += (int64_t) bq->tlength - (int64_t) old_tlength; + + if (log_to_history && bq->history_enabled) { + save_state(bq, OPERATION_SET_TLENGTH); + bq->history[bq->last_history_item_index].set_tlength_info.tlength = original_tlength; + } } -void pa_memblockq_set_minreq(pa_memblockq *bq, size_t minreq) { +void pa_memblockq_set_tlength(pa_memblockq *bq, size_t tlength) { + set_tlength_internal(bq, tlength, TRUE); +} + +static void set_minreq_internal(pa_memblockq *bq, size_t minreq, pa_bool_t log_to_history) { pa_assert(bq); bq->minreq = (minreq/bq->base)*bq->base; @@ -897,10 +1293,21 @@ void pa_memblockq_set_minreq(pa_memblockq *bq, size_t minreq) { bq->minreq = bq->base; if (bq->prebuf > bq->tlength+bq->base-bq->minreq) - pa_memblockq_set_prebuf(bq, bq->tlength+bq->base-bq->minreq); + set_prebuf_internal(bq, bq->tlength + bq->base-bq->minreq, FALSE); + + if (log_to_history && bq->history_enabled) { + save_state(bq, OPERATION_SET_MINREQ); + bq->history[bq->last_history_item_index].set_minreq_info.minreq = minreq; + } } -void pa_memblockq_set_prebuf(pa_memblockq *bq, size_t prebuf) { +void pa_memblockq_set_minreq(pa_memblockq *bq, size_t minreq) { + set_minreq_internal(bq, minreq, TRUE); +} + +static void set_prebuf_internal(pa_memblockq *bq, size_t prebuf, pa_bool_t log_to_history) { + size_t original_prebuf = prebuf; + pa_assert(bq); if (prebuf == (size_t) -1) @@ -916,22 +1323,45 @@ void pa_memblockq_set_prebuf(pa_memblockq *bq, size_t prebuf) { if (bq->prebuf <= 0 || pa_memblockq_get_length(bq) >= bq->prebuf) bq->in_prebuf = FALSE; + + if (log_to_history && bq->history_enabled) { + save_state(bq, OPERATION_SET_PREBUF); + bq->history[bq->last_history_item_index].set_prebuf_info.prebuf = original_prebuf; + } } -void pa_memblockq_set_maxrewind(pa_memblockq *bq, size_t maxrewind) { +void pa_memblockq_set_prebuf(pa_memblockq *bq, size_t prebuf) { + set_prebuf_internal(bq, prebuf, TRUE); +} + +static void set_maxrewind_internal(pa_memblockq *bq, size_t maxrewind, pa_bool_t log_to_history) { pa_assert(bq); bq->maxrewind = (maxrewind/bq->base)*bq->base; + + if (log_to_history && bq->history_enabled) { + save_state(bq, OPERATION_SET_MAXREWIND); + bq->history[bq->last_history_item_index].set_maxrewind_info.maxrewind = maxrewind; + } +} + +void pa_memblockq_set_maxrewind(pa_memblockq *bq, size_t maxrewind) { + set_maxrewind_internal(bq, maxrewind, TRUE); } void pa_memblockq_apply_attr(pa_memblockq *bq, const pa_buffer_attr *a) { pa_assert(bq); pa_assert(a); - pa_memblockq_set_maxlength(bq, a->maxlength); - pa_memblockq_set_tlength(bq, a->tlength); - pa_memblockq_set_minreq(bq, a->minreq); - pa_memblockq_set_prebuf(bq, a->prebuf); + set_maxlength_internal(bq, a->maxlength, FALSE); + set_tlength_internal(bq, a->tlength, FALSE); + set_minreq_internal(bq, a->minreq, FALSE); + set_prebuf_internal(bq, a->prebuf, FALSE); + + if (bq->history_enabled) { + save_state(bq, OPERATION_APPLY_ATTR); + bq->history[bq->last_history_item_index].apply_attr_info.a = *a; + } } void pa_memblockq_get_attr(pa_memblockq *bq, pa_buffer_attr *a) { @@ -996,6 +1426,11 @@ void pa_memblockq_set_silence(pa_memblockq *bq, pa_memchunk *silence) { pa_memblock_ref(bq->silence.memblock); } else pa_memchunk_reset(&bq->silence); + + if (bq->history_enabled) { + save_state(bq, OPERATION_SET_SILENCE); + bq->history[bq->last_history_item_index].set_silence_info.silence = silence; + } } pa_bool_t pa_memblockq_is_empty(pa_memblockq *bq) { -- 1.7.10
