View Bug Details
|ID||Project||Category||View Status||Date Submitted||Last Update|
|0001205||DCP-o-matic||[All Projects] Bugs||public||2018-02-12 22:30||2018-02-18 22:20|
|Platform||Mac||OS||OS X||OS Version||10.11|
|Target Version||2.12.0||Fixed in Version|
|Summary||0001205: 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)
|Tags||No tags attached.|
|Estimated work required||Unknown|
Bildschirmfoto 2018-02-12 um 23.11.13-2.png (53,574 bytes)
Bildschirmfoto 2018-02-12 um 23.11.13-2.png (53,574 bytes)log.zip (31,645 bytes)
||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.|
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.
Bildschirmfoto 2018-02-12 um 23.42.28.png (54,551 bytes)
Bildschirmfoto 2018-02-12 um 23.42.28.png (54,551 bytes)log (446,281 bytes)
metadata.xml (18,360 bytes)
ffprobe.log (1,157 bytes)
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)
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.
||Strange... can I get one of those MTS files?|
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.
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.
||I'm struggling to reproduce this. Did you get the space station video from a youtube rip or did you download it from somewhere?|
||Are you using .52 or later?|
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?
||Can I get the log from a run with the spacestations video?|
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.
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.
log-2.zip (10,519 bytes)
||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|
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...
||Yeah. It's seeking that really makes things hairy. That and hitting the deadlines to get the audio and video ready.|
||Having said that, this bug is just a plain old-fashioned mistake!|
Otherwise - solved for me in 2.11.57
|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|