Merge "st-hal: Update latency logging"
diff --git a/st_hw_session_lsm.c b/st_hw_session_lsm.c
index 5b5f6f7..6a01641 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 4a4c2a8..6a5c0ca 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 49af69f..b0a81d6 100644
--- a/st_session.c
+++ b/st_session.c
@@ -3660,6 +3660,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__);
@@ -3762,8 +3763,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);
@@ -4514,6 +4519,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;
};
/*