Time-to-first-frame metrics benchmarking using datachannel (#1846)

* data channel benchmarking message

* fix calculation

* send peerconnection, iceagent, signaling metrics to viewer via dc

* signaling breakdown

* data channel benchmarking message

* fix calculation

* send peerconnection, iceagent, signaling metrics to viewer via dc

* signaling breakdown

* cmake flag, ifdef

* move signaling and offer / answer metrics out of signaling stats

* remove callTime for start and end times in signaling

* remove new lines

* clang format

* fix clang format

* fix macos-gcc-ci

* put cleanup in ifdef

* add cmake flag

* additional builds with cmake flags for mac and ubuntu, max string size for dc, no strlen calc in max string sizes

* fix clang-format

* mac-os-dc-metrics-build-gcc

* increase signaling metrics message size

* address comments: bool, add back calltimes, remove hns

* missed an hns

* dlogp

* fix the build

* remove extra space from ci

* cleanup-1

* clang-format

* fix git_tag from master to fix the ci

* Revert "fix git_tag from master to fix the ci"

This reverts commit 870deb3.

* move message defs to common

* remove unused var

* remove unused var

* cleanup-3

* cleanup-4

* fix macos build

* Revert "fix macos build"

This reverts commit 041c858.

* use double quotes instead of single for char array

* forgot to rename in the string

* fix initialization + readme

* remove offerTime and use offerReceivedTime instead

* move globals to streamingsession

* rename + memset

* fix clang format

* add null check for streaming session

* null check for streaming session and psampleconfigurtion

* add error messages

* clang

* error message

* ubuntu sample check update

* fix sample check

.github/workflows/ci.yml

@@ -416,27 +416,29 @@ jobs:
           timeout --signal=SIGABRT 60m ./tst/webrtc_client_test
   sample-check:
     if: github.repository == 'awslabs/amazon-kinesis-video-streams-webrtc-sdk-c'
-    runs-on: ubuntu-20.04
+    runs-on: ubuntu-latest
     env:
       AWS_KVS_LOG_LEVEL: 2
     permissions:
       id-token: write
       contents: read
     steps:
       - name: Clone repository
-        uses: actions/checkout@v3
+        uses: actions/checkout@v4
       - name: Configure AWS Credentials
-        uses: aws-actions/configure-aws-credentials@v2
+        uses: aws-actions/configure-aws-credentials@v4
         with:
           role-to-assume: ${{ secrets.AWS_ROLE_TO_ASSUME }}
           aws-region: ${{ secrets.AWS_REGION }}
+          role-duration-seconds: 10800
       - name: Build repository
         run: |
           sudo sh -c 'echo 0 > /proc/sys/net/ipv6/conf/all/disable_ipv6'
           mkdir build && cd build
           cmake ..
           make
-          cd ..
+      - name: Sample check
+        run: |
           ./scripts/check-sample.sh
   ubuntu-os-build:
     runs-on: ubuntu-20.04

README.md

@@ -243,6 +243,11 @@ The SDK also tracks entry and exit of functions which increases the verbosity of
 `add_definitions(-DLOG_STREAMING)`
 Note: This log level is extremely VERBOSE and could flood the files if using file based logging strategy.
 
+<details>
+  <summary>Time-to-first-frame breakdown metrics</summary>
+    There is a flag in the sample application which (pSampleConfiguration->enableSendingMetricsToViewerViaDc) can be set to TRUE to send metrics from the master to the [JS](https://awslabs.github.io/amazon-kinesis-video-streams-webrtc-sdk-js/examples/index.html) viewer. This helps get a detailed breakdown of time-to-first-frame and all the processes and API calls on master and the viewer both. This is intended to be used with the KVS WebRTC C SDK running as the master and the JS SDK as the viewer. The master sends peer, ice-agent, signaling and data-channel metrics to the viewer which are plotted ~ 20 seconds after the viewer is started. Since the timeline plot is intended to understand the time-to-first-frame, the sample web page needs to be refreshed and the master needs to be restarted if a new / updated plot is needed. While using the SDK in this mode, it is expected that all datachannel messages are JSON messages. This feature is only meant to be used for a single viewer at a time.
+</details>
+
 ### Set path to SSL CA certificate (**Optional**)
 
 If you have a custom CA certificate path to set, you can set it using:

samples/Common.c

@@ -34,18 +34,172 @@ STATUS signalingCallFailed(STATUS status)
 
 VOID onDataChannelMessage(UINT64 customData, PRtcDataChannel pDataChannel, BOOL isBinary, PBYTE pMessage, UINT32 pMessageLen)
 {
-    UNUSED_PARAM(customData);
-    if (isBinary) {
-        DLOGI("DataChannel Binary Message");
+    STATUS retStatus = STATUS_SUCCESS;
+    UINT32 i, strLen, tokenCount;
+    CHAR pMessageSend[MAX_DATA_CHANNEL_METRICS_MESSAGE_SIZE], errorMessage[200];
+    PCHAR json;
+    PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData;
+    PSampleConfiguration pSampleConfiguration;
+    DataChannelMessage dataChannelMessage;
+    jsmn_parser parser;
+    jsmntok_t tokens[MAX_JSON_TOKEN_COUNT];
+
+    CHK(pMessage != NULL && pDataChannel != NULL, STATUS_NULL_ARG);
+
+    if (pSampleStreamingSession == NULL) {
+        STRCPY(errorMessage, "Could not generate stats since the streaming session is NULL");
+        retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) errorMessage, STRLEN(errorMessage));
+        DLOGE("%s", errorMessage);
+        goto CleanUp;
+    }
+
+    pSampleConfiguration = pSampleStreamingSession->pSampleConfiguration;
+    if (pSampleConfiguration == NULL) {
+        STRCPY(errorMessage, "Could not generate stats since the sample configuration is NULL");
+        retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) errorMessage, STRLEN(errorMessage));
+        DLOGE("%s", errorMessage);
+        goto CleanUp;
+    }
+
+    if (pSampleConfiguration->enableSendingMetricsToViewerViaDc) {
+        jsmn_init(&parser);
+        json = (PCHAR) pMessage;
+        tokenCount = jsmn_parse(&parser, json, STRLEN(json), tokens, SIZEOF(tokens) / SIZEOF(jsmntok_t));
+
+        MEMSET(dataChannelMessage.content, '\0', SIZEOF(dataChannelMessage.content));
+        MEMSET(dataChannelMessage.firstMessageFromViewerTs, '\0', SIZEOF(dataChannelMessage.firstMessageFromViewerTs));
+        MEMSET(dataChannelMessage.firstMessageFromMasterTs, '\0', SIZEOF(dataChannelMessage.firstMessageFromMasterTs));
+        MEMSET(dataChannelMessage.secondMessageFromViewerTs, '\0', SIZEOF(dataChannelMessage.secondMessageFromViewerTs));
+        MEMSET(dataChannelMessage.secondMessageFromMasterTs, '\0', SIZEOF(dataChannelMessage.secondMessageFromMasterTs));
+        MEMSET(dataChannelMessage.lastMessageFromViewerTs, '\0', SIZEOF(dataChannelMessage.lastMessageFromViewerTs));
+
+        if (tokenCount > 1) {
+            if (tokens[0].type != JSMN_OBJECT) {
+                STRCPY(errorMessage, "Invalid JSON received, please send a valid json as the SDK is operating in datachannel-benchmarking mode");
+                retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) errorMessage, STRLEN(errorMessage));
+                DLOGE("%s", errorMessage);
+                retStatus = STATUS_INVALID_API_CALL_RETURN_JSON;
+                goto CleanUp;
+            }
+            DLOGI("DataChannel json message: %.*s\n", pMessageLen, pMessage);
+
+            for (i = 1; i < tokenCount; i++) {
+                if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "content")) {
+                    strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                    if (strLen != 0) {
+                        STRNCPY(dataChannelMessage.content, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                    }
+                } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "firstMessageFromViewerTs")) {
+                    strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                    // parse and retain this message from the viewer to send it back again
+                    if (strLen != 0) {
+                        // since the length is not zero, we have already attached this timestamp to structure in the last iteration
+                        STRNCPY(dataChannelMessage.firstMessageFromViewerTs, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                    }
+                } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "firstMessageFromMasterTs")) {
+                    strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                    if (strLen != 0) {
+                        // since the length is not zero, we have already attached this timestamp to structure in the last iteration
+                        STRNCPY(dataChannelMessage.firstMessageFromMasterTs, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                    } else {
+                        // if this timestamp was not assigned during the previous message session, add it now
+                        SNPRINTF(dataChannelMessage.firstMessageFromMasterTs, 20, "%llu", GETTIME() / 10000);
+                        break;
+                    }
+                } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "secondMessageFromViewerTs")) {
+                    strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                    // parse and retain this message from the viewer to send it back again
+                    if (strLen != 0) {
+                        STRNCPY(dataChannelMessage.secondMessageFromViewerTs, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                    }
+                } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "secondMessageFromMasterTs")) {
+                    strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                    if (strLen != 0) {
+                        // since the length is not zero, we have already attached this timestamp to structure in the last iteration
+                        STRNCPY(dataChannelMessage.secondMessageFromMasterTs, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                    } else {
+                        // if this timestamp was not assigned during the previous message session, add it now
+                        SNPRINTF(dataChannelMessage.secondMessageFromMasterTs, 20, "%llu", GETTIME() / 10000);
+                        break;
+                    }
+                } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "lastMessageFromViewerTs")) {
+                    strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                    if (strLen != 0) {
+                        STRNCPY(dataChannelMessage.lastMessageFromViewerTs, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                    }
+                }
+            }
+
+            if (STRLEN(dataChannelMessage.lastMessageFromViewerTs) == 0) {
+                // continue sending the data_channel_metrics_message with new timestamps until we receive the lastMessageFromViewerTs from the viewer
+                SNPRINTF(pMessageSend, MAX_DATA_CHANNEL_METRICS_MESSAGE_SIZE, DATA_CHANNEL_MESSAGE_TEMPLATE, MASTER_DATA_CHANNEL_MESSAGE,
+                         dataChannelMessage.firstMessageFromViewerTs, dataChannelMessage.firstMessageFromMasterTs,
+                         dataChannelMessage.secondMessageFromViewerTs, dataChannelMessage.secondMessageFromMasterTs,
+                         dataChannelMessage.lastMessageFromViewerTs);
+                DLOGI("Master's response: %s", pMessageSend);
+
+                retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pMessageSend, STRLEN(pMessageSend));
+            } else {
+                // now that we've received the last message, send across the signaling, peerConnection, ice metrics
+                SNPRINTF(pSampleStreamingSession->pSignalingClientMetricsMessage, MAX_SIGNALING_CLIENT_METRICS_MESSAGE_SIZE,
+                         SIGNALING_CLIENT_METRICS_JSON_TEMPLATE, pSampleConfiguration->signalingClientMetrics.signalingStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingEndTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerReceivedTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.answerTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.describeChannelStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.describeChannelEndTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.getSignalingChannelEndpointStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.getSignalingChannelEndpointEndTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.getIceServerConfigStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.getIceServerConfigEndTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.getTokenStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.getTokenEndTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.createChannelStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.createChannelEndTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.connectStartTime,
+                         pSampleConfiguration->signalingClientMetrics.signalingClientStats.connectEndTime);
+                DLOGI("Sending signaling metrics to the viewer: %s", pSampleStreamingSession->pSignalingClientMetricsMessage);
+
+                CHK_STATUS(peerConnectionGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->peerConnectionMetrics));
+                SNPRINTF(pSampleStreamingSession->pPeerConnectionMetricsMessage, MAX_PEER_CONNECTION_METRICS_MESSAGE_SIZE,
+                         PEER_CONNECTION_METRICS_JSON_TEMPLATE,
+                         pSampleStreamingSession->peerConnectionMetrics.peerConnectionStats.peerConnectionStartTime,
+                         pSampleStreamingSession->peerConnectionMetrics.peerConnectionStats.peerConnectionConnectedTime);
+                DLOGI("Sending peer-connection metrics to the viewer: %s", pSampleStreamingSession->pPeerConnectionMetricsMessage);
+
+                CHK_STATUS(iceAgentGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->iceMetrics));
+                SNPRINTF(pSampleStreamingSession->pIceAgentMetricsMessage, MAX_ICE_AGENT_METRICS_MESSAGE_SIZE, ICE_AGENT_METRICS_JSON_TEMPLATE,
+                         pSampleStreamingSession->iceMetrics.kvsIceAgentStats.candidateGatheringStartTime,
+                         pSampleStreamingSession->iceMetrics.kvsIceAgentStats.candidateGatheringEndTime);
+                DLOGI("Sending ice-agent metrics to the viewer: %s", pSampleStreamingSession->pIceAgentMetricsMessage);
+
+                retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pSampleStreamingSession->pSignalingClientMetricsMessage,
+                                            STRLEN(pSampleStreamingSession->pSignalingClientMetricsMessage));
+                retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pSampleStreamingSession->pPeerConnectionMetricsMessage,
+                                            STRLEN(pSampleStreamingSession->pPeerConnectionMetricsMessage));
+                retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pSampleStreamingSession->pIceAgentMetricsMessage,
+                                            STRLEN(pSampleStreamingSession->pIceAgentMetricsMessage));
+            }
+        } else {
+            DLOGI("DataChannel string message: %.*s\n", pMessageLen, pMessage);
+            STRCPY(errorMessage, "Send a json message for benchmarking as the C SDK is operating in benchmarking mode");
+            retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) errorMessage, STRLEN(errorMessage));
+        }
     } else {
-        DLOGI("DataChannel String Message: %.*s\n", pMessageLen, pMessage);
+        if (isBinary) {
+            DLOGI("DataChannel Binary Message");
+        } else {
+            DLOGI("DataChannel String Message: %.*s\n", pMessageLen, pMessage);
+        }
+        // Send a response to the message sent by the viewer
+        retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) MASTER_DATA_CHANNEL_MESSAGE, STRLEN(MASTER_DATA_CHANNEL_MESSAGE));
     }
-    // Send a response to the message sent by the viewer
-    STATUS retStatus = STATUS_SUCCESS;
-    retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) MASTER_DATA_CHANNEL_MESSAGE, STRLEN(MASTER_DATA_CHANNEL_MESSAGE));
     if (retStatus != STATUS_SUCCESS) {
         DLOGI("[KVS Master] dataChannelSend(): operation returned status code: 0x%08x \n", retStatus);
     }
+
+CleanUp:
+    CHK_LOG_ERR(retStatus);
 }
 
 VOID onDataChannel(UINT64 customData, PRtcDataChannel pRtcDataChannel)
@@ -68,6 +222,8 @@ VOID onConnectionStateChange(UINT64 customData, RTC_PEER_CONNECTION_STATE newSta
             ATOMIC_STORE_BOOL(&pSampleConfiguration->connected, TRUE);
             CVAR_BROADCAST(pSampleConfiguration->cvar);
 
+            pSampleStreamingSession->peerConnectionMetrics.peerConnectionStats.peerConnectionConnectedTime =
+                GETTIME() / HUNDREDS_OF_NANOS_IN_A_MILLISECOND;
             CHK_STATUS(peerConnectionGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->peerConnectionMetrics));
             CHK_STATUS(iceAgentGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->iceMetrics));
 
@@ -552,6 +708,7 @@ STATUS createSampleStreamingSession(PSampleConfiguration pSampleConfiguration, P
     ATOMIC_STORE_BOOL(&pSampleStreamingSession->terminateFlag, FALSE);
     ATOMIC_STORE_BOOL(&pSampleStreamingSession->candidateGatheringDone, FALSE);
 
+    pSampleStreamingSession->peerConnectionMetrics.peerConnectionStats.peerConnectionStartTime = GETTIME() / HUNDREDS_OF_NANOS_IN_A_MILLISECOND;
     CHK_STATUS(initializePeerConnection(pSampleConfiguration, &pSampleStreamingSession->pPeerConnection));
     CHK_STATUS(peerConnectionOnIceCandidate(pSampleStreamingSession->pPeerConnection, (UINT64) pSampleStreamingSession, onIceCandidateHandler));
     CHK_STATUS(
@@ -864,6 +1021,7 @@ STATUS createSampleConfiguration(PCHAR channelName, SIGNALING_CHANNEL_ROLE_TYPE
      * not ahead of time. */
     pSampleConfiguration->trickleIce = trickleIce;
     pSampleConfiguration->useTurn = useTurn;
+    pSampleConfiguration->enableSendingMetricsToViewerViaDc = FALSE;
 
     pSampleConfiguration->channelInfo.version = CHANNEL_INFO_CURRENT_VERSION;
     pSampleConfiguration->channelInfo.pChannelName = channelName;