From ba2daf9e69c7ab74d0bd874795eb6ae3d059dadb Mon Sep 17 00:00:00 2001 From: Ji-hoon Lee Date: Wed, 10 Nov 2021 21:44:52 +0900 Subject: [PATCH] Add audio data mileage and long-running dbus events in logs Change-Id: Iba38154d8bf3d3bdcf59658679c8b6108a1bc789 --- .../src/dependency_default_audio.cpp | 2 ++ src/service_ipc_dbus.cpp | 36 +++++++++++++++++++--- 2 files changed, 34 insertions(+), 4 deletions(-) diff --git a/plugins/wakeup-manager/dependency-default/src/dependency_default_audio.cpp b/plugins/wakeup-manager/dependency-default/src/dependency_default_audio.cpp index 9f59d08..78b5195 100644 --- a/plugins/wakeup-manager/dependency-default/src/dependency_default_audio.cpp +++ b/plugins/wakeup-manager/dependency-default/src/dependency_default_audio.cpp @@ -338,6 +338,7 @@ void dependency_default_audio_voice_key_pressed_set(bool pressed) void dependency_default_audio_set_background_volume(double ratio) { + LOGD("[ENTER]"); int ret; if (ratio >= 0.5) { @@ -386,6 +387,7 @@ void dependency_default_audio_set_background_volume(double ratio) } } } + LOGD("[EXIT]"); } void dependency_default_audio_get_audio_format(int* rate, int* channel, int* audio_type) diff --git a/src/service_ipc_dbus.cpp b/src/service_ipc_dbus.cpp index f57d9cf..a832279 100644 --- a/src/service_ipc_dbus.cpp +++ b/src/service_ipc_dbus.cpp @@ -25,6 +25,8 @@ #include "service_main.h" #include "service_ipc_dbus.h" +size_t gAudioDataMileage{0}; + int CServiceIpcDbus::reconnect() { if (!mConnectionSender || !mConnectionListener) { @@ -275,7 +277,8 @@ int CServiceIpcDbus::send_streaming_audio_data(pid_t pid, int event, void* data, static int last_serial_waiting_for_flush = -1; if (0 == header.streaming_data_serial % 50 || MAS_SPEECH_STREAMING_EVENT_CONTINUE != event) { last_serial_waiting_for_flush = header.streaming_data_serial; - MAS_LOGE("queueing streaming data, serial : %d", last_serial_waiting_for_flush); + MAS_LOGE("queueing streaming data, serial : %d %d %zu", + last_serial_waiting_for_flush, event, gAudioDataMileage); } if (pending_buffer_size + total_size > STREAMING_BUFFER_SIZE || MAS_SPEECH_STREAMING_EVENT_FINISH == event || @@ -304,13 +307,14 @@ int CServiceIpcDbus::send_streaming_audio_data(pid_t pid, int event, void* data, } if (-1 != last_serial_waiting_for_flush) { - MAS_LOGE("flushing streaming data, serial : %d", last_serial_waiting_for_flush); + MAS_LOGE("flushing streaming data, serial : %d %zu", + last_serial_waiting_for_flush, gAudioDataMileage); last_serial_waiting_for_flush = -1; } } if (MAS_SPEECH_STREAMING_EVENT_FINISH == event) { - MAS_LOGE("Sending FINISH event"); + MAS_LOGE("Sending FINISH event : %zu", gAudioDataMileage); bundle *b = bundle_create(); if (b) { bundle_add_byte(b, "content", buffer, total_size); @@ -1072,23 +1076,40 @@ int CServiceIpcDbus::masc_ui_dbus_enable_common_ui(int enable) return 0; } +static void print_duration(int num_messages, std::chrono::time_point started) +{ + const std::chrono::milliseconds threshold(100); + auto finished = std::chrono::steady_clock::now(); + auto interval = finished - started; + if (interval > threshold) { + MAS_LOGE("DBus messages processed : %d, %lld", num_messages, + std::chrono::duration_cast(interval).count()); + } +} + static Eina_Bool listener_event_callback(void* data, Ecore_Fd_Handler *fd_handler) { + int num_messages = 0; + auto started = std::chrono::steady_clock::now(); + CServiceIpcDbus* service_ipc = static_cast(data); if (NULL == service_ipc) { MAS_LOGE("Error : service_ipc NULL"); + print_duration(num_messages, started); return ECORE_CALLBACK_RENEW; } DBusConnection* mConnectionListener = service_ipc->get_connection_listener(); if (NULL == mConnectionListener) { MAS_LOGE("Error : mConnectionListener NULL"); + print_duration(num_messages, started); return ECORE_CALLBACK_RENEW; } CServiceIpcDbusDispatcher* dispatcher = service_ipc->get_dispatcher(); if (NULL == dispatcher) { MAS_LOGE("Error : dispatcher NULL"); + print_duration(num_messages, started); return ECORE_CALLBACK_RENEW; } @@ -1100,11 +1121,13 @@ static Eina_Bool listener_event_callback(void* data, Ecore_Fd_Handler *fd_handle if (TRUE != dbus_connection_get_is_connected(mConnectionListener)) { MAS_LOGE("[ERROR] Connection is disconnected"); + print_duration(num_messages, started); return ECORE_CALLBACK_RENEW; } /* loop again if we haven't read a message */ if (NULL == msg) { + print_duration(num_messages, started); return ECORE_CALLBACK_RENEW; } @@ -1134,6 +1157,8 @@ static Eina_Bool listener_event_callback(void* data, Ecore_Fd_Handler *fd_handle dispatcher->on_send_recognition_result(mConnectionListener, msg); } else if (dbus_message_is_method_call(msg, MA_SERVER_SERVICE_INTERFACE, MA_METHOD_START_STREAMING_AUDIO_DATA)) { + /* Reset mileage data for logging */ + gAudioDataMileage = 0; dispatcher->on_start_streaming_audio_data(mConnectionListener, msg); } else if (dbus_message_is_method_call(msg, MA_SERVER_SERVICE_INTERFACE, MA_METHOD_STOP_STREAMING_AUDIO_DATA)) { @@ -1176,13 +1201,16 @@ static Eina_Bool listener_event_callback(void* data, Ecore_Fd_Handler *fd_handle dispatcher->on_ui_change_assistant(mConnectionListener, msg); } else { - MAS_LOGD("Message is NOT valid"); + MAS_LOGE("Message is NOT valid"); /* Invalid method */ } /* free the message */ dbus_message_unref(msg); + + num_messages++; } + print_duration(num_messages, started); return ECORE_CALLBACK_RENEW; } -- 2.7.4