View Bug Details

IDProjectCategoryView StatusLast Update
0001194DCP-o-maticBugspublic2018-10-17 20:15
Reportercarl Assigned Tocarl  
PrioritynormalSeverityminorReproducibilityhave not tried
Status closedResolutionfixed 
Target Version2.12.0 
Summary0001194: Changing of cropping is slow
Description

Also seen it mentioned that nudge in the player is slow.

TagsNo tags attached.
Branch
Estimated weeks required
Estimated work requiredUnknown

Relationships

related to 0001205 closedcarl Memory leak in 2.11.5x? 

Activities

Markus

2018-02-09 19:38

reporter   ~0002114

Also changing the container format is slow

Markus

2018-02-13 22:10

reporter   ~0002163

I noticed that the cropping is only slow when there is an image in preview. When I scroll back to fram 0 (which is most times black) speed is normal.

carl

2018-02-13 22:13

administrator   ~0002164

Is it possible to get hold of a content file which is slow to crop?

Markus

2018-02-13 22:15

reporter   ~0002165

happens with all files

carl

2018-02-13 22:23

administrator   ~0002166

On all operating systems?

Markus

2018-02-13 22:24

reporter   ~0002167

Sorry, I only have Win10...

carl

2018-02-13 22:25

administrator   ~0002168

Last edited: 2018-02-13 22:26

OK. Could be a Win 10 thing. It's nowhere near so bad with any content for me on Linux. I'll see if I can get my hands on a Win 10 system to evaluate. Thanks!

Carsten

2018-02-14 01:53

manager   ~0002169

Last edited: 2018-02-14 02:22

I don't see slow reaction on cropping, container change, etc. with content visible in preview. I just installed 2.11.55 on my 11 year old MacBook C2D, and even on this old machine the current DCP-o-matic is still usable, only the heavy duty stuff like J2C, export, etc. is noticeably slow.

So, it doesn't seem to be a general issue. Will try in WIN7 as well. Still trying to avoid WIN10.

Markus - is it possible you are trying to crop, change container etc. while the content/audio analysis is still running? Because that slows it down considerably.

Ooops - there is something - it seems to be linked to this one: https://dcpomatic.com/mantis/view.php?id=1205

I just loaded a 4k file, and I see the same enormous memory consumption - when the preview slider is dragged to the right. Unfortunately, I can't reproduce it at will. That's the reason I didn't report it when it occured the first time. The only solid way currently is to load that project with the two MTS files which has it baked in and where the memory leak occurs right after loading the project. How do we find the reason for this... Even with Markus' issue, the memory thing could only be happening in OS X?

Hmmm...

  • Carsten

Carsten

2018-02-14 02:30

manager   ~0002170

Last edited: 2018-02-14 02:34

I get the effect when playing around with a single 4k MP4 file (The ISS flythrough video). So it's not just my two Sony MTS files...

As long as the preview slider is at zero, I can do everything without delay, and DCP-o-matic memory consumption stays reasonable. I drag the preview slider to about 75%, then change container from flat to scope - and my activity monitor shows DCP-o-matic memory consumption to rise above 1GB, 2...4...6...8 Gbytes. I change the container back to flat, and memory consumption immediately drops to below 200Mbyte... This is a SSD system, it will be very slow on a disc based system.

And it's true, when content is long, and the preview slider set to a position half way through or further, changing container, scaling, cropping, etc, is indeed very slow, I always get the spinning ball even on my i7 notebook.

What can I do?

  • Carsten

Carsten

2018-02-14 02:46

manager   ~0002171

Last edited: 2018-02-14 02:50

The log fills up quickly again with lines 'Mi 14 Feb 03:38:17 2018: WARNING: Butler video buffers reached 1029 frames (audio is 0)'

Mostly 'audio is 0', but while playing around, I sometimes geht different numbers there. Maybe that happens when I change container, or preview slider?


Mi 14 Feb 03:35:27 2018: WARNING: Butler video buffers reached 1552 frames (audio is 0)
Mi 14 Feb 03:35:27 2018: WARNING: Butler video buffers reached 1553 frames (audio is 0)
Mi 14 Feb 03:35:27 2018: WARNING: Butler video buffers reached 1553 frames (audio is 0)
Mi 14 Feb 03:35:27 2018: WARNING: Butler video buffers reached 1554 frames (audio is 0)
Mi 14 Feb 03:35:27 2018: WARNING: Butler video buffers reached 1554 frames (audio is 0)
Mi 14 Feb 03:35:27 2018: WARNING: Butler video buffers reached 1554 frames (audio is 497)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1555 frames (audio is 497)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1555 frames (audio is 1610)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1556 frames (audio is 1610)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1556 frames (audio is 2724)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1556 frames (audio is 3837)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1557 frames (audio is 3837)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1557 frames (audio is 4951)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1558 frames (audio is 4951)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1558 frames (audio is 6064)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1558 frames (audio is 7178)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1559 frames (audio is 7178)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1559 frames (audio is 8291)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1560 frames (audio is 8291)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1560 frames (audio is 9405)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1560 frames (audio is 10518)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1561 frames (audio is 10518)
Mi 14 Feb 03:35:28 2018: WARNING: Butler video buffers reached 1561 frames (audio is 11631)

Carl, I made a video that shows the behaviour. It is currently uploading to my dropbox, will send you an email once it is finished.

  • Carsten

Markus

2018-02-14 12:47

reporter   ~0002172

Hi Carl,

I can also see these errors, but with the audio bufer and not the video buffer.Also when I use the preview slider these errors appear:
When cropping I get this:
14/02/2018 13:43:53: WARNING: Butler audio buffers reached 48237 frames (video is 12)
14/02/2018 13:43:53: WARNING: Butler audio buffers reached 48237 frames (video is 12)
When moving the slider I get this:
14/02/2018 13:44:06: WARNING: Butler audio buffers reached 48000 frames (video is 18)
14/02/2018 13:44:06: WARNING: Butler audio buffers reached 48000 frames (video is 18)
Hope this helps...

Markus

Carsten

2018-02-14 15:50

manager   ~0002173

Last edited: 2018-02-14 17:28

Yes, it seems DCP-o-matic is trying to buffer everything from start to current playhead position, or something like that...

Currently trying to replicate it in WIN7 - but I guess Carl will already have an idea what to look for.

  • Carsten

Carsten

2018-02-15 14:50

manager   ~0002174

Last edited: 2018-02-15 15:03

Yes, I see exactly the same behaviour in 2.11.55/WIN7-64. I load the SpaceStation FlyThrough, analysis runs through, all is normal. I put the preview slider to around 75%, change the container from flat to scope - it takes ages for the GUI to catch up. I switch to task manager and see memory consumption rising and rising...
That's a disc based system with just 4GB RAM, within half a minute, the system is paging like mad. No issue changing anything as long as the playhead stays at zero or at short positions into the content.

Carl - it doesn't seem to be strictly content related. You should be able to replicate it even with the 2k SINTEL. If not, I can supply you with that SpaceStation Flythrough (nice to watch anyway).

  • Carsten

carl

2018-02-16 22:02

administrator   ~0002183

Last edited: 2018-02-24 01:06

I think there's two bugs here; 0001205 (which should be gone in 2.11.56) but also re-display of the same frame is inherently slow with the way DoM does things now (as a consequence of the changes to support audio). I have a few ideas, one of which will need to go into 2.12.0.

@carl caching FFmpeg I-frame byte positions helps if you're on a I-frame; otherwise may need some caching of frames somewhere at the decoder level; these cached frames would have to be fed out again on pass(), or something. Or perhaps a whole new "re-get" API.

If you're caching at the decoder it seems fairly easy (on pass() emit the cached image and add 1 frame to _last_video). But which frame to cache? Worst case is that there's a slider seek, the video display ends up on some frame and the decoder/player runs 1s on (or whatever) to fill the butler. How does the decoder know which frame is being displayed? Maybe it could be passed down, but it would have to be passed down early (so that the decoder knew to keep it).

MAXIMUM_VIDEO_READAHEAD is 24 frames so you could cache the last 24 frames to come out of FFmpegDecoder; raw 24-bit 1920x1080 this is 142Mb; not so bad.

It's pretty messy; attempt in ffmpeg-decoder-cache.

speed-some-refresh branch does it by resetting metadata in PlayerVideo where possible; only works for some cases (but the common ones are covered, I think). Needs review.

Carsten

2018-02-17 03:17

manager   ~0002188

https://dcpomatic.com/mantis/view.php?id=1205 is indeed solved. There is still some sluggishness with complex content when cropping, etc. when the playhead is at non zero positions, but I guess no one is really hurt by this, it's just a noticeable lag, not annoying.

  • Carsten

carl

2018-02-24 23:42

administrator   ~0002204

d08123f5e160b5737fa912cd36119e810abaa4cd should help with this (2.11.63)

Bug History

Date Modified Username Field Change
2018-02-09 01:09 carl New Bug
2018-02-09 19:38 Markus Note Added: 0002114
2018-02-13 22:10 Markus Note Added: 0002163
2018-02-13 22:13 carl Note Added: 0002164
2018-02-13 22:14 carl Assigned To => carl
2018-02-13 22:14 carl Status new => feedback
2018-02-13 22:15 Markus Note Added: 0002165
2018-02-13 22:23 carl Note Added: 0002166
2018-02-13 22:24 Markus Note Added: 0002167
2018-02-13 22:25 carl Note Added: 0002168
2018-02-13 22:26 carl Note Edited: 0002168
2018-02-14 01:53 Carsten Note Added: 0002169
2018-02-14 02:20 Carsten Note Edited: 0002169
2018-02-14 02:22 Carsten Note Edited: 0002169
2018-02-14 02:30 Carsten Note Added: 0002170
2018-02-14 02:34 Carsten Note Edited: 0002170
2018-02-14 02:46 Carsten Note Added: 0002171
2018-02-14 02:50 Carsten Note Edited: 0002171
2018-02-14 12:47 Markus Note Added: 0002172
2018-02-14 15:50 Carsten Note Added: 0002173
2018-02-14 17:28 Carsten Note Edited: 0002173
2018-02-15 14:50 Carsten Note Added: 0002174
2018-02-15 14:52 Carsten Relationship added related to 0001205
2018-02-15 14:56 Carsten Note Edited: 0002174
2018-02-15 15:00 Carsten Note Edited: 0002174
2018-02-15 15:01 Carsten Note Edited: 0002174
2018-02-15 15:03 Carsten Note Edited: 0002174
2018-02-16 22:02 carl Note Added: 0002183
2018-02-17 03:17 Carsten Note Added: 0002188
2018-02-22 01:24 carl Note Edited: 0002183
2018-02-22 01:25 carl Note Edited: 0002183
2018-02-24 01:06 carl Note Edited: 0002183
2018-02-24 01:06 carl Status feedback => acknowledged
2018-02-24 23:42 carl Status acknowledged => resolved
2018-02-24 23:42 carl Resolution open => fixed
2018-02-24 23:42 carl Note Added: 0002204
2018-10-17 20:15 carl Status resolved => closed