search

digitalsputnik / DS-Voyager-controller

Application to control Digital Sputnik Voyager lights
0 stars 0 forks source link

Stream out of sync on lamps with lower Delay and higher FPS #340

Closed marirohtla closed 3 years ago

marirohtla commented 4 years ago

Describe the bug With the beta version v2.4.5 where there are now Stream FPS and Delay sliders - it appears that the lower the Delay and the higher the FPS is set, the more out of sync the lamps go VIDEO 1 : Delay 3000 - best VIDEO 2 : Delay 1500 VIDEO 3 : Delay 1

VIDEO 4 : FPS 60 VIDEO 5 : FPS 35 VIDEO 6 : FPS 15 - best

Setup that was used

To Reproduce Steps to reproduce the behavior: Set Spout Stream as FX

Expected behavior Video on lamps should be in sync

Olenjan commented 4 years ago

Achieved much better stream performance by removing logging while in stream and DMX mode. From Lamp v1.600

Olenjan commented 4 years ago

Another possible bug found, Fixed in version 1.601 Current time used instead of PlayerTime.

Olenjan commented 4 years ago

This fix breaks system when timestamps are negative - Added < 0 back in v1.602

Olenjan commented 4 years ago

With higher FPS, lamp does not receive 60 FPS. Logged packets once per sec: Lamp 1: Recv(38) : [1455997349.3358245, 1455997349.352819, 1455997349.385871, 1455997349.4058175, 1455997349.4217334, 1455997349.4691415, 1455997349.4863806, 1455997349.5023775, 1455997349.535595, 1455997349.552548, 1455997349.586484, 1455997349.603262, 1455997349.636248, 1455997349.6523833, 1455997349.6694236, 1455997349.6973228, 1455997349.7093816, 1455997349.7556877, 1455997349.7696495, 1455997349.8047647, 1455997349.820733, 1455997349.8695927, 1455997349.8865156, 1455997349.904467, 1455997349.9198828, 1455997349.9527636, 1455997349.9747052, 1455997349.9886675, 1455997350.0395713, 1455997350.0545325, 1455997350.0854502, 1455997350.1034021, 1455997350.1243505, 1455997350.1413007, 1455997350.1951714, 1455997350.2081227, 1455997350.2531152, 1455997350.269886] Recv(24) : [1455997350.3037646, 1455997350.322717, 1455997350.3376749, 1455997350.4016256, 1455997350.415095, 1455997350.4551997, 1455997350.4701638, 1455997350.503293, 1455997350.5202456, 1455997350.553654, 1455997350.5697687, 1455997350.5867264, 1455997350.6205664, 1455997350.637457, 1455997350.6533499, 1455997350.688483, 1455997350.7038693, 1455997350.7370827, 1455997350.7531457, 1455997350.770105, 1455997350.8032472, 1455997350.819748, 1455997350.8529809, 1455997350.8705297] Recv(35) : [1455997350.8872256, 1455997350.904963, 1455997350.920745, 1455997350.9547565, 1455997350.9706755, 1455997351.0048518, 1455997351.0268605, 1455997351.0398016, 1455997351.0898404, 1455997351.1035697, 1455997351.141498, 1455997351.1594243, 1455997351.1746345, 1455997351.2201471, 1455997351.2570534, 1455997351.2760024, 1455997351.3019805, 1455997351.3140864, 1455997351.353053, 1455997351.3695865, 1455997351.408312, 1455997351.422275, 1455997351.470146, 1455997351.5205407, 1455997351.5375311, 1455997351.5534532, 1455997351.5706668, 1455997351.6045709, 1455997351.6205404, 1455997351.6538846, 1455997351.6700747, 1455997351.7038524, 1455997351.7198637, 1455997351.7540936, 1455997351.7700512] Recv(17) : [1455997351.808994, 1455997351.8249047, 1455997351.8702607, 1455997351.8872116, 1455997351.9051309, 1455997351.9210877, 1455997351.954215, 1455997351.9709017, 1455997351.9932783, 1455997352.0082366, 1455997352.0596275, 1455997352.103545, 1455997352.1243725, 1455997352.1430871, 1455997352.1570427, 1455997352.2038898, 1455997352.2208784] Recv(35) : [1455997352.253238, 1455997352.271223, 1455997352.2871819, 1455997352.341044, 1455997352.3570366, 1455997352.4039047, 1455997352.4201148, 1455997352.459439, 1455997352.4724371, 1455997352.520278, 1455997352.5372605, 1455997352.554186, 1455997352.570174, 1455997352.6040769, 1455997352.6196327, 1455997352.6365876, 1455997352.6532683, 1455997352.6867952, 1455997352.7030463, 1455997352.7199683, 1455997352.752881, 1455997352.770976, 1455997352.7869205, 1455997352.8199534, 1455997352.8366122, 1455997352.8701038, 1455997352.887383, 1455997352.9208903, 1455997352.9368224, 1455997352.9707332, 1455997352.9869523, 1455997353.0198975, 1455997353.0368552, 1455997353.053841, 1455997353.0917082]

5 sec = 35 + 17 + 35 + 24 + 38 = 149 => 149 / 5 = 29.8FPS

Lamp 2: Recv(30) : [1455997349.2230577, 1455997349.269351, 1455997349.2863016, 1455997349.3022285, 1455997349.3358245, 1455997349.352819, 1455997349.385871, 1455997349.4058175, 1455997349.4217334, 1455997349.4691415, 1455997349.4863806, 1455997349.5023775, 1455997349.535595, 1455997349.552548, 1455997349.586484, 1455997349.603262, 1455997349.636248, 1455997349.6523833, 1455997349.6694236, 1455997349.6973228, 1455997349.7093816, 1455997349.7556877, 1455997349.7696495, 1455997349.8047647, 1455997349.820733, 1455997349.8695927, 1455997349.8865156, 1455997349.904467, 1455997349.9198828, 1455997349.9527636] Recv(36) : [1455997349.9747052, 1455997349.9886675, 1455997350.0395713, 1455997350.0545325, 1455997350.0854502, 1455997350.1034021, 1455997350.1243505, 1455997350.1413007, 1455997350.1951714, 1455997350.2081227, 1455997350.2531152, 1455997350.269886, 1455997350.3037646, 1455997350.322717, 1455997350.3376749, 1455997350.4016256, 1455997350.415095, 1455997350.4551997, 1455997350.4701638, 1455997350.503293, 1455997350.5202456, 1455997350.553654, 1455997350.5697687, 1455997350.5867264, 1455997350.6205664, 1455997350.637457, 1455997350.6533499, 1455997350.688483, 1455997350.7038693, 1455997350.7370827, 1455997350.7531457, 1455997350.770105, 1455997350.8032472, 1455997350.819748, 1455997350.8529809, 1455997350.8705297] Recv(32) : [1455997350.8872256, 1455997350.904963, 1455997350.920745, 1455997350.9547565, 1455997350.9706755, 1455997351.0048518, 1455997351.0268605, 1455997351.0398016, 1455997351.0898404, 1455997351.1035697, 1455997351.141498, 1455997351.1594243, 1455997351.1746345, 1455997351.2201471, 1455997351.2570534, 1455997351.2760024, 1455997351.3019805, 1455997351.3140864, 1455997351.353053, 1455997351.3695865, 1455997351.408312, 1455997351.422275, 1455997351.470146, 1455997351.5205407, 1455997351.5375311, 1455997351.5534532, 1455997351.5706668, 1455997351.6045709, 1455997351.6205404, 1455997351.6538846, 1455997351.6700747, 1455997351.7038524] Recv(31) : [1455997351.7198637, 1455997351.7540936, 1455997351.7700512, 1455997351.808994, 1455997351.8249047, 1455997351.8702607, 1455997351.8872116, 1455997351.9051309, 1455997351.9210877, 1455997351.954215, 1455997351.9709017, 1455997351.9932783, 1455997352.0082366, 1455997352.0596275, 1455997352.103545, 1455997352.1243725, 1455997352.1430871, 1455997352.1570427, 1455997352.2038898, 1455997352.2208784, 1455997352.253238, 1455997352.271223, 1455997352.2871819, 1455997352.341044, 1455997352.3570366, 1455997352.4039047, 1455997352.4201148, 1455997352.459439, 1455997352.4724371, 1455997352.520278, 1455997352.5372605] Recv(36) : [1455997352.554186, 1455997352.570174, 1455997352.6040769, 1455997352.6196327, 1455997352.6365876, 1455997352.6532683, 1455997352.6867952, 1455997352.7030463, 1455997352.7199683, 1455997352.752881, 1455997352.770976, 1455997352.7869205, 1455997352.8199534, 1455997352.8366122, 1455997352.8701038, 1455997352.887383, 1455997352.9208903, 1455997352.9368224, 1455997352.9707332, 1455997352.9869523, 1455997353.0198975, 1455997353.0368552, 1455997353.053841, 1455997353.0917082, 1455997353.1096606, 1455997353.1605568, 1455997353.176518, 1455997353.2204747, 1455997353.2364392, 1455997353.2700868, 1455997353.2860436, 1455997353.3196187, 1455997353.336557, 1455997353.3699021, 1455997353.3868833, 1455997353.4228816]

5 sec = 36 + 31 + 32 + 36 + 30 = 165 => 165/5 = 33 FPS

Olenjan commented 4 years ago

Stream packet with index seems to be sent twice on PC

image

Olenjan commented 4 years ago

Another example with 60FPS and 3sec delay image

Olenjan commented 4 years ago

Log from voyager:

Recv: 1458766059.563718, diff: 16.00360870361328 Recv: 1458766059.5807223, diff: 17.00425148010254 Recv: 1458766059.5807223, diff: 0.0 Recv: 1458766059.597726, diff: 17.003774642944336 Recv: 1458766059.597726, diff: 0.0 Recv: 1458766059.6177309, diff: 20.004749298095703 Recv: 1458766059.6177309, diff: 0.0 Recv: 1458766059.6347344, diff: 17.003536224365234 Recv: 1458766059.6347344, diff: 0.0 Recv: 1458766059.6507382, diff: 16.003847122192383 Recv: 1458766059.6507382, diff: 0.0 Recv: 1458766059.6687422, diff: 18.00394058227539 Recv: 1458766059.6687422, diff: 0.0 Recv: 1458766059.684746, diff: 16.003847122192383 Recv: 1458766059.684746, diff: 0.0 Recv: 1458766059.7027497, diff: 18.00370216369629 Recv: 1458766059.7027497, diff: 0.0

Olenjan commented 4 years ago

It seems that when FPS increases, the DelayMS is inverted. This happend > 30FPS

30FPS: ~30 Frames are stored When Frame is received, Diff is calculated from current time, indicating that this frame needs to be displayed X ms in the future. + Packet receive time

Removed: [1.45877571e+09], now: 26
Recv: 1458775715.2677572, diff: 881.3779354095459
Recv: 1458775715.3017654, diff: 890.1984691619873
Removed: [1.45877571e+09], now: 27
Removed: [1.45877571e+09], now: 26
Removed: [1.45877571e+09], now: 25
Recv: 1458775715.3357737, diff: 824.207067489624
Removed: [1.45877571e+09], now: 25
Removed: [1.45877571e+09], now: 24
Recv: 1458775715.3707824, diff: 794.0547466278076

15FPS:

Removed: [1.45877577e+09], now: 18
Recv: 1458775776.1865933, diff: 1192.0034885406494
Removed: [1.45877577e+09], now: 18
Recv: 1458775776.2536101, diff: 1193.5560703277588
Removed: [1.45877578e+09], now: 18
Recv: 1458775776.3216262, diff: 1194.610834121704
Removed: [1.45877578e+09], now: 18
Recv: 1458775776.3876417, diff: 1192.4121379852295
Removed: [1.45877578e+09], now: 18
Recv: 1458775776.454658, diff: 1192.1107769012451
Removed: [1.45877578e+09], now: 18
Recv: 1458775776.5226743, diff: 1192.5950050354004

Now when FPS is increased to 40: FPS 40: Over time diff goes negative Buffered: 1 frame Diff is now slowly goes to negative

FPS: 60

Recv: 1458776190.928166, diff: 1104.7954559326172
Recv: 1458776191.4612942, diff: 623.1133937835693
Removed: [7.], now: 35
Recv: 1458776192.121452, diff: 274.54662322998047
Removed: [1.45877619e+09], now: 13
Recv: 1458776192.9046402, diff: 56.69283866882324
Removed: [1.45877619e+09], now: 3
Recv: 1458776193.7407353, diff: -120.16987800598145
Removed: [1.45877619e+09], now: 1
Recv: 1458776194.4018996, diff: -495.1438903808594
Removed: [1.45877619e+09], now: 1
Recv: 1458776195.3661354, diff: -546.8099117279053
Removed: [1.4587762e+09], now: 1
Recv: 1458776196.1293514, diff: -795.8805561065674
Removed: [1.4587762e+09], now: 1
Recv: 1458776197.103542, diff: -846.4059829711914
Removed: [1.4587762e+09], now: 1
Recv: 1458776197.9329362, diff: -1030.4648876190186
Removed: [1.4587762e+09], now: 1
Recv: 1458776198.9603503, diff: -1003.6971569061279
Removed: [1.4587762e+09], now: 1
Olenjan commented 4 years ago

It seems that calibrator(StreamProcess) cannot handle all those incoming packets

Olenjan commented 4 years ago

This is confirmed: BitmapStreamProcess cannot handle > ~30 FPS This needs to be optimized

Counting number of unhandled polls every 10 sec: For 60 FPS: POOOOLLLLLLSSSSSSPolls: 182 For 15 FPS: POOOOLLLLLLSSSSSSPolls: 1

Even without calibration (Black frame) This process cannot handle 60FPS POOOOLLLLLLSSSSSSPolls: 30

Olenjan commented 4 years ago

According to Wireshark, ~106 Frames are sent per second, with 60FPS Duplicate frame indices are not handled

Olenjan commented 4 years ago

Calibration can take up to and above 100ms some some unknown reason

Olenjan commented 4 years ago

Debugging line: decodedBase64 = base64.b64decode(Message['frame'])

results:

CAAAAAALIIIIIB1: 0.05412101745605469
Handle UDP: poll_request
CAAAAAALIIIIIB1: 21.805524826049805
Handle UDP: poll_request
CAAAAAALIIIIIB1: 0.087738037109375
Handle UDP: poll_request
CAAAAAALIIIIIB1: 1.5790462493896484
Handle UDP: poll_request
CAAAAAALIIIIIB1: 0.05269050598144531
Olenjan commented 4 years ago

~300 ms with 30FPS seems to work best

marirohtla commented 4 years ago

VIDEO: Testing with OSX MadMapper stream: Video seems to be very out of sync with lower Delay - gets a little better with high Delay. Windows: sync seems to be better but not perfect on the lowest Delay. Needs more testing together with developers.

Olenjan commented 4 years ago

With newer non-cal version where much of the animation system is reworked and cores are retargeted Average and median calibration time is < 10ms https://docs.google.com/spreadsheets/d/19jPj5BOatVG5IhvOBnomjz2eywG0kxNYM6eeaOQ2KXg/edit?usp=sharing

Olenjan commented 4 years ago

>10ms calibration occurs for 5% of frames

Olenjan commented 4 years ago

There should be way more time than necessary in 150ms to calibrate and display frames.

Olenjan commented 4 years ago
  1. Calibration time is 95% above necessary performance - IT IS NOT CALIBRATION
  2. FrameTime is very variable, only other variable element is UDP Receiver - Python Pipe - Message process
Olenjan commented 4 years ago

There is still big latency spikes when data is sent locally. This spike can be up to 150ms. Removed StreamReceiver system - This system had no purpose and introduced useless pipes. BitmapStream(Calibrator) now owns Connection objects and receives, validates their data. Also along with calibration.

This improved latency spikes. Both captured locally for 1 minute. image Now: image

Olenjan commented 4 years ago

Maximum of 30 FPS stream is recommended, system is unable to handle bigger values. It is currently unknown why and where this limit comes from. Average calibration frametime for 300 frames without network delay is 27ms. which is equal about 37 FPS.