Time-to-first-frame metrics benchmarking using datachannel

.github/build_windows_openssl.bat

@@ -2,5 +2,5 @@ call "C:\Program Files\Microsoft Visual Studio\2022\Enterprise\VC\Auxiliary\Buil
 mkdir build
 cd build
 cmd.exe /c cmake -G "NMake Makefiles" ..
-cmake -G "NMake Makefiles" -DBUILD_TEST=TRUE -DEXT_PTHREAD_INCLUDE_DIR="C:/tools/pthreads-w32-2-9-1-release/Pre-built.2/include/" -DEXT_PTHREAD_LIBRARIES="C:/tools/pthreads-w32-2-9-1-release/Pre-built.2/lib/x64/libpthreadGC2.a" ..
+cmake -G "NMake Makefiles" -DENABLE_SENDING_METRICS_TO_VIEWER=ON -DBUILD_TEST=TRUE -DEXT_PTHREAD_INCLUDE_DIR="C:/tools/pthreads-w32-2-9-1-release/Pre-built.2/include/" -DEXT_PTHREAD_LIBRARIES="C:/tools/pthreads-w32-2-9-1-release/Pre-built.2/lib/x64/libpthreadGC2.a" ..
 nmake

.github/workflows/ci.yml

@@ -49,7 +49,29 @@ jobs:
       - name: Run tests
         run:  |
           cd build
-          ./tst/webrtc_client_test
+          ./tst/webrtc_client_test    
+  mac-os-dc-metrics-build-gcc:
+    runs-on: macos-11
+    env:
+      CC: gcc
+      CXX: g++
+      AWS_KVS_LOG_LEVEL: 2
+    permissions:
+      id-token: write
+      contents: read
+    steps:
+      - name: Clone repository
+        uses: actions/checkout@v3
+      - name: Configure AWS Credentials
+        uses: aws-actions/configure-aws-credentials@v2
+        with:
+          role-to-assume: ${{ secrets.AWS_ROLE_TO_ASSUME }}
+          aws-region: ${{ secrets.AWS_REGION }}
+      - name: Build repository
+        run: |
+          mkdir build && cd build
+          cmake .. -DBUILD_TEST=TRUE -DENABLE_SENDING_METRICS_TO_VIEWER=ON
+          make
   mac-os-build-gcc:
     runs-on: macos-11
     env:
@@ -466,6 +488,32 @@ jobs:
         run:  |
           cd build
           timeout --signal=SIGABRT 60m ./tst/webrtc_client_test
+  ubuntu-os-dc-metrics-build:
+    runs-on: ubuntu-20.04
+    env:
+      AWS_KVS_LOG_LEVEL: 2
+    permissions:
+      id-token: write
+      contents: read
+    steps:
+      - name: Clone repository
+        uses: actions/checkout@v3
+      - name: Configure AWS Credentials
+        uses: aws-actions/configure-aws-credentials@v2
+        with:
+          role-to-assume: ${{ secrets.AWS_ROLE_TO_ASSUME }}
+          aws-region: ${{ secrets.AWS_REGION }}
+      - name: Build repository
+        run: |
+          # TODO: Remove the following line. This is only a workaround for enabling IPv6, https://github.com/travis-ci/travis-ci/issues/8891.
+          sudo sh -c 'echo 0 > /proc/sys/net/ipv6/conf/all/disable_ipv6'
+          mkdir build && cd build
+          cmake .. -DBUILD_TEST=TRUE -DENABLE_SENDING_METRICS_TO_VIEWER=ON
+          make
+      - name: Run tests
+        run:  |
+          cd build
+          timeout --signal=SIGABRT 60m ./tst/webrtc_client_test
   windows-msvc-openssl:
     runs-on: windows-2022
     env:

CMakeLists.txt

@@ -19,6 +19,7 @@ option(BUILD_LIBSRTP_DESTINATION_PLATFORM "If buildng LibSRTP what is the destin
 option(BUILD_SAMPLE "Build available samples" ON)
 option(ENABLE_DATA_CHANNEL "Enable support for data channel" ON)
 option(ENABLE_KVS_THREADPOOL "Enable support for KVS thread pool in signaling" ON)
+option(ENABLE_SENDING_METRICS_TO_VIEWER "Enable sending master-side metrics to the viewer as a json string via the datachannel" OFF)
 option(INSTRUMENTED_ALLOCATORS "Enable memory instrumentation" OFF)
 
 # Developer Flags
@@ -103,6 +104,10 @@ if (ENABLE_KVS_THREADPOOL)
   add_definitions(-DENABLE_KVS_THREADPOOL)
 endif()
 
+if (ENABLE_SENDING_METRICS_TO_VIEWER)
+  add_definitions(-DENABLE_SENDING_METRICS_TO_VIEWER)
+endif()
+
 if(USE_OPENSSL)
   add_definitions(-DKVS_USE_OPENSSL)
 elseif(USE_MBEDTLS)

samples/Common.c

@@ -33,18 +33,124 @@ STATUS signalingCallFailed(STATUS status)
 
 VOID onDataChannelMessage(UINT64 customData, PRtcDataChannel pDataChannel, BOOL isBinary, PBYTE pMessage, UINT32 pMessageLen)
 {
+    STATUS retStatus = STATUS_SUCCESS;
+#ifdef ENABLE_SENDING_METRICS_TO_VIEWER
+    UINT32 i, strLen, tokenCount;
+    UINT64 masterToViewerE2E = 0, viewerToMasterE2E = 0, t1, t2, t3, t4, t5;
+    PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData;
+    PSampleConfiguration pSampleConfiguration = pSampleStreamingSession->pSampleConfiguration;
+    DataChannelMessage dataChannelMessage = {'\0', '\0', '\0', '\0', '\0', '\0'};
+    CHAR pMessageSend[SIZEOF(DataChannelMessage)];
+    jsmn_parser parser;
+    jsmn_init(&parser);
+    jsmntok_t tokens[MAX_JSON_TOKEN_COUNT];
+    PCHAR json = (PCHAR) pMessage;
+
+    tokenCount = jsmn_parse(&parser, json, STRLEN(json), tokens, SIZEOF(tokens) / SIZEOF(jsmntok_t));
+
+    if (tokenCount > 1) {
+        CHK(tokens[0].type == JSMN_OBJECT, STATUS_INVALID_API_CALL_RETURN_JSON);
+        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);
+                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) "t1")) {
+                strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                STRNCPY(dataChannelMessage.t1, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+            } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "t2")) {
+                strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                if (strLen != 0) {
+                    STRNCPY(dataChannelMessage.t2, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                } else {
+                    SNPRINTF(dataChannelMessage.t2, 20, "%llu", GETTIME() / 10000);
+                    dataChannelMessage.t3[0] = '\0';
+                    dataChannelMessage.t4[0] = '\0';
+                    dataChannelMessage.t5[0] = '\0';
+                    break;
+                }
+            } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "t3")) {
+                strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                STRNCPY(dataChannelMessage.t3, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+            } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "t4")) {
+                strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                if (strLen != 0) {
+                    STRNCPY(dataChannelMessage.t4, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+                } else {
+                    SNPRINTF(dataChannelMessage.t4, 20, "%llu", GETTIME() / 10000);
+                    dataChannelMessage.t5[0] = '\0';
+                    break;
+                }
+            } else if (compareJsonString(json, &tokens[i], JSMN_STRING, (PCHAR) "t5")) {
+                strLen = (UINT32) (tokens[i + 1].end - tokens[i + 1].start);
+                STRNCPY(dataChannelMessage.t5, json + tokens[i + 1].start, tokens[i + 1].end - tokens[i + 1].start);
+            }
+        }
+
+        if (STRLEN(dataChannelMessage.t5) == 0) {
+            SNPRINTF(pMessageSend, SIZEOF(DataChannelMessage), DATA_CHANNEL_MESSAGE_TEMPLATE, MASTER_DATA_CHANNEL_MESSAGE, dataChannelMessage.t1,
+                     dataChannelMessage.t2, dataChannelMessage.t3, dataChannelMessage.t4, dataChannelMessage.t5);
+            DLOGI("Master's response: %s", pMessageSend);
+
+            retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pMessageSend, STRLEN(pMessageSend));
+        } else {
+            SNPRINTF(pSignalingClientMetricsMessage, MAX_SIGNALING_CLIENT_METRICS_MESSAGE_SIZE, SIGNALING_CLIENT_METRICS_JSON_TEMPLATE,
+                     pSampleConfiguration->signalingClientMetrics.signalingStartTime, pSampleConfiguration->signalingClientMetrics.signalingEndTime,
+                     pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerTime,
+                     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", pSignalingClientMetricsMessage);
+
+            CHK_STATUS(peerConnectionGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->peerConnectionMetrics));
+            SNPRINTF(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", pPeerConnectionMetricsMessage);
+
+            CHK_STATUS(iceAgentGetMetrics(pSampleStreamingSession->pPeerConnection, &pSampleStreamingSession->iceMetrics));
+            SNPRINTF(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", pIceAgentMetricsMessage);
+
+            retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pSignalingClientMetricsMessage, STRLEN(pSignalingClientMetricsMessage));
+            retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pPeerConnectionMetricsMessage, STRLEN(pPeerConnectionMetricsMessage));
+            retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) pIceAgentMetricsMessage, STRLEN(pIceAgentMetricsMessage));
+        }
+    } else {
+        DLOGI("DataChannel string message: %.*s\n", pMessageLen, pMessage);
+        retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) MASTER_DATA_CHANNEL_MESSAGE, STRLEN(MASTER_DATA_CHANNEL_MESSAGE));
+    }
+#else
     UNUSED_PARAM(customData);
     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
-    STATUS retStatus = STATUS_SUCCESS;
     retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) MASTER_DATA_CHANNEL_MESSAGE, STRLEN(MASTER_DATA_CHANNEL_MESSAGE));
+#endif
     if (retStatus != STATUS_SUCCESS) {
         DLOGI("[KVS Master] dataChannelSend(): operation returned status code: 0x%08x \n", retStatus);
     }
+
+#ifdef ENABLE_SENDING_METRICS_TO_VIEWER
+CleanUp:
+    CHK_LOG_ERR(retStatus);
+#endif
 }
 
 VOID onDataChannel(UINT64 customData, PRtcDataChannel pRtcDataChannel)
@@ -67,6 +173,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));
 
@@ -273,7 +381,9 @@ STATUS sendSignalingMessage(PSampleStreamingSession pSampleStreamingSession, PSi
     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);
+        DLOGP("[Signaling offer to answer] %" PRIu64 " ms",
+              pSampleConfiguration->signalingClientMetrics.signalingClientStats.answerTime -
+                  pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerTime);
     }
 
 CleanUp:
@@ -507,6 +617,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(
@@ -896,12 +1007,20 @@ STATUS initSignaling(PSampleConfiguration pSampleConfiguration, PCHAR clientId)
     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 Get token] %" PRIu64 " ms",
+          signalingClientMetrics.signalingClientStats.getTokenEndTime - signalingClientMetrics.signalingClientStats.getTokenStartTime);
+    DLOGP("[Signaling Describe] %" PRIu64 " ms",
+          signalingClientMetrics.signalingClientStats.describeChannelEndTime - signalingClientMetrics.signalingClientStats.describeChannelStartTime);
+    DLOGP("[Signaling Create Channel] %" PRIu64 " ms",
+          signalingClientMetrics.signalingClientStats.createChannelEndTime - signalingClientMetrics.signalingClientStats.createChannelStartTime);
+    DLOGP("[Signaling Get endpoint] %" PRIu64 " ms",
+          signalingClientMetrics.signalingClientStats.getSignalingChannelEndpointEndTime -
+              signalingClientMetrics.signalingClientStats.getSignalingChannelEndpointStartTime);
+    DLOGP("[Signaling Get ICE config] %" PRIu64 " ms",
+          signalingClientMetrics.signalingClientStats.getIceServerConfigEndTime -
+              signalingClientMetrics.signalingClientStats.getIceServerConfigStartTime);
+    DLOGP("[Signaling Connect] %" PRIu64 " ms",
+          signalingClientMetrics.signalingClientStats.connectEndTime - signalingClientMetrics.signalingClientStats.connectStartTime);
     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);
@@ -1427,7 +1546,9 @@ 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);
+            DLOGP("[Signaling offer to answer] %" PRIu64 " ms",
+                  pSampleConfiguration->signalingClientMetrics.signalingClientStats.answerTime -
+                      pSampleConfiguration->signalingClientMetrics.signalingClientStats.offerTime);
             break;
 
         case SIGNALING_MESSAGE_TYPE_ICE_CANDIDATE: