st-hal: Update latency logging
Previously, the systrace measuring the buffer reads from LSM was
handled by having a single measurement of the 2 second transfer
latency. Now that the keyword start is determined by the preroll,
it is more sensible to measure the LSM buffer reads individually.
Also print FTRT latency and second stage latency logs.
Change-Id: I982ebceeb1695acdb70dd775a71d628b40818a3e
diff --git a/st_hw_session_lsm.c b/st_hw_session_lsm.c
index a2c41c4..8f7cdd1 100644
--- a/st_hw_session_lsm.c
+++ b/st_hw_session_lsm.c
@@ -1377,9 +1377,9 @@
st_arm_second_stage_t *st_sec_stage = NULL;
unsigned int prepend_bytes = 0, cnn_append_bytes = 0, vop_append_bytes = 0;
unsigned int kw_duration_bytes = 0;
- bool real_time_check = false;
+ bool real_time_check = true;
uint64_t frame_receive_time = 0, frame_send_time = 0;
- uint64_t frame_read_time = 0;
+ uint64_t frame_read_time = 0, buffering_start_time = 0;
ST_DBG_DECLARE(FILE *fptr_drv = NULL; static int file_cnt = 0);
ST_DBG_FILE_OPEN_WR(fptr_drv, ST_DEBUG_DUMP_LOCATION,
@@ -1479,22 +1479,20 @@
p_lsm_ses->move_client_ptr = true;
else
p_lsm_ses->move_client_ptr = false;
-
- if (!p_lsm_ses->common.is_generic_event)
- real_time_check = true;
}
- ST_DBG_ATRACE_ASYNC_BEGIN_IF(!(dbg_trace_lab_buf_cnt = 0),"sthal:lsm:ape: lsm_buffer_read",
- p_lsm_ses->common.sm_handle);
+ buffering_start_time = get_current_time_ns();
while (!p_lsm_ses->exit_lab_processing) {
ALOGVV("%s: pcm_read reading bytes=%d", __func__, p_lsm_ses->lab_drv_buf_size);
pthread_mutex_unlock(&p_lsm_ses->lock);
frame_send_time = get_current_time_ns();
+ ATRACE_ASYNC_BEGIN("sthal:lsm:ape: pcm_read",
+ p_lsm_ses->common.sm_handle);
status = pcm_read(p_lsm_ses->pcm, p_lsm_ses->lab_drv_buf, p_lsm_ses->lab_drv_buf_size);
+ ATRACE_ASYNC_END("sthal:lsm:ape: pcm_read",
+ p_lsm_ses->common.sm_handle);
pthread_mutex_lock(&p_lsm_ses->lock);
- ST_DBG_ATRACE_ASYNC_END_IF((++dbg_trace_lab_buf_cnt == dbg_trace_max_lab_reads),
- "sthal:lsm:ape: lsm_buffer_read", p_lsm_ses->common.sm_handle);
frame_receive_time = get_current_time_ns();
ALOGVV("%s: pcm_read done", __func__);
@@ -1513,15 +1511,20 @@
frame_read_time = frame_receive_time - frame_send_time;
if (real_time_check &&
(frame_read_time > APE_MAX_LAB_FTRT_FRAME_RD_TIME_NS)) {
- uint32_t bytes_written_ms =
- convert_bytes_to_ms(p_lsm_ses->bytes_written,
- &p_lsm_ses->common.config);
+ uint32_t ftrt_bytes_written_ms =
+ convert_bytes_to_ms(p_lsm_ses->bytes_written -
+ p_lsm_ses->lab_drv_buf_size, &p_lsm_ses->common.config);
- ALOGD("%s: Real time frame received after %dms took %llums",
- __func__, bytes_written_ms,
- (frame_read_time / NSECS_PER_MSEC));
- adjust_ss_buff_end(&p_lsm_ses->common, cnn_append_bytes,
- vop_append_bytes);
+ ALOGD("%s: FTRT data transfer: %dms of data received in %llums",
+ __func__, ftrt_bytes_written_ms, ((frame_send_time -
+ buffering_start_time) / NSECS_PER_MSEC));
+
+ if (!p_lsm_ses->common.is_generic_event) {
+ ALOGD("%s: First real time frame took %llums", __func__,
+ (frame_read_time / NSECS_PER_MSEC));
+ adjust_ss_buff_end(&p_lsm_ses->common, cnn_append_bytes,
+ vop_append_bytes);
+ }
real_time_check = false;
}
}
@@ -3624,7 +3627,7 @@
int status = 0;
st_hw_session_lsm_t *p_lsm_ses = (st_hw_session_lsm_t *)p_ses;
- ATRACE_BEGIN("sthal:lsm: read_pcm_data");
+ ATRACE_BEGIN("sthal:lsm:client: read_pcm_data");
status = read_pcm_data(p_lsm_ses, buf, bytes);
ATRACE_END();
diff --git a/st_hw_session_lsm.h b/st_hw_session_lsm.h
index bbb6b63..652b1bc 100644
--- a/st_hw_session_lsm.h
+++ b/st_hw_session_lsm.h
@@ -55,8 +55,8 @@
SOUND_TRIGGER_SAMPLING_RATE_16000, SOUND_TRIGGER_CPE_PERIOD_COUNT, 32)
/*
- * The chosen theshold for determining FTRT vs. RT data is half the buffer
- * duration. There can be frames received that are partially FTRT and
+ * The chosen theshold for determining FTRT vs. RT data is one tenth of the
+ * buffer duration. There can be frames received that are partially FTRT and
* partially RT, so the threshold should be less than the full buffer duration
* to account for that usecase. However, if the threshold is too small, then
* some issue in the lower layers could lead to false identification of RT
@@ -64,7 +64,7 @@
*/
#define APE_MAX_LAB_FTRT_FRAME_RD_TIME_NS \
((SOUND_TRIGGER_APE_BUFFER_DURATION_MS * NSECS_PER_MSEC)\
- / (2 * SOUND_TRIGGER_APE_PERIOD_COUNT))
+ / (10 * SOUND_TRIGGER_APE_PERIOD_COUNT))
#define CPE_MAX_LAB_FTRT_FRAME_RD_TIME_NS \
((SOUND_TRIGGER_CPE_LAB_DRV_BUF_DURATION_MS * NSECS_PER_MSEC)\
/ (2 * SOUND_TRIGGER_CPE_PERIOD_COUNT))
diff --git a/st_second_stage.c b/st_second_stage.c
index e153e39..f27b045 100644
--- a/st_second_stage.c
+++ b/st_second_stage.c
@@ -124,9 +124,13 @@
capi_v2_stream_data_t *stream_input = NULL;
sva_result_t *result_cfg_ptr = NULL;
unsigned int det_status = KEYWORD_DETECTION_PENDING;
+ uint64_t start_time = 0, end_time = 0;
+ uint32_t bytes_processed_ms = 0;
ALOGV("%s: Enter", __func__);
+ start_time = get_current_time_ns();
+
process_input_buff = calloc(1, ss_session->buff_sz);
if (!process_input_buff) {
ALOGE("%s: failed to allocate process_input_buff", __func__);
@@ -213,6 +217,11 @@
*/
pthread_mutex_unlock(&ss_session->lock);
pthread_mutex_lock(&ss_session->st_ses->ss_detections_lock);
+ end_time = get_current_time_ns();
+ bytes_processed_ms = convert_bytes_to_ms(ss_session->bytes_processed,
+ &ss_session->st_ses->hw_ses_current->config);
+ ALOGD("%s: Processed %dms of data in %llums", __func__,
+ bytes_processed_ms, (end_time - start_time) / NSECS_PER_MSEC);
if (det_status == KEYWORD_DETECTION_SUCCESS) {
uint32_t kw_start_ms = 0, kw_end_ms = 0;
@@ -319,9 +328,13 @@
voiceprint2_result_t *result_cfg_ptr = NULL;
voiceprint2_sva_uv_score_t *uv_cfg_ptr = NULL;
unsigned int det_status = USER_VERIFICATION_PENDING;
+ uint64_t start_time = 0, end_time = 0;
+ uint32_t bytes_processed_ms = 0;
ALOGV("%s: Enter", __func__);
+ start_time = get_current_time_ns();
+
process_input_buff = calloc(1, ss_session->buff_sz);
if (!process_input_buff) {
ALOGE("%s: failed to allocate process_input_buff", __func__);
@@ -417,6 +430,7 @@
ALOGE("%s: Processing through capi wrapper failed", __func__);
break;
}
+ ss_session->bytes_processed += ss_session->buff_sz;
ss_session->exit_buffering = true;
}
@@ -424,6 +438,11 @@
pthread_mutex_unlock(&ss_session->lock);
pthread_mutex_lock(&ss_session->st_ses->ss_detections_lock);
+ end_time = get_current_time_ns();
+ bytes_processed_ms = convert_bytes_to_ms(ss_session->bytes_processed,
+ &ss_session->st_ses->hw_ses_current->config);
+ ALOGD("%s: Processed %dms of data in %llums", __func__,
+ bytes_processed_ms, (end_time - start_time) / NSECS_PER_MSEC);
if (det_status == USER_VERIFICATION_SUCCESS) {
ss_session->det_status = USER_VERIFICATION_SUCCESS;
ALOGD("%s: Detection success, confidence level = %d", __func__,
diff --git a/st_session.c b/st_session.c
index 5993fe5..c727ec9 100644
--- a/st_session.c
+++ b/st_session.c
@@ -3650,6 +3650,7 @@
struct timespec tspec = {0};
struct sound_trigger_recognition_event *event = NULL;
bool capture_requested = false;
+ uint64_t callback_time = 0;
ALOGV("%s: Enter", __func__);
@@ -3752,8 +3753,12 @@
callback = stc_ses->callback;
capture_requested = stc_ses->rc_config->capture_requested;
cookie = stc_ses->cookie;
+ callback_time = get_current_time_ns();
ALOGD("%s:[c%d] Second stage detected successfully, "
"calling client callback", __func__, stc_ses->sm_handle);
+ ALOGD("%s: Total sthal processing time: %llums", __func__,
+ (callback_time - st_ses->detection_event_time) /
+ NSECS_PER_MSEC);
pthread_mutex_unlock(&st_ses->lock);
ATRACE_BEGIN("sthal: client detection callback");
callback(event, cookie);
@@ -4504,6 +4509,8 @@
break;
case ST_SES_EV_DETECTED:
+
+ st_ses->detection_event_time = get_current_time_ns();
/*
* Find which client is this detection for.
* Note that only one keyword detection can happen at a time.
diff --git a/st_session.h b/st_session.h
index c37751b..5cd73eb 100644
--- a/st_session.h
+++ b/st_session.h
@@ -187,6 +187,7 @@
struct sound_model_info sm_info;
FILE *lab_fp;
+ uint64_t detection_event_time;
};
/*