View Bug Details

IDProjectCategoryView StatusLast Update
0001154DCP-o-maticBugspublic2018-10-17 20:16
ReporterCarsten Assigned Tocarl  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionfixed 
PlatformMacOSOS XOS VersionSierra/10.12.6
Product Version2.11.0 
Target Version2.12.0 
Summary0001154: DOM 2.11.34 stalls when creating DCP from trimmed content
Description

Looks as if the recent test versions stall after encoding frames when using trimming. I noticed this when doing tests with 2.11.34 and longer source files when I couldn't wait to finish in full length.

When e.g. I create a DCP from SINTEL-2048 and trim to e.g. 415 frames, the conversion runs at 'normal' speed up until 99% within roughly a minute - then it comes to a halt. At that time, analysis, info and video folders have been created, and audio.mxf.
The log at this point ends with:

Di 2 Jan 19:58:57 2018: Writer FULL-writes 414 (0)
1514919537:649618 encoder-sleep thread=123145570435072
1514919537:652629 writer-sleep queue=0
Di 2 Jan 19:58:57 2018: Finished locally-encoded frame 415 for mono
1514919537:660909 finish-local-encode thread=123145572044800 frame=415
1514919537:661020 encoder-sleep thread=123145572044800
1514919537:661094 writer-wake queue=1
Di 2 Jan 19:58:57 2018: Writer FULL-writes 415 (0)
1514919537:663893 writer-sleep queue=0

The program in this specific case then halts for about 2.5 min, then creates the remaining files, DCP folder, coversheet, and removes the audio MXF from the project directory.

The log then continues with:

Di 2 Jan 20:01:26 2018: Clearing queue of 0
Di 2 Jan 20:01:26 2018: Terminating encoder threads
Di 2 Jan 20:01:26 2018: Terminating thread 1 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 2 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 3 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 4 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 5 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 6 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 7 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Terminating thread 8 of 8
Di 2 Jan 20:01:26 2018: Thread terminated
Di 2 Jan 20:01:26 2018: Mopping up 0
Di 2 Jan 20:01:26 2018: Terminating writer thread
1514919686:626785 writer-wake queue=0
Di 2 Jan 20:01:26 2018: Finishing ReelWriters
Di 2 Jan 20:01:26 2018: Writing XML
Di 2 Jan 20:01:26 2018: Sub-job Zusammenfassung ('Hashes') berechnen starting
Di 2 Jan 20:01:27 2018: create_reel for 0-1664000; 0 of 1
Di 2 Jan 20:01:27 2018: Wrote 416 FULL, 0 FAKE, 0 REPEAT, 0 pushed to disk
Di 2 Jan 20:01:27 2018: Transcode job completed successfully: 1 fps

There is nothing in the log between

Di 2 Jan 19:58:57 2018: Writer FULL-writes 415 (0)
1514919537:663893 writer-sleep queue=0

and

Di 2 Jan 20:01:26 2018: Clearing queue of 0
...

I have all log options checked. This seems to happen with previous test versions as well, down to 2.11.17

It doesn't happen in 2.10.5, though:

Di 2 Jan 20:21:58 2018: Finished locally-encoded frame 414 for mono
1514920918:928204 finish-local-encode thread=123145407164416 frame=414
1514920918:929498 writer-wake queue=1
Di 2 Jan 20:21:58 2018: Writer FULL-writes 414 (0)
1514920918:930801 encoder-sleep thread=123145407164416
Di 2 Jan 20:21:58 2018: Thread terminated
Di 2 Jan 20:21:58 2018: Terminating thread 7 of 8
1514920918:933525 writer-sleep queue=0
Di 2 Jan 20:21:58 2018: Finished locally-encoded frame 415 for mono
1514920918:996205 finish-local-encode thread=123145407700992 frame=415
1514920918:997767 encoder-sleep thread=123145407700992
1514920918:998002 writer-wake queue=1
Di 2 Jan 20:21:58 2018: Thread terminated
Di 2 Jan 20:21:58 2018: Writer FULL-writes 415 (0)
Di 2 Jan 20:21:58 2018: Terminating thread 8 of 8
Di 2 Jan 20:21:58 2018: Thread terminated
Di 2 Jan 20:21:58 2018: Mopping up 0
Di 2 Jan 20:21:58 2018: Terminating writer thread
Di 2 Jan 20:21:59 2018: Finishing ReelWriters
Di 2 Jan 20:21:59 2018: Writing XML
Di 2 Jan 20:21:59 2018: Sub-job Zusammenfassung ('Hashes') berechnen starting
Di 2 Jan 20:22:00 2018: create_reel for 0-1664000; 0 of 1
Di 2 Jan 20:22:00 2018: Wrote 416 FULL, 0 FAKE, 0 REPEAT, 0 pushed to disk
Di 2 Jan 20:22:00 2018: Transcode job completed successfully: 5 fps

Log for 2.11.34, 2.11.17, 2.10.5 and metadata attached. source file is the benchmark sintel-2048.

  • Carsten
TagsNo tags attached.
Branch
Estimated weeks required
Estimated work requiredUnknown

Activities

Carsten

2018-01-02 19:29

manager  

log (1,114,126 bytes)
metadata.xml (7,573 bytes)   
<?xml version="1.0"?>
<Metadata>
  <Version>36</Version>
  <Name>Trimtest</Name>
  <UseISDCFName>1</UseISDCFName>
  <DCPContentType>FTR</DCPContentType>
  <Container>185</Container>
  <Resolution>2K</Resolution>
  <J2KBandwidth>235000000</J2KBandwidth>
  <ISDCFMetadata>
    <ContentVersion>1</ContentVersion>
    <AudioLanguage></AudioLanguage>
    <SubtitleLanguage></SubtitleLanguage>
    <Territory></Territory>
    <Rating></Rating>
    <Studio></Studio>
    <Facility></Facility>
    <TempVersion>0</TempVersion>
    <PreRelease>0</PreRelease>
    <RedBand>0</RedBand>
    <Chain></Chain>
    <TwoDVersionOfThreeD>0</TwoDVersionOfThreeD>
    <MasteredLuminance></MasteredLuminance>
  </ISDCFMetadata>
  <VideoFrameRate>24</VideoFrameRate>
  <ISDCFDate>20180102</ISDCFDate>
  <AudioChannels>6</AudioChannels>
  <ThreeD>0</ThreeD>
  <Sequence>1</Sequence>
  <Interop>0</Interop>
  <Signed>1</Signed>
  <Encrypted>0</Encrypted>
  <Key>a9c3f1b4dc14e89dc32e9e85a8a03b7e</Key>
  <ContextID>2469ce54-ad0b-4393-af78-95bdcd06f99c</ContextID>
  <ReelType>0</ReelType>
  <ReelLength>2000000000</ReelLength>
  <UploadAfterMakeDCP>0</UploadAfterMakeDCP>
  <Playlist>
    <Content>
      <Type>FFmpeg</Type>
      <Path>/Users/carstenkurz/Movies/DOM Benchmark/Sintel/sintel-2048-surround.mp4</Path>
      <Digest>138b7192a8f850e30bd880ac2aed7db8310674005</Digest>
      <Position>0</Position>
      <TrimStart>1348000</TrimStart>
      <TrimEnd>82244000</TrimEnd>
      <VideoFrameRate>24</VideoFrameRate>
      <VideoLength>21314</VideoLength>
      <VideoWidth>2048</VideoWidth>
      <VideoHeight>872</VideoHeight>
      <VideoFrameType>2d</VideoFrameType>
      <SampleAspectRatio>1</SampleAspectRatio>
      <LeftCrop>0</LeftCrop>
      <RightCrop>0</RightCrop>
      <TopCrop>0</TopCrop>
      <BottomCrop>0</BottomCrop>
      <Scale>
        <Ratio>235</Ratio>
      </Scale>
      <ColourConversion>
        <InputTransferFunction>
          <Type>Gamma</Type>
          <Gamma>2.2</Gamma>
        </InputTransferFunction>
        <YUVToRGB>1</YUVToRGB>
        <RedX>0.64</RedX>
        <RedY>0.33</RedY>
        <GreenX>0.3</GreenX>
        <GreenY>0.6</GreenY>
        <BlueX>0.15</BlueX>
        <BlueY>0.06</BlueY>
        <WhiteX>0.3127</WhiteX>
        <WhiteY>0.329</WhiteY>
        <OutputGamma>2.6</OutputGamma>
      </ColourConversion>
      <YUV>1</YUV>
      <FadeIn>0</FadeIn>
      <FadeOut>0</FadeOut>
      <AudioGain>0</AudioGain>
      <AudioDelay>0</AudioDelay>
      <AudioStream>
        <Name>eng</Name>
        <Id>2</Id>
        <FrameRate>48000</FrameRate>
        <Length>42627072</Length>
        <Mapping>
          <InputChannels>6</InputChannels>
          <OutputChannels>16</OutputChannels>
          <Gain Input="0" Output="0">1</Gain>
          <Gain Input="0" Output="1">0</Gain>
          <Gain Input="0" Output="2">0</Gain>
          <Gain Input="0" Output="3">0</Gain>
          <Gain Input="0" Output="4">0</Gain>
          <Gain Input="0" Output="5">0</Gain>
          <Gain Input="0" Output="6">0</Gain>
          <Gain Input="0" Output="7">0</Gain>
          <Gain Input="0" Output="8">0</Gain>
          <Gain Input="0" Output="9">0</Gain>
          <Gain Input="0" Output="10">0</Gain>
          <Gain Input="0" Output="11">0</Gain>
          <Gain Input="0" Output="12">0</Gain>
          <Gain Input="0" Output="13">0</Gain>
          <Gain Input="0" Output="14">0</Gain>
          <Gain Input="0" Output="15">0</Gain>
          <Gain Input="1" Output="0">0</Gain>
          <Gain Input="1" Output="1">1</Gain>
          <Gain Input="1" Output="2">0</Gain>
          <Gain Input="1" Output="3">0</Gain>
          <Gain Input="1" Output="4">0</Gain>
          <Gain Input="1" Output="5">0</Gain>
          <Gain Input="1" Output="6">0</Gain>
          <Gain Input="1" Output="7">0</Gain>
          <Gain Input="1" Output="8">0</Gain>
          <Gain Input="1" Output="9">0</Gain>
          <Gain Input="1" Output="10">0</Gain>
          <Gain Input="1" Output="11">0</Gain>
          <Gain Input="1" Output="12">0</Gain>
          <Gain Input="1" Output="13">0</Gain>
          <Gain Input="1" Output="14">0</Gain>
          <Gain Input="1" Output="15">0</Gain>
          <Gain Input="2" Output="0">0</Gain>
          <Gain Input="2" Output="1">0</Gain>
          <Gain Input="2" Output="2">1</Gain>
          <Gain Input="2" Output="3">0</Gain>
          <Gain Input="2" Output="4">0</Gain>
          <Gain Input="2" Output="5">0</Gain>
          <Gain Input="2" Output="6">0</Gain>
          <Gain Input="2" Output="7">0</Gain>
          <Gain Input="2" Output="8">0</Gain>
          <Gain Input="2" Output="9">0</Gain>
          <Gain Input="2" Output="10">0</Gain>
          <Gain Input="2" Output="11">0</Gain>
          <Gain Input="2" Output="12">0</Gain>
          <Gain Input="2" Output="13">0</Gain>
          <Gain Input="2" Output="14">0</Gain>
          <Gain Input="2" Output="15">0</Gain>
          <Gain Input="3" Output="0">0</Gain>
          <Gain Input="3" Output="1">0</Gain>
          <Gain Input="3" Output="2">0</Gain>
          <Gain Input="3" Output="3">1</Gain>
          <Gain Input="3" Output="4">0</Gain>
          <Gain Input="3" Output="5">0</Gain>
          <Gain Input="3" Output="6">0</Gain>
          <Gain Input="3" Output="7">0</Gain>
          <Gain Input="3" Output="8">0</Gain>
          <Gain Input="3" Output="9">0</Gain>
          <Gain Input="3" Output="10">0</Gain>
          <Gain Input="3" Output="11">0</Gain>
          <Gain Input="3" Output="12">0</Gain>
          <Gain Input="3" Output="13">0</Gain>
          <Gain Input="3" Output="14">0</Gain>
          <Gain Input="3" Output="15">0</Gain>
          <Gain Input="4" Output="0">0</Gain>
          <Gain Input="4" Output="1">0</Gain>
          <Gain Input="4" Output="2">0</Gain>
          <Gain Input="4" Output="3">0</Gain>
          <Gain Input="4" Output="4">1</Gain>
          <Gain Input="4" Output="5">0</Gain>
          <Gain Input="4" Output="6">0</Gain>
          <Gain Input="4" Output="7">0</Gain>
          <Gain Input="4" Output="8">0</Gain>
          <Gain Input="4" Output="9">0</Gain>
          <Gain Input="4" Output="10">0</Gain>
          <Gain Input="4" Output="11">0</Gain>
          <Gain Input="4" Output="12">0</Gain>
          <Gain Input="4" Output="13">0</Gain>
          <Gain Input="4" Output="14">0</Gain>
          <Gain Input="4" Output="15">0</Gain>
          <Gain Input="5" Output="0">0</Gain>
          <Gain Input="5" Output="1">0</Gain>
          <Gain Input="5" Output="2">0</Gain>
          <Gain Input="5" Output="3">0</Gain>
          <Gain Input="5" Output="4">0</Gain>
          <Gain Input="5" Output="5">1</Gain>
          <Gain Input="5" Output="6">0</Gain>
          <Gain Input="5" Output="7">0</Gain>
          <Gain Input="5" Output="8">0</Gain>
          <Gain Input="5" Output="9">0</Gain>
          <Gain Input="5" Output="10">0</Gain>
          <Gain Input="5" Output="11">0</Gain>
          <Gain Input="5" Output="12">0</Gain>
          <Gain Input="5" Output="13">0</Gain>
          <Gain Input="5" Output="14">0</Gain>
          <Gain Input="5" Output="15">0</Gain>
        </Mapping>
        <FirstAudio>0</FirstAudio>
        <CodecName>aac</CodecName>
      </AudioStream>
      <FirstVideo>0</FirstVideo>
      <ColorRange>0</ColorRange>
      <ColorPrimaries>2</ColorPrimaries>
      <ColorTransferCharacteristic>2</ColorTransferCharacteristic>
      <Colorspace>2</Colorspace>
      <BitsPerPixel>12</BitsPerPixel>
    </Content>
  </Playlist>
</Metadata>
metadata.xml (7,573 bytes)   

Carsten

2018-01-02 20:08

manager   ~0001895

When I try this with the 1440p ISS walkthrough and in 4k (trimmed down to the initial 192 frames from roughly 18min total runtime) , it stalls even longer (17min). It may be related to full source length? It's not a big deal once you know it continues creating the DCP, but it took me quite some time to realize that DOM hasn't hung up there, as there is absolutely no progress or any movement during that phase. There is some CPU activity, but not much.

Is it possible that DOM runs through the whole source file, decoding, and discarding the trimmed off images without encoding?
...
Di 2 Jan 20:40:50 2018: Writer FULL-writes 190 (0)
Di 2 Jan 20:40:50 2018: Writer FULL-writes 191 (0)
1514922050:854030 writer-sleep queue=0
1514922050:854847 encoder-sleep thread=123145496518656
Di 2 Jan 20:57:10 2018: Frame @ [DCP 612210 6,377187s] ENCODE
1514923030:132604 add-frame-to-queue queue=0
1514923030:133038 encoder-wake thread=123145498664960 queue=1
1514923030:133166 encoder-pop thread=123145498664960 frame=191 eyes=0
1514923030:133291 start-local-encode thread=123145498664960 frame=191
Di 2 Jan 20:57:10 2018: Clearing queue of 0
Di 2 Jan 20:57:10 2018: Terminating encoder threads
Di 2 Jan 20:57:10 2018: Terminating thread 1 of 8
Di 2 Jan 20:57:10 2018: Thread terminated

  • Carsten

carl

2018-01-02 21:25

administrator   ~0001896

1154 branch

carl

2018-01-03 15:46

administrator   ~0001900

Should be fixed by 65c3b3a815545fef4d0373bb588eb815b8b544b0

Bug History

Date Modified Username Field Change
2018-01-02 19:29 Carsten New Bug
2018-01-02 19:29 Carsten File Added: log
2018-01-02 19:29 Carsten File Added: metadata.xml
2018-01-02 20:08 Carsten Note Added: 0001895
2018-01-02 20:37 carl Status new => confirmed
2018-01-02 20:37 carl Target Version => 2.12.0
2018-01-02 21:25 carl Note Added: 0001896
2018-01-03 15:46 carl Assigned To => carl
2018-01-03 15:46 carl Status confirmed => resolved
2018-01-03 15:46 carl Resolution open => fixed
2018-01-03 15:46 carl Note Added: 0001900
2018-10-17 20:16 carl Status resolved => closed