Performance issues with a 1080i5994 decklink input on Server 2.3.0 nightly

noquierouser · October 29, 2019, 7:13pm

I’m using 2.3.0 d442a8f8 Dev and I’m presenting serious performance issues while using a Decklink input and HTML templates. Here’s an excerpt of my log:

[2019-10-26 22:16:55.738] [info]    Received message from 127.0.0.1: LOADBG 1-2 DECKLINK DEVICE 1 FORMAT 1080i5994\r\n
[2019-10-26 22:16:55.738] [debug]   Executing command: LOADBG
[2019-10-26 22:16:55.775] [info]    DeckLink Duo 2 [1|1080i5994] Initialized
[2019-10-26 22:16:55.775] [debug]   Executed command (0.037s): LOADBG
[2019-10-26 22:16:55.775] [info]    Sent message to 127.0.0.1:202 LOADBG OK\r\n
[2019-10-26 22:16:55.779] [info]    Received message from 127.0.0.1: LOADBG 1-2 DECKLINK DEVICE 1 FORMAT 1080i5994\r\n
[2019-10-26 22:16:55.779] [debug]   Executing command: LOADBG
[2019-10-26 22:16:55.919] [debug]   0 0
[2019-10-26 22:16:55.944] [debug]   1 801
[2019-10-26 22:16:55.944] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -16.6875
[2019-10-26 22:16:55.951] [debug]   2 1602
[2019-10-26 22:16:55.951] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -33.375
[2019-10-26 22:16:55.995] [debug]   3 2402
[2019-10-26 22:16:55.996] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -50.0417
[2019-10-26 22:16:56.043] [debug]   4 3203
[2019-10-26 22:16:56.043] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -66.7292
[2019-10-26 22:16:55.813] [error]   Exception: C:\Program Files (x86)\Jenkins\workspace\casparcg-server-dep\master\src\modules\decklink\producer\decklink_producer.cpp(380): Throw in function __cdecl caspar::decklink::decklink_producer::decklink_producer(const struct caspar::core::video_format_desc &,int,const class caspar::spl::shared_ptr<class caspar::core::frame_factory> &,const class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,const class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,const class std::basic_string<wchar_t,struct std::char_traits<wchar_t>,class std::allocator<wchar_t> > &,bool)
[2019-10-26 22:16:55.813] [error]   Dynamic exception type: class boost::exception_detail::clone_impl<struct caspar::caspar_exception>
[2019-10-26 22:16:55.813] [error]   [struct boost::errinfo_api_function_ * __ptr64] = EnableVideoInput
[2019-10-26 22:16:55.813] [error]   [struct caspar::tag_msg_info * __ptr64] = DeckLink Duo 2 [1|1080i5994] Could not enable video input.
[2019-10-26 22:16:55.813] [error]   [struct caspar::tag_stacktrace_info * __ptr64] =  0# 0x00007FF76459919E in casparcg
[2019-10-26 22:16:55.813] [error]    1# 0x00007FF7645C7090 in casparcg
[2019-10-26 22:16:55.813] [error]    2# 0x00007FF7647C7062 in casparcg
[2019-10-26 22:16:55.813] [error]    3# 0x00007FF7647C9CFF in casparcg
[2019-10-26 22:16:55.813] [error]    4# 0x00007FF764600798 in casparcg
[2019-10-26 22:16:55.813] [error]    5# 0x00007FF764668E0E in casparcg
[2019-10-26 22:16:55.813] [error]    6# 0x00007FF764665EB0 in casparcg
[2019-10-26 22:16:55.813] [error]    7# 0x00007FF764593ED9 in casparcg
[2019-10-26 22:16:55.813] [error]    8# beginthreadex in ucrtbase
[2019-10-26 22:16:55.813] [error]    9# BaseThreadInitThunk in KERNEL32
[2019-10-26 22:16:55.813] [error]   10# RtlUserThreadStart in ntdll
[2019-10-26 22:16:55.813] [error]   
[2019-10-26 22:16:55.813] [error]   

[2019-10-26 22:16:55.813] [error]    0# 0x00007FF76459919E in casparcg
[2019-10-26 22:16:55.813] [error]    1# 0x00007FF764598ACF in casparcg
[2019-10-26 22:16:55.813] [error]    2# 0x00007FF764A74CDB in casparcg
[2019-10-26 22:16:55.813] [error]    3# 0x00007FFB39351030 in VCRUNTIME140
[2019-10-26 22:16:55.813] [error]    4# is_exception_typeof in VCRUNTIME140
[2019-10-26 22:16:55.813] [error]    5# RtlCaptureContext in ntdll
[2019-10-26 22:16:55.813] [error]    6# 0x00007FF764664718 in casparcg
[2019-10-26 22:16:55.813] [error]    7# 0x00007FF764667E2C in casparcg
[2019-10-26 22:16:55.813] [error]    8# 0x00007FF764666EB3 in casparcg
[2019-10-26 22:16:55.813] [error]    9# 0x00007FF76470A6BE in casparcg
[2019-10-26 22:16:55.813] [error]   10# 0x00007FF7646FB3EC in casparcg
[2019-10-26 22:16:55.813] [error]   11# 0x00007FF76474624D in casparcg
[2019-10-26 22:16:55.813] [error]   12# 0x00007FF76474525B in casparcg
[2019-10-26 22:16:55.813] [error]   13# 0x00007FF764600798 in casparcg
[2019-10-26 22:16:55.813] [error]   14# 0x00007FF764668E0E in casparcg
[2019-10-26 22:16:55.813] [error]   15# 0x00007FF764665EB0 in casparcg
[2019-10-26 22:16:55.813] [error]   16# 0x00007FF764593ED9 in casparcg
[2019-10-26 22:16:55.813] [error]   17# beginthreadex in ucrtbase
[2019-10-26 22:16:55.813] [error]   18# BaseThreadInitThunk in KERNEL32
[2019-10-26 22:16:55.813] [error]   19# RtlUserThreadStart in ntdll
[2019-10-26 22:16:55.813] [error]   
[2019-10-26 22:16:56.045] [error]    Turn on log level debug for stacktrace.
[2019-10-26 22:16:56.047] [info]    Sent message to 127.0.0.1:404 LOADBG FAILED\r\n
[2019-10-26 22:16:56.094] [debug]   5 4004
[2019-10-26 22:16:56.094] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -83.4167
[2019-10-26 22:16:56.103] [debug]   6 4805
[2019-10-26 22:16:56.104] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -100.104
[2019-10-26 22:16:56.122] [debug]   7 5605
[2019-10-26 22:16:56.122] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -116.771
[2019-10-26 22:16:56.170] [debug]   8 6406
[2019-10-26 22:16:56.170] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -133.458
[2019-10-26 22:16:56.190] [debug]   9 7207
[2019-10-26 22:16:56.190] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -150.146
[2019-10-26 22:16:56.196] [debug]   10 8008
[2019-10-26 22:16:56.196] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -166.833
[2019-10-26 22:16:56.207] [debug]   11 8809
[2019-10-26 22:16:56.207] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -183.521
[2019-10-26 22:16:56.248] [debug]   12 9610
[2019-10-26 22:16:56.248] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -200.208
[2019-10-26 22:16:56.271] [debug]   13 10410
[2019-10-26 22:16:56.272] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -216.875
[2019-10-26 22:16:56.277] [debug]   14 11211
[2019-10-26 22:16:56.277] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -233.562
[2019-10-26 22:16:56.286] [debug]   15 12012
[2019-10-26 22:16:56.287] [warning] DeckLink Duo 2 [1|1080i5994] out-sync changed: -250.25

For the sake of completion, this is my config file:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
   <log-level>debug</log-level>
   <paths>
      <media-path>..\CasparCGMedia\media</media-path>
      <log-path>..\CasparCGMedia\log</log-path>
      <data-path>..\CasparCGMedia\data</data-path>
      <template-path>..\CasparCGMedia\template</template-path>
   </paths>
   <channels>
      <channel>
         <video-mode>1080i5994</video-mode>
         <consumers>
            <screen>
               <device>1</device>
               <aspect-ratio>16:9</aspect-ratio>
               <stretch>uniform</stretch>
               <windowed>true</windowed>
               <key-only>false</key-only>
               <vsync>false</vsync>
               <borderless>true</borderless>
               <interactive>true</interactive>
               <always-on-top>false</always-on-top>
               <x>0</x>
               <y>0</y>
               <width>512</width>
               <height>288</height>
               <sbs-key>false</sbs-key>
               <colour-space>RGB</colour-space>
            </screen>
            <decklink>
               <device>4</device>
               <key-device>2</key-device>
               <embedded-audio>true</embedded-audio>
               <latency>normal</latency>
               <keyer>external</keyer>
               <key-only>false</key-only>
               <buffer-depth>5</buffer-depth>
            </decklink>
            <ndi>
               <name>Transmision-Aire</name>
               <allow-fields>false</allow-fields>
            </ndi>
         </consumers>
      </channel>
      <channel>
         <video-mode>1080i5994</video-mode>
         <consumers>
            <decklink>
               <device>3</device>
               <key-device>2</key-device>
               <embedded-audio>true</embedded-audio>
               <latency>normal</latency>
               <keyer>external</keyer>
               <key-only>false</key-only>
               <buffer-depth>3</buffer-depth>
            </decklink>
         </consumers>
      </channel>
      <channel>
         <video-mode>1080i5994</video-mode>
         <consumers>
            <decklink>
               <device>2</device>
               <key-device>2</key-device>
               <embedded-audio>true</embedded-audio>
               <latency>normal</latency>
               <keyer>external</keyer>
               <key-only>false</key-only>
               <buffer-depth>3</buffer-depth>
            </decklink>
         </consumers>
      </channel>
   </channels>
   <controllers>
      <tcp>
         <port>5250</port>
         <protocol>AMCP</protocol>
      </tcp>
   </controllers>
   <amcp>
      <media-server>
         <host>localhost</host>
         <port>8000</port>
      </media-server>
   </amcp>
   <flash>
      <buffer-depth>auto</buffer-depth>
   </flash>
   <html>
      <remote-debugging-port>7250</remote-debugging-port>
      <enable-gpu>true</enable-gpu>
   </html>
   <ndi>
      <auto-load>false</auto-load>
   </ndi>
   <osc>
      <default-port>6250</default-port>
      <disable-send-to-amcp-clients>false</disable-send-to-amcp-clients>
      <predefined-clients/>
   </osc>
   <audio>
      <mix-configs>
         <mix-config>
            <from>5.1</from>
            <to>2.0</to>
            <mix>average</mix>
            <mappings>
               <mapping>L L 1.0</mapping>
               <mapping>R R 1.0</mapping>
               <mapping>C L 0.707</mapping>
               <mapping>C R 0.707</mapping>
               <mapping>Ls L 0.707</mapping>
               <mapping>Rs R 0.707</mapping>
            </mappings>
         </mix-config>
      </mix-configs>
   </audio>
</configuration>

To reproduce my issue:

Play a Decklink input on Channel 1
Overlay 2 HTML producers (bug logo and lower third) to Channel 1
Route Channel 1 to Channels 2 and 3

Symptoms of this issue are inconsistent. Sometimes HTML animation playing is laggy, some other times output video stutters every once in a while. CPU usage rises significantly while Decklink is playing.

noumaan · October 29, 2019, 9:24pm

you are getting sync out warning because of decklink input that you are playing and performance is getting worse must be because of memory leak.

i was having this issue when i shift from server 2.0 to server 2.2 on HP z820 but on dell t5500 everything was fine

i guess this memory leak issue is because of reference clock. but i resolve my issue by updating drivers of decklink and GPU.
you can also try

noquierouser · October 30, 2019, 12:03am

I’m going to try updating drivers, as I see there are significant changes in NVIDIA Quadro drivers as well as BMD Desktop Video software updates.

I’ll report my results.

noquierouser · October 30, 2019, 10:58pm

I updated drivers last night and ran a little test recently, and errors kept popping up and performance still stuttery. This is a capture I did of DIAG while running:

PLAY 2-2 DECKLINK DEVICE 1 FORMAT 1080i5994
CG 2-8 ADD 1 "COCTELGC-2019/LT-PERSONA" 1 "{\"f0\":\" \",\"f1\":\" \"}"
CG 2-8 STOP 1 after a few seconds

noumaan · October 31, 2019, 1:48pm

And how much memory CasparCG is using ?

Just play Decklink input and check for system memory if it is continuous increasing

noquierouser · October 31, 2019, 10:00pm

RAM usage stays pretty much the same, but CPU usage rises dramatically:

This is with 1 screen consumer and no decklink device input.

image847×727 46.1 KB
This is with 1 screen consumer and 1 decklink device input.

image845×733 46.3 KB
This is with no screen consumer and no decklink device input.

image849×729 47.4 KB
This is with no screen consumer and 1 declink device input.

image849×727 48.2 KB

For what I can tell, CasparLauncher rises its CPU usage because of the huge amount of messages generated by the Server console (that can easily get an integer overflow in 1 hour of playing), but what puzzles me is the sheer amount of CPU usage while playing a decklink input.

noumaan · November 1, 2019, 7:53pm

I thing according to these snapshots your ram is increasing continuously. 1GB ram usage is not normal for just playing a single Decklink video

Test with blank Decklink input signal and also check with looping ( Decklink output to Same Decklink input ) and play with CasparCG.

noquierouser · November 1, 2019, 9:25pm

I tested playing a blank input into a secondary channel and the issue remains pretty much the same.

To be fair, as far as I can tell, it isn’t a single video churning 1 GB of RAM single-handedly, rather than the decklink input using about 300 MB of RAM, 15% of CPU power and 12% GPU power, but it stays in those values consistently over time.

So far I’ve been unable to test this with a channel in a format different from 1080i5994, but as far as I tested this happens with any decklink format input (1080p2997, 720p2997, 720p5994).

I also can’t tell with certainty if this is a product of this being a build server version, because these issues were not happening while using Server 2.1.8 NRK.

noumaan · November 1, 2019, 9:48pm

as i understand is server 2.1.8 is an updated version of 2.1.0 Beta 2 with new and updated module but in some cases server 2.2 using different logic and may be that is the reason that we are seeing so many issues in 2.2 and hopefully 2.3 final build will resolve all these issues soon in future.
so you should also report your issue on casparcg github with developers.

noquierouser · November 2, 2019, 12:31am

I’ll make a report on GitHub later, but I have the suspicion that this is related to issue #920 because I have interlaced channels and sources while Server 2.2.x and above are focused only on progressive channels performance. Because of that, maybe there are two possible solutions to this issue:

Request on GitHub to bring back interlaced support to Server, which I don’t see happening as it was declared deprecated at some point.
I convert my workflow to progressive, which is going to be a major hassle.

The problem is that my cameras only output 1080i5994, 1080p5994 and 720p5994, so no 1080p2997 or similar options. Also, despite having a 1080 workflow, all of this gets converted to NTSC using a BMD SDI to Analog mini converter which doesn’t accept 1080p5994. Also, I don’t know which performance issues might bring the usage of a 1080p5994 workflow either.

So I guess I’ll have to go back to Server 2.1.8 NRK and bite the bullet about NDI support, which is why I went 2.3.0 in the first place. Maybe test in production the build I did on this thread. At least I can live without a screen consumer in my production environment.

noumaan · November 2, 2019, 11:35am

I’m also using 2.1.8 because from server 2.2 Decklink in interlaced mode has this bug there is also an pull request for this but it is not merged in master till now

noquierouser · November 2, 2019, 7:41pm

From the bug report you linked, a symptom of my issues happens when running a SEEK command, as I have to double the number of frames I’m seeking to get to the point I need. Server 2.2.x, for some reason, assumes fields as frames in interlaced modes.