GCC Code Coverage Report

Directory: ./
File: channeloutput/channeloutputthread.cpp
Date: 2026-10-29 08:11:58
Exec Total Coverage
Lines: 389 420 92.6%
Functions: 31 35 88.6%
Branches: 377 514 73.3%
Line Branch Exec Source
1 /*
2 * This file is part of the Falcon Player (FPP) and is Copyright (C)
3 * 2013-2022 by the Falcon Player Developers.
4 *
5 * The Falcon Player (FPP) is free software, and is covered under
6 * multiple Open Source licenses. Please see the included 'LICENSES'
7 * file for descriptions of what files are covered by each license.
8 *
9 * This source file is covered under the LGPL v2.1 as described in the
10 * included LICENSE.LGPL file.
11 */
12
13 #include "../fpp-pch.h"
14
15 #include <sys/time.h>
16 #include <algorithm>
17 #include <atomic>
18 #include <chrono>
19 #include <cmath>
20 #include <condition_variable>
21 #include <cstring>
22 #include <ctime>
23 #include <deque>
24 #include <errno.h>
25 #include <mutex>
26 #include <thread>
27
28 #include "../MultiSync.h"
29 #include "../Sequence.h"
30 #include "../Warnings.h"
31 #include "../channeltester/ChannelTester.h"
32 #include "../commands/Commands.h"
33 #include "../common.h"
34 #include "../effects.h"
35 #include "../log.h"
36 #include "../mediaoutput/GStreamerOut.h"
37 #include "../overlays/PixelOverlay.h"
38 #include "../settings.h"
39
40 #include "ChannelOutputSetup.h"
41 #include "channeloutputthread.h"
42
43 /* used by external sync code */
44 // Atomic: the output thread, media sync (on the media or MultiSync thread)
45 // and sequence start all read and write these.
46 std::atomic<float> RefreshRate{ 20 };
47 std::atomic_int SequenceLightDelay{ 50000 };
48 std::atomic_int BridgeLightDelay{ 0 };
49 std::atomic_int LightDelay{ 50000 };
50 std::atomic_int FrameSkip{ 0 };
51 std::atomic_int MasterFramesPlayed{ -1 };
52 std::atomic_int OutputFrames{ 1 };
53 // Set by every StartChannelOutputThread(), which an overlay model switched on
54 // from an API thread calls too, and read on the playlist's thread.
55 std::atomic<float> mediaOffset{ 0.0 };
56
57 /* local variables */
58 // Atomic, not volatile: volatile orders nothing between threads, and the main
59 // loop, HTTP threads and MultiSync read and set these while the output thread
60 // runs.
61 std::atomic_int RunThread{ 0 };
62 std::atomic_int ThreadIsRunning{ 0 };
63 std::atomic_int ThreadIsExiting{ 0 };
64 std::atomic_int outputForced{ 0 };
65 std::atomic_int alwaysTransmit{ 0 };
66
67 // declared in channeloutputthread.h, which documents what it protects
68 std::mutex outputThreadLock;
69 // Threads blocked in LockOutputThread(); the output thread hands the lock over
70 // at the end of a pass while this is non-zero.
71 static std::atomic_int outputThreadLockWaiters{ 0 };
72 std::recursive_mutex inlineOutputLock;
73 std::mutex outputThreadStatusLock;
74 // Bumped under outputThreadStatusLock by every StartChannelOutputThread(),
75 // which its callers make after setting up what they want output for (an
76 // effect, an active overlay, a video). The thread reads it at the top of each
77 // pass, before it samples what needs output, and won't idle past a change.
78 static std::atomic<uint64_t> outputStartRequests{ 0 };
79 // Set (under outputThreadStatusLock) by StopChannelOutputThread(), which only
80 // fppd's shutdown calls, and never cleared. The teardown after it closes
81 // outputs and removes overlay models, and a model state change restarts the
82 // thread; one restarted there outlived the sequence it reads, which main()
83 // deletes next. So once stopped, the thread stays stopped.
84 static bool outputThreadShutDown = false;
85 std::condition_variable outputThreadCond;
86 std::condition_variable outputThreadSatusCond;
87
88 // The pace of the media clock the sequence follows, relative to the system
89 // clock, and when it was last reported (GetMonotonicTimeMicros()). A card's crystal is
90 // tens to hundreds of ppm off; frames run at its pace so the lights don't walk
91 // across media sync's whole-frame dead band over a song. It goes stale (back
92 // to 1.0) a second after the media stops reporting it.
93 static std::atomic<double> mediaClockRate{ 1.0 };
94 static std::atomic<long long> mediaClockRateAt{ 0 };
95
96 // Relaxed: two independent values read once a frame. A reader that pairs a
97 // new time with the previous rate uses a rate one report old for one frame.
98 // On an AM335x each seq_cst access is a pair of barriers (~0.1 us), and the
99 // 64-bit and double ones are ldrexd/strexd as well.
100 150747 void SetMediaClockRate(double rate) {
101 150747 mediaClockRate.store(rate, std::memory_order_relaxed);
102 150747 mediaClockRateAt.store(GetMonotonicTimeMicros(), std::memory_order_relaxed);
103 150747 }
104
105 250358 static double CurrentMediaClockRate(long long now) {
106 // A remote follows the master's frame numbers, not its own media.
107
6/6
✓ Branch 0 taken 145033 times.
✓ Branch 1 taken 105325 times.
✓ Branch 2 taken 144916 times.
✓ Branch 3 taken 117 times.
✓ Branch 4 taken 105442 times.
✓ Branch 5 taken 144916 times.
 395274 if (now - mediaClockRateAt.load(std::memory_order_relaxed) > 1000000 || !sequence->IsSequenceRunning() ||
108
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 144916 times.
 144916 getFPPmode() == REMOTE_MODE) {
109 105442 return 1.0;
110 }
111 144916 return mediaClockRate.load(std::memory_order_relaxed);
112 }
113
114 // Media phase servo. Media sync used to compare whole frame counts once a
115 // second and leave anything within a frame alone, so the lights sat anywhere
116 // up to two frames (100 ms at 20 fps) from the sound. Now the output thread
117 // publishes which frame it sends next and when that is due, each media
118 // position report works out when the media says it should be due, and the
119 // difference is closed a little each frame. Whole-frame skips and holds
120 // (CalculateNewChannelOutputDelayForFrame()) still handle anything larger.
121 //
122 // A MultiSync remote has no media of its own to follow; it holds its frames
123 // to the master's sync packets the same way (UpdateMasterPosition()).
124 //
125 // Pending correction in us: > 0 delays the frames to come, < 0 brings them
126 // forward. The output thread takes at most kMaxPhaseStep of a period from it
127 // per frame, so the cadence never visibly jumps. It goes stale a second after
128 // the media (or the master) stops reporting, like the clock rate.
129 static constexpr double kMaxPhaseStep = 0.1;
130 static std::atomic<long long> mediaPhaseCorrUs{ 0 };
131 static std::atomic<long long> mediaPhaseCorrAt{ 0 };
132 // The next frame the thread sends and when it is due, published together.
133 static std::mutex nextSendLock;
134 static long nextSendFrame = -1;
135 static long long nextSendDueUs = 0;
136
137 64275 static void PublishNextSend(long frame, long long dueUs) {
138
1/2
✓ Branch 0 taken 64275 times.
✗ Branch 1 not taken.
 64275 std::unique_lock<std::mutex> l(nextSendLock);
139 64275 nextSendFrame = frame;
140 64275 nextSendDueUs = dueUs;
141 64275 }
142
143 120804 static double TakeMediaPhaseStep(long long now, double period) {
144
7/8
✓ Branch 0 taken 29387 times.
✓ Branch 1 taken 91417 times.
✓ Branch 2 taken 29387 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 169 times.
✓ Branch 5 taken 29218 times.
✓ Branch 6 taken 91586 times.
✓ Branch 7 taken 29218 times.
 120804 if (now - mediaPhaseCorrAt.load(std::memory_order_relaxed) > 1000000 || !sequence->IsSequenceRunning()) {
145 91586 return 0.0;
146 }
147 29218 long long pending = mediaPhaseCorrUs.load(std::memory_order_relaxed);
148 29218 long long maxStep = (long long)(period * kMaxPhaseStep);
149
1/2
✓ Branch 0 taken 29218 times.
✗ Branch 1 not taken.
 29218 long long step = std::clamp(pending, -maxStep, maxStep);
150
2/2
✓ Branch 0 taken 24981 times.
✓ Branch 1 taken 4237 times.
 29218 if (step) {
151 mediaPhaseCorrUs.fetch_sub(step, std::memory_order_relaxed);
152 }
153 29218 return (double)step;
154 }
155
156 /* prototypes for functions below */
157 void CalculateNewChannelOutputDelayForFrame(int expectedFramesSent);
158 static void AdjustForFrame(int expectedFramesSent, bool phaseServo);
159
160 /*
161 * Check to see if the channel output thread is running
162 */
163 709699 int ChannelOutputThreadIsRunning(void) {
164 // Acquire, not relaxed: callers wait on this for the thread's startup
165 // (StartingOutput()) to have happened. The main loop asks every pass.
166 709699 return ThreadIsRunning.load(std::memory_order_acquire);
167 }
168
169 static std::atomic<std::thread::id> outputThreadId{};
170 10857 std::unique_lock<std::mutex> LockOutputThread(void) {
171 10857 ++outputThreadLockWaiters;
172 10857 std::unique_lock<std::mutex> lock(outputThreadLock);
173 10857 --outputThreadLockWaiters;
174 10857 return lock;
175 }
176
177 1156 bool IsChannelOutputThread(void) {
178 1156 return outputThreadId.load(std::memory_order_relaxed) == std::this_thread::get_id();
179 }
180
181 15167 int ChannelOutputThreadIsEnabled() {
182 15167 return OutputFrames.load(std::memory_order_relaxed);
183 }
184
185 /*
186 *
187 */
188 2 void DisableChannelOutput(void) {
189 2 LogDebug(VB_CHANNELOUT, "DisableChannelOutput()\n");
190 2 OutputFrames = 0;
191 2 }
192
193 /*
194 *
195 */
196 1 void EnableChannelOutput(void) {
197 1 LogDebug(VB_CHANNELOUT, "EnableChannelOutput()\n");
198 1 OutputFrames = 1;
199 1 }
200
201 // Bumped under outputThreadStatusLock by every ForceChannelOutputNow(). The
202 // thread sends a frame for each change it sees, whichever wait it is in. A
203 // bare notify was lost whenever the thread wasn't waiting on that condition
204 // at that moment -- and the idle wait never listened for it at all -- so a
205 // Stop Now landing within a frame of a sequence hand-over blanked the buffer
206 // and nothing ever sent it: the last frame stayed lit.
207 static std::atomic<uint64_t> outputForceRequests{ 0 };
208 // Set with a force request by ForceChannelOutputSendNow(): the pass that picks
209 // the request up sends even while output is disabled.
210 static std::atomic<bool> sendWhileDisabledRequested{ false };
211
212 18332 static bool RequestForcedOutput(bool evenIfDisabled) {
213 {
214
1/2
✓ Branch 0 taken 18332 times.
✗ Branch 1 not taken.
 18332 std::unique_lock<std::mutex> statusLock(outputThreadStatusLock);
215
5/6
✓ Branch 0 taken 6511 times.
✓ Branch 1 taken 11821 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 6511 times.
✓ Branch 4 taken 11821 times.
✓ Branch 5 taken 6511 times.
 18332 if (!ThreadIsRunning || !RunThread) {
216 // Not running, or on its way out: it won't send again.
217 11821 return false;
218 }
219
2/2
✓ Branch 0 taken 180 times.
✓ Branch 1 taken 6331 times.
 6511 if (evenIfDisabled) {
220 // Before the request it rides on: the thread reads it on seeing
221 // the request (acquire on outputForceRequests).
222 180 sendWhileDisabledRequested.store(true, std::memory_order_relaxed);
223 }
224 outputForceRequests.fetch_add(1, std::memory_order_release);
225
2/2
✓ Branch 0 taken 6511 times.
✓ Branch 1 taken 11821 times.
 18332 }
226 6511 outputThreadSatusCond.notify_all();
227 6511 outputThreadCond.notify_all();
228 6511 return true;
229 }
230
231 18152 bool ForceChannelOutputNow(void) {
232 18152 LogDebug(VB_CHANNELOUT, "ForceChannelOutputNow()\n");
233 18152 return RequestForcedOutput(false);
234 }
235
236 180 bool ForceChannelOutputSendNow(void) {
237 180 LogDebug(VB_CHANNELOUT, "ForceChannelOutputSendNow()\n");
238 180 return RequestForcedOutput(true);
239 }
240
241 198660 static inline bool forceOutput() {
242 198660 return IsEffectRunning() ||
243
2/2
✓ Branch 0 taken 172149 times.
✓ Branch 1 taken 25488 times.
 197637 PixelOverlayManager::INSTANCE.hasActiveOverlays() ||
244 #ifdef HAS_GSTREAMER
245
2/2
✓ Branch 0 taken 172141 times.
✓ Branch 1 taken 8 times.
 172149 GStreamerOutput::IsOverlayingVideo() ||
246 #endif
247
2/2
✓ Branch 0 taken 142575 times.
✓ Branch 1 taken 29566 times.
 172141 ChannelTester::INSTANCE.Testing() ||
248
1/2
✓ Branch 0 taken 142575 times.
✗ Branch 1 not taken.
 142575 alwaysTransmit.load(std::memory_order_relaxed) ||
249
4/4
✓ Branch 0 taken 197637 times.
✓ Branch 1 taken 1023 times.
✓ Branch 2 taken 138541 times.
✓ Branch 3 taken 4034 times.
 534838 sequence->hasBridgeData() ||
250
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 138541 times.
 337201 outputForced.load(std::memory_order_relaxed);
251 }
252
253 /*
254 * Main loop in channel output thread
255 */
256 1956 void RunChannelOutputThread(void) {
257
2/4
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 1956 times.
✗ Branch 3 not taken.
 1956 SetThreadName("FPP-ChannelOut");
258
259 // Frame timing must stay consistent under load; a delayed frame bunches
260 // with the next one and doubles the size of the UDP burst hitting the
261 // network. The loop sleeps every frame (and kernel RT throttling caps
262 // RT CPU at ~95%) so this will not starve the rest of the system.
263
2/4
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 1956 times.
✗ Branch 3 not taken.
 1956 if (SetThreadRealtimePriority(10)) {
264
1/2
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
 1956 LogInfo(VB_CHANNELOUT, "Channel output thread running with real-time priority\n");
265 } else {
266 ✗ LogInfo(VB_CHANNELOUT, "Could not set real-time priority on channel output thread; frame timing may jitter under load\n");
267 }
268
269 static long long lastStatTime = 0;
270 long long startTime;
271 long long sendTime;
272 long long readTime;
273 long long processTime;
274
3/4
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 41 times.
✓ Branch 3 taken 1915 times.
 1956 int onceMore = (getFPPmode() == REMOTE_MODE) ? 20 : 1;
275 // When the next frame is due (GetMonotonicTimeMicros()), 0 before the
276 // first. Every time in this loop is on the monotonic clock: the cadence
277 // carries nextFrameTime from frame to frame, so on the wall clock a step
278 // back (NTP, an RTC that boots in the past) left the next frame due that
279 // much later, and output stopped for as long as the step.
280 1956 long long nextFrameTime = 0;
281 1956 double frameTimeCarry = 0.0;
282 struct timespec ts;
283 struct timeval tv;
284 1956 int slowFrameCount = 0;
285
286
1/2
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
 1956 LogDebug(VB_CHANNELOUT, "RunChannelOutputThread() starting\n");
287
288
1/2
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
 1956 std::unique_lock<std::mutex> lock(outputThreadLock);
289
1/2
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
 1956 std::unique_lock<std::mutex> statusLock(outputThreadStatusLock);
290
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1956 times.
 1956 if (outputThreadShutDown) {
291 // created just before shutdown stopped the output; touch nothing
292 ✗ return;
293 }
294 1956 outputThreadId = std::this_thread::get_id();
295 struct ClearThreadId {
296 // Only our own id: this runs after outputThreadLock is released, by
297 // which time a replacement thread may already have stored its id.
298 1947 ~ClearThreadId() {
299 1947 std::thread::id self = std::this_thread::get_id();
300 1947 outputThreadId.compare_exchange_strong(self, std::thread::id());
301 1947 }
302 } clearThreadId;
303 1956 ThreadIsRunning = 1;
304 1956 ThreadIsExiting = 0;
305
1/2
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
 1956 statusLock.unlock();
306
307
1/2
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
 1956 StartingOutput();
308
309
7/10
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 41 times.
✓ Branch 3 taken 1915 times.
✓ Branch 4 taken 41 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 41 times.
✗ Branch 7 not taken.
✓ Branch 8 taken 41 times.
✓ Branch 9 taken 1915 times.
 1956 if ((getFPPmode() == REMOTE_MODE) && !forceOutput()) {
310 // Sleep about 2 seconds waiting for the master
311 41 int loops = 0;
312
8/10
✓ Branch 0 taken 66899 times.
✓ Branch 1 taken 15 times.
✓ Branch 2 taken 66873 times.
✓ Branch 3 taken 26 times.
✓ Branch 4 taken 66873 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 66873 times.
✗ Branch 7 not taken.
✓ Branch 8 taken 66873 times.
✓ Branch 9 taken 41 times.
 66914 while ((MasterFramesPlayed < 0) && (loops < 2000) && !forceOutput()) {
313
1/2
✓ Branch 0 taken 66873 times.
✗ Branch 1 not taken.
 66873 std::this_thread::sleep_for(std::chrono::milliseconds(1));
314 66873 loops++;
315 }
316
317 // Stop playback if the master hasn't sent any sync packets yet
318
2/2
✓ Branch 0 taken 26 times.
✓ Branch 1 taken 15 times.
 41 if (MasterFramesPlayed < 0)
319 26 RunThread = 0;
320 }
321
322 1956 bool doForceOutput = false;
323 1956 bool sendWhileDisabled = false;
324 1956 uint64_t forceSeen = outputForceRequests.load();
325 // Every frame reads these shared values several times. They are plain
326 // values (frame number, rate, delay, on/off flags) that publish no other
327 // data, so the per-frame reads below are relaxed: each seq_cst access is a
328 // pair of barriers on an AM335x, about 0.1 us apiece.
329 1956 constexpr auto relaxed = std::memory_order_relaxed;
330
2/2
✓ Branch 0 taken 131746 times.
✓ Branch 1 taken 1947 times.
 135649 while (RunThread.load(relaxed)) {
331
1/2
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
 131746 startTime = GetMonotonicTimeMicros();
332 // A forced frame asked for before this pass's send is that send.
333 // Acquire: the request is made after the state it wants sent.
334 131746 uint64_t forceNow = outputForceRequests.load(std::memory_order_acquire);
335
2/2
✓ Branch 0 taken 6457 times.
✓ Branch 1 taken 125289 times.
 131746 if (forceNow != forceSeen) {
336 6457 forceSeen = forceNow;
337 6457 doForceOutput = true;
338 6457 sendWhileDisabled = sendWhileDisabledRequested.exchange(false, std::memory_order_relaxed);
339 }
340 // Before forceOutput() below: what a start counted by now set up is
341 // seen there, and the idle wait catches any start counted after.
342 // Taken at the wait, it missed a start made while this pass sent and
343 // processed: the effect was set up too late for forceOutput(), the
344 // starter saw a running thread and returned, and the thread idled
345 // out under the effect. Acquire, as for outputForceRequests.
346 131746 const uint64_t startsSeen = outputStartRequests.load(std::memory_order_acquire);
347
7/8
✓ Branch 0 taken 5058 times.
✓ Branch 1 taken 126688 times.
✓ Branch 2 taken 5058 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 4827 times.
✓ Branch 5 taken 231 times.
✓ Branch 6 taken 4827 times.
✓ Branch 7 taken 126919 times.
 131746 if (multiSync->isMultiSyncEnabled() && sequence->IsSequenceRunning()) {
348 // Per-frame string copy under an uncontended leaf lock: the name is
349 // short and the only writers are the open/close paths, so this costs
350 // far less than the sync packet it feeds.
351 4827 const unsigned long frame = channelOutputFrame.load(relaxed);
352
2/4
✓ Branch 0 taken 4827 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 4827 times.
✗ Branch 3 not taken.
 4827 multiSync->SendSeqSyncPacket(sequence->GetSeqFilenameCopy(), frame, 1.0 * ((float)frame) / RefreshRate.load(relaxed));
353 }
354
355
1/2
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
 131746 doForceOutput |= forceOutput();
356
6/6
✓ Branch 0 taken 1013 times.
✓ Branch 1 taken 130733 times.
✓ Branch 2 taken 180 times.
✓ Branch 3 taken 833 times.
✓ Branch 4 taken 130913 times.
✓ Branch 5 taken 833 times.
 131746 if (OutputFrames.load(relaxed) || sendWhileDisabled) {
357 130913 sendWhileDisabled = false;
358
6/8
✓ Branch 0 taken 120740 times.
✓ Branch 1 taken 10173 times.
✓ Branch 2 taken 120740 times.
✗ Branch 3 not taken.
✗ Branch 4 not taken.
✓ Branch 5 taken 120740 times.
✓ Branch 6 taken 10173 times.
✓ Branch 7 taken 120740 times.
 130913 if (!sequence->isDataProcessed() || sequence->hasBridgeData()) {
359 // first time through or immediately after sequence load, the data might not be
360 // processed yet, need to do it
361 10173 int msTime = 1000.0 * channelOutputFrame.load(relaxed) / RefreshRate.load(relaxed);
362
3/4
✓ Branch 0 taken 10173 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 9468 times.
✓ Branch 3 taken 705 times.
 10173 if (!sequence->IsSequenceRunning()) {
363 9468 msTime = mediaElapsedSeconds.load(relaxed) * 1000;
364 }
365
1/2
✓ Branch 0 taken 10173 times.
✗ Branch 1 not taken.
 10173 sequence->ProcessSequenceData(msTime);
366 }
367
6/8
✓ Branch 0 taken 130913 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 4924 times.
✓ Branch 3 taken 125989 times.
✓ Branch 4 taken 4924 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 4924 times.
✓ Branch 7 taken 125989 times.
 130913 if (getFPPmode() == REMOTE_MODE && !doForceOutput) {
368 // Sleep about 1 seconds waiting for the master
369 4924 int loops = 0;
370
8/10
✓ Branch 0 taken 2384 times.
✓ Branch 1 taken 4923 times.
✓ Branch 2 taken 2383 times.
✓ Branch 3 taken 1 times.
✓ Branch 4 taken 2383 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 2383 times.
✗ Branch 7 not taken.
✓ Branch 8 taken 2383 times.
✓ Branch 9 taken 4924 times.
 12231 while ((MasterFramesPlayed.load(relaxed) < 0) && (loops < 1000) && !sequence->hasBridgeData()) {
371
1/2
✓ Branch 0 taken 2383 times.
✗ Branch 1 not taken.
 2383 std::this_thread::sleep_for(std::chrono::milliseconds(1));
372 2383 loops++;
373 }
374 }
375
1/2
✓ Branch 0 taken 130913 times.
✗ Branch 1 not taken.
 130913 sequence->SendSequenceData();
376 }
377
378
1/2
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
 131746 sendTime = GetMonotonicTimeMicros();
379
380
7/8
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 66867 times.
✓ Branch 3 taken 64879 times.
✓ Branch 4 taken 62260 times.
✓ Branch 5 taken 4607 times.
✓ Branch 6 taken 127139 times.
✓ Branch 7 taken 4607 times.
 131746 if (sequence->IsSequenceRunning() || (onceMore >= 1)) {
381
3/4
✓ Branch 0 taken 127139 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 64879 times.
✓ Branch 3 taken 62260 times.
 127139 if (sequence->IsSequenceRunning()) {
382 // Taken in one step: media sync sets it from another thread,
383 // and a skip it set between a read and a reset was lost.
384 // The plain load first keeps the exchange (a locked RMW)
385 // off the frames with nothing to skip, which is nearly all.
386
2/2
✓ Branch 0 taken 97 times.
✓ Branch 1 taken 64782 times.
 64879 if (FrameSkip.load(relaxed) != 0) {
387
1/2
✓ Branch 0 taken 97 times.
✗ Branch 1 not taken.
 97 sequence->SkipFrames(FrameSkip);
388 }
389 }
390
1/2
✓ Branch 0 taken 127139 times.
✗ Branch 1 not taken.
 127139 sequence->ReadSequenceData();
391 }
392
1/2
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
 131746 readTime = GetMonotonicTimeMicros();
393
394 131746 int msTime = 1000.0 * channelOutputFrame.load(relaxed) / RefreshRate.load(relaxed);
395
3/4
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 67472 times.
✓ Branch 3 taken 64274 times.
 131746 if (!sequence->IsSequenceRunning()) {
396 67472 msTime = mediaElapsedSeconds.load(relaxed) * 1000;
397 }
398
3/4
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 127675 times.
✓ Branch 3 taken 4071 times.
 131746 if (!sequence->hasBridgeData()) {
399 // if bridging, we'll have to process later
400
1/2
✓ Branch 0 taken 127675 times.
✗ Branch 1 not taken.
 127675 sequence->ProcessSequenceData(msTime);
401 }
402
1/2
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
 131746 processTime = GetMonotonicTimeMicros();
403
404 131746 long long totalTime = processTime - startTime;
405
2/2
✓ Branch 0 taken 260 times.
✓ Branch 1 taken 131486 times.
 131746 if (totalTime > 150000) {
406 // very slow, log immediately (this was 3, which the "> 3" test
407 // below didn't pass, so it waited for the next slow frame)
408 260 slowFrameCount = 4;
409
2/2
✓ Branch 0 taken 1288 times.
✓ Branch 1 taken 130198 times.
 131486 } else if (totalTime > 50000) {
410 // could be a very transient blip, we'll log if
411 // it happens 3 frames in a row
412 1288 slowFrameCount++;
413 } else {
414 130198 slowFrameCount = 0;
415 }
416
2/2
✓ Branch 0 taken 339 times.
✓ Branch 1 taken 131407 times.
 131746 if (slowFrameCount > 3) {
417 // Once slow, every frame is slow: logging each one wrote a line
418 // per frame to the SD card for as long as it lasted. Log when it
419 // starts and then every 10 s, counting the slow frames between.
420 static long long lastSlowLogUS = 0;
421 static int slowFramesSinceLog = 0;
422 339 slowFramesSinceLog++;
423
4/4
✓ Branch 0 taken 330 times.
✓ Branch 1 taken 9 times.
✓ Branch 2 taken 8 times.
✓ Branch 3 taken 322 times.
 339 if (!lastSlowLogUS || processTime - lastSlowLogUS >= 10000000) {
424
3/4
✓ Branch 0 taken 8 times.
✓ Branch 1 taken 9 times.
✓ Branch 2 taken 17 times.
✗ Branch 3 not taken.
 51 LogWarn(VB_CHANNELOUT,
425 "SLOW Output Thread: Loop: %dus, Send: %lldus, Read: %lldus, Process: %lldus, FrameNum: %ld (%d slow frames%s)\n",
426 LightDelay.load(),
427 sendTime - startTime,
428 readTime - sendTime,
429 processTime - readTime,
430 channelOutputFrame.load(),
431 slowFramesSinceLog, lastSlowLogUS ? " in the last 10 s" : "");
432 17 lastSlowLogUS = processTime;
433 17 slowFramesSinceLog = 0;
434 }
435 }
436
437
1/2
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
 131746 statusLock.lock();
438
9/12
✓ Branch 0 taken 131746 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 67471 times.
✓ Branch 3 taken 64275 times.
✓ Branch 4 taken 7790 times.
✓ Branch 5 taken 59681 times.
✓ Branch 6 taken 7790 times.
✗ Branch 7 not taken.
✗ Branch 8 not taken.
✓ Branch 9 taken 7790 times.
✓ Branch 10 taken 123956 times.
✓ Branch 11 taken 7790 times.
 131746 if (sequence->IsSequenceRunning() || doForceOutput || sequence->hasBridgeData()) {
439 // REMOTE mode keeps looping a few extra times before we blank
440
3/4
✓ Branch 0 taken 123956 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 4783 times.
✓ Branch 3 taken 119173 times.
 123956 onceMore = (getFPPmode() == REMOTE_MODE) ? 20 : 1;
441 123956 int sleepTime = LightDelay.load(relaxed) - (processTime - startTime);
442
8/8
✓ Branch 0 taken 63930 times.
✓ Branch 1 taken 60026 times.
✓ Branch 2 taken 63840 times.
✓ Branch 3 taken 90 times.
✓ Branch 4 taken 2495 times.
✓ Branch 5 taken 61345 times.
✓ Branch 6 taken 62611 times.
✓ Branch 7 taken 61345 times.
 123956 if ((channelOutputFrame.load(relaxed) <= 1) || (sleepTime <= 0) || (startTime > (lastStatTime + 1000000))) {
443
2/2
✓ Branch 0 taken 1530 times.
✓ Branch 1 taken 61081 times.
 62611 if (sleepTime < 0)
444 1530 sleepTime = 0;
445
2/2
✓ Branch 0 taken 7118 times.
✓ Branch 1 taken 55493 times.
 62611 if (startTime > (lastStatTime + 1000000)) {
446 7118 lastStatTime = startTime;
447 }
448
1/2
✓ Branch 0 taken 62611 times.
✗ Branch 1 not taken.
 125222 LogDebug(VB_CHANNELOUT,
449 "Output Thread: Loop: %dus, Send: %lldus, Read: %lldus, Process: %lldus, Sleep: %dus, FrameNum: %ld\n",
450 LightDelay.load(),
451 sendTime - startTime,
452 readTime - sendTime,
453 processTime - readTime,
454 sleepTime, channelOutputFrame.load());
455 }
456 } else {
457 7790 LightDelay = BridgeLightDelay.load();
458
2/2
✓ Branch 0 taken 5318 times.
✓ Branch 1 taken 2472 times.
 7790 if (onceMore) {
459 5318 onceMore--;
460 } else {
461 // we will wait up to 2500ms to see if the thread is still needed
462 2472 ThreadIsExiting = 1;
463 // On a start request, counted under statusLock, not on any
464 // notify: StartChannelOutputThread() used to notify without
465 // the lock, and a notify that landed before this wait began
466 // was lost - the start then spawned a replacement and this
467 // thread's timeout below cleared RunThread under it.
468 // Shutdown ends the wait too: left to time out, every fppd
469 // stop took the rest of the 2.5 s.
470
1/2
✓ Branch 0 taken 2463 times.
✗ Branch 1 not taken.
 2472 if (outputThreadSatusCond.wait_for(statusLock, std::chrono::milliseconds(2500),
471 4926 [startsSeen, forceSeen]() {
472 4184 return outputThreadShutDown ||
473
4/4
✓ Branch 0 taken 4184 times.
✓ Branch 1 taken 742 times.
✓ Branch 2 taken 3241 times.
✓ Branch 3 taken 943 times.
 12351 outputStartRequests.load() != startsSeen ||
474
2/2
✓ Branch 0 taken 394 times.
✓ Branch 1 taken 2847 times.
 8167 outputForceRequests.load() != forceSeen;
475
4/4
✓ Branch 0 taken 2079 times.
✓ Branch 1 taken 384 times.
✓ Branch 2 taken 1337 times.
✓ Branch 3 taken 1126 times.
 4542 }) &&
476
2/2
✓ Branch 0 taken 1337 times.
✓ Branch 1 taken 742 times.
 2079 !outputThreadShutDown) {
477 // signal to keep going
478 1337 ThreadIsExiting = 0;
479
1/2
✓ Branch 0 taken 1337 times.
✗ Branch 1 not taken.
 1337 statusLock.unlock();
480 1337 outputThreadSatusCond.notify_all();
481 1337 onceMore = 1;
482 // Back from idle: the cadence starts again at this wake.
483 // Left to the "more than a frame behind" test below, a
484 // start within a frame of the last idle pass (a playlist's
485 // next sequence, as the last one's blanking ends) kept the
486 // old phase: the first frame went out at the wake and the
487 // second at the old tick, a few ms later, and the
488 // sequence's timing sync then slowed the next frames by up
489 // to 15 ms each to give the lead back.
490 1337 nextFrameTime = 0;
491 1337 continue;
492 } else {
493 1126 RunThread = 0;
494 1126 ThreadIsExiting = 1;
495 }
496 }
497 }
498
1/2
✓ Branch 0 taken 130400 times.
✗ Branch 1 not taken.
 130400 statusLock.unlock();
499 130400 doForceOutput = false;
500 // Frames are due on a fixed cadence: each one LightDelay after the
501 // previous one was due, not after this pass happened to start. Waking
502 // is always a little late, and measuring from the wake-up added that
503 // to every frame: on a Pi 5 the lights ran 125 ppm slow, and media
504 // sync, which only acts on whole frames, let them fall behind the
505 // sound by tens of ms over a song before correcting.
506 // The period is LightDelay of media time (see SetMediaClockRate()),
507 // kept to a fraction of a microsecond so 100 fps doesn't round it off.
508 130400 const int lightDelay = LightDelay.load(relaxed);
509
1/2
✓ Branch 0 taken 130400 times.
✗ Branch 1 not taken.
 130400 double period = lightDelay / CurrentMediaClockRate(startTime);
510
4/4
✓ Branch 0 taken 127133 times.
✓ Branch 1 taken 3267 times.
✓ Branch 2 taken 286 times.
✓ Branch 3 taken 126847 times.
 130400 if (nextFrameTime == 0 || startTime >= nextFrameTime + lightDelay) {
511 // First frame, or more than a frame behind (back from idle, or a
512 // stall): start the cadence again here rather than racing to catch up.
513 3553 nextFrameTime = startTime + lightDelay;
514 3553 frameTimeCarry = 0.0;
515
2/2
✓ Branch 0 taken 120804 times.
✓ Branch 1 taken 6043 times.
 126847 } else if (startTime >= nextFrameTime) {
516
1/2
✓ Branch 0 taken 120804 times.
✗ Branch 1 not taken.
 120804 frameTimeCarry += period + TakeMediaPhaseStep(startTime, period);
517 120804 long long whole = (long long)std::floor(frameTimeCarry);
518 120804 frameTimeCarry -= whole;
519 120804 nextFrameTime += whole;
520 }
521 // else: a forced wake ran this pass early; the regular frame stays due
522 // when it was.
523
3/4
✓ Branch 0 taken 130400 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 64275 times.
✓ Branch 3 taken 66125 times.
 130400 if (sequence->IsSequenceRunning()) {
524 // The frame just read goes out at the next wake.
525
1/2
✓ Branch 0 taken 64275 times.
✗ Branch 1 not taken.
 64275 PublishNextSend((long)channelOutputFrame.load(relaxed), nextFrameTime);
526 }
527
1/2
✓ Branch 0 taken 130400 times.
✗ Branch 1 not taken.
 130400 long dt = (nextFrameTime - GetMonotonicTimeMicros()) * 1000;
528
6/6
✓ Branch 0 taken 129260 times.
✓ Branch 1 taken 1140 times.
✓ Branch 2 taken 127467 times.
✓ Branch 3 taken 1793 times.
✓ Branch 4 taken 127467 times.
✓ Branch 5 taken 2933 times.
 130400 if (RunThread.load(relaxed) && dt > 0) {
529
3/4
✓ Branch 0 taken 127467 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 6050 times.
✓ Branch 3 taken 121417 times.
 127467 if (outputThreadCond.wait_for(lock, std::chrono::nanoseconds(dt),
530 511292 [&forceSeen]() { return outputForceRequests.load() != forceSeen; })) {
531
1/2
✓ Branch 0 taken 6050 times.
✗ Branch 1 not taken.
 6050 LogDebug(VB_CHANNELOUT, "Forced output\n");
532 }
533 }
534
2/2
✓ Branch 0 taken 44 times.
✓ Branch 1 taken 130356 times.
 130400 if (outputThreadLockWaiters.load(relaxed)) {
535 // Another thread is waiting in LockOutputThread() (an output
536 // reload). The wait above lets it in, but not while the next
537 // frame is already due, and while every cycle runs over its frame
538 // time that is every pass. Let go until it has the lock: a bare
539 // unlock() and lock() would most likely take it straight back.
540
1/2
✓ Branch 0 taken 44 times.
✗ Branch 1 not taken.
 44 lock.unlock();
541
5/6
✓ Branch 0 taken 88 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 44 times.
✓ Branch 3 taken 44 times.
✓ Branch 4 taken 44 times.
✓ Branch 5 taken 44 times.
 176 for (int i = 0; i < 100 && outputThreadLockWaiters.load(); ++i) {
542
1/2
✓ Branch 0 taken 44 times.
✗ Branch 1 not taken.
 44 std::this_thread::sleep_for(std::chrono::microseconds(500));
543 }
544
1/2
✓ Branch 0 taken 44 times.
✗ Branch 1 not taken.
 44 lock.lock();
545 }
546 }
547
548 // StoppingOutput() fires the OUTPUTS_DISABLED presets, which run arbitrary
549 // commands on this thread. It must run while outputThreadLock is still held
550 // so a replacement thread's StartingOutput() cannot interleave with it (a
551 // disable landing after the new thread's enable would leave outputs dark),
552 // but ThreadIsRunning must still be set and statusLock must be released.
553 // Previously ThreadIsRunning was cleared first: a preset that reached
554 // StartChannelOutputThread() spawned a replacement that blocked on
555 // outputThreadLock (held here) while the preset spun on
556 // ChannelOutputThreadIsRunning() -- which only the blocked replacement
557 // could set -- wedging this thread, the replacement, and then the main
558 // loop at the next config reload. With ThreadIsRunning still set, such a
559 // preset queues its replacement on outputThreadLock (it runs once this
560 // thread releases) and its startup wait returns immediately.
561 // ThreadIsExiting is set so a Start during this window falls through to
562 // spawn rather than early-returning against a thread already on its way
563 // out.
564
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 statusLock.lock();
565 1947 ThreadIsExiting = 1;
566
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 statusLock.unlock();
567
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 StoppingOutput();
568
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 statusLock.lock();
569 1947 ThreadIsRunning = 0;
570
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 statusLock.unlock();
571
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 lock.unlock();
572
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 statusLock.lock();
573 1947 ThreadIsExiting = 0;
574
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 statusLock.unlock();
575 1947 outputThreadSatusCond.notify_all();
576
577
1/2
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
 1947 LogDebug(VB_CHANNELOUT, "RunChannelOutputThread() completed\n");
578
2/4
✓ Branch 0 taken 1947 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 1947 times.
✗ Branch 3 not taken.
 1947 }
579
580 /*
581 * Set the step time
582 */
583 2403 void SetChannelOutputRefreshRate(float rate) {
584 // Under the status lock, because the output thread sets LightDelay to the
585 // bridging interval, under that lock, when it finds no sequence running.
586 // Unlocked, that store could land just after this one when a sequence was
587 // starting, and the whole sequence then ran at the bridging interval
588 // (50ms by default) instead of its own frame time. StartSequence() marks
589 // the sequence running before calling this, so the thread either sees it
590 // running or finishes its store first.
591
1/2
✓ Branch 0 taken 2403 times.
✗ Branch 1 not taken.
 2403 std::unique_lock<std::mutex> statusLock(outputThreadStatusLock);
592 2403 RefreshRate = rate;
593 2403 SequenceLightDelay = 1000000 / RefreshRate;
594 2403 LightDelay = SequenceLightDelay.load();
595 2403 }
596 19290 float GetChannelOutputRefreshRate() {
597 19290 return RefreshRate;
598 }
599
600 /*
601 * Kick off the channel output thread
602 */
603 228169 void StartChannelOutputThread(void) {
604 228169 LogDebug(VB_CHANNELOUT, "StartChannelOutputThread()\n");
605
606
2/2
✓ Branch 0 taken 1885 times.
✓ Branch 1 taken 226284 times.
 228169 if (BridgeLightDelay == 0) {
607 1885 alwaysTransmit = getSettingInt("alwaysTransmit");
608 1885 BridgeLightDelay = getSettingInt("E131BridgingInterval", 50) * 1000;
609
3/6
✓ Branch 0 taken 1885 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 1885 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 1885 times.
✗ Branch 5 not taken.
 9265 registerSettingsListener("ChannelOutputThread", "alwaysTransmit", [](const std::string& value) {
610 ✗ alwaysTransmit = getSettingInt("alwaysTransmit");
611 ✗ });
612
3/6
✓ Branch 0 taken 1885 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 1885 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 1885 times.
✗ Branch 5 not taken.
 9265 registerSettingsListener("ChannelOutputThread", "E131BridgingInterval", [](const std::string& value) {
613 1 BridgeLightDelay = getSettingInt("E131BridgingInterval", 50) * 1000;
614 1 });
615 }
616
2/2
✓ Branch 0 taken 228080 times.
✓ Branch 1 taken 89 times.
 228169 if (getFPPmode() & PLAYER_MODE) {
617 228080 int mediaOffsetInt = getSettingInt("mediaOffset");
618
2/2
✓ Branch 0 taken 19554 times.
✓ Branch 1 taken 208526 times.
 228080 if (mediaOffsetInt) {
619 19554 mediaOffset = (float)mediaOffsetInt * 0.001;
620 } else {
621 208526 mediaOffset = 0.0;
622 }
623 228080 LogDebug(VB_MEDIAOUT, "Using mediaOffset of %.3f\n", mediaOffset.load());
624 }
625
626 {
627
1/2
✓ Branch 0 taken 228169 times.
✗ Branch 1 not taken.
 228169 std::unique_lock<std::mutex> lock(outputThreadStatusLock);
628 228169 ++outputStartRequests;
629 228169 }
630 228169 outputThreadSatusCond.notify_all();
631
2/2
✓ Branch 0 taken 226210 times.
✓ Branch 1 taken 1959 times.
 228169 if (ChannelOutputThreadIsRunning()) {
632 // Give a little time in case we were shutting down
633
1/2
✓ Branch 0 taken 226210 times.
✗ Branch 1 not taken.
 226210 std::unique_lock<std::mutex> lock(outputThreadStatusLock);
634
2/2
✓ Branch 0 taken 756 times.
✓ Branch 1 taken 225454 times.
 226210 if (ThreadIsExiting) {
635
1/2
✓ Branch 0 taken 756 times.
✗ Branch 1 not taken.
 756 outputThreadSatusCond.wait_for(lock, std::chrono::milliseconds(10));
636 }
637
5/6
✓ Branch 0 taken 226210 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 226209 times.
✓ Branch 3 taken 1 times.
✓ Branch 4 taken 226209 times.
✓ Branch 5 taken 1 times.
 226210 if (ThreadIsRunning && !ThreadIsExiting) {
638
1/2
✓ Branch 0 taken 226209 times.
✗ Branch 1 not taken.
 226209 LogDebug(VB_CHANNELOUT, "Channel Output thread is already running\n");
639 226209 return;
640 }
641
2/2
✓ Branch 0 taken 1 times.
✓ Branch 1 taken 226209 times.
 226210 }
642
643 {
644 // Checked and started under the lock StopChannelOutputThread() latches
645 // outputThreadShutDown under, so a start can't slip in after it.
646
1/2
✓ Branch 0 taken 1960 times.
✗ Branch 1 not taken.
 1960 std::unique_lock<std::mutex> lock(outputThreadStatusLock);
647
2/2
✓ Branch 0 taken 4 times.
✓ Branch 1 taken 1956 times.
 1960 if (outputThreadShutDown) {
648
1/2
✓ Branch 0 taken 4 times.
✗ Branch 1 not taken.
 4 LogDebug(VB_CHANNELOUT, "Not starting the channel output thread: fppd is shutting down\n");
649 4 return;
650 }
651 1956 RunThread = 1;
652 1956 ThreadIsExiting = 0;
653 // The thread is detached immediately (as the pthread version was via
654 // pthread_detach) — its lifecycle is coordinated through the
655 // RunThread/ThreadIsRunning/ThreadIsExiting flags and condition
656 // variables, never by joining. std::thread reports creation failure
657 // by throwing std::system_error rather than returning an errno.
658 try {
659
2/4
✓ Branch 0 taken 1956 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 1956 times.
✗ Branch 3 not taken.
 1956 std::thread(RunChannelOutputThread).detach();
660 ✗ } catch (const std::system_error& ex) {
661 ✗ RunThread = 0;
662 ✗ LogErr(VB_CHANNELOUT, "ERROR creating channel output thread: %s (code %d)\n",
663 ex.what(), ex.code().value());
664 ✗ return;
665 ✗ }
666
2/2
✓ Branch 0 taken 1956 times.
✓ Branch 1 taken 4 times.
 1960 }
667
668 // Wait for thread to start, but bounded (mirrors StopChannelOutputThread's
669 // cap): if the new thread cannot come up — e.g. it is queued on
670 // outputThreadLock behind an exiting thread that is stuck in a slow
671 // OUTPUTS_DISABLED command — spinning here forever would pin the calling
672 // thread (which can be an HTTP handler or a command preset) as well.
673 1956 int waitLoops = 0;
674
5/6
✓ Branch 0 taken 1936 times.
✓ Branch 1 taken 1956 times.
✓ Branch 2 taken 1936 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 1936 times.
✓ Branch 5 taken 1956 times.
 3892 while (!ChannelOutputThreadIsRunning() && (waitLoops++ < 1000))
675
1/2
✓ Branch 0 taken 1936 times.
✗ Branch 1 not taken.
 1936 std::this_thread::sleep_for(std::chrono::milliseconds(5));
676
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1956 times.
 1956 if (!ChannelOutputThreadIsRunning())
677 ✗ LogErr(VB_CHANNELOUT, "Channel output thread did not start within 5 seconds\n");
678 }
679
680 /*
681 *
682 */
683 1867 int StopChannelOutputThread(void) {
684
1/2
✓ Branch 0 taken 1867 times.
✗ Branch 1 not taken.
 1867 LogDebug(VB_CHANNELOUT, "StopChannelOutputThread()\n");
685
686 // Stop the thread for good (see outputThreadShutDown), wake it from
687 // whichever wait it is in, and wait a few seconds for it to exit (it
688 // notifies outputThreadSatusCond once ThreadIsRunning is clear).
689
1/2
✓ Branch 0 taken 1867 times.
✗ Branch 1 not taken.
 1867 std::unique_lock<std::mutex> lock(outputThreadStatusLock);
690 1867 outputThreadShutDown = true;
691 1867 RunThread = 0;
692 1867 outputThreadSatusCond.notify_all();
693 1867 outputThreadCond.notify_all();
694
2/4
✓ Branch 0 taken 1867 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 1867 times.
 5275 if (!outputThreadSatusCond.wait_for(lock, std::chrono::seconds(5), []() { return !ThreadIsRunning; })) {
695 // Didn't stop for some reason, so it was hung somewhere
696 ✗ return -1;
697 }
698 1867 return 0;
699 1867 }
700
701 ✗ void StartForcingChannelOutput(void) {
702 ✗ outputForced = outputForced + 1;
703
704 ✗ StartChannelOutputThread();
705 ✗ }
706
707 ✗ void StopForcingChannelOutput(void) {
708 ✗ outputForced = outputForced - 1;
709
710 ✗ if (outputForced < 0)
711 ✗ outputForced = 0;
712 ✗ }
713
714 // Where the master's recent sync packets put its frame 0 on our clock. A
715 // packet can arrive late -- the master's own loop, the network, this box's
716 // scheduling -- but never early, so the earliest of the last couple of
717 // seconds is the master's timeline; following each packet as it came put
718 // half of every delay on the lights, frame to frame.
719 static constexpr long long kMasterWindowUs = 2000000;
720 struct MasterEpoch {
721 long long at;
722 double frame0Us;
723 };
724 static std::mutex masterEpochLock;
725 static std::deque<MasterEpoch> masterEpochs;
726 static int masterLastFrame = -1;
727 static double masterFrameUs = 0.0;
728
729 /*
730 * Reset the master frames played position
731 */
732 91 void ResetMasterPosition(void) {
733 91 MasterFramesPlayed = -1;
734
1/2
✓ Branch 0 taken 91 times.
✗ Branch 1 not taken.
 91 std::unique_lock<std::mutex> l(masterEpochLock);
735 91 masterEpochs.clear();
736 91 }
737
738 1890 void CancelFrameSkip(void) {
739 1890 FrameSkip = 0;
740 1890 }
741
742 // The master's frame 0 on our clock, from the packet that put it at
743 // framePosition (frameNumber rounded) arriving now, and the ones before it.
744 652 static double MasterFrame0(int frameNumber, double framePosition, long long now, double frameUs) {
745 652 double frame0 = now - framePosition * frameUs;
746
1/2
✓ Branch 0 taken 652 times.
✗ Branch 1 not taken.
 652 std::unique_lock<std::mutex> l(masterEpochLock);
747
4/4
✓ Branch 0 taken 637 times.
✓ Branch 1 taken 15 times.
✓ Branch 2 taken 4 times.
✓ Branch 3 taken 633 times.
 652 if (frameUs != masterFrameUs || frameNumber < masterLastFrame) {
748 // Another rate, or the master went back: a new timeline.
749 19 masterEpochs.clear();
750 }
751 652 masterFrameUs = frameUs;
752 652 masterLastFrame = frameNumber;
753
6/6
✓ Branch 0 taken 1157 times.
✓ Branch 1 taken 21 times.
✓ Branch 2 taken 526 times.
✓ Branch 3 taken 631 times.
✓ Branch 4 taken 526 times.
✓ Branch 5 taken 652 times.
 1178 while (!masterEpochs.empty() && now - masterEpochs.front().at > kMasterWindowUs) {
754 526 masterEpochs.pop_front();
755 }
756 652 double best = frame0;
757
2/2
✓ Branch 0 taken 7765 times.
✓ Branch 1 taken 652 times.
 8417 for (auto& e : masterEpochs) {
758 7765 best = std::min(best, e.frame0Us);
759 }
760
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 652 times.
 652 if (frame0 - best > 3 * frameUs) {
761 // Far later than all of them: the master held or paused, or this
762 // packet is very late. Start over from it; a late one is replaced
763 // by the next packet, and is too far off to steer by meanwhile.
764 ✗ masterEpochs.clear();
765 ✗ best = frame0;
766 }
767
1/2
✓ Branch 0 taken 652 times.
✗ Branch 1 not taken.
 652 masterEpochs.push_back({ now, frame0 });
768 652 return best;
769 652 }
770
771 /*
772 * Update the count of frames that the master has played so we can sync to it
773 */
774 ✗ void UpdateMasterPosition(int frameNumber) {
775 ✗ UpdateMasterPosition(frameNumber, (double)frameNumber);
776 ✗ }
777
778 652 void UpdateMasterPosition(int frameNumber, double framePosition) {
779 652 MasterFramesPlayed = frameNumber;
780 // The master sends frame F's sync packet just before it puts F on the
781 // wire, so F goes out there about when the packet arrives (the earliest
782 // arrival of the last few, MasterFrame0()). The frame this thread sends
783 // next is due that many frames on; the difference from when it is
784 // actually due is closed by the phase servo, as a player's lights follow
785 // its media. Frame counts alone left a remote's lights most of a frame
786 // late at 40 fps, and one also playing the show's audio settled a
787 // different distance late each start, up to most of a frame at 20 fps.
788 //
789 // A packet comes every ten frames, so the correction left from the last
790 // one has been taken by the next; each takes half the error it measures,
791 // which closes it without overshoot.
792 652 bool phaseServo = false;
793
3/6
✓ Branch 0 taken 652 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 652 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 652 times.
✗ Branch 5 not taken.
 652 if (sequence->IsSequenceRunning() && RefreshRate > 0) {
794 652 long long now = GetMonotonicTimeMicros();
795 652 double frameUs = 1000000.0 / RefreshRate;
796 652 double frame0 = MasterFrame0(frameNumber, framePosition, now, frameUs);
797 long frame;
798 long long due;
799 {
800
1/2
✓ Branch 0 taken 652 times.
✗ Branch 1 not taken.
 652 std::unique_lock<std::mutex> l(nextSendLock);
801 652 frame = nextSendFrame;
802 652 due = nextSendDueUs;
803 652 }
804
3/4
✓ Branch 0 taken 636 times.
✓ Branch 1 taken 16 times.
✓ Branch 2 taken 636 times.
✗ Branch 3 not taken.
 652 if (frame >= 0 && due > 0) {
805 636 double ideal = frame0 + (double)frame * frameUs;
806 636 double err = (double)due - ideal; // > 0: our frames are late
807
2/2
✓ Branch 0 taken 620 times.
✓ Branch 1 taken 16 times.
 636 if (std::fabs(err) < 3 * frameUs) {
808 620 mediaPhaseCorrUs.store(llround(-0.5 * err), std::memory_order_relaxed);
809 mediaPhaseCorrAt.store(now, std::memory_order_relaxed);
810 620 phaseServo = true;
811 }
812 }
813 }
814 652 AdjustForFrame(frameNumber, phaseServo);
815 652 }
816
817 /*
818 * Calculate the new sync offset based on the current position reported
819 * by the media player.
820 */
821 152444 void CalculateNewChannelOutputDelay(float mediaPosition) {
822 static float nextSyncCheck = 0.5;
823 static double phaseErrUs = 0.0;
824 static long long phaseErrAt = 0;
825
826 152444 const float offset = mediaOffset;
827 152444 float offsetMediaPosition = mediaPosition - offset;
828
2/2
✓ Branch 0 taken 916 times.
✓ Branch 1 taken 151528 times.
 152444 mediaElapsedSeconds = offsetMediaPosition < 0.0 ? 0.0 : offsetMediaPosition;
829
830
6/6
✓ Branch 0 taken 141105 times.
✓ Branch 1 taken 11339 times.
✓ Branch 2 taken 20092 times.
✓ Branch 3 taken 121013 times.
✓ Branch 4 taken 31431 times.
✓ Branch 5 taken 121013 times.
 152444 if (getFPPmode() == REMOTE_MODE || !sequence->IsSequenceRunning())
831 31431 return;
832
833 // Frame F belongs on the wire when the media reaches F / RefreshRate.
834 121013 long long now = GetMonotonicTimeMicros();
835 long frame;
836 long long due;
837 {
838
1/2
✓ Branch 0 taken 121013 times.
✗ Branch 1 not taken.
 121013 std::unique_lock<std::mutex> l(nextSendLock);
839 121013 frame = nextSendFrame;
840 121013 due = nextSendDueUs;
841 121013 }
842 121013 double frameUs = 1000000.0 / RefreshRate;
843 121013 bool phaseServo = false;
844
5/6
✓ Branch 0 taken 121011 times.
✓ Branch 1 taken 2 times.
✓ Branch 2 taken 121011 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 119958 times.
✓ Branch 5 taken 1053 times.
 121013 if (frame >= 0 && due > 0 && offsetMediaPosition > 0.0) {
845 119958 double rate = CurrentMediaClockRate(now);
846 119958 double ideal = now + ((double)frame / RefreshRate - offsetMediaPosition) * 1000000.0 / rate;
847 119958 double err = (double)due - ideal; // > 0: the lights are late
848
2/2
✓ Branch 0 taken 119169 times.
✓ Branch 1 taken 789 times.
 119958 if (std::fabs(err) < 3 * frameUs) {
849 // Smoothed: each report is only as good as the position query.
850
2/2
✓ Branch 0 taken 119136 times.
✓ Branch 1 taken 33 times.
 119169 phaseErrUs = (now - phaseErrAt > 1000000) ? err : phaseErrUs + 0.2 * (err - phaseErrUs);
851 119169 phaseErrAt = now;
852 119169 mediaPhaseCorrUs.store(llround(-phaseErrUs), std::memory_order_relaxed);
853 mediaPhaseCorrAt.store(now, std::memory_order_relaxed);
854 119169 phaseServo = true;
855 } else {
856 789 phaseErrAt = 0;
857 }
858 }
859
860
2/2
✓ Branch 0 taken 119787 times.
✓ Branch 1 taken 1226 times.
 121013 if ((mediaPosition <= nextSyncCheck) &&
861
2/2
✓ Branch 0 taken 119768 times.
✓ Branch 1 taken 19 times.
 119787 (nextSyncCheck < (mediaPosition + 2.0))) {
862 119768 return;
863 }
864
865 1245 nextSyncCheck = mediaPosition + (20.0 / RefreshRate);
866
867 1245 int expectedFramesSent = (int)(offsetMediaPosition * RefreshRate);
868
869 2490 LogDebug(VB_CHANNELOUT,
870 "Media Position: %.2f, Offset: %.3f, Frames Sent: %d, Expected: %d, Diff: %d\n",
871 mediaPosition, offset, channelOutputFrame.load(), expectedFramesSent,
872 channelOutputFrame - expectedFramesSent);
873
874 1245 AdjustForFrame(expectedFramesSent, phaseServo);
875 }
876
877 /*
878 * Calculate the new sync offset based on a desired frame number
879 */
880 115696 void CalculateNewChannelOutputDelayForFrame(int expectedFramesSent) {
881 115696 AdjustForFrame(expectedFramesSent, false);
882 115696 }
883
884 117593 static void AdjustForFrame(int expectedFramesSent, bool phaseServo) {
885 117593 int diff = channelOutputFrame - expectedFramesSent;
886 117593 bool allowFrameSkip = !multiSync->isMultiSyncEnabled();
887
4/6
✓ Branch 0 taken 11242 times.
✓ Branch 1 taken 106351 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 11242 times.
✗ Branch 4 not taken.
✓ Branch 5 taken 117593 times.
 117593 if (!allowFrameSkip && diff <= -(RefreshRate / 2)) {
888 // A player sending multisync normally only slews LightDelay so the
889 // remotes aren't yanked around by frame jumps, but the slew is capped
890 // at 15ms per frame. If the output is persistently slower than the
891 // step time, slewing can never catch back up to the media clock and
892 // playback drifts out of sync without bound. Once we are more than
893 // half a second behind, jump — the remotes follow the frame numbers
894 // in the sync packets, so they jump with us.
895 ✗ LogWarn(VB_CHANNELOUT, "Sequence is %d frames behind the media position and cannot catch up by slewing; skipping ahead. Channel output may be too slow for %d fps.\n",
896 -diff, (int)RefreshRate);
897 ✗ WarningHolder::AddWarningTimeout("Sequence playback cannot keep up with the media; skipping frames to stay in sync", 30);
898 ✗ allowFrameSkip = true;
899 }
900
2/2
✓ Branch 0 taken 106351 times.
✓ Branch 1 taken 11242 times.
 117593 if (allowFrameSkip) {
901
2/2
✓ Branch 0 taken 387 times.
✓ Branch 1 taken 105964 times.
 106351 if (diff < -4) {
902 // pretty far behind master, lets just skip forward
903
2/2
✓ Branch 0 taken 141 times.
✓ Branch 1 taken 246 times.
 387 if (diff > -(RefreshRate / 2)) {
904 141 LogDebug(VB_CHANNELOUT, "Skipping a few frames - We are at %d, master is at: %d\n", (int)channelOutputFrame.load(), expectedFramesSent);
905 // off, but not super off, we'll skip a few frames, but not too much to try and keep using
906 // the frames in the cache and avoid hitting the storage, we'll then have the OS preload
907 // the next bunch and we can skip a few more next time
908 141 FrameSkip = 4;
909 141 diff += 4;
910 } else {
911 246 LogDebug(VB_CHANNELOUT, "Skipping many frames - We are at %d, master is at: %d\n", (int)channelOutputFrame.load(), expectedFramesSent);
912 // more than 1/2 second behind, just jump
913 246 FrameSkip = expectedFramesSent - channelOutputFrame;
914
1/2
✓ Branch 0 taken 246 times.
✗ Branch 1 not taken.
 492 LightDelay = sequence->IsSequenceRunning() ? SequenceLightDelay.load() : BridgeLightDelay.load();
915 246 return;
916 }
917
2/2
✓ Branch 0 taken 68 times.
✓ Branch 1 taken 105896 times.
 105964 } else if (diff > 2) {
918 // hold the last frame
919 68 FrameSkip = -1;
920 68 diff--;
921 }
922 }
923
1/2
✓ Branch 0 taken 117347 times.
✗ Branch 1 not taken.
 234694 int DefaultLightDelay = sequence->IsSequenceRunning() ? SequenceLightDelay.load() : BridgeLightDelay.load();
924
5/6
✓ Branch 0 taken 1844 times.
✓ Branch 1 taken 115503 times.
✓ Branch 2 taken 1844 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 1843 times.
✓ Branch 5 taken 1 times.
 117347 if (phaseServo && diff >= -3 && diff <= 3) {
925 // Within a few frames the phase servo has it, to well under a frame.
926 1843 LightDelay = DefaultLightDelay;
927 1843 return;
928 }
929
4/4
✓ Branch 0 taken 115431 times.
✓ Branch 1 taken 73 times.
✓ Branch 2 taken 610 times.
✓ Branch 3 taken 114821 times.
 115504 if (diff > 1 || diff < -1) {
930 683 int timerOffset = diff * (DefaultLightDelay / 100);
931 683 int newLightDelay = LightDelay;
932
2/2
✓ Branch 0 taken 64 times.
✓ Branch 1 taken 619 times.
 683 if (channelOutputFrame > expectedFramesSent) {
933 // correct if we slingshot past 0, otherwise offset further
934
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 64 times.
 64 if (LightDelay < DefaultLightDelay)
935 ✗ newLightDelay = DefaultLightDelay;
936 else
937 64 newLightDelay += timerOffset;
938 } else {
939 // correct if we slingshot past 0, otherwise offset further
940
2/2
✓ Branch 0 taken 4 times.
✓ Branch 1 taken 615 times.
 619 if (LightDelay > DefaultLightDelay)
941 4 newLightDelay = DefaultLightDelay;
942 else
943 615 newLightDelay += timerOffset;
944 }
945
946 // Don't let us go more than 15ms out from the default. If we
947 // can't keep up using that delta then we probably won't be able to.
948
2/2
✓ Branch 0 taken 134 times.
✓ Branch 1 taken 549 times.
 683 if ((DefaultLightDelay - 15000) > newLightDelay)
949 134 newLightDelay = DefaultLightDelay - 15000;
950 // Same bound when we are ahead. The offset added above scales with
951 // the frame difference and accumulates on every check, so without it a
952 // large lead (a media position that fell back to 0 while the sequence
953 // resumed minutes in) grew LightDelay to seconds. The output thread
954 // sleeps for LightDelay, so the lights froze until the media caught
955 // up. At +15ms per frame a lead still closes steadily.
956
2/2
✓ Branch 0 taken 54 times.
✓ Branch 1 taken 629 times.
 683 if ((DefaultLightDelay + 15000) < newLightDelay)
957 54 newLightDelay = DefaultLightDelay + 15000;
958
959 1366 LogDebug(VB_CHANNELOUT, "LightDelay: %d, newLightDelay: %d, DiffFrames: %d %d/%d\n",
960 LightDelay.load(), newLightDelay, diff, channelOutputFrame.load(), expectedFramesSent);
961 683 LightDelay = newLightDelay;
962
2/2
✓ Branch 0 taken 374 times.
✓ Branch 1 taken 114447 times.
 115504 } else if (diff == -1) {
963 // for the one frame off cases, keep the existing light delay unless the
964 // previous "off" frame was on the other side of default
965
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 374 times.
 374 if (LightDelay > DefaultLightDelay) {
966 ✗ LightDelay = DefaultLightDelay;
967 }
968
2/2
✓ Branch 0 taken 75727 times.
✓ Branch 1 taken 38720 times.
 114447 } else if (diff == 1) {
969
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 75727 times.
 75727 if (LightDelay < DefaultLightDelay) {
970 ✗ LightDelay = DefaultLightDelay;
971 }
972
2/2
✓ Branch 0 taken 37 times.
✓ Branch 1 taken 38683 times.
 38720 } else if (LightDelay != DefaultLightDelay) {
973 37 LightDelay = DefaultLightDelay;
974 }
975 }
976