View Bug Details

IDProjectCategoryView StatusLast Update
0001472DCP-o-maticBugspublic2024-01-03 00:22
Reporteralexthebassist Assigned Tocarl  
PriorityhighSeverityblockReproducibilityrandom
Status acknowledgedResolutionopen 
PlatformLinux 64-bitOSFedoraOS Version29
Summary0001472: Sudden video freezes in DCP-o-matic Player, followed by crash
Description

I'm randomly getting an error in butler.cc: video buffer reached 480 frames, audio is blahblahblah frames. I coudn't save the exact error text (the error appears really randomly, and I am usually not around when it happens. This problem persists in all current test builds since introduction of dual screen playback mode to version 2.13.117. This could also be in any previous stable builds, but I can't verify that since the PC the bug is caught on is being used in actual movie theatre for DCP playback. The problem seems to jump out randomly; this definitely is not because of CPU overheating—its temperature is always under 58°C; other software running in background (a file manager, browser, terminal emulator, VLC) doesn't seem to have any effect either: we tried using player both with and without “background” software, and still caught the bug.

I also sent logs via “Report a problem…” interface, because I can't find them anywhere I could search them in. It's marked with this ticket's number.

Steps To Reproduce

Just try playing DCPs for about 8 hours a day, and you'll definitely get this error in a week or so.

Additional Information

Hardware:
CPU: AMD Ryzen 2600X
RAM: 16 Gb
Video chip: AMD Radeon R7 340, serving two Full HD displays

Software environment:
Kernel version: 4.20.4
DE: KDE Plasma 5.14
DCP-o-matic version: 2.13.117

Tagsplayer
Branch
Estimated weeks required
Estimated work requiredUnknown

Relationships

related to 0001431 closedcarl Investigate opengl canvas for rendering preview/player. 
related to 0001546 acknowledged Option to set playback size to a multiple of the original 

Activities

Carsten

2019-02-15 16:09

manager   ~0003087

You are using DCP-o-matic player for playback in front of audiences? Wow.

What display resolution are you using, and which decode resolution have you chosen?

  • Carsten

carl

2019-02-15 16:29

administrator   ~0003088

You get the first annual DCP-o-matic bravery award!

The logging in the player is fairly minimal. Please could you install 2.13.120, go into prefs and set a file name for the "debug log" option. Then send me the contents of that file after a crash?

Carsten

2019-02-15 18:45

manager   ~0003089

Wondering how you get decent playback performance for full screen (assuming 1920/1080) display resolutions? Brings uns back to the fact that the current frame writing seems to be pretty slow. Since you started to implement logging to the player, is there a way to e.g. separate the time needed to decompress J2K vs. the time needed to display a frame? Because, it looks as if with many/high clocked cores, the J2K is fast enough, but the display scaling/frame updating can not follow. And this may be platform dependent as well. I remember e.g. WIN has so many different APIs for video rendering.

  • Carsten

carl

2019-02-15 18:54

administrator   ~0003090

I'm getting pretty good real time playback with my recent ish i7.

Better logging is necessary, you're right.

I've got an OpenGL renderer nearly ready to test, which might help. It can also do the scaling, I think.

Carsten

2019-02-17 13:49

manager   ~0003091

Last edited: 2019-02-17 14:06

Would be interesting to see performance when display resolution matches decode resolution (as scaling doesn't happen then).
It's difficult to set the window size exactly to the decode resolution manually. I'd love to have a setting for this. Maybe, when you set a decode resolution, set display resolution to exactly that initially. Then, if necessary, let users resize manually with window controls.

It is weird that small changes to window size have a large impact on playback performance.

Yeah, maybe that'll all be solved with a GPU assisted renderer. What do you believe, how much does the inverse x'y'z' cost you?

Hmm, is there a way to set/remember a specific display resolution in prefs? I can't see something like that in my config, but maybe it would be useful.

  • Carsten

alexthebassist

2019-02-17 16:51

reporter   ~0003092

Here's the log.

log_16_02.19 (631,892 bytes)

carl

2019-02-18 00:21

administrator   ~0003093

Thanks. There's some more logging in 2.13.121; please could you install that and, again, upload the log?

alexbukreev

2019-02-18 13:18

reporter   ~0003094

Thanks, we'll do it tomorrow and send here the log.

Carsten

2019-02-18 22:39

manager   ~0003095

Alright, looks as if player performance has increased again, in 2.13.121 it is also more solid against other parallel tasks. This is still on my 2013 i7-4coreHT notebook. It's running hot, but, it's running...

Is this already the OpenGL renderer? I get better performance also in full screen.

  • Carsten

carl

2019-02-18 23:09

administrator   ~0003097

Not much has changed recently, I don't think... what are you compaing 2.13.121 to?

The OpenGL renderer is not there yet.

Carsten

2019-02-19 12:30

manager   ~0003099

My last test on the Mac was 2.13.111 I think. There were some issues switching to/from full screen I think, these are gone now.

I now see two options to go full screen in player on my Mac - the F11, and the one below decoding resolution. The one below quarter-res decoding only hides the menu bar. Is that an OS X specific GUI thing?

Also, I see a thin bright horizontal line in (real) full screen mode, I think below the lower container edge (visible with e.g. letterboxed scope content). But I have seen that before, so it's not new.

btw - player crashes hard when I select a DCP/CPL from the 'recent list' when the content/directory is no longer available. Maybe give a simple 'Not available' message.

  • Carsten

carl

2019-02-19 14:50

administrator   ~0003100

The crash on non-existent history is fixed now. I'm not adding anything below "quarter resolution" so I think that must be an OS X thing.

alexthebassist

2019-02-22 14:41

reporter   ~0003104

Hi! Since 19.02.2019 everything was ok. But today stoped. Here's the log - https://cloud.mail.ru/public/7izg/ZuTf9HfXm

Here's the system log:
Feb 22 16:27:09 localhost kwin_x11[1534]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 23653, resource id: 58720577, maj
or code: 15 (QueryTree), minor code: 0

alexthebassist

2019-02-22 14:56

reporter   ~0003105

The error on freeze was the same: buffer reach 480 frames. Then the player crashed, just as I described before.

A note on previous comment: it wasn't actually sent by me, so I must add that this system log line is suspected (by us) to have relation with the problem we're solving here. What's also strange is that we couldn't find anything about freeze or crash in player's log.

carl

2019-02-27 16:43

administrator   ~0003106

Hm, that BadWindow sounds like something in X11 is giving up the ghost. If that happened, the buffer error could conceivably follow.

carl

2019-02-27 16:50

administrator   ~0003107

Maybe you should be an early tester of the OpenGL view code...

alexthebassist

2019-03-05 20:15

reporter   ~0003122

We'll surely be, but then we need to set up an additional server, or a separate test environment. I don't think that it's safe for us to test that new renderer right in production.

We also bought a new CPU, now it's a Ryzen 7 2700X. We don't encounter the bug anymore, and my personal thought on it is that a frame drop itself is processed somehow “dangerously”. I may be wrong, as all my coding experience consists of shell scripts (if this can be considered coding at all), and some stuff in Pascal back in the days I was a school student.

carl

2019-03-11 22:16

administrator   ~0003127

Interesting; ok, thanks for getting back. It sounds like, as you say, underruns are being unsafely-handled. I will bump this to 2.16.0 and see if it is reproducible with some long playback runs. To my knowledge there are not many users who are running DoM player in production.

alexthebassist

2019-03-12 13:59

reporter   ~0003134

Today we caught it again, but without a crash: playback just had frozen, both video and audio. Player version was the most recent test build available in RPM package (2.3.127). I'll also send logs a little later, when I get to the PC we use for playback.

alexbukreev

2019-03-13 18:05

reporter   ~0003141

Hi, it's Alexandr, we are testing toghether with Alexey. The player is working, but suddenly in logs began write

Ср 13 мар 2019 15:40:57: 1394,208333333333 -> 1394,176479166667; delay 31,85416666656238
Ср 13 мар 2019 15:40:57: 1394,25 -> 1394,21921875; delay 30,78125000001819
Ср 13 мар 2019 15:41:00: WARNING: Butler video buffers reached 96 frames (audio is 21376)
Ср 13 мар 2019 15:41:00: WARNING: Butler video buffers reached 96 frames (audio is 21376)
Ср 13 мар 2019 15:41:00: WARNING: Butler video buffers reached 96 frames (audio is 21376)

and after
Ср 13 мар 2019 15:41:16: WARNING: Butler video buffers reached 479 frames (audio is 19376)
stopted again.

We have the projector fullHD, but show dcp in full resolution (flat or scope). Can it be the reason?

Here's the log - https://cloud.mail.ru/public/pG57/1L73qP5wL

carl

2019-03-13 23:21

administrator   ~0003142

Hi Alexandr. I am guessing that the image freezes but the sound continues just before the crash? is that right? Can you tell if the image stops (in these logs) at the 15:40:57 point or at the 15:41:16 point?

carl

2019-03-13 23:21

administrator   ~0003143

When the xxxx.xx -> xxx.xx; delay xx.xxxx messages stop it suggests that the GUI thread of the player has died, for some reason.

alexbukreev

2019-03-14 00:53

reporter   ~0003144

Yes? The image stops and sound continues. It's very difficutt to say it has stopped at 15:40:57 point or at the 15:41:16 point, because it has stopped at 24 minut. I think the problem begins at the 15:40:57 point and at the 15:41:16 point player stops. For player 480 frame is crytical.

Why it begins i don know. We show different films. It can happen in begin of film, in middle or in the end. It can happen once a day or once a week. Always in log it begins from 96 frame (WARNING: Butler video buffers reached 96 frames (audio is 19520), and ends at nearly 400 (for example one month ago it stopped at 397 frames - WARNING: Butler video buffers reached 397 frames (audio is 21872).

That the reason it could be which keels the GUI thread of the player? I see no regularity:(

alexthebassist

2019-03-14 12:19

reporter   ~0003145

2carl: yes, crash is usually preceded with a video freeze, but sometimes playback freezes for both audio and video. This way the player doesn't crash, but works again only after restart: none of the controls work. However, it seems to exit with code 0. We need to check that also, and we will as soon as we build another PC, which will be used exclusively as testing environment.

alexthebassist

2019-03-28 15:13

reporter   ~0003207

Seems that with latest test builds, the bug is “gone”. Looks like it's strongly related to frame dropping. With the latest builds, we have frame dropouts only when starting playback, and no frame drops afterwards no matter how long do we play movies for. However, we are still ready to test this on a slower machine, as soon as we build it.

carl

2019-03-28 20:32

administrator   ~0003208

OK, keep us updated!

alexbukreev

2019-03-29 20:43

reporter   ~0003216

Hi, Carl. Today used last version 2.13.141, and it freezed again. The bag the same: WARNING: Butler video buffers reached

Here's screenshot, and here's the log. The problem begins at 21:56:05

alexbukreev

2019-03-29 20:47

reporter   ~0003217

We retturned to version 2.13.137

Sorry,

screenshot - https://cloud.mail.ru/public/BaT5/fsfJEHNiv
and log - https://cloud.mail.ru/public/FhkY/qJ78B5zkb

Carsten

2019-03-30 12:47

manager   ~0003218

Do you run a playlist? How long is that playlist, how many items?

I guess I could easily set up something similar on a system here and see what happens.

  • Carsten

alexbukreev

2019-03-30 13:17

reporter   ~0003219

Hi, Carsten. We can't do any playlist because when we open playlist editor we cant't add any dcp in it. We are working in this mode - open player show some trailers, close program and open again and show movie. As I sad this bug happens suddenly in different times and I can't see any regularity :(

Carsten

2019-03-30 13:59

manager   ~0003220

That means, it happens during a single movie showing, and you restart the player always before the next showing?

alexbukreev

2019-03-30 14:11

reporter   ~0003221

Yes.

alexthebassist

2019-04-25 17:18

reporter   ~0003272

New build (2.13.150) seems to be more hangup-prone than a previous one.

alexthebassist

2019-05-09 20:39

reporter   ~0003329

No changes regarding this bug whatsoever in any of downloadable builds. Hangups still occur, happily for both sound and video, so it's at least possible to precisely capture the glitch point and restart playback from the same frame again. However, there's still nothing interesting in logs, so I can't provide any more info. What can I do to get more data on this? We're ready to sponsor this particular bug fix since the issue first appeared.

carl

2019-05-09 21:00

administrator   ~0003330

Sorry there hasn't been much progress here. I've been getting 2.14.0 out of the door and fixing the bugs that are inevitably discovered by the early adopters :\

The OpenGL display code is more-or-less ready to roll. Would you be interested in trying that? Even if it doesn't work it would eliminate some possible causes.

The other thing I could try is to run some long-term tests on my PC (i.e. play DCPs all day). if I can reproduce there is much more chance of a fix. It would need a few hardware adjustments on my end, though (mostly more disc space).

Carsten

2019-05-09 21:38

manager   ~0003331

But, it 2.13.137 safe?

  • Carsten

alexbukreev

2019-05-09 21:53

reporter   ~0003332

Yes!!! We would be interested!!! We are waiting! We are ready!:)))

alexthebassist

2019-05-09 21:54

reporter   ~0003333

2carl: yes, we're eager to test this code.

2Carsten: no, crashes have occured occur on that build too. I still think it has something to do with XCB rendering, because what can be caught in system (not player) log is an XCB error.

carl

2019-05-11 00:22

administrator   ~0003334

2.15.1 is incoming to dcpomatic.com/test-download

You need to select OpenGL mode from advanced preferences. It's all very bleeding-edge but I'd be interested to hear how you get on if you try it.

alexbukreev

2019-05-12 14:18

reporter   ~0003337

Carl, hello. It's great!

But we're using linux Fedora 29, can you make rpm for us? Thank you ever so much:)

carl

2019-05-13 10:27

administrator   ~0003342

Fedora 29 RPM is up now.

alexthebassist

2019-05-28 14:18

reporter   ~0003361

Still the same on 2.15.5, still occurs randomly.

alexthebassist

2019-06-09 13:23

reporter   ~0003371

Does not occur on CentOS 7, still does on Fedora. Other distributions were not tested due to lack of time. However, on CentOS 7, there are huge frame drops in certain movies, probably related to varying decoding difficulty level. Most of movies are unaffected, and this is clearly not to be connected with image resize, as there are both Scope 2K and Full HD Flat movies affected by this.

alexthebassist

2019-06-18 15:12

reporter   ~0003377

According to my research, this problem has something to do with X11 or XCB version.

alexthebassist

2019-09-24 15:39

reporter   ~0003430

I confirm this bug on Ubuntu 18.04 (actually KDE Neon, but the base is virtually the same) and almost any version of Fedora I could get, both stable and testing branch.

alexthebassist

2019-10-02 19:36

reporter   ~0003442

Confirmed also on CentOS 7, but it was first time in several months, and occured only twice while playing movies back as usual.

Bug History

Date Modified Username Field Change
2019-02-14 20:46 alexthebassist New Bug
2019-02-14 20:46 alexthebassist Tag Attached: player
2019-02-14 21:38 carl Target Version => 2.14.0
2019-02-15 16:09 Carsten Note Added: 0003087
2019-02-15 16:29 carl Note Added: 0003088
2019-02-15 16:29 carl Assigned To => carl
2019-02-15 16:29 carl Status new => feedback
2019-02-15 18:45 Carsten Note Added: 0003089
2019-02-15 18:54 carl Note Added: 0003090
2019-02-17 13:49 Carsten Note Added: 0003091
2019-02-17 14:06 Carsten Note Edited: 0003091
2019-02-17 16:51 alexthebassist File Added: log_16_02.19
2019-02-17 16:51 alexthebassist Note Added: 0003092
2019-02-17 16:51 alexthebassist Status feedback => assigned
2019-02-18 00:21 carl Note Added: 0003093
2019-02-18 00:21 carl Status assigned => feedback
2019-02-18 13:18 alexbukreev Note Added: 0003094
2019-02-18 22:39 Carsten Note Added: 0003095
2019-02-18 23:09 carl Note Added: 0003097
2019-02-19 12:30 Carsten File Added: Bildschirmfoto 2019-02-19 um 13.29.14.png
2019-02-19 12:30 Carsten Note Added: 0003099
2019-02-19 14:50 carl Note Added: 0003100
2019-02-22 14:41 alexthebassist Note Added: 0003104
2019-02-22 14:41 alexthebassist Status feedback => assigned
2019-02-22 14:56 alexthebassist Note Added: 0003105
2019-02-27 16:43 carl Note Added: 0003106
2019-02-27 16:50 carl Note Added: 0003107
2019-03-05 20:15 alexthebassist Note Added: 0003122
2019-03-11 22:16 carl Note Added: 0003127
2019-03-11 22:17 carl Target Version 2.14.0 => 2.16.0
2019-03-12 13:59 alexthebassist Note Added: 0003134
2019-03-13 18:05 alexbukreev Note Added: 0003141
2019-03-13 23:21 carl Note Added: 0003142
2019-03-13 23:21 carl Note Added: 0003143
2019-03-14 00:53 alexbukreev Note Added: 0003144
2019-03-14 12:19 alexthebassist Note Added: 0003145
2019-03-28 15:13 alexthebassist Note Added: 0003207
2019-03-28 20:32 carl Note Added: 0003208
2019-03-29 20:43 alexbukreev Note Added: 0003216
2019-03-29 20:47 alexbukreev Note Added: 0003217
2019-03-30 12:47 Carsten Note Added: 0003218
2019-03-30 13:17 alexbukreev Note Added: 0003219
2019-03-30 13:59 Carsten Note Added: 0003220
2019-03-30 14:11 alexbukreev Note Added: 0003221
2019-04-25 17:18 alexthebassist Note Added: 0003272
2019-05-09 20:39 alexthebassist Note Added: 0003329
2019-05-09 21:00 carl Note Added: 0003330
2019-05-09 21:38 Carsten Note Added: 0003331
2019-05-09 21:53 alexbukreev Note Added: 0003332
2019-05-09 21:54 alexthebassist Note Added: 0003333
2019-05-10 01:37 carl Relationship added related to 0001431
2019-05-11 00:22 carl Note Added: 0003334
2019-05-12 14:18 alexbukreev Note Added: 0003337
2019-05-12 17:13 Carsten Relationship added related to 0001546
2019-05-13 10:27 carl Note Added: 0003342
2019-05-28 14:18 alexthebassist Note Added: 0003361
2019-06-09 13:23 alexthebassist Note Added: 0003371
2019-06-18 15:12 alexthebassist Note Added: 0003377
2019-09-24 15:39 alexthebassist Note Added: 0003430
2019-10-02 19:36 alexthebassist Note Added: 0003442
2021-05-23 00:03 carl Target Version 2.16.0 =>
2024-01-03 00:22 carl Status assigned => acknowledged