View Bug Details

IDProjectCategoryView StatusLast Update
0001205DCP-o-matic[All Projects] Bugspublic2018-02-18 22:20
ReporterCarstenAssigned Tocarl 
PrioritynormalSeveritycrashReproducibilityrandom
Status resolvedResolutionfixed 
PlatformMacOSOS X OS Version10.11
Product Version2.11.0 
Target Version2.12.0Fixed in Version 
Summary0001205: Memory leak in 2.11.5x?
Description

I have seen this happening a few times before when testing 2.11.4x, it seems I have either missed reporting it, or came to the conclusion it was fixed in a later version.

In testing for another bug,. I added 4 MP3 files and two MTS files to a new project. While the analysis went okay for them, I noticed that DCP-o-matic's memory consumption grew enormously, bringing my system to a halt.

Now, this even happens when I reload that project, but do nothing at all - the moment the project is loaded, DCP-o-matic starts to eat up memory in GBytes...
I goes back to normal when I quit DCP-o-matic, or delete either of these MTS files (files from my camera, segmented, to be joined). The strange thing is, it doesn't happen when I load these two MTS files into a new project. It starts again, though, when I add 4 MP3 files. Loading just those 4 MP3 files doesn't trigger it...

I ticked all debug log options, see attached file, maybe it leads to something...

Maybe it's this:

Mo 12 Feb 23:12:09 2018: FFmpeg: Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x10893ea00] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x108934c00] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x10a0a1e00] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x10a225600] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x10a224c00] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x10a25e800] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:09 2018: FFmpeg: [mp3 @ 0x10a26ba00] Estimating duration from bitrate, this may be inaccurate
Mo 12 Feb 23:12:10 2018: New graph for 1920x1080, pixel format 0
Mo 12 Feb 23:12:10 2018: FFmpeg: [swscaler @ 0x10a17c800] Warning: data is not aligned! This can lead to a speedloss
Mo 12 Feb 23:12:10 2018: Check /Users/carstenkurz/Movies/00013.MTS yes answer yes
Mo 12 Feb 23:12:10 2018: Check /Users/carstenkurz/Movies/00012.MTS yes answer yes
Mo 12 Feb 23:12:10 2018: Check /Users/carstenkurz/Music/Funky ABBA/09 Dancing Queen.mp3 yes answer yes
Mo 12 Feb 23:12:10 2018: Check /Users/carstenkurz/Music/Funky ABBA/07 Gimme! Gimme! Gimme!.mp3 yes answer yes
Mo 12 Feb 23:12:10 2018: Check /Users/carstenkurz/Music/Funky ABBA/08 The Name Of The Game.mp3 yes answer yes
Mo 12 Feb 23:12:10 2018: Check /Users/carstenkurz/Music/Funky ABBA/01 Money, Money, Money.mp3 yes answer yes
Mo 12 Feb 23:12:10 2018: WARNING: Butler video buffers reached 24 frames (audio is 0)
Mo 12 Feb 23:12:10 2018: WARNING: Butler video buffers reached 24 frames (audio is 0)
Mon Feb 12 23:12:10 2018: WARNING: Butler video buffers reached 25 frames (audio is 0)
Mon Feb 12 23:12:10 2018: WARNING: Butler video buffers reached 26 frames (audio is 0)
(zillions of these lines)

  • Carsten
TagsNo tags attached.
Estimated work requiredUnknown

Relationships

related to 0001194 resolvedcarl Changing of cropping is slow 

Activities

Carsten

2018-02-12 22:30

manager  

log.zip (31,645 bytes)

carl

2018-02-12 22:36

administrator   ~0002149

That's not good. It's trying to prefill some buffers so that playback starts smoothly. But it can't find any audio to put in them. Can you show the metadata.xml? It probably has to do with the arrangement of the content.

Carsten

2018-02-12 22:40

manager   ~0002151

Last edited: 2018-02-12 22:43

View 2 revisions

See screenshot. This project wasn't meant to do anything useful, other than testing wether https://dcpomatic.com/mantis/view.php?id=1203 was fixed, so I just added the content and waited for the analysis to finish.

Carsten

2018-02-12 22:44

manager  

log (446,281 bytes)
metadata.xml (18,360 bytes)
ffprobe.log (1,157 bytes)

Carsten

2018-02-12 22:49

manager   ~0002152

Hmm, now that I notice it in ffprobe, my Sony camera seems to add time and date as a subtitle track with 1s time increments...



Bildschirmfoto 2018-02-12 um 23.48.11.png (601,252 bytes)

Carsten

2018-02-12 22:58

manager   ~0002153

Last edited: 2018-02-12 23:20

View 4 revisions

Weird, it looks as if I can stop the memory consumption when doing some simple actions - e.g. selecting other content. It goes back to normal, then grows again. When I move the preview slider into the last third, it stops forever (goes back to e.g. 171MB). When I put the slider back to zero, it starts to grow again. Must be something with the playback buffering. Let's hope it is not the dreadful recueing for the subs to stay visible ;-)

Err, and, while there is plenty of audio in the project and assigned to L/R in the matrix, no audio is audible. MP3 audio is 44100Hz, MTS audio 48000Hz.

It doesn't happen with any content, though, when I create a similar project with MP4s from a GoPro, all is okay, no memory leak, and all audio plays in a nice chaos.

  • Carsten

carl

2018-02-13 00:05

administrator   ~0002155

Strange... can I get one of those MTS files?

Carsten

2018-02-13 00:43

manager   ~0002156

Last edited: 2018-02-13 00:46

View 2 revisions

There is nothing special about them, other than they are from my Sony camera, and the fact that they are split (unjoined) files, one is around 2GBytes, the other carries the remaining recording time in around 450MByte. So, they are a bit large to transfer. I may try to recreate shorter files from other recordings. The splitting, or the way that I grabbed them from my Cam may be the source of this. My new MacBook shows all video recordings on the camera card as a single BDMV. I can still control-open that file(folder) and drag the individual MTS files out. The proper way to do this in OS X would be to open the BDMV in a capable application (like Quicktime X) or Apple Photos and select the clips to be exported in a different format. I am not too surprised that not many users experience this so far.

  • Carsten

Carsten

2018-02-15 14:51

manager   ~0002175

Last edited: 2018-02-15 15:23

View 2 revisions

Same behaviour in WIN7-64:


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.

On my MacBook, and with the SpaceStation Flythrough, memory consumption clearly follows playhead position - around 3.6GBytes at 25%, 5.6GB at 50%, 9,33GB at 75%. Really looks as if DCP-o-matic is trying to buffer all content from 0 to playhead position.

  • Carsten

carl

2018-02-15 23:17

administrator   ~0002176

I'm struggling to reproduce this. Did you get the space station video from a youtube rip or did you download it from somewhere?

carl

2018-02-15 23:18

administrator   ~0002177

Are you using .52 or later?

Carsten

2018-02-16 00:41

manager   ~0002178

Last edited: 2018-02-16 01:17

View 3 revisions

I am using 2.11.55, but it also appeared earlier on, I am sure even in .4x at some point. At the time, I only noticed it once and couldn't reproduce it. Now I have it both with these MTS files, as well as the SpaceStation MP4. It's a long, 4k MP4 file, maybe resolution/complexity/length plays a role. I can't get this behaviour with the 2k Sintel.

I downloaded the SpaceStations from another bug reports discussion, I just can't remember where and how, but it was YouTube, yes...

Have you seen the video I sent you the dropbox link to?

  • Carsten

carl

2018-02-16 01:07

administrator   ~0002179

Can I get the log from a run with the spacestations video?

Carsten

2018-02-16 01:13

manager   ~0002180

Last edited: 2018-02-16 01:15

View 2 revisions

Yup. I found where I saw it referenced on Mantis, but I downloaded it with a download helper from youtube. It could be useless if you perform your own download.

It's over 800MB, and my upstream here is only 768kBit/s, but 'Ill try with WeTransfer.

I will provide a log.

  • Carsten

Carsten

2018-02-16 01:42

manager   ~0002181

Last edited: 2018-02-16 03:15

View 2 revisions

Here is the log:

  • load space station video on 02:30:00, analysis runs until around 02:30:42, around 02:31:00 I set the preview playhead to about 50% and switch from the default flat container to scope - after a few seconds, the preview snaps to scope and the memory consumption rises to about 6.3GByte and stays there after around 30s. Around 02:32:00 I set the container back to flat. Memory usage suddenly drops to around 280MByte shortly, then rises again to the same value as before (6.3GBytes, playhead remains at around 50%). On 02:33:00, I reset the playhead to 0. Memory consumption drops back to normal immediately and stays there.

Video is on it's way, but will take a few hours.

  • Carsten


log-2.zip (10,519 bytes)

carl

2018-02-16 21:58

administrator   ~0002182

Thanks for the video: it triggered it for me. The problem arises when seeking late into long-ish projects with audio that has been significantly resampled (e.g. 44.1kHz to 48kHz). Should be fixed by 7147957ea5485a70580135cf32c43a05ed97a7f2

Carsten

2018-02-16 23:06

manager   ~0002184

Okay, while this other project showing the issue had MTS files with 48kHz audio, it also had mp3 files with 44.1kHz, so these probably triggered it. It's amazing how difficult things can get when going from non-realtime to realtime...

  • Carsten

carl

2018-02-16 23:08

administrator   ~0002185

Yeah. It's seeking that really makes things hairy. That and hitting the deadlines to get the audio and video ready.

carl

2018-02-16 23:08

administrator   ~0002186

Having said that, this bug is just a plain old-fashioned mistake!

Carsten

2018-02-16 23:27

manager   ~0002187

Last edited: 2018-02-17 03:18

View 2 revisions

Boooooooh!

Otherwise - solved for me in 2.11.57

  • Carsten

carl

2018-02-18 22:20

administrator   ~0002189

Thanks.

Bug History

Date Modified Username Field Change
2018-02-12 22:30 Carsten New Bug
2018-02-12 22:30 Carsten Status new => assigned
2018-02-12 22:30 Carsten Assigned To => carl
2018-02-12 22:30 Carsten File Added: Bildschirmfoto 2018-02-12 um 23.11.13.png
2018-02-12 22:30 Carsten File Added: Bildschirmfoto 2018-02-12 um 23.11.13-2.png
2018-02-12 22:30 Carsten File Added: log.zip
2018-02-12 22:31 Carsten File Deleted: Bildschirmfoto 2018-02-12 um 23.11.13.png
2018-02-12 22:36 carl Note Added: 0002149
2018-02-12 22:40 Carsten Note Added: 0002151
2018-02-12 22:43 Carsten Note Edited: 0002151 View Revisions
2018-02-12 22:44 Carsten File Added: Bildschirmfoto 2018-02-12 um 23.42.28.png
2018-02-12 22:44 Carsten File Added: log
2018-02-12 22:44 Carsten File Added: metadata.xml
2018-02-12 22:44 Carsten File Added: ffprobe.log
2018-02-12 22:49 Carsten File Added: Bildschirmfoto 2018-02-12 um 23.48.11.png
2018-02-12 22:49 Carsten Note Added: 0002152
2018-02-12 22:58 Carsten Note Added: 0002153
2018-02-12 23:06 Carsten Note Edited: 0002153 View Revisions
2018-02-12 23:11 Carsten Note Edited: 0002153 View Revisions
2018-02-12 23:20 Carsten Note Edited: 0002153 View Revisions
2018-02-13 00:05 carl Note Added: 0002155
2018-02-13 00:43 Carsten Note Added: 0002156
2018-02-13 00:46 Carsten Note Edited: 0002156 View Revisions
2018-02-15 14:51 Carsten Note Added: 0002175
2018-02-15 14:52 Carsten Relationship added related to 0001194
2018-02-15 15:23 Carsten Note Edited: 0002175 View Revisions
2018-02-15 23:17 carl Note Added: 0002176
2018-02-15 23:18 carl Note Added: 0002177
2018-02-16 00:41 Carsten Note Added: 0002178
2018-02-16 00:42 Carsten Note Edited: 0002178 View Revisions
2018-02-16 01:07 carl Note Added: 0002179
2018-02-16 01:13 Carsten Note Added: 0002180
2018-02-16 01:15 Carsten Note Edited: 0002180 View Revisions
2018-02-16 01:17 Carsten Note Edited: 0002178 View Revisions
2018-02-16 01:42 Carsten File Added: log-2.zip
2018-02-16 01:42 Carsten Note Added: 0002181
2018-02-16 03:15 Carsten Note Edited: 0002181 View Revisions
2018-02-16 21:58 carl Note Added: 0002182
2018-02-16 23:06 Carsten Note Added: 0002184
2018-02-16 23:08 carl Note Added: 0002185
2018-02-16 23:08 carl Note Added: 0002186
2018-02-16 23:27 Carsten Note Added: 0002187
2018-02-17 03:18 Carsten Note Edited: 0002187 View Revisions
2018-02-18 22:20 carl Status assigned => resolved
2018-02-18 22:20 carl Resolution open => fixed
2018-02-18 22:20 carl Note Added: 0002189