awslabs / amazon-kinesis-video-streams-producer-sdk-cpp

Amazon Kinesis Video Streams Producer SDK for C++ is for developers to install and customize for their connected camera and other devices to securely stream video, audio, and time-encoded data to Kinesis Video Streams.
Apache License 2.0
373 stars 334 forks source link

[QUESTION] DTS out of order after getEarliestTrack() and audioVideoFrameTimestampComparator() causing 0x30000005 error #637

Closed wlinInspire closed 3 years ago

wlinInspire commented 3 years ago

Hi KVS team,

I am streaming RTSP video and audio to KVS using GStreamer plugin built from the master branch. I see "putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client" with error code 0x30000005 (STATUS_CONTENT_VIEW_INVALID_TIMESTAMP). I added more logging and found that although frame DTS is indeed monotonically increasing inside frameOrderCoordinatorPutFrame(), it becomes out of order inside putFrame() sometimes. Below is the sample debugging info and you can see that putFrame(): putting Frame DTS: 29490462 comes before putFrame(): putting Frame DTS: 29489342, which should be the other way around. (Note the warning message is not referring to the frame DTS causing the problem)

[2020-12-22 07:36:19:100.470 GMT] [DEBUG] frameOrderCoordinatorPutFrame(): putting Frame DTS: 29489342
[2020-12-22 07:36:19:116.196 GMT] [DEBUG] frameOrderCoordinatorPutFrame(): putting Frame DTS: 29490462
[2020-12-22 07:36:19:116.585 GMT] [DEBUG] putFrame(): putting Frame DTS: 29490462
[2020-12-22 07:36:19:146.471 GMT] [DEBUG] putFrame(): putting Frame DTS: 29489342
[2020-12-22 07:36:19:146.620 GMT] [WARN ] putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x30000005 decoding timestamp: 29824174 presentation timestamp: 16086225793525763

The logging code I added is as below at this

DLOGD("putting Frame DTS: %" PRIu64, pFrame->decodingTs);
CHK_STATUS(stackQueueEnqueue(pPutFrameTrackData->frameQueue, (UINT64) pFrame));

and this

DLOGD("putting Frame DTS: %" PRIu64, pFrame->decodingTs);
if (!CHECK_FRAME_FLAG_END_OF_FRAGMENT(pFrame->flags)) {
    // Lookup the track that pFrame belong to
    CHK_STATUS(mkvgenGetTrackInfo(pKinesisVideoStream->streamInfo.streamCaps.trackInfoList,
                                  pKinesisVideoStream->streamInfo.streamCaps.trackInfoCount,
                                  pFrame->trackId,
                                  &pTrackInfo,
                                  &trackIndex));
}

After some debugging, I think the problem is caused by this .

if (pStreamInfo->streamCaps.frameOrderingMode == FRAME_ORDERING_MODE_MULTI_TRACK_AV_COMPARE_DTS_ONE_MS_COMPENSATE ||
            pStreamInfo->streamCaps.frameOrderingMode == FRAME_ORDERING_MODE_MULTI_TRACK_AV_COMPARE_DTS_ONE_MS_COMPENSATE_EOFR) {
    mkvTimestamp1 = pFirst->decodingTs;
    mkvTimestamp2 = pSecond->decodingTs;
} else {
    mkvTimestamp1 = pFirst->presentationTs;
    mkvTimestamp2 = pSecond->presentationTs;
}

The default frame ordering mode is FRAME_ORDERING_MODE_MULTI_TRACK_AV_COMPARE_PTS_ONE_MS_COMPENSATE, so the code will compare PTS instead of DTS. If I force to compare DTS, the error 0x30000005 is gone and frames are put in the order of DTS. However, new errors come out from backend with error code 0x52000060 (STATUS_ACK_ERR_FRAGMENT_TIMECODE_NOT_MONOTONIC)

[2020-12-23 01:32:39:076.830 GMT] [WARN ] continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 103120000 Status: 0x52000060

Is the backend comparing PTS instead of DTS? Is there any more debugging I can do?

MushMal commented 3 years ago

@wlinInspire the code in frame order coordinator is very involved. It has to handle multiple edge cases to "massage" the frame timestamps in the right order in a streamable fashion and handle different track frame timestamp collisions and handle A/V sync issue. This is all done so we can have a streamable multi-track MKV which is syntactically correct and semantically valid. The frame order coordinator can indeed modify the timestamps of the frames in order to handle frames from different tracks. The default mode in Producer C for multi-track Audio Video is FRAME_ORDERING_MODE_MULTI_TRACK_AV_COMPARE_PTS_ONE_MS_COMPENSATE which will compare and reorder frames according to the presentation timestamp. The reordering of the frames between different tracks is done so they can be monotonically increasing (across the tracks) as long as they are in decode order (MKV requirement) and the timestamps are self-contained. This works OK for most of the pipelines but for some reason for your pipeline it seems that the DTS will cause an issue.

Can you dump out the pts and dts of the frames that cause this issue? I would expect that for your case the pts and dts of the frames should be the same. We have a certain handling of the pts/dts in the GStreamer plugin to adapt for different behaviors for different pipelines. Looking at the pts and dts of the frames, it's likely that the pts is not "properly" set.

There is also a discussion in here: https://github.com/awslabs/amazon-kinesis-video-streams-producer-sdk-cpp/issues/594

wlinInspire commented 3 years ago

Hi @MushMal ,

I added the logging below before this line

DLOGI("Cluster DTS: %" PRIu64 " Cluster PTS: %" PRIu64 " Frame DTS: %" PRIu64 " Frame PTS: %" PRIu64,
    encodedFrameInfo.clusterDts, 
    encodedFrameInfo.clusterPts, 
    encodedFrameInfo.frameDts, 
    encodedFrameInfo.framePts);

If we are in FRAME_ORDERING_MODE_MULTI_TRACK_AV_COMPARE_PTS_ONE_MS_COMPENSATE mode, frames are ordered by PTS. You can see from below that frame PTS is monotonically increasing while frame DTS sometimes is out of order causing 0x30000005 error

[2020-12-24 19:29:49:994.845 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 0 Frame PTS: 0
[2020-12-24 19:29:50:049.278 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 130000 Frame PTS: 200000
[2020-12-24 19:29:50:049.580 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 360000 Frame PTS: 430000
[2020-12-24 19:29:50:049.982 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 590000 Frame PTS: 660000
[2020-12-24 19:29:50:065.068 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 520000 Frame PTS: 670000
[2020-12-24 19:29:50:065.167 GMT] [WARN ] putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x30000005 decoding timestamp: 14628571 presentation timestamp: 16088381903991180
[2020-12-24 19:29:50:149.256 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 820000 Frame PTS: 900000
[2020-12-24 19:29:50:149.850 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1060000 Frame PTS: 1130000
[2020-12-24 19:29:50:149.968 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1290000 Frame PTS: 1360000
[2020-12-24 19:29:50:151.856 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1310000 Frame PTS: 1470000
[2020-12-24 19:29:50:184.205 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1520000 Frame PTS: 1590000
[2020-12-24 19:29:50:184.359 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1750000 Frame PTS: 1820000
[2020-12-24 19:29:50:185.112 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1980000 Frame PTS: 2060000
[2020-12-24 19:29:50:202.729 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 1980000 Frame PTS: 2140000
[2020-12-24 19:29:50:252.859 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 2220000 Frame PTS: 2290000
[2020-12-24 19:29:50:253.039 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 2450000 Frame PTS: 2520000
[2020-12-24 19:29:50:255.043 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 2680000 Frame PTS: 2750000
[2020-12-24 19:29:50:271.387 GMT] [INFO ] putFrame(): Cluster DTS: 13800000 Cluster PTS: 16088381903090000 Frame DTS: 2650000 Frame PTS: 2790000
[2020-12-24 19:29:50:271.464 GMT] [WARN ] putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x30000005 decoding timestamp: 16718367 presentation timestamp: 16088381906080976

If I force frames to be ordered by DTS. You can see from below that frames are now order by DTS while frame PTS sometimes is out of order (causing 0x52000060 in the backend?)

[2020-12-24 19:40:57:822.057 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 0 Frame PTS: 0
[2020-12-24 19:40:57:852.239 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 220000 Frame PTS: 440000
[2020-12-24 19:40:57:854.805 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 400000 Frame PTS: 670000
[2020-12-24 19:40:57:941.999 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 450000 Frame PTS: 670000
[2020-12-24 19:40:57:942.202 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 680000 Frame PTS: 900000
[2020-12-24 19:40:57:942.328 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 910000 Frame PTS: 1140000
[2020-12-24 19:40:57:942.449 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 1150000 Frame PTS: 1370000
[2020-12-24 19:40:57:943.251 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 1200000 Frame PTS: 1470000
[2020-12-24 19:40:58:007.415 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 1380000 Frame PTS: 1600000
[2020-12-24 19:40:58:007.563 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 1610000 Frame PTS: 1830000
[2020-12-24 19:40:58:007.683 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 1840000 Frame PTS: 2060000
[2020-12-24 19:40:58:009.089 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 1860000 Frame PTS: 2140000
[2020-12-24 19:40:58:059.033 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 2080000 Frame PTS: 2300000
[2020-12-24 19:40:58:059.234 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 2310000 Frame PTS: 2530000
[2020-12-24 19:40:58:060.875 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 2520000 Frame PTS: 2790000
[2020-12-24 19:40:58:128.607 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 2540000 Frame PTS: 2760000
[2020-12-24 19:40:58:128.870 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 2770000 Frame PTS: 2990000
[2020-12-24 19:40:58:129.002 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3000000 Frame PTS: 3230000
[2020-12-24 19:40:58:130.398 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3190000 Frame PTS: 3460000
[2020-12-24 19:40:58:199.064 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3240000 Frame PTS: 3460000
[2020-12-24 19:40:58:199.263 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3470000 Frame PTS: 3690000
[2020-12-24 19:40:58:199.397 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3700000 Frame PTS: 3920000
[2020-12-24 19:40:58:199.716 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3850000 Frame PTS: 4130000
[2020-12-24 19:40:58:270.707 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 3930000 Frame PTS: 4150000
[2020-12-24 19:40:58:270.906 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 4170000 Frame PTS: 4390000
[2020-12-24 19:40:58:271.028 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 4400000 Frame PTS: 4620000
[2020-12-24 19:40:58:271.529 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 4520000 Frame PTS: 4790000
[2020-12-24 19:40:58:337.633 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 4630000 Frame PTS: 4850000
[2020-12-24 19:40:58:337.820 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 4860000 Frame PTS: 5080000
[2020-12-24 19:40:58:337.949 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 5090000 Frame PTS: 5310000
[2020-12-24 19:40:58:338.291 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 5190000 Frame PTS: 5450000
[2020-12-24 19:40:58:408.172 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 5330000 Frame PTS: 5550000
[2020-12-24 19:40:58:408.331 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 5560000 Frame PTS: 5780000
[2020-12-24 19:40:58:408.452 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 5790000 Frame PTS: 6010000
[2020-12-24 19:40:58:408.861 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 5850000 Frame PTS: 6110000
[2020-12-24 19:40:58:468.252 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 6020000 Frame PTS: 6240000
[2020-12-24 19:40:58:468.412 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 6260000 Frame PTS: 6480000
[2020-12-24 19:40:58:468.536 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 6490000 Frame PTS: 6710000
[2020-12-24 19:40:58:468.921 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 6520000 Frame PTS: 6770000
[2020-12-24 19:40:58:520.600 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 6720000 Frame PTS: 6940000
[2020-12-24 19:40:58:520.746 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 6950000 Frame PTS: 7170000
[2020-12-24 19:40:58:521.055 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 7180000 Frame PTS: 7440000
[2020-12-24 19:40:58:597.312 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 7180000 Frame PTS: 7400000
[2020-12-24 19:40:58:597.515 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 7420000 Frame PTS: 7640000
[2020-12-24 19:40:58:597.647 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 7650000 Frame PTS: 7870000
[2020-12-24 19:40:58:598.031 GMT] [INFO ] putFrame(): Cluster DTS: 33910000 Cluster PTS: 16088388581850000 Frame DTS: 7850000 Frame PTS: 8090000
[2020-12-24 19:40:58:651.669 GMT] [ERROR] Reported stream error. Errored timecode: 33660000 Status: 0x52000060
[2020-12-24 19:40:58:652.752 GMT] [WARN ] continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 33660000 Status: 0x52000060
[2020-12-24 19:40:58:653.042 GMT] [INFO ] describeStreamResultEvent(): Describe stream result event.
[2020-12-24 19:40:58:653.134 GMT] [INFO ] getStreamingEndpointResultEvent(): Get streaming endpoint result event.
[2020-12-24 19:40:58:653.220 GMT] [INFO ] getStreamingTokenResultEvent(): Get streaming token result event.
[2020-12-24 19:40:58:654.020 GMT] [INFO ] putStreamResultEvent(): Put stream result event. New upload handle 1
[2020-12-24 19:40:58:672.016 GMT] [WARN ] getStreamData(): Indicating an end-of-stream for a terminated stream upload handle 0
[2020-12-24 19:40:58:672.256 GMT] [INFO ] postReadCallback(): Reported end-of-stream for stream opal_sandbox_helium_alpha_302_acu_94. Upload handle: 0
wlinInspire commented 3 years ago

@MushMal I found the DTS and PTS are actually good within the each audio and video track itself. However, the 0x30000005 error occurs when DTS(n) < DTS(n-1) where DTS(n) is from video track and DTS(n-1) is from audio track. As shown below, DTS: 40621829 PTS: 16089228372386931 Track ID: 1 comes after DTS: 40634920 PTS: 16089228372363769 Track ID: 2

[2020-12-25 19:00:36:648.275 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39241723 PTS: 16089228370970572 Track ID: 2
[2020-12-25 19:00:36:650.565 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39291098 PTS: 16089228371077439 Track ID: 1
[2020-12-25 19:00:36:666.212 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39473922 PTS: 16089228371202772 Track ID: 2
[2020-12-25 19:00:36:667.232 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39623052 PTS: 16089228371402490 Track ID: 1
[2020-12-25 19:00:36:716.656 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39706122 PTS: 16089228371434971 Track ID: 2
[2020-12-25 19:00:36:717.303 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39938321 PTS: 16089228371667171 Track ID: 2
[2020-12-25 19:00:36:717.649 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 39953181 PTS: 16089228371727556 Track ID: 1
[2020-12-25 19:00:36:735.361 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 40170521 PTS: 16089228371899370 Track ID: 2
[2020-12-25 19:00:36:735.890 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 40283257 PTS: 16089228372052336 Track ID: 1
[2020-12-25 19:00:36:755.311 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 40402721 PTS: 16089228372131570 Track ID: 2
[2020-12-25 19:00:36:766.418 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 40634920 PTS: 16089228372363769 Track ID: 2
[2020-12-25 19:00:36:782.700 GMT] [INFO ] putEarliestFrame(): Putting Frame DTS: 40621829 PTS: 16089228372386931 Track ID: 1
[2020-12-25 19:00:36:783.388 GMT] [WARN ] putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x30000005 decoding timestamp: 40867120 presentation timestamp: 16089228372595969
MushMal commented 3 years ago

Unfortunately, multi-track is a very poor solution for streaming. We do certain compensation in gstreamer plugin. See if you can replicate this.

https://github.com/awslabs/amazon-kinesis-video-streams-producer-sdk-cpp/blob/master/src/gstreamer/gstkvssink.cpp#L1084

wlinInspire commented 3 years ago

@MushMal The above cannot be replicated as I did not see the logging message after adding LOG_INFO below.

if (IS_OFFLINE_STREAMING_MODE(kvssink->streaming_type)) {
    buf->dts = 0; // if offline mode, i.e. streaming a file, the dts from gstreamer is undefined.
    buf->pts += data->pts_base;
} else if (!GST_BUFFER_DTS_IS_VALID(buf)) {
    LOG_INFO("Buffer DTS is not valid");
    buf->dts = data->last_dts + DEFAULT_FRAME_DURATION_MS * HUNDREDS_OF_NANOS_IN_A_MILLISECOND * DEFAULT_TIME_UNIT_IN_NANOS;
}
wlinInspire commented 3 years ago

I can re-timestamp DTS=PTS for MKV frames by updating function mkvgenValidateFrame as follows

// if (pStreamMkvGenerator->streamTimestamps) {
//     dts = pFrame->decodingTs;
//     pts = pFrame->presentationTs;
// } else {
    pts = dts = pStreamMkvGenerator->getTimeFn(pStreamMkvGenerator->customData);
// }

This will make sure DTS and PTS are increasing for any tracks.

MushMal commented 3 years ago

Try it. I am just not exposed to your custom pipeline. Also, it will be hard to support b-frames in multi-track

wlinInspire commented 3 years ago

@MushMal I tried forcing pts = dts for mkv frames. Now, 0x30000005 is gone but 0x52000060 appears. I found it is most likely because Audio and Video Frames are too close to each other and mkv timecode scale is only 1ms. After adding the following logging to function mkvgenValidateFrame, two consecutive Frame DTS 16089367428914439 and 16089367428917939 get truncated to the same 1608936742891 timecode after dividing it by 10000 (# of 100ns in a ms). I tried the video only case and frames are nicely separated by (1/fps * 1000) ms, which does not cause any error. Is there a way to make mkv timecode scale more granular?

// Adjust to timescale - slight chance of an overflow if we didn't check for sane values
DLOGI("Before Adjusting MKV TS-- Frame DTS: %" PRIu64 " PTS: %" PRIu64 " Last DTS: %" PRIu64 " Last PTS: %" PRIu64,
    dts,
    pts,
    pStreamMkvGenerator->timecodeScale,
    pStreamMkvGenerator->lastClusterPts);

DLOGI("Timecode Scale: %" PRIu64, pStreamMkvGenerator->timecodeScale);

pts = TIMESTAMP_TO_MKV_TIMECODE(pts, pStreamMkvGenerator->timecodeScale);
dts = TIMESTAMP_TO_MKV_TIMECODE(dts, pStreamMkvGenerator->timecodeScale);
duration = TIMESTAMP_TO_MKV_TIMECODE(duration, pStreamMkvGenerator->timecodeScale);

DLOGI("After Adjusting MKV TS -- Frame DTS: %" PRIu64 " PTS: %" PRIu64 " Last DTS: %" PRIu64 " Last PTS: %" PRIu64,
    dts,
    pts,
    pStreamMkvGenerator->timecodeScale,
    pStreamMkvGenerator->lastClusterPts);
[2020-12-25 22:52:22:891.469 GMT] mkvgenValidateFrame(): Before Adjusting MKV TS-- Frame DTS: 16089367428914439 PTS: 16089367428914439 Last Cluster DTS: 1000000 Last Cluster PTS: 1608936742778
[2020-12-25 22:52:22:891.668 GMT] mkvgenValidateFrame(): Timecode Scale: 1000000
[2020-12-25 22:52:22:891.725 GMT] mkvgenValidateFrame(): After Adjusting MKV TS -- Frame DTS: 1608936742891 PTS: 1608936742891 Last Cluster DTS: 1000000 Last Cluster PTS: 1608936742778
[2020-12-25 22:52:22:891.800 GMT] mkvgenValidateFrame(): Before Adjusting MKV TS-- Frame DTS: 16089367428917939 PTS: 16089367428917939 Last Cluster DTS: 1000000 Last Cluster PTS: 1608936742778
[2020-12-25 22:52:22:891.845 GMT] mkvgenValidateFrame(): Timecode Scale: 1000000
[2020-12-25 22:52:22:891.892 GMT] mkvgenValidateFrame(): After Adjusting MKV TS -- Frame DTS: 1608936742891 PTS: 1608936742891 Last DTS: 1000000 Last PTS: 1608936742778
MushMal commented 3 years ago

The frame order coordinator should take care of the colliding timestamps when we attempt to represent in 1ms default MKV granularity. Are you using FrameOrderCoordinator mode with compensation? Here are some suggestions.

1) Equate dts = pts 2) Use the default frame order coordinator 3) Ensure there are no b-frames

As I mentioned before, the GStreamer plugin code does modify the timestamps initially to ensure they work with the frame order coordinator.

Unfortunately, it is very difficult to get b-frames working with multi-track - it's simply not designed to be working in a streamable fashion.

wlinInspire commented 3 years ago

@MushMal All the suggestions were satisfied in the previous logs. There are no b-frames and frame coordinator is the default (FRAME_ORDERING_MODE_MULTI_TRACK_AV_COMPARE_PTS_ONE_MS_COMPENSATE). MKV DTS is forced equal to PTS by pts = dts = pStreamMkvGenerator->getTimeFn(pStreamMkvGenerator->customData);

MushMal commented 3 years ago

I am wondering if you are hitting the strict monotonicity requirement in our backend. What this means is that the backend enforces strict greater (instead of greater or equal like in SDK) for each of the fragments. What this means is that the backend will fail if the timestamp of the first frame of the fragment is not strictly greater than the timestamp of the last frame of the previous fragment.

For this purpose the frame order coordinator adds a single timeunit to the key-frame here:

https://github.com/awslabs/amazon-kinesis-video-streams-pic/blob/master/src/client/src/FrameOrderCoordinator.c#L145

If you have unmodified code then I am not sure why you have overlaps. You will need to dump out the frames and debug into.

wlinInspire commented 3 years ago

@MushMal You are right. I originally set pts = dts = pStreamMkvGenerator->getTimeFn(pStreamMkvGenerator->customData);, which nullifies the PTS compensation. Now I set dts = pts = pFrame->presentationTs; and all the errors are gone.

wlinInspire commented 3 years ago

@MushMal The video I see from KVS console is now nice and smooth. However, the audio and video are somewhat out of sync. Is that expected as you said the multi-track streaming is a poor solution?

MushMal commented 3 years ago

It’s hard to say. If your encoder is stable and you have no b-frames then it should work.

In your case you should have neutered that the original timestamps for audio and video are on the same timeline. The only information that the sdk frame order coordinator has is the timestamp and flags in order to perform the av sync.

try to understand what the sync issues are first of all. Is this a constant delta drift? Is it increasing drift? Is it audio ahead of video or the opposite? Do you see smooth video or jumpy? So you see green frames or macro blocking? Is your producer dropping frames?

there are many aspects to this that you need to have a clear understanding to root cause

wlinInspire commented 3 years ago

@MushMal I see the video is smooth. Audio is behind video at first. After a few loading ... in the kvs console player, the video is behind audio. Happy the cut another issue as this one is solved. Thanks.