Add audio data mileage and long-running dbus events in logs

Change-Id: Iba38154d8bf3d3bdcf59658679c8b6108a1bc789

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 (file)
--- 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 (file)
--- 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<std::chrono::steady_clock> 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<std::chrono::milliseconds>(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<CServiceIpcDbus*>(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;
 }