X-Git-Url: https://git.sesse.net/?a=blobdiff_plain;ds=sidebyside;f=nageru%2Fdecklink_output.cpp;h=f061766bf256f4fbf08ae7a09e83e87bce5cf15a;hb=refs%2Fheads%2Funsync-output;hp=6b21edb0c45d066ebf3d8d68a6f8ed27410f4f8d;hpb=0eaa4d8a29782ae20d7b54fd8334371e724f1c57;p=nageru diff --git a/nageru/decklink_output.cpp b/nageru/decklink_output.cpp index 6b21edb..f061766 100644 --- a/nageru/decklink_output.cpp +++ b/nageru/decklink_output.cpp @@ -84,6 +84,9 @@ DeckLinkOutput::DeckLinkOutput(ResourcePool *resource_pool, QSurface *surface, u bool DeckLinkOutput::set_device(IDeckLink *decklink) { + if (decklink->QueryInterface(IID_IDeckLinkInput, (void**)&input) != S_OK) { + input = nullptr; + } if (decklink->QueryInterface(IID_IDeckLinkOutput, (void**)&output) != S_OK) { fprintf(stderr, "Warning: Card %u has no outputs\n", card_index); return false; @@ -123,7 +126,7 @@ bool DeckLinkOutput::set_device(IDeckLink *decklink) return true; } -void DeckLinkOutput::start_output(uint32_t mode, int64_t base_pts) +void DeckLinkOutput::start_output(uint32_t mode, int64_t base_pts, bool is_master_card) { assert(output); assert(!playback_initiated); @@ -136,7 +139,11 @@ void DeckLinkOutput::start_output(uint32_t mode, int64_t base_pts) should_quit.unquit(); playback_initiated = true; playback_started = false; - this->base_pts = base_pts; + if (is_master_card) { + this->base_pts = base_pts; + } else { + this->next_output_pts = 0; + } IDeckLinkConfiguration *config = nullptr; if (output->QueryInterface(IID_IDeckLinkConfiguration, (void**)&config) != S_OK) { @@ -151,7 +158,7 @@ void DeckLinkOutput::start_output(uint32_t mode, int64_t base_pts) fprintf(stderr, "Failed to set video output connection for card %u\n", card_index); abort(); } - if (config->SetFlag(bmdDeckLinkConfigUse1080pNotPsF, true) != S_OK) { + if (config->SetFlag(bmdDeckLinkConfigOutput1080pAsPsF, true) != S_OK) { fprintf(stderr, "Failed to set PsF flag for card\n"); abort(); } @@ -193,6 +200,15 @@ void DeckLinkOutput::start_output(uint32_t mode, int64_t base_pts) display_mode->Release(); + if (input != nullptr) { + if (input->DisableVideoInput() != S_OK) { + fprintf(stderr, "Warning: Failed to disable video input for card %d\n", card_index); + } + if (input->DisableAudioInput() != S_OK) { + fprintf(stderr, "Warning: Failed to disable audio input for card %d\n", card_index); + } + } + HRESULT result = output->EnableVideoOutput(mode, bmdVideoOutputFlagDefault); if (result != S_OK) { fprintf(stderr, "Couldn't enable output with error 0x%x\n", result); @@ -207,9 +223,17 @@ void DeckLinkOutput::start_output(uint32_t mode, int64_t base_pts) fprintf(stderr, "Couldn't enable audio output\n"); abort(); } - if (output->BeginAudioPreroll() != S_OK) { - fprintf(stderr, "Couldn't begin audio preroll\n"); - abort(); + if (is_master_card) { + if (output->BeginAudioPreroll() != S_OK) { + fprintf(stderr, "Couldn't begin audio preroll\n"); + abort(); + } + } else { + if (output->StartScheduledPlayback(/*base_pts=*/0, TIMEBASE, 1.0) != S_OK) { + fprintf(stderr, "Could not start playback\n"); + abort(); // TODO + } + playback_started = true; } present_thread = thread([this]{ @@ -243,12 +267,16 @@ void DeckLinkOutput::end_output() // Wait until all frames are accounted for, and free them. { unique_lock lock(frame_queue_mutex); - while (!(frame_freelist.empty() && num_frames_in_flight == 0)) { + while (!(frame_freelist.empty() && scheduled_frames.empty())) { frame_queues_changed.wait(lock, [this]{ return !frame_freelist.empty(); }); frame_freelist.pop(); } } + if (input != nullptr) { + input->Release(); + input = nullptr; + } if (output != nullptr) { output->Release(); output = nullptr; @@ -259,6 +287,8 @@ void DeckLinkOutput::send_frame(GLuint y_tex, GLuint cbcr_tex, YCbCrLumaCoeffici { assert(!should_quit.should_quit()); + input_jitter_history.frame_arrived(steady_clock::now(), duration, /*dropped_frames=*/0, true); + if ((current_mode_flags & bmdDisplayModeColorspaceRec601) && output_ycbcr_coefficients == YCBCR_REC_709) { if (!last_frame_had_mode_mismatch) { fprintf(stderr, "WARNING: Chosen output mode expects Rec. 601 Y'CbCr coefficients.\n"); @@ -330,6 +360,8 @@ void DeckLinkOutput::send_frame(GLuint y_tex, GLuint cbcr_tex, YCbCrLumaCoeffici void DeckLinkOutput::send_audio(int64_t pts, const std::vector &samples) { + return; // FIXME we may need to map pts or something? + unique_ptr int_samples(new int32_t[samples.size()]); for (size_t i = 0; i < samples.size(); ++i) { int_samples[i] = lrintf(samples[i] * 2147483648.0f); @@ -423,7 +455,7 @@ uint32_t DeckLinkOutput::pick_video_mode(uint32_t mode) const } // Prioritize 59.94 > 60 > 29.97. If none of those are found, then pick the highest one. - for (const pair &desired : vector>{ { 60000, 1001 }, { 60, 0 }, { 30000, 1001 } }) { + for (const pair &desired : vector>{ { 50, 1 }, { 60000, 1001 }, { 60, 1 }, { 30000, 1001 } }) { for (const auto &it : video_modes) { if (it.second.frame_rate_num * desired.second == desired.first * it.second.frame_rate_den) { return it.first; @@ -457,22 +489,70 @@ YCbCrLumaCoefficients DeckLinkOutput::preferred_ycbcr_coefficients() const HRESULT DeckLinkOutput::ScheduledFrameCompleted(/* in */ IDeckLinkVideoFrame *completedFrame, /* in */ BMDOutputFrameCompletionResult result) { Frame *frame = static_cast(completedFrame); + + BMDTimeValue stream_frame_time, played_at_time; + BMDTimeValue hardwareTime, timeInFrame, ticksPerFrame; + double playback_speed; + output->GetFrameCompletionReferenceTimestamp(frame, TIMEBASE, &played_at_time); + output->GetScheduledStreamTime(TIMEBASE, &stream_frame_time, &playback_speed); + output->GetHardwareReferenceClock(TIMEBASE, &hardwareTime, &timeInFrame, &ticksPerFrame); + + steady_clock::time_point now = steady_clock::now(); + int frame_delay = (stream_frame_time - frame->pts) / frame_duration - 1; + map status = { + { bmdOutputFrameCompleted, "played" }, + { bmdOutputFrameDisplayedLate, "DELAYED" }, + { bmdOutputFrameDropped, "DROPPED" }, + { bmdOutputFrameFlushed, "FLUSHED" } + }; + + if ((result == bmdOutputFrameCompleted || result == bmdOutputFrameDisplayedLate) && false) { + fprintf(stderr, "now=%ld / %.2f: frame with pts=%ld (%ld ago, %d delay) / %.2f was %s at time %ld (%ld ago)\n", + stream_frame_time, PTSToTime(stream_frame_time), + frame->pts, stream_frame_time - frame->pts, frame_delay, PTSToTime(frame->pts), + status[result].c_str(), + played_at_time, hardwareTime - played_at_time); + } else if (result == bmdOutputFrameDisplayedLate) { + fprintf(stderr, "now=%ld / %.2f: frame with pts=%ld (%ld ago, %d delay) / %.2f was %s to %.2f\n", + stream_frame_time, PTSToTime(stream_frame_time), + frame->pts, stream_frame_time - frame->pts, frame_delay, PTSToTime(frame->pts), + status[result].c_str(), PTSToTime(frame->pts) + frame_delay); + } else { + fprintf(stderr, "now=%ld / %.2f: frame with pts=%ld (%ld ago, %d delay) / %.2f was %s\n", + stream_frame_time, PTSToTime(stream_frame_time), + frame->pts, stream_frame_time - frame->pts, frame_delay, PTSToTime(frame->pts), + status[result].c_str()); + } + if (frame_delay < 0) { + fprintf(stderr, "ERROR: Frame went backwards in time (scheduled to start at pts=%ld, ended at or before pts=%ld), something is strange.\n", + frame->pts, stream_frame_time); + frame_delay = 0; + } + switch (result) { case bmdOutputFrameCompleted: ++metric_decklink_output_completed_frames_completed; + if (frame_delay != 0) { + fprintf(stderr, "ERROR: Frame was reportedly completed without delay, but was delayed nevertheless.\n"); + // Our callback _might_ be delayed 1+ frame for other reasons, + // so ignore this. It's a pity GetFrameCompletionReferenceTimestamp() + // cannot give us a timestamp on the same time scale as + // GetScheduledStreamTime(); it would be more robust. + frame_delay = 0; + } break; case bmdOutputFrameDisplayedLate: - fprintf(stderr, "Output frame displayed late (pts=%" PRId64 ")\n", frame->pts); - fprintf(stderr, "Consider increasing --output-buffer-frames if this persists.\n"); + // fprintf(stderr, "Output frame displayed late (pts=%" PRId64 ")\n", frame->pts); + //fprintf(stderr, "Consider increasing --output-buffer-frames if this persists.\n"); ++metric_decklink_output_completed_frames_late; break; case bmdOutputFrameDropped: - fprintf(stderr, "Output frame was dropped (pts=%" PRId64 ")\n", frame->pts); - fprintf(stderr, "Consider increasing --output-buffer-frames if this persists.\n"); + // fprintf(stderr, "Output frame was dropped (pts=%" PRId64 ")\n", frame->pts); + //fprintf(stderr, "Consider increasing --output-buffer-frames if this persists.\n"); ++metric_decklink_output_completed_frames_dropped; break; case bmdOutputFrameFlushed: - fprintf(stderr, "Output frame was flushed (pts=%" PRId64 ")\n", frame->pts); + // fprintf(stderr, "Output frame was flushed (pts=%" PRId64 ")\n", frame->pts); ++metric_decklink_output_completed_frames_flushed; break; default: @@ -487,8 +567,55 @@ HRESULT DeckLinkOutput::ScheduledFrameCompleted(/* in */ IDeckLinkVideoFrame *co { lock_guard lock(frame_queue_mutex); frame_freelist.push(unique_ptr(frame)); - --num_frames_in_flight; + + // Dropped frames can come out-of-order, so we can't just look at the front; + // we need to go and find it in the list. + auto it = find(scheduled_frames.begin(), scheduled_frames.end(), frame); + assert(it != scheduled_frames.end()); + scheduled_frames.erase(it); --metric_decklink_output_inflight_frames; + + if (frame_delay > 0 && result == bmdOutputFrameDisplayedLate) { + // All frames that were queued earlier will be delayed, + // so update so that we don't double-count the delay. + int64_t prev_frame_pts = frame->pts + frame_delay * frame_duration; + for (Frame *other_frame : scheduled_frames) { + int64_t old_pts = other_frame->pts; + other_frame->pts = std::max(other_frame->pts, prev_frame_pts + frame_duration); + fprintf(stderr, " - moving frame from pts=%ld (%.3f) to pts=%ld (%.3f)\n", + old_pts, PTSToTime(old_pts), other_frame->pts, PTSToTime(other_frame->pts)); + prev_frame_pts = other_frame->pts; + } + + int64_t earliest_next_frame = (stream_frame_time + frame_duration - 1) / frame_duration * frame_duration; + earliest_next_frame = std::max(earliest_next_frame, prev_frame_pts + frame_duration); + if (next_output_pts < earliest_next_frame) { + // In effect, duplicate a frame. FIXME write something about this + // FIXME is this really right now? but perhaps we're forced + // and it messes up the queue length calculation temporarily, we need something else there + //fprintf(stderr, "Duplicating frame %d times due to starvation!\n", frame_delay); + + // FIXME this causes us to believe in output jitter? + fprintf(stderr, " - moving output pointer from pts=%ld (%.3f) to pts=%ld (%.3f)\n", + next_output_pts, PTSToTime(next_output_pts), earliest_next_frame, PTSToTime(earliest_next_frame)); + next_output_pts = earliest_next_frame; + // FIXME metric + } + } + + if (result == bmdOutputFrameCompleted || result == bmdOutputFrameDisplayedLate) { + //output_jitter_history.frame_arrived(now, frame_duration, /*dropped_frames=*/frame_delay, true); + // TODO: backdate now, and possibly also get_expected_next_frame()? + queue_length_policy.update_policy( + now, + input_jitter_history.get_expected_next_frame(), + frame->duration, frame_duration, + input_jitter_history.estimate_max_jitter(), + // output_jitter_history.estimate_max_jitter(), true); + 0.0, true); + num_safe_frames = queue_length_policy.get_safe_queue_length(); + } + fprintf(stderr, "%zu frames in flight, safe queue length = %u (starv=%d)\n", scheduled_frames.size(), queue_length_policy.get_safe_queue_length(), frame_delay); } return S_OK; @@ -548,17 +675,26 @@ void DeckLinkOutput::present_thread_func() for ( ;; ) { unique_ptr frame; { - unique_lock lock(frame_queue_mutex); - frame_queues_changed.wait(lock, [this]{ - return should_quit.should_quit() || !pending_video_frames.empty(); - }); - if (should_quit.should_quit()) { + unique_lock lock(frame_queue_mutex); + frame_queues_changed.wait(lock, [this]{ + return should_quit.should_quit() || !pending_video_frames.empty(); + }); + if (should_quit.should_quit()) { return; } frame = move(pending_video_frames.front()); pending_video_frames.pop(); - ++num_frames_in_flight; - ++metric_decklink_output_inflight_frames; + + if (scheduled_frames.size() > num_safe_frames) { // FIXME check off-by-one here + fprintf(stderr, "Dropping frame to keep latency down!\n"); + // FIXME metric + continue; + } + + // Overwrite the pts given by the client; it doesn't own our clock. + // TODO: Write something about what semi-unsynchronized really means. + frame->pts = next_output_pts; + next_output_pts += frame_duration; } for ( ;; ) { @@ -585,19 +721,23 @@ void DeckLinkOutput::present_thread_func() BMDTimeValue pts = frame->pts; BMDTimeValue duration = frame->duration; HRESULT res = output->ScheduleVideoFrame(frame.get(), pts, duration, TIMEBASE); + lock_guard lock(frame_queue_mutex); if (res == S_OK) { - frame.release(); // Owned by the driver now. + scheduled_frames.push_back(frame.release()); // Owned by the driver now. + ++metric_decklink_output_inflight_frames; } else { fprintf(stderr, "Could not schedule video frame! (error=0x%08x)\n", res); - lock_guard lock(frame_queue_mutex); frame_freelist.push(move(frame)); - --num_frames_in_flight; - --metric_decklink_output_inflight_frames; } } } +double DeckLinkOutput::PTSToTime(int64_t pts) +{ + return double(pts) / frame_duration; +} + HRESULT STDMETHODCALLTYPE DeckLinkOutput::QueryInterface(REFIID, LPVOID *) { return E_NOINTERFACE;