Fix ice agent profling to store in variables, new APIs for getting ic…

…e agent metrics
awslabs · Jul 27, 2023 · 45002d8 · 45002d8
1 parent 4155433
commit 45002d8
Show file tree

Hide file tree

Showing 23 changed files with 225 additions and 93 deletions.
diff --git a/CMake/Dependencies/libkvsCommonLws-CMakeLists.txt b/CMake/Dependencies/libkvsCommonLws-CMakeLists.txt
@@ -6,7 +6,7 @@ include(ExternalProject)
 
 ExternalProject_Add(libkvsCommonLws-download
     GIT_REPOSITORY    https://github.com/awslabs/amazon-kinesis-video-streams-producer-c.git
-    GIT_TAG           add-new-log-level
+    GIT_TAG           ed51d7f00aabce9181ea4897b1671551a93d780b
     PREFIX            ${CMAKE_CURRENT_BINARY_DIR}/build
     CMAKE_ARGS        
       -DCMAKE_INSTALL_PREFIX=${OPEN_SRC_INSTALL_PREFIX}

diff --git a/README.md b/README.md
@@ -6,7 +6,6 @@
 <h4 align="center">Pure C WebRTC Client for Amazon Kinesis Video Streams </h4>
 
 <p align="center">
-  <a href="https://travis-ci.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c"> <img src="https://travis-ci.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c.svg?branch=master" alt="Build Status"> </a>
   <a href="https://codecov.io/gh/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c"> <img src="https://codecov.io/gh/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c/branch/master/graph/badge.svg" alt="Coverage Status"> </a>
 </p>
 
@@ -164,7 +163,7 @@ export AWS_SESSION_TOKEN=<session token>
 export AWS_DEFAULT_REGION= <AWS region>
 ```
 
-### Setup desired log level:
+### Setup logging:
 Set up the desired log level. The log levels and corresponding values currently available are:
 1. `LOG_LEVEL_VERBOSE` ---- 1
 2. `LOG_LEVEL_DEBUG`   ---- 2
@@ -186,12 +185,23 @@ export AWS_KVS_LOG_LEVEL = 2 switches on DEBUG level logs while runnning the sam
 
 Note: The default log level is `LOG_LEVEL_WARN`.
 
-* Optionally, set path to SSL CA certificate with variable (`../certs/cert.pem` is default one and points to file in this repository):
+Starting v1.7.x (**TO_BE_UPDATED**), by default, the SDK creates a log file that would have execution timing details of certain steps in connection establishment. It would be stored in the `build` directory as `kvsFileLogFilter.x`. In case you do not want to use defaults, you can modify certain parameters such as log file directory, log file size and file rotation index in the `createFileLoggerWithLevelFiltering` function in the samples.
+In addition to these logs, if you would like to have other level logs in a file as well, run:
+
+```
+export AWS_ENABLE_FILE_LOGGING=TRUE
+```
+
+### Set path to SSL CA certificate (**Optional**)
+
+If you have a custom CA certificate path to set, you can set it using:
 
 ```
 export AWS_KVS_CACERT_PATH=../certs/cert.pem
 ```
 
+By defaut, the SSL CA certificate is set to `../certs/cert.pem` which points to the file in this repository:
+
 ### Running the Samples
 After executing `make` you will have sample applications in your `build/samples` directory. From the `build/` directory, run any of the sample applications by passing to it the name of your signaling channel. If a signaling channel does not exist with the name you provide, the application creates one.
 
@@ -298,11 +308,6 @@ In the mbedTLS version, the SDK uses /dev/urandom on Unix and CryptGenRandom API
 If you would like to print out the SDPs, run this command:
 `export DEBUG_LOG_SDP=TRUE`
 
-### File logging
-If you would like to enable file logging, run this command:
-`export AWS_ENABLE_FILE_LOGGING=TRUE`
-You can also change settings such as buffer size, number of log files for rotation and log file path in the samples
-
 ### Adjust MTU
 If ICE connection can be established successfully but media can not be transferred, make sure the actual MTU is higher than the MTU setting here: https://github.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c/blob/master/src/source/PeerConnection/Rtp.h#L12.
 

diff --git a/samples/Common.c b/samples/Common.c
@@ -66,8 +66,10 @@ VOID onConnectionStateChange(UINT64 customData, RTC_PEER_CONNECTION_STATE newSta
         case RTC_PEER_CONNECTION_STATE_CONNECTED:
             ATOMIC_STORE_BOOL(&pSampleConfiguration->connected, TRUE);
             CVAR_BROADCAST(pSampleConfiguration->cvar);
-            PeerConnectionMetrics metrics;
-            getPeerConnectionMetrics(pSampleStreamingSession->pPeerConnection, &metrics);
+
+            CHK_STATUS(peerConnectionGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->peerConnectionMetrics));
+            CHK_STATUS(iceAgentGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->iceMetrics));
+
             if (STATUS_FAILED(retStatus = logSelectedIceCandidatesInformation(pSampleStreamingSession))) {
                 DLOGW("Failed to get information about selected Ice candidates: 0x%08x", retStatus);
             }
@@ -256,16 +258,23 @@ STATUS sendSignalingMessage(PSampleStreamingSession pSampleStreamingSession, PSi
 {
     STATUS retStatus = STATUS_SUCCESS;
     BOOL locked = FALSE;
-
+    PSampleConfiguration pSampleConfiguration;
     // Validate the input params
     CHK(pSampleStreamingSession != NULL && pSampleStreamingSession->pSampleConfiguration != NULL && pMessage != NULL, STATUS_NULL_ARG);
-    CHK(IS_VALID_MUTEX_VALUE(pSampleStreamingSession->pSampleConfiguration->signalingSendMessageLock) &&
-            IS_VALID_SIGNALING_CLIENT_HANDLE(pSampleStreamingSession->pSampleConfiguration->signalingClientHandle),
+
+    pSampleConfiguration = pSampleStreamingSession->pSampleConfiguration;
+
+    CHK(IS_VALID_MUTEX_VALUE(pSampleConfiguration->signalingSendMessageLock) &&
+            IS_VALID_SIGNALING_CLIENT_HANDLE(pSampleConfiguration->signalingClientHandle),
         STATUS_INVALID_OPERATION);
 
-    MUTEX_LOCK(pSampleStreamingSession->pSampleConfiguration->signalingSendMessageLock);
+    MUTEX_LOCK(pSampleConfiguration->signalingSendMessageLock);
     locked = TRUE;
-    CHK_STATUS(signalingClientSendMessageSync(pSampleStreamingSession->pSampleConfiguration->signalingClientHandle, pMessage));
+    CHK_STATUS(signalingClientSendMessageSync(pSampleConfiguration->signalingClientHandle, pMessage));
+    if (pMessage->messageType == SIGNALING_MESSAGE_TYPE_ANSWER) {
+        CHK_STATUS(signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &pSampleConfiguration->signalingClientMetrics));
+        DLOGP("[Signaling offer to answer] %" PRIu64 " ms", pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerToAnswerTime);
+    }
 
 CleanUp:
 
@@ -482,6 +491,10 @@ STATUS createSampleStreamingSession(PSampleConfiguration pSampleConfiguration, P
 
     pSampleStreamingSession->pSampleConfiguration = pSampleConfiguration;
     pSampleStreamingSession->rtcMetricsHistory.prevTs = GETTIME();
+
+    pSampleStreamingSession->peerConnectionMetrics.version = PEER_CONNECTION_METRICS_CURRENT_VERSION;
+    pSampleStreamingSession->iceMetrics.version = ICE_AGENT_METRICS_CURRENT_VERSION;
+
     // if we're the viewer, we control the trickle ice mode
     pSampleStreamingSession->remoteCanTrickleIce = !isMaster && pSampleConfiguration->trickleIce;
 
@@ -607,14 +620,12 @@ VOID sampleVideoFrameHandler(UINT64 customData, PFrame pFrame)
 {
     UNUSED_PARAM(customData);
     DLOGV("Video Frame received. TrackId: %" PRIu64 ", Size: %u, Flags %u", pFrame->trackId, pFrame->size, pFrame->flags);
-    PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData;
 }
 
 VOID sampleAudioFrameHandler(UINT64 customData, PFrame pFrame)
 {
     UNUSED_PARAM(customData);
     DLOGV("Audio Frame received. TrackId: %" PRIu64 ", Size: %u, Flags %u", pFrame->trackId, pFrame->size, pFrame->flags);
-    PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData;
 }
 
 VOID sampleBandwidthEstimationHandler(UINT64 customData, DOUBLE maximumBitrate)
@@ -746,17 +757,17 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE
     // If the env is set, we generate normal log files apart from filtered profile log files
     // If not set, we generate only the filtered profile log files
     if (NULL != getenv(ENABLE_FILE_LOGGING)) {
-        retStatus =
-                createFileLoggerWithLevelFiltering(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, TRUE, TRUE, TRUE, LOG_LEVEL_PROFILE, NULL);
+        retStatus = createFileLoggerWithLevelFiltering(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH,
+                                                       TRUE, TRUE, TRUE, LOG_LEVEL_PROFILE, NULL);
 
         if (retStatus != STATUS_SUCCESS) {
             DLOGW("[KVS Master] createFileLogger(): operation returned status code: 0x%08x", retStatus);
         } else {
             pSampleConfiguration->enableFileLogging = TRUE;
         }
     } else {
-        retStatus =
-                createFileLoggerWithLevelFiltering(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH, TRUE, TRUE, FALSE, LOG_LEVEL_PROFILE, NULL);
+        retStatus = createFileLoggerWithLevelFiltering(FILE_LOGGING_BUFFER_SIZE, MAX_NUMBER_OF_LOG_FILES, (PCHAR) FILE_LOGGER_LOG_FILE_DIRECTORY_PATH,
+                                                       TRUE, TRUE, FALSE, LOG_LEVEL_PROFILE, NULL);
 
         if (retStatus != STATUS_SUCCESS) {
             DLOGW("[KVS Master] createFileLogger(): operation returned status code: 0x%08x", retStatus);
@@ -823,6 +834,7 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE
     pSampleConfiguration->clientInfo.signalingClientCreationMaxRetryAttempts = CREATE_SIGNALING_CLIENT_RETRY_ATTEMPTS_SENTINEL_VALUE;
     pSampleConfiguration->iceCandidatePairStatsTimerId = MAX_UINT32;
     pSampleConfiguration->pregenerateCertTimerId = MAX_UINT32;
+    pSampleConfiguration->signalingClientMetrics.version = SIGNALING_CLIENT_METRICS_CURRENT_VERSION;
 
     ATOMIC_STORE_BOOL(&pSampleConfiguration->interrupted, FALSE);
     ATOMIC_STORE_BOOL(&pSampleConfiguration->mediaThreadStarted, FALSE);
@@ -863,6 +875,7 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE
 STATUS initSignaling(PSampleConfiguration pSampleConfiguration, PCHAR clientId)
 {
     STATUS retStatus = STATUS_SUCCESS;
+    SignalingClientMetrics signalingClientMetrics = pSampleConfiguration->signalingClientMetrics;
     pSampleConfiguration->signalingClientCallbacks.messageReceivedFn = signalingMessageReceived;
     STRCPY(pSampleConfiguration->clientInfo.clientId, clientId);
     CHK_STATUS(createSignalingClientSync(&pSampleConfiguration->clientInfo, &pSampleConfiguration->channelInfo,
@@ -872,8 +885,21 @@ STATUS initSignaling(PSampleConfiguration pSampleConfiguration, PCHAR clientId)
     // Enable the processing of the messages
     CHK_STATUS(signalingClientFetchSync(pSampleConfiguration->signalingClientHandle));
     CHK_STATUS(signalingClientConnectSync(pSampleConfiguration->signalingClientHandle));
-    gSampleConfiguration = pSampleConfiguration;
 
+    signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &signalingClientMetrics);
+
+    // Logging this here since the logs in signaling library do not get routed to file
+    DLOGP("[Signaling Get token] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.getTokenCallTime);
+    DLOGP("[Signaling Describe] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.describeCallTime);
+    DLOGP("[Signaling Create Channel] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.createCallTime);
+    DLOGP("[Signaling Get endpoint] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.getEndpointCallTime);
+    DLOGP("[Signaling Get ICE config] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.getIceConfigCallTime);
+    DLOGP("[Signaling Connect] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.connectCallTime);
+    DLOGP("[Signaling create client] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.createClientTime);
+    DLOGP("[Signaling fetch client] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.fetchClientTime);
+    DLOGP("[Signaling connect client] %" PRIu64 " ms", signalingClientMetrics.signalingClientStats.connectClientTime);
+    pSampleConfiguration->signalingClientMetrics = signalingClientMetrics;
+    gSampleConfiguration = pSampleConfiguration;
 CleanUp:
     return retStatus;
 }
@@ -1393,6 +1419,8 @@ STATUS signalingMessageReceived(UINT64 customData, PReceivedSignalingMessage pRe
             }
 
             startStats = pSampleConfiguration->iceCandidatePairStatsTimerId == MAX_UINT32;
+            CHK_STATUS(signalingClientGetMetrics(pSampleConfiguration->signalingClientHandle, &pSampleConfiguration->signalingClientMetrics));
+            DLOGP("[Signaling offer to answer] %" PRIu64 " ms", pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerToAnswerTime);
             break;
 
         case SIGNALING_MESSAGE_TYPE_ICE_CANDIDATE:

diff --git a/samples/Samples.h b/samples/Samples.h
@@ -103,6 +103,7 @@ typedef struct {
     startRoutine videoSource;
     startRoutine receiveAudioVideoSource;
     RtcOnDataChannel onDataChannel;
+    SignalingClientMetrics signalingClientMetrics;
 
     PStackQueue pPendingSignalingMessageForRemoteClient;
     PHashTable pRtcPeerConnectionForRemoteClient;
@@ -161,6 +162,8 @@ struct __SampleStreamingSession {
     StreamSessionShutdownCallback shutdownCallback;
     UINT64 shutdownCallbackCustomData;
     UINT64 offerReceiveTime;
+    PeerConnectionMetrics peerConnectionMetrics;
+    KvsIceAgentMetrics iceMetrics;
 };
 
 VOID sigintHandler(INT32);

diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h
@@ -25,33 +25,33 @@ extern "C" {
 #pragma clang diagnostic pop
 #endif
 
+/* TODO: Potentially move these call to PIC instead. Moving to PIC in the future would not cause any backward compatibility issues */
 #define PROFILE_CALL(f, msg)                                                                                                                         \
     do {                                                                                                                                             \
         UINT64 startTime = GETTIME();                                                                                                                \
         f;                                                                                                                                           \
         DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, (GETTIME() - startTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND);                                 \
     } while (FALSE)
 
-#define PROFILE_CALL_WITH_T_OBJ(f, t, msg)                                                                                                                         \
+#define PROFILE_CALL_WITH_T_OBJ(f, t, msg)                                                                                                           \
     do {                                                                                                                                             \
         UINT64 startTime = GETTIME();                                                                                                                \
         f;                                                                                                                                           \
-        t = (GETTIME() - startTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND;                                                                                                                                          \
-        DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, t);                                 \
+        t = (GETTIME() - startTime) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND;                                                                            \
+        DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, t);                                                                                            \
     } while (FALSE)
 
 #define PROFILE_WITH_START_TIME(t, msg)                                                                                                              \
     do {                                                                                                                                             \
         DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, (GETTIME() - t) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND);                                         \
     } while (FALSE)
 
-#define PROFILE_WITH_START_TIME_OBJ(t1, t2, msg)                                                                                                              \
+#define PROFILE_WITH_START_TIME_OBJ(t1, t2, msg)                                                                                                     \
     do {                                                                                                                                             \
-        t2 = (GETTIME() - t1) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND;                                                                                                                                           \
-        DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, t2);                                         \
+        t2 = (GETTIME() - t1) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND;                                                                                  \
+        DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, t2);                                                                                           \
     } while (FALSE)
 
-
 /*! \addtogroup StatusCodes
  * WEBRTC related status codes. Each value is an positive integer formed by adding
  * a base integer inticating the category to an index. Users may run scripts/parse_status.py
@@ -563,7 +563,12 @@ extern "C" {
 /**
  * Version of PeerConnectionMetrics structure
  */
-#define PEER_CONNECTION_METRICS_CURRENT_VERSION  0
+#define PEER_CONNECTION_METRICS_CURRENT_VERSION 0
+
+/**
+ * Version of KvsIceAgentMetrics structure
+ */
+#define ICE_AGENT_METRICS_CURRENT_VERSION 0
 
 /*!@} */
 
@@ -1471,12 +1476,20 @@ typedef struct {
     SignalingClientStats signalingClientStats; //!< Signaling client metrics stats. Reference in Stats.h
 } SignalingClientMetrics, *PSignalingClientMetrics;
 
+/**
+ * @brief KVS ICE Agent Collection of ICE agent related stats. Can be expanded in the future
+ */
+typedef struct {
+    UINT32 version;                    //!< Structure version
+    KvsIceAgentStats kvsIceAgentStats; //!< ICE agent metrics. Reference in Stats.h
+} KvsIceAgentMetrics, *PKvsIceAgentMetrics;
+
 /**
  * @brief SignalingStats Collection of signaling related stats. Can be expanded in the future
  */
 typedef struct {
-    UINT32 version;                            //!< Structure version
-    PeerConnectionStats peerConnectionStats;   //!< Peer connection metrics stats. Reference in Stats.h
+    UINT32 version;                          //!< Structure version
+    PeerConnectionStats peerConnectionStats; //!< Peer connection metrics stats. Reference in Stats.h
 } PeerConnectionMetrics, *PPeerConnectionMetrics;
 
 /**
@@ -2067,7 +2080,15 @@ PUBLIC_API STATUS signalingClientGetMetrics(SIGNALING_CLIENT_HANDLE, PSignalingC
  * @param[in] PRtcPeerConnection Peer connection object
  * @param[in,out] PPeerConnectionMetrics Peer connection stats object
  */
-PUBLIC_API STATUS getPeerConnectionMetrics(PRtcPeerConnection, PPeerConnectionMetrics);
+PUBLIC_API STATUS peerConnectionGetMetrics(PRtcPeerConnection, PPeerConnectionMetrics);
+
+/**
+ * @brief Get peer connection related metrics
+ *
+ * @param[in] PRtcPeerConnection Peer connection object
+ * @param[in,out] PKvsIceAgentMetrics KVS ICE agent stats object
+ */
+PUBLIC_API STATUS iceAgentGetMetrics(PRtcPeerConnection, PKvsIceAgentMetrics);
 
 /**
  * @brief Get the relevant/all metrics based on the RTCStatsType field. This does not include