From 3789289dfd90be0d5b6167662c12f2aecd6bd556 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Tue, 30 Jul 2019 22:55:16 +0200 Subject: [PATCH 01/11] kpb: improve timeout handling in kpb_buffer_data This patch changes the datatype of timeout variable and adds more information into error log message. Also we set up timeout limit right before we enter the while loop. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 94a1b58268d9..f7c59fa8b6ff 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -624,8 +624,8 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, struct comp_data *kpb = comp_get_drvdata(dev); struct hb *buff = kpb->history_buffer; void *read_ptr = source->r_ptr; - size_t timeout = platform_timer_get(platform_timer) + - clock_ms_to_ticks(PLATFORM_DEFAULT_CLOCK, 1); + uint64_t timeout = 0; + uint64_t current_time = 0; enum kpb_state state_preserved = kpb->state; struct dd *draining_data = &kpb->draining_task_data; @@ -639,6 +639,8 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, if (kpb->state == KPB_STATE_DRAINING) draining_data->buffered_while_draining += size_to_copy; + timeout = platform_timer_get(platform_timer) + + clock_ms_to_ticks(PLATFORM_DEFAULT_CLOCK, 1); /* Let's store audio stream data in internal history buffer */ while (size_to_copy) { /* Reset was requested, it's time to stop buffering and finish @@ -651,8 +653,10 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, } /* Are we stuck in buffering? */ - if (timeout < platform_timer_get(platform_timer)) { - trace_kpb_error("kpb_buffer_data(): timeout."); + current_time = platform_timer_get(platform_timer); + if (timeout < current_time) { + trace_kpb_error("kpb_buffer_data(): timeout of %d [ms]", + (current_time - timeout)); return -ETIME; } From 07966044813defb2da28712284019324c426f82c Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Tue, 30 Jul 2019 22:58:19 +0200 Subject: [PATCH 02/11] kpb: add current state log to reset function This patch improves kpb_reset() log message by adding the state from which we start resetting. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index f7c59fa8b6ff..3d6d886557af 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -453,7 +453,7 @@ static int kpb_reset(struct comp_dev *dev) { struct comp_data *kpb = comp_get_drvdata(dev); - trace_kpb("kpb_reset()"); + trace_kpb("kpb_reset(): resetting from state %d", kpb->state); kpb->buffered_data = 0; kpb->is_internal_buffer_full = false; From 2e43318a1a0cf99fe71088efd855c08b96bbe59f Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Tue, 30 Jul 2019 23:01:09 +0200 Subject: [PATCH 03/11] kpb: improve log message in kpb_copy() function This patch adds state to the error log message of kpb_copy() function. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 3d6d886557af..060051286d9c 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -598,7 +598,8 @@ static int kpb_copy(struct comp_dev *dev) ret = PPL_STATUS_PATH_STOP; break; default: - trace_kpb_error("kpb_copy(): wrong state! Copy forbidden."); + trace_kpb_error("kpb_copy(): wrong state - %d! " + " Copy forbidden.", kpb->state); ret = -EIO; break; } From b21dc207c5b1708abf9a8069462ceb214a2975fa Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Wed, 31 Jul 2019 11:57:30 +0200 Subject: [PATCH 04/11] kpb: add internal status logger This patch adds a container of KPB statuses. So every time KPB changes its status it can also log that change. In case of any error this log of status changes can be read back providing nice history of KPB actions. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 060051286d9c..82ee36866770 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -43,6 +43,7 @@ /* KPB private data, runtime data */ struct comp_data { + uint64_t state_log; enum kpb_state state; /**< current state of KPB component */ uint32_t kpb_no_of_clients; /**< number of registered clients */ struct kpb_client clients[KPB_MAX_NO_OF_CLIENTS]; @@ -81,6 +82,8 @@ static void kpb_drain_samples(void *source, struct comp_buffer *sink, static void kpb_reset_history_buffer(struct hb *buff); static inline bool validate_host_params(size_t host_period_size, size_t host_buffer_size); +static inline void kpb_change_state(struct comp_data *kpb, + enum kpb_state state); /** * \brief Create a key phrase buffer component. @@ -145,6 +148,7 @@ static struct comp_dev *kpb_new(struct sof_ipc_comp *comp) /* Init basic component data */ kpb->history_buffer = NULL; kpb->kpb_no_of_clients = 0; + kpb->state_log = 0; /* Kpb has been created successfully */ dev->state = COMP_STATE_READY; @@ -1252,6 +1256,23 @@ static inline bool validate_host_params(size_t host_period_size, return (drained_per_interval > host_period_size) ? true : false; } + +/** + * \brief Change KPB state and log this change internally. + * \param[in] kpb - KPB component data pointer. + * \param[in] state - current KPB state. + * + * \return none. + */ +static inline void kpb_change_state(struct comp_data *kpb, + enum kpb_state state) +{ + trace_kpb("kpb_change_state(): from %d to %d", + kpb->state, state); + kpb->state = state; + kpb->state_log = (kpb->state_log << 4) | state; +} + struct comp_driver comp_kpb = { .type = SOF_COMP_KPB, .ops = { From 6d1ca1e46575ca43d984a26313a9420cf1bec995 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Wed, 31 Jul 2019 12:18:40 +0200 Subject: [PATCH 05/11] kpb: change state only via interface This patch replaces all explicit kpb state changes via a call to dedicated interface which in the same time also logs the change in the internal logger. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 29 ++++++++++++++--------------- src/include/sof/audio/kpb.h | 1 - 2 files changed, 14 insertions(+), 16 deletions(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 82ee36866770..08ecd1d56c34 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -152,7 +152,7 @@ static struct comp_dev *kpb_new(struct sof_ipc_comp *comp) /* Kpb has been created successfully */ dev->state = COMP_STATE_READY; - kpb->state = KPB_STATE_CREATED; + kpb_change_state(kpb, KPB_STATE_CREATED); return dev; } @@ -356,7 +356,7 @@ static int kpb_prepare(struct comp_dev *dev) return PPL_STATUS_PATH_STOP; /* Init private data */ - kpb->state = KPB_STATE_PREPARING; + kpb_change_state(kpb, KPB_STATE_PREPARING); kpb->kpb_no_of_clients = 0; kpb->buffered_data = 0; kpb->host_buffer_size = dev->params.buffer.size; @@ -423,7 +423,7 @@ static int kpb_prepare(struct comp_dev *dev) } } - kpb->state = KPB_STATE_RUN; + kpb_change_state(kpb, KPB_STATE_RUN); return ret; } @@ -470,7 +470,7 @@ static int kpb_reset(struct comp_dev *dev) /* KPB is performing some task now, * terminate it gently. */ - kpb->state = KPB_STATE_RESETTING; + kpb_change_state(kpb, KPB_STATE_RESETTING); return -EBUSY; } @@ -483,9 +483,8 @@ static int kpb_reset(struct comp_dev *dev) /* Unregister KPB for async notification */ notifier_unregister(&kpb->kpb_events); - /* Finally KPB is ready after reset */ - kpb->state = KPB_STATE_PREPARING; + kpb_change_state(kpb, KPB_STATE_PREPARING); return comp_set_state(dev, COMP_TRIGGER_RESET); } @@ -639,7 +638,7 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, if (kpb->state != KPB_STATE_RUN && kpb->state != KPB_STATE_DRAINING) return PPL_STATUS_PATH_STOP; - kpb->state = KPB_STATE_BUFFERING; + kpb_change_state(kpb, KPB_STATE_BUFFERING); if (kpb->state == KPB_STATE_DRAINING) draining_data->buffered_while_draining += size_to_copy; @@ -652,7 +651,7 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, * KPB reset. */ if (kpb->state == KPB_STATE_RESETTING) { - kpb->state = KPB_STATE_RESET_FINISHING; + kpb_change_state(kpb, KPB_STATE_RESET_FINISHING); kpb_reset(dev); return PPL_STATUS_PATH_STOP; } @@ -720,7 +719,7 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, } } - kpb->state = state_preserved; + kpb_change_state(kpb, state_preserved); return ret; } @@ -932,7 +931,6 @@ static void kpb_init_draining(struct comp_dev *dev, struct kpb_client *cli) kpb->draining_task_data.sink = kpb->host_sink; kpb->draining_task_data.history_buffer = buff; kpb->draining_task_data.history_depth = history_depth; - kpb->draining_task_data.state = &kpb->state; kpb->draining_task_data.sample_width = sample_width; kpb->draining_task_data.drain_interval = drain_interval; kpb->draining_task_data.pb_limit = period_bytes_limit; @@ -983,18 +981,19 @@ static enum task_state kpb_draining_task(void *arg) size_t period_copy_start = platform_timer_get(platform_timer); size_t time_taken = 0; size_t *rt_stream_update = &draining_data->buffered_while_draining; + struct comp_data *kpb = comp_get_drvdata(draining_data->dev); trace_kpb("kpb_draining_task(), start."); /* Change KPB internal state to DRAINING */ - *draining_data->state = KPB_STATE_DRAINING; + kpb_change_state(kpb, KPB_STATE_DRAINING); draining_time_start = platform_timer_get(platform_timer); while (history_depth > 0) { /* Have we received reset request? */ - if (*draining_data->state == KPB_STATE_RESETTING) { - *draining_data->state = KPB_STATE_RESET_FINISHING; + if (kpb->state == KPB_STATE_RESETTING) { + kpb_change_state(kpb, KPB_STATE_RESET_FINISHING); kpb_reset(draining_data->dev); goto out; } @@ -1068,8 +1067,8 @@ static enum task_state kpb_draining_task(void *arg) * Note! If KPB state changed during draining due to i.e reset request * we should not change that state. */ - *draining_data->state = (*draining_data->state == KPB_STATE_DRAINING) ? - KPB_STATE_HOST_COPY : *draining_data->state; + if (kpb->state == KPB_STATE_DRAINING) + kpb_change_state(kpb, KPB_STATE_HOST_COPY); /* Reset host-sink copy mode back to unblocking */ comp_set_attribute(sink->sink, COMP_ATTR_COPY_TYPE, ©_type); diff --git a/src/include/sof/audio/kpb.h b/src/include/sof/audio/kpb.h index 9ca9c6df65e2..01875eba490e 100644 --- a/src/include/sof/audio/kpb.h +++ b/src/include/sof/audio/kpb.h @@ -103,7 +103,6 @@ struct dd { struct hb *history_buffer; size_t history_depth; uint8_t is_draining_active; - enum kpb_state *state; size_t sample_width; size_t buffered_while_draining; size_t drain_interval; From 79a05481bb7e8ddf20f0684775994fccdc81dce1 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Wed, 31 Jul 2019 12:53:18 +0200 Subject: [PATCH 06/11] kpb: add history of state changes to some crucial logs This patch adds history of status changes into some important error logs. Thanks to this, in case of some serious failure we can check how KPB was changing its state prior to failure. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 08ecd1d56c34..fd197d7bf367 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -344,7 +344,8 @@ static int kpb_prepare(struct comp_dev *dev) if (kpb->state == KPB_STATE_RESETTING || kpb->state == KPB_STATE_RESET_FINISHING) { trace_kpb_error("kpb_prepare() error: can not prepare KPB " - "due to ongoing reset."); + "due to ongoing reset, state log %d", + kpb->state_log); return -EBUSY; } @@ -457,7 +458,8 @@ static int kpb_reset(struct comp_dev *dev) { struct comp_data *kpb = comp_get_drvdata(dev); - trace_kpb("kpb_reset(): resetting from state %d", kpb->state); + trace_kpb("kpb_reset(): resetting from state %d, state log %d", + kpb->state, kpb->state_log); kpb->buffered_data = 0; kpb->is_internal_buffer_full = false; @@ -601,8 +603,9 @@ static int kpb_copy(struct comp_dev *dev) ret = PPL_STATUS_PATH_STOP; break; default: - trace_kpb_error("kpb_copy(): wrong state - %d! " - " Copy forbidden.", kpb->state); + trace_kpb_error("kpb_copy(): wrong state, copy forbidden. " + "(state %d, state log %d)", + kpb->state, kpb->state_log); ret = -EIO; break; } @@ -659,8 +662,10 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, /* Are we stuck in buffering? */ current_time = platform_timer_get(platform_timer); if (timeout < current_time) { - trace_kpb_error("kpb_buffer_data(): timeout of %d [ms]", - (current_time - timeout)); + trace_kpb_error("kpb_buffer_data(): timeout of %d [ms] " + "(current state %d, state log %d)", + (current_time - timeout), kpb->state, + kpb->state_log); return -ETIME; } From c031dd8664845b42de91dfc8e042944dca0431f9 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Wed, 31 Jul 2019 22:59:11 +0200 Subject: [PATCH 07/11] kpb: check if KPB's sinks have been found at prepare() This patch checks during prepare we managed to find KPB's sinks. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index fd197d7bf367..14a92e985606 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -364,6 +364,8 @@ static int kpb_prepare(struct comp_dev *dev) kpb->host_period_size = dev->params.host_period_bytes; kpb->config.sampling_width = dev->params.sample_container_bytes * 8; kpb->kpb_buffer_size = KPB_MAX_BUFFER_SIZE(kpb->config.sampling_width); + kpb->sel_sink = NULL; + kpb->host_sink = NULL; if (!kpb->history_buffer) { /* Allocate history buffer */ @@ -424,6 +426,13 @@ static int kpb_prepare(struct comp_dev *dev) } } + if (!kpb->sel_sink || !kpb->host_sink) { + trace_kpb("kpb_prepare() error: could not find " + "sinks: sel_sink %d host_sink %d", + (uint32_t)kpb->sel_sink, (uint32_t)kpb->host_sink); + ret = -EIO; + } + kpb_change_state(kpb, KPB_STATE_RUN); return ret; From 49eb7c0d5dae816608a299d75038f785850711f7 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Thu, 1 Aug 2019 16:56:03 +0200 Subject: [PATCH 08/11] kpb: improve reset handling This patch improves KPB reset handling by adding explicit state handling. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 50 ++++++++++++++++++++++++++++--------------------- 1 file changed, 29 insertions(+), 21 deletions(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 14a92e985606..c73702911a76 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -466,38 +466,46 @@ static void kpb_cache(struct comp_dev *dev, int cmd) static int kpb_reset(struct comp_dev *dev) { struct comp_data *kpb = comp_get_drvdata(dev); + int ret = 0; trace_kpb("kpb_reset(): resetting from state %d, state log %d", kpb->state, kpb->state_log); - kpb->buffered_data = 0; - kpb->is_internal_buffer_full = false; - - /* Change KPB state to RESET. If there is any ongoing job it will - * shut itself gracefully first. - */ - if (kpb->state == KPB_STATE_BUFFERING || - kpb->state == KPB_STATE_DRAINING) { + switch (kpb->state) { + case KPB_STATE_BUFFERING: + case KPB_STATE_DRAINING: /* KPB is performing some task now, * terminate it gently. */ kpb_change_state(kpb, KPB_STATE_RESETTING); - return -EBUSY; - } + ret = -EBUSY; + break; + case KPB_STATE_DISABLED: + case KPB_STATE_CREATED: + /* Nothing to reset */ + ret = comp_set_state(dev, COMP_TRIGGER_RESET); + break; + default: + kpb->buffered_data = 0; + kpb->is_internal_buffer_full = false; - if (kpb->history_buffer) { - /* Reset history buffer - zero its data reset pointers - * and states. - */ - kpb_reset_history_buffer(kpb->history_buffer); - } + if (kpb->history_buffer) { + /* Reset history buffer - zero its data, reset pointers + * and states. + */ + kpb_reset_history_buffer(kpb->history_buffer); + } - /* Unregister KPB for async notification */ - notifier_unregister(&kpb->kpb_events); - /* Finally KPB is ready after reset */ - kpb_change_state(kpb, KPB_STATE_PREPARING); + /* Unregister KPB for async notification */ + notifier_unregister(&kpb->kpb_events); + /* Finally KPB is ready after reset */ + kpb_change_state(kpb, KPB_STATE_PREPARING); - return comp_set_state(dev, COMP_TRIGGER_RESET); + ret = comp_set_state(dev, COMP_TRIGGER_RESET); + break; + } + + return ret; } /** From 13a428cd35d1f287a123a3a1dc60817d3b0676a9 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Thu, 1 Aug 2019 23:55:12 +0200 Subject: [PATCH 09/11] kpb: fix buffering size during draining This patch fixes the bug of zero buffering size during draining. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index c73702911a76..836ec846f2a4 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -605,7 +605,7 @@ static int kpb_copy(struct comp_dev *dev) * history buffer. */ if (source->avail <= kpb->kpb_buffer_size) { - ret = kpb_buffer_data(dev, source, copy_bytes); + ret = kpb_buffer_data(dev, source, source->avail); if (ret) { trace_kpb_error("kpb_copy(): internal " "buffering failed."); From 62e858f81a4232dbb610d7d43ee4e54253cfd855 Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Thu, 1 Aug 2019 21:23:00 +0200 Subject: [PATCH 10/11] kpb: log error and stop pipeline copy if no bytes to copy This patch checks if "copy_bytes" which is the minimum of sink->free and source->avail is != 0. If so we go further with copy and internal buffering. If no we log error message and return from copy function. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 836ec846f2a4..887a880d7231 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -555,6 +555,14 @@ static int kpb_copy(struct comp_dev *dev) } copy_bytes = MIN(sink->free, source->avail); + if (!copy_bytes) { + trace_kpb_error("kpb_copy() error: nothing to copy " + "sink->free %d source->avail %d", + sink->free, source->avail); + ret = PPL_STATUS_PATH_STOP; + goto out; + } + kpb_copy_samples(sink, source, copy_bytes, sample_width); /* Buffer source data internally in history buffer for future @@ -593,12 +601,20 @@ static int kpb_copy(struct comp_dev *dev) } copy_bytes = MIN(sink->free, source->avail); + if (!copy_bytes) { + trace_kpb_error("kpb_copy() error: nothing to copy " + "sink->free %d source->avail %d", + sink->free, source->avail); + ret = PPL_STATUS_PATH_STOP; + goto out; + } + kpb_copy_samples(sink, source, copy_bytes, sample_width); comp_update_buffer_produce(sink, copy_bytes); comp_update_buffer_consume(source, copy_bytes); - ret = 0; + ret = PPL_STATUS_PATH_STOP; break; case KPB_STATE_DRAINING: /* In draining state we only buffer data in internal, From b286510260bcfc6a9a31e6bce28e02136dd8c49b Mon Sep 17 00:00:00 2001 From: Marcin Rajwa Date: Tue, 27 Aug 2019 23:04:15 +0200 Subject: [PATCH 11/11] kpb: fix premature state change in buffering function This patch fixes state change in buffering function before the check of state from previous stage. This issue resulted in missing samples from stream during draining. Signed-off-by: Marcin Rajwa --- src/audio/kpb.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/audio/kpb.c b/src/audio/kpb.c index 887a880d7231..fa059d3ddf50 100644 --- a/src/audio/kpb.c +++ b/src/audio/kpb.c @@ -674,11 +674,11 @@ static int kpb_buffer_data(struct comp_dev *dev, struct comp_buffer *source, if (kpb->state != KPB_STATE_RUN && kpb->state != KPB_STATE_DRAINING) return PPL_STATUS_PATH_STOP; - kpb_change_state(kpb, KPB_STATE_BUFFERING); - if (kpb->state == KPB_STATE_DRAINING) draining_data->buffered_while_draining += size_to_copy; + kpb_change_state(kpb, KPB_STATE_BUFFERING); + timeout = platform_timer_get(platform_timer) + clock_ms_to_ticks(PLATFORM_DEFAULT_CLOCK, 1); /* Let's store audio stream data in internal history buffer */