diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 55b77db60f..178833ee7a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -416,7 +416,7 @@ 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: @@ -424,19 +424,21 @@ jobs: 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 diff --git a/README.md b/README.md index 4edd145e11..7ac8e6bafe 100644 --- a/README.md +++ b/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. +
+ Time-to-first-frame breakdown metrics + 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. +
+ ### Set path to SSL CA certificate (**Optional**) If you have a custom CA certificate path to set, you can set it using: diff --git a/samples/Common.c b/samples/Common.c index df0ec4af14..1518cee1e6 100644 --- a/samples/Common.c +++ b/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; diff --git a/samples/Samples.h b/samples/Samples.h index 2719fec056..83644c0689 100644 --- a/samples/Samples.h +++ b/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 diff --git a/samples/kvsWebRTCClientMaster.c b/samples/kvsWebRTCClientMaster.c index ac74c9864c..fcc5a1835b 100644 --- a/samples/kvsWebRTCClientMaster.c +++ b/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 diff --git a/scripts/check-sample.sh b/scripts/check-sample.sh index 3615265174..d4d8cdbe5b 100755 --- a/scripts/check-sample.sh +++ b/scripts/check-sample.sh @@ -1,14 +1,11 @@ #!/bin/bash -if [[ -z "$AWS_ACCESS_KEY_ID" || -z "$AWS_SECRET_ACCESS_KEY" ]] +if [[ -z "$AWS_ACCESS_KEY_ID" || -z "$AWS_SECRET_ACCESS_KEY" || -z "$AWS_SESSION_TOKEN" ]] then echo "Couldn't find AWS credentials. Very likely this build is coming from a fork. Ignoring." exit 0 fi -# Set session token to empty string to check that it gets ignored -export AWS_SESSION_TOKEN= - # Set bash to print out every command that's running to the screen # Set logging after checking credentials so that we don't leak them set -xv diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h index cecc45c7ed..a3c990ea7a 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h @@ -46,6 +46,23 @@ extern "C" { DLOGP("[%s] Time taken: %" PRIu64 " ms", msg, (GETTIME() - (t)) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); \ } while (FALSE) +#define PROFILE_CALL_WITH_START_END_T_OBJ(f, s, e, d, msg) \ + do { \ + s = GETTIME() / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; \ + f; \ + e = GETTIME() / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; \ + d = ((e) - (s)); \ + DLOGP("[%s] Time taken: %" PRIu64 " ms", (msg), (d)); \ + } while (FALSE) + +#define PROFILE_WITH_START_END_TIME_OBJ(t1, t2, d, msg) \ + do { \ + t1 = (t1 / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); \ + t2 = (GETTIME() / HUNDREDS_OF_NANOS_IN_A_MILLISECOND); \ + d = ((t2) - (t1)); \ + DLOGP("[%s] Time taken: %" PRIu64 " ms", (msg), (d)); \ + } while (FALSE) + #define PROFILE_WITH_START_TIME_OBJ(t1, t2, msg) \ do { \ t2 = (GETTIME() - (t1)) / HUNDREDS_OF_NANOS_IN_A_MILLISECOND; \ @@ -1530,7 +1547,10 @@ typedef struct { * @brief SignalingStats Collection of signaling related stats. Can be expanded in the future */ typedef struct { - UINT32 version; //!< Structure version + UINT32 version; //!< Structure version + UINT64 signalingStartTime; + UINT64 signalingEndTime; + UINT64 signalingCallTime; SignalingClientStats signalingClientStats; //!< Signaling client metrics stats. Reference in Stats.h } SignalingClientMetrics, *PSignalingClientMetrics; diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h index 7696cf2035..72fffb67ba 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Stats.h @@ -256,6 +256,8 @@ typedef struct { UINT64 iceCandidatePairNominationTime; UINT64 candidateGatheringTime; UINT64 iceAgentSetUpTime; + UINT64 candidateGatheringStartTime; + UINT64 candidateGatheringEndTime; } KvsIceAgentStats, *PKvsIceAgentStats; /** @@ -571,6 +573,18 @@ typedef struct { * @brief SignalingClientMetrics Represent the stats related to the KVS WebRTC SDK signaling client */ typedef struct { + UINT64 describeChannelStartTime; + UINT64 describeChannelEndTime; + UINT64 getSignalingChannelEndpointStartTime; + UINT64 getSignalingChannelEndpointEndTime; + UINT64 getIceServerConfigStartTime; + UINT64 getIceServerConfigEndTime; + UINT64 getTokenStartTime; + UINT64 getTokenEndTime; + UINT64 createChannelStartTime; + UINT64 createChannelEndTime; + UINT64 connectStartTime; + UINT64 connectEndTime; UINT64 cpApiCallLatency; //!< Latency (in 100 ns) incurred per backend API call for the control plane APIs UINT64 dpApiCallLatency; //!< Latency (in 100 ns) incurred per backend API call for the data plane APIs UINT64 signalingClientUptime; //!< Client uptime (in 100 ns). Timestamp will be recorded at every SIGNALING_CLIENT_STATE_CONNECTED @@ -606,10 +620,14 @@ typedef struct { fetchClientTime; //!< Total time (ms) taken to fetch signaling client which includes describe, create, get endpoint and get ICE server config UINT64 connectClientTime; //!< Total time (ms) taken to connect the signaling client which includes connecting to the signaling channel UINT64 offerToAnswerTime; + UINT64 offerReceivedTime; + UINT64 answerTime; UINT64 joinSessionToOfferRecvTime; //!< Total time (ms) taken from joinSession call until offer is received } SignalingClientStats, *PSignalingClientStats; typedef struct { + UINT64 peerConnectionStartTime; + UINT64 peerConnectionConnectedTime; UINT64 peerConnectionCreationTime; //!< Time taken (ms) for peer connection object creation time UINT64 dtlsSessionSetupTime; //!< Time taken (ms) for DTLS handshake to complete UINT64 iceHolePunchingTime; //!< Time taken (ms) for ICE agent set up to complete diff --git a/src/source/Ice/IceAgent.c b/src/source/Ice/IceAgent.c index de660ee816..fde9db6394 100644 --- a/src/source/Ice/IceAgent.c +++ b/src/source/Ice/IceAgent.c @@ -1683,8 +1683,8 @@ STATUS iceAgentGatherCandidateTimerCallback(UINT32 timerId, UINT64 currentTime, if (stopScheduling) { ATOMIC_STORE_BOOL(&pIceAgent->candidateGatheringFinished, TRUE); - PROFILE_WITH_START_TIME_OBJ(pIceAgent->candidateGatheringStartTime, pIceAgent->iceAgentProfileDiagnostics.candidateGatheringTime, - "Candidate gathering time"); + PROFILE_WITH_START_END_TIME_OBJ(pIceAgent->candidateGatheringStartTime, pIceAgent->candidateGatheringProcessEndTime, + pIceAgent->iceAgentProfileDiagnostics.candidateGatheringTime, "Candidate gathering time"); /* notify that candidate gathering is finished. */ if (pIceAgent->iceAgentCallbacks.newLocalCandidateFn != NULL) { pIceAgent->iceAgentCallbacks.newLocalCandidateFn(pIceAgent->iceAgentCallbacks.customData, NULL); @@ -2946,6 +2946,8 @@ STATUS getIceAgentStats(PIceAgent pIceAgent, PKvsIceAgentMetrics pKvsIceAgentMet pKvsIceAgentMetrics->kvsIceAgentStats.iceCandidatePairNominationTime = pIceAgent->iceAgentProfileDiagnostics.iceCandidatePairNominationTime; pKvsIceAgentMetrics->kvsIceAgentStats.candidateGatheringTime = pIceAgent->iceAgentProfileDiagnostics.candidateGatheringTime; pKvsIceAgentMetrics->kvsIceAgentStats.iceAgentSetUpTime = pIceAgent->iceAgentProfileDiagnostics.iceAgentSetUpTime; + pKvsIceAgentMetrics->kvsIceAgentStats.candidateGatheringStartTime = pIceAgent->candidateGatheringStartTime; + pKvsIceAgentMetrics->kvsIceAgentStats.candidateGatheringEndTime = pIceAgent->candidateGatheringProcessEndTime; CleanUp: return retStatus; } diff --git a/src/source/Ice/IceAgent.h b/src/source/Ice/IceAgent.h index e0577dab2d..a2027f87ca 100644 --- a/src/source/Ice/IceAgent.h +++ b/src/source/Ice/IceAgent.h @@ -265,6 +265,7 @@ struct __IceAgent { PTransactionIdStore pStunBindingRequestTransactionIdStore; UINT64 candidateGatheringStartTime; + UINT64 candidateGatheringProcessEndTime; UINT64 iceAgentStartTime; }; diff --git a/src/source/Signaling/Signaling.c b/src/source/Signaling/Signaling.c index 07165bd288..7b7a312a72 100644 --- a/src/source/Signaling/Signaling.c +++ b/src/source/Signaling/Signaling.c @@ -416,8 +416,8 @@ STATUS signalingSendMessageSync(PSignalingClient pSignalingClient, PSignalingMes if (pSignalingMessage->messageType == SIGNALING_MESSAGE_TYPE_OFFER) { pSignalingClient->offerSentTime = GETTIME(); } else if (pSignalingMessage->messageType == SIGNALING_MESSAGE_TYPE_ANSWER) { - PROFILE_WITH_START_TIME_OBJ(pSignalingClient->offerReceivedTime, pSignalingClient->diagnostics.offerToAnswerTime, - "Offer Received to Answer Sent time"); + PROFILE_WITH_START_END_TIME_OBJ(pSignalingClient->offerReceivedTime, pSignalingClient->answerTime, + pSignalingClient->diagnostics.offerToAnswerTime, "Offer Received to Answer Sent time"); } MUTEX_UNLOCK(pSignalingClient->offerSendReceiveTimeLock); // Update the internal diagnostics only after successfully sending @@ -1422,6 +1422,22 @@ STATUS signalingGetMetrics(PSignalingClient pSignalingClient, PSignalingClientMe pSignalingClientMetrics->signalingClientStats.connectClientTime = pSignalingClient->diagnostics.connectClientTime; pSignalingClientMetrics->signalingClientStats.joinSessionCallTime = pSignalingClient->diagnostics.joinSessionCallTime; pSignalingClientMetrics->signalingClientStats.offerToAnswerTime = pSignalingClient->diagnostics.offerToAnswerTime; + pSignalingClientMetrics->signalingClientStats.answerTime = pSignalingClient->answerTime; + pSignalingClientMetrics->signalingClientStats.offerReceivedTime = pSignalingClient->offerReceivedTime; + pSignalingClientMetrics->signalingClientStats.describeChannelStartTime = pSignalingClient->diagnostics.describeChannelStartTime; + pSignalingClientMetrics->signalingClientStats.describeChannelEndTime = pSignalingClient->diagnostics.describeChannelEndTime; + pSignalingClientMetrics->signalingClientStats.getSignalingChannelEndpointStartTime = + pSignalingClient->diagnostics.getSignalingChannelEndpointStartTime; + pSignalingClientMetrics->signalingClientStats.getSignalingChannelEndpointEndTime = + pSignalingClient->diagnostics.getSignalingChannelEndpointEndTime; + pSignalingClientMetrics->signalingClientStats.getIceServerConfigStartTime = pSignalingClient->diagnostics.getIceServerConfigStartTime; + pSignalingClientMetrics->signalingClientStats.getIceServerConfigEndTime = pSignalingClient->diagnostics.getIceServerConfigEndTime; + pSignalingClientMetrics->signalingClientStats.getTokenStartTime = pSignalingClient->diagnostics.getTokenStartTime; + pSignalingClientMetrics->signalingClientStats.getTokenEndTime = pSignalingClient->diagnostics.getTokenEndTime; + pSignalingClientMetrics->signalingClientStats.createChannelStartTime = pSignalingClient->diagnostics.createChannelStartTime; + pSignalingClientMetrics->signalingClientStats.createChannelEndTime = pSignalingClient->diagnostics.createChannelEndTime; + pSignalingClientMetrics->signalingClientStats.connectStartTime = pSignalingClient->diagnostics.connectStartTime; + pSignalingClientMetrics->signalingClientStats.connectEndTime = pSignalingClient->diagnostics.connectEndTime; pSignalingClientMetrics->signalingClientStats.joinSessionToOfferRecvTime = pSignalingClient->diagnostics.joinSessionToOfferRecvTime; case 0: // Fill in the data structures according to the version of the requested structure diff --git a/src/source/Signaling/Signaling.h b/src/source/Signaling/Signaling.h index c4004b1b17..10d2813255 100644 --- a/src/source/Signaling/Signaling.h +++ b/src/source/Signaling/Signaling.h @@ -184,6 +184,18 @@ typedef struct { volatile SIZE_T numberOfErrors; volatile SIZE_T numberOfRuntimeErrors; volatile SIZE_T numberOfReconnects; + UINT64 describeChannelStartTime; + UINT64 describeChannelEndTime; + UINT64 getSignalingChannelEndpointStartTime; + UINT64 getSignalingChannelEndpointEndTime; + UINT64 getIceServerConfigStartTime; + UINT64 getIceServerConfigEndTime; + UINT64 getTokenStartTime; + UINT64 getTokenEndTime; + UINT64 createChannelStartTime; + UINT64 createChannelEndTime; + UINT64 connectStartTime; + UINT64 connectEndTime; UINT64 createTime; UINT64 connectTime; UINT64 cpApiLatency; @@ -358,6 +370,7 @@ typedef struct { UINT64 deleteTime; UINT64 connectTime; UINT64 describeMediaTime; + UINT64 answerTime; #ifdef KVS_USE_SIGNALING_CHANNEL_THREADPOOL PThreadpool pThreadpool; diff --git a/src/source/Signaling/StateMachine.c b/src/source/Signaling/StateMachine.c index c1f647e669..c865a626be 100644 --- a/src/source/Signaling/StateMachine.c +++ b/src/source/Signaling/StateMachine.c @@ -347,7 +347,6 @@ STATUS executeGetTokenSignalingState(UINT64 customData, UINT64 time) STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); SERVICE_CALL_RESULT serviceCallResult; - UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); @@ -363,9 +362,10 @@ STATUS executeGetTokenSignalingState(UINT64 customData, UINT64 time) THREAD_SLEEP_UNTIL(time); // Use the credential provider to get the token - PROFILE_CALL_WITH_T_OBJ(retStatus = pSignalingClient->pCredentialProvider->getCredentialsFn(pSignalingClient->pCredentialProvider, - &pSignalingClient->pAwsCredentials), - pSignalingClient->diagnostics.getTokenCallTime, "Get token call"); + PROFILE_CALL_WITH_START_END_T_OBJ(retStatus = pSignalingClient->pCredentialProvider->getCredentialsFn(pSignalingClient->pCredentialProvider, + &pSignalingClient->pAwsCredentials), + pSignalingClient->diagnostics.getTokenStartTime, pSignalingClient->diagnostics.getTokenEndTime, + pSignalingClient->diagnostics.getTokenCallTime, "Get token call"); // Check the expiration if (NULL == pSignalingClient->pAwsCredentials || SIGNALING_GET_CURRENT_TIME(pSignalingClient) >= pSignalingClient->pAwsCredentials->expiration) { @@ -434,7 +434,6 @@ STATUS executeDescribeSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); - UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -447,8 +446,9 @@ STATUS executeDescribeSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - PROFILE_CALL_WITH_T_OBJ(retStatus = describeChannel(pSignalingClient, time), pSignalingClient->diagnostics.describeCallTime, - "Describe signaling call"); + PROFILE_CALL_WITH_START_END_T_OBJ(retStatus = describeChannel(pSignalingClient, time), pSignalingClient->diagnostics.describeChannelStartTime, + pSignalingClient->diagnostics.describeChannelEndTime, pSignalingClient->diagnostics.describeCallTime, + "Describe signaling call"); CleanUp: @@ -562,7 +562,6 @@ STATUS executeCreateSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); - UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -575,7 +574,9 @@ STATUS executeCreateSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - PROFILE_CALL_WITH_T_OBJ(retStatus = createChannel(pSignalingClient, time), pSignalingClient->diagnostics.createCallTime, "Create signaling call"); + PROFILE_CALL_WITH_START_END_T_OBJ(retStatus = createChannel(pSignalingClient, time), pSignalingClient->diagnostics.createChannelStartTime, + pSignalingClient->diagnostics.createChannelEndTime, pSignalingClient->diagnostics.createCallTime, + "Create signaling call"); CleanUp: @@ -620,7 +621,6 @@ STATUS executeGetEndpointSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); - UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -633,8 +633,10 @@ STATUS executeGetEndpointSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - PROFILE_CALL_WITH_T_OBJ(retStatus = getChannelEndpoint(pSignalingClient, time), pSignalingClient->diagnostics.getEndpointCallTime, - "Get endpoint signaling call"); + PROFILE_CALL_WITH_START_END_T_OBJ(retStatus = getChannelEndpoint(pSignalingClient, time), + pSignalingClient->diagnostics.getSignalingChannelEndpointStartTime, + pSignalingClient->diagnostics.getSignalingChannelEndpointEndTime, + pSignalingClient->diagnostics.getEndpointCallTime, "Get endpoint signaling call"); CleanUp: @@ -688,7 +690,6 @@ STATUS executeGetIceConfigSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); - UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); ATOMIC_STORE(&pSignalingClient->result, (SIZE_T) SERVICE_CALL_RESULT_NOT_SET); @@ -701,8 +702,10 @@ STATUS executeGetIceConfigSignalingState(UINT64 customData, UINT64 time) } // Call the aggregate function - PROFILE_CALL_WITH_T_OBJ(retStatus = getIceConfig(pSignalingClient, time), pSignalingClient->diagnostics.getIceConfigCallTime, - "Get ICE config signaling call"); + PROFILE_CALL_WITH_START_END_T_OBJ(retStatus = getIceConfig(pSignalingClient, time), pSignalingClient->diagnostics.getIceServerConfigStartTime, + pSignalingClient->diagnostics.getIceServerConfigEndTime, pSignalingClient->diagnostics.getIceConfigCallTime, + "Get ICE config signaling call"); + CleanUp: LEAVES(); @@ -846,7 +849,6 @@ STATUS executeConnectSignalingState(UINT64 customData, UINT64 time) ENTERS(); STATUS retStatus = STATUS_SUCCESS; PSignalingClient pSignalingClient = SIGNALING_CLIENT_FROM_CUSTOM_DATA(customData); - UINT64 startTimeInMacro = 0; CHK(pSignalingClient != NULL, STATUS_NULL_ARG); @@ -856,8 +858,9 @@ STATUS executeConnectSignalingState(UINT64 customData, UINT64 time) SIGNALING_CLIENT_STATE_CONNECTING)); } - PROFILE_CALL_WITH_T_OBJ(retStatus = connectSignalingChannel(pSignalingClient, time), pSignalingClient->diagnostics.connectCallTime, - "Connect signaling call"); + PROFILE_CALL_WITH_START_END_T_OBJ(retStatus = connectSignalingChannel(pSignalingClient, time), pSignalingClient->diagnostics.connectStartTime, + pSignalingClient->diagnostics.connectEndTime, pSignalingClient->diagnostics.connectCallTime, + "Connect signaling call"); CleanUp: