Time-to-first-frame metrics benchmarking using datachannel

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,150 @@ 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];
+    PCHAR json;
+    PSampleStreamingSession pSampleStreamingSession = (PSampleStreamingSession) customData;
+    PSampleConfiguration pSampleConfiguration = pSampleStreamingSession->pSampleConfiguration;
+    DataChannelMessage dataChannelMessage;
+    jsmn_parser parser;
+    jsmntok_t tokens[MAX_JSON_TOKEN_COUNT];
+
+    CHK(pMessage != NULL && pDataChannel != NULL, STATUS_NULL_ARG);
+
+    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) {
+            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);
+                    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);
+            retStatus = dataChannelSend(pDataChannel, FALSE, (PBYTE) MASTER_DATA_CHANNEL_MESSAGE, STRLEN(MASTER_DATA_CHANNEL_MESSAGE));
+        }
     } 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 +200,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 +686,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 +999,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;

samples/Samples.h

@@ -49,11 +49,28 @@ extern "C" {
 #define IOT_CORE_THING_NAME          ((PCHAR) "AWS_IOT_CORE_THING_NAME")
 #define IOT_CORE_CERTIFICATE_ID      ((PCHAR) "AWS_IOT_CORE_CERTIFICATE_ID")
 
+/* Uncomment the following line in order to enable IoT credentials checks in the provided samples */
+// #define IOT_CORE_ENABLE_CREDENTIALS  1
+
 #define MASTER_DATA_CHANNEL_MESSAGE "This message is from the KVS Master"
 #define VIEWER_DATA_CHANNEL_MESSAGE "This message is from the KVS Viewer"
 
-/* Uncomment the following line in order to enable IoT credentials checks in the provided samples */
-// #define IOT_CORE_ENABLE_CREDENTIALS  1
+#define DATA_CHANNEL_MESSAGE_TEMPLATE                                                                                                                \
+    "{\"content\":\"%s\",\"firstMessageFromViewerTs\":\"%s\",\"firstMessageFromMasterTs\":\"%s\",\"secondMessageFromViewerTs\":\"%s\","              \
+    "\"secondMessageFromMasterTs\":\"%s\",\"lastMessageFromViewerTs\":\"%s\" }"
+#define PEER_CONNECTION_METRICS_JSON_TEMPLATE "{\"peerConnectionStartTime\": %llu, \"peerConnectionEndTime\": %llu }"
+#define SIGNALING_CLIENT_METRICS_JSON_TEMPLATE                                                                                                       \
+    "{\"signalingStartTime\": %llu, \"signalingEndTime\": %llu, \"offerReceiptTime\": %llu, \"sendAnswerTime\": %llu, "                              \
+    "\"describeChannelStartTime\": %llu, \"describeChannelEndTime\": %llu, \"getSignalingChannelEndpointStartTime\": %llu, "                         \
+    "\"getSignalingChannelEndpointEndTime\": %llu, \"getIceServerConfigStartTime\": %llu, \"getIceServerConfigEndTime\": %llu, "                     \
+    "\"getTokenStartTime\": %llu, \"getTokenEndTime\": %llu, \"createChannelStartTime\": %llu, \"createChannelEndTime\": %llu, "                     \
+    "\"connectStartTime\": %llu, \"connectEndTime\": %llu }"
+#define ICE_AGENT_METRICS_JSON_TEMPLATE "{\"candidateGatheringStartTime\": %llu, \"candidateGatheringEndTime\": %llu }"
+
+#define MAX_DATA_CHANNEL_METRICS_MESSAGE_SIZE     260 // strlen(DATA_CHANNEL_MESSAGE_TEMPLATE) + 20 * 5
+#define MAX_PEER_CONNECTION_METRICS_MESSAGE_SIZE  105 // strlen(PEER_CONNECTION_METRICS_JSON_TEMPLATE) + 20 * 2
+#define MAX_SIGNALING_CLIENT_METRICS_MESSAGE_SIZE 736 // strlen(SIGNALING_CLIENT_METRICS_JSON_TEMPLATE) + 20 * 10
+#define MAX_ICE_AGENT_METRICS_MESSAGE_SIZE        113 // strlen(ICE_AGENT_METRICS_JSON_TEMPLATE) + 20 * 2
 
 typedef enum {
     SAMPLE_STREAMING_VIDEO_ONLY,
@@ -112,6 +129,7 @@ typedef struct {
     CVAR cvar;
     BOOL trickleIce;
     BOOL useTurn;
+    BOOL enableSendingMetricsToViewerViaDc;
     BOOL enableFileLogging;
     UINT64 customData;
     PSampleStreamingSession sampleStreamingSessionList[DEFAULT_MAX_CONCURRENT_STREAMING_SESSION];
@@ -132,6 +150,15 @@ typedef struct {
     UINT32 logLevel;
 } SampleConfiguration, *PSampleConfiguration;
 
+typedef struct {
+    CHAR content[100];
+    CHAR firstMessageFromViewerTs[20];
+    CHAR firstMessageFromMasterTs[20];
+    CHAR secondMessageFromViewerTs[20];
+    CHAR secondMessageFromMasterTs[20];
+    CHAR lastMessageFromViewerTs[20];
+} DataChannelMessage;
+
 typedef struct {
     UINT64 hashValue;
     UINT64 createTime;
@@ -166,6 +193,9 @@ struct __SampleStreamingSession {
     UINT64 offerReceiveTime;
     PeerConnectionMetrics peerConnectionMetrics;
     KvsIceAgentMetrics iceMetrics;
+    CHAR pPeerConnectionMetricsMessage[MAX_PEER_CONNECTION_METRICS_MESSAGE_SIZE];
+    CHAR pSignalingClientMetricsMessage[MAX_SIGNALING_CLIENT_METRICS_MESSAGE_SIZE];
+    CHAR pIceAgentMetricsMessage[MAX_ICE_AGENT_METRICS_MESSAGE_SIZE];
 };
 
 // TODO this should all be in a higher webrtccontext layer above PeerConnection

samples/kvsWebRTCClientMaster.c

@@ -54,7 +54,11 @@ INT32 main(INT32 argc, CHAR* argv[])
     CHK_STATUS(initKvsWebRtc());
     DLOGI("[KVS Master] KVS WebRTC initialization completed successfully");
 
-    CHK_STATUS(initSignaling(pSampleConfiguration, SAMPLE_MASTER_CLIENT_ID));
+    PROFILE_CALL_WITH_START_END_T_OBJ(
+        retStatus = initSignaling(pSampleConfiguration, SAMPLE_MASTER_CLIENT_ID), pSampleConfiguration->signalingClientMetrics.signalingStartTime,
+        pSampleConfiguration->signalingClientMetrics.signalingEndTime, pSampleConfiguration->signalingClientMetrics.signalingCallTime,
+        "Initialize signaling client and connect to the signaling channel");
+
     DLOGI("[KVS Master] Channel %s set up done ", pChannelName);
 
     // Checking for termination