Profiling Overview
The profiling module provides notification and performance measurements for each condition.
When nugu_prof_mark () or nugu_prof_mark_data () is called, the timestamp and additional data are stored in the internal cache, and events can be received through the callback.
Developers can fetch and analyze the profiled data at the moment they want via a callback (nugu_prof_set_callback ()) or nugu_prof_get_last_data () API.
In addition, it is possible to simply print out the profiling result of a specific range through the nugu_prof_dump() API. The log module NUGU_LOG_MODULE_PROFILING must be enabled to check the results with the console.
export NUGU_LOG_MODULE=preset_default,profiling
You can check the profiling point of the entire source code through the sequence diagram below.
The figure below shows the process of getting policy information from the device gateway registry and connecting to the device gateway server.
The figure below shows the failure of receiving policy information from the device gateway registry, the first part of the connection.
The policy information includes server list information. The figure below shows a case in which connection to all servers fails.
The client must periodically send a ping message to the server to keep the server initiative directive stream.
The long polling technique is used to receive a server-initiated directive. If the stream is suddenly closed by the server, the client must quickly reconnect the stream.
There are two types of directives: event response directives and server initiative directives.
TODO
TODO
Each profiling point defined above can be checked when it is called through the output of nugu_prof_dump (). Below is the output of profiling for each step.
Add nugu_prof_dump () to ASRAgent's onState callback ASRState::IDLE state as below.
void ASRListener::onState(ASRState state, const std::string& dialog_id)
{
switch (state) {
case ASRState::IDLE: {
nugu_prof_dump(NUGU_PROF_TYPE_ASR_LISTENING_STARTED, NUGU_PROF_TYPE_ASR_RESULT);
break;
}
...
}Whenever one ASR process is finished, the profiling results are displayed as follows.
--------------------------
Profiling: 29(Listening started) ~ 36(ASR Result)
[29] Listening started: <04-27 02:23:42.261> 0 msec [28 ~ 29]: 1 msec
[30] ASR.Recognize: <04-27 02:23:42.261> 0 msec [29 ~ 30]: 0 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcc8b5014e69f74bf4c3dbb562c3
[31] Recognizing: <04-27 02:23:43.530> 1269 msec [29 ~ 31]: 1269 msec
[32] End detected: <04-27 02:23:44.557> 2296 msec [31 ~ 32]: 1026 msec
[34] First attachment: <04-27 02:23:43.530> 1269 msec [31 ~ 34]: -1 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bccdaa014e69f74bf4c3cb339f28
[35] Last attachment: <04-27 02:23:44.558> 2297 msec [34 ~ 35]: 1027 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd1ad014e69f74bf4c3d922a9c2
[36] ASR Result: <04-27 02:23:44.720> 2459 msec [30 ~ 36]: 2458 msec
--------------------------
Add nugu_prof_dump () to TTSAgent's onTTSState callback TTSState::TTS_SPEECH_FINISH state as below.
void TTSListener::onTTSState(TTSState state, const std::string& dialog_id)
{
switch (state) {
...
case TTSState::TTS_SPEECH_FINISH:
nugu_prof_dump(NUGU_PROF_TYPE_TTS_SPEAK_DIRECTIVE, NUGU_PROF_TYPE_TTS_FINISHED);
break;
}
}Whenever one TTS process is finished, the profiling results are displayed as follows.
--------------------------
Profiling: 37(TTS Speak directive) ~ 43(TTS finished)
[37] TTS Speak directive: <04-27 02:23:45.274> 0 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd413014e69f74bf4c32910d12a
[39] TTS started: <04-27 02:23:45.331> 57 msec [37 ~ 39]: 57 msec 09b2bcd4b2014e69f74bf4c308e8e4ee 09b2bcd4b2014e69f74bf4c386a8278c
[40] TTS first data: <04-27 02:23:45.332> 58 msec [37 ~ 40]: 58 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd413014e69f74bf4c32910d12a
[41] TTS last data: <04-27 02:23:45.380> 106 msec [40 ~ 41]: 48 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd413014e69f74bf4c32910d12a
[43] TTS finished: <04-27 02:23:48.811> 3536 msec [37 ~ 43]: 3536 msec 09b2bce249014e69f74bf4c3f8ad5863 09b2bce249014e69f74bf4c31acaf204
--------------------------
You can check the entire profiling point by adding nugu_prof_dump() at the end of the SDK.
int main()
{
...
nugu_prof_dump(NUGU_PROF_TYPE_SDK_CREATED, NUGU_PROF_TYPE_MAX);
return EXIT_SUCCESS;
}Below is the result.
--------------------------
Profiling: 0(Created) ~ 46(END)
[ 0] Created: <04-27 02:23:38.606> 0 msec
[ 1] Plugin init: <04-27 02:23:38.622> 16 msec [ 0 ~ 1]: 16 msec
[ 2] Plugin done: <04-27 02:23:38.733> 127 msec [ 1 ~ 2]: 111 msec
[ 3] Initialized: <04-27 02:23:38.743> 137 msec [ 0 ~ 3]: 137 msec
[ 4] Connect request: <04-27 02:23:38.618> 12 msec
[ 5] Registry request: <04-27 02:23:38.620> 13 msec [ 4 ~ 5]: 1 msec
[ 6] Registry response: <04-27 02:23:38.768> 161 msec [ 5 ~ 6]: 148 msec
[ 8] Server request: <04-27 02:23:38.771> 165 msec [ 4 ~ 8]: 152 msec
[ 9] Server establish: <04-27 02:23:38.934> 328 msec [ 8 ~ 9]: 162 msec
[11] Connected: <04-27 02:23:38.934> 328 msec [ 4 ~ 11]: 315 msec
[21] Event request: <04-27 02:23:48.810> 10 sec 09b2bce249014e69f74bf4c3f8ad5863 09b2bce249014e69f74bf4c31acaf204
[22] Event response: <04-27 02:23:48.826> 10 sec [21 ~ 22]: 15 msec 09b2bce249014e69f74bf4c3f8ad5863 09b2bce249014e69f74bf4c31acaf204
[24] Attachment request: <04-27 02:23:44.558> 5951 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd1ad014e69f74bf4c3d922a9c2
[25] Directive response: <04-27 02:23:48.941> 10 sec [21 ~ 25]: 131 msec 09b2bce249014e69f74bf4c3f8ad5863 09b2bce2cb01302dacdd1bd3e2a7d84f
[27] Last push-data: <04-27 02:23:38.940> 334 msec 09b2bcbbb401cf9f37a7fc2df1758de5 09b2bcbbb401d626eab736fa68c4d2b6
[28] wakeup detected: <04-27 02:23:42.259> 3653 msec
[29] Listening started: <04-27 02:23:42.261> 3654 msec [28 ~ 29]: 1 msec
[30] ASR.Recognize: <04-27 02:23:42.261> 3655 msec [29 ~ 30]: 0 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcc8b5014e69f74bf4c3dbb562c3
[31] Recognizing: <04-27 02:23:43.530> 4924 msec [29 ~ 31]: 1269 msec
[32] End detected: <04-27 02:23:44.557> 5951 msec [31 ~ 32]: 1026 msec
[34] First attachment: <04-27 02:23:43.530> 4924 msec [31 ~ 34]: -1 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bccdaa014e69f74bf4c3cb339f28
[35] Last attachment: <04-27 02:23:44.558> 5951 msec [34 ~ 35]: 1027 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd1ad014e69f74bf4c3d922a9c2
[36] ASR Result: <04-27 02:23:44.720> 6113 msec [30 ~ 36]: 2458 msec
[37] TTS Speak directive: <04-27 02:23:45.274> 6668 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd413014e69f74bf4c32910d12a
[39] TTS started: <04-27 02:23:45.331> 6725 msec [37 ~ 39]: 57 msec 09b2bcd4b2014e69f74bf4c308e8e4ee 09b2bcd4b2014e69f74bf4c386a8278c
[40] TTS first data: <04-27 02:23:45.332> 6726 msec [37 ~ 40]: 58 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd413014e69f74bf4c32910d12a
[41] TTS last data: <04-27 02:23:45.380> 6774 msec [40 ~ 41]: 48 msec 09b2bcc8b5014e69f74bf4c321f6f7bd 09b2bcd413014e69f74bf4c32910d12a
[43] TTS finished: <04-27 02:23:48.811> 10 sec [37 ~ 43]: 3536 msec 09b2bce249014e69f74bf4c3f8ad5863 09b2bce249014e69f74bf4c31acaf204
--------------------------