Strange performance on high core count machine

Support for HandBrake on Linux, Solaris, and other Unix-like platforms
Forum rules
An Activity Log is required for support requests. Please read How-to get an activity log? for details on how and why this should be provided.
Post Reply
sirjorj
Posts: 7
Joined: Mon Nov 12, 2007 5:38 am

Strange performance on high core count machine

Post by sirjorj »

Please detail your question or problem in as much detail as possible:
I am running Handbrake on a system with 64 logical cores (4x 8-core hyperthreaded xeons) and when encoding with some more processor intensive settings (nl-means is on), I will see all the cores maxed for a few seconds, and then they all work their way to idle for a few seconds, and then it repeats. The overall CPU utilization oscillates like that. Any idea what would cause this? This is a dell server so I doubt it is a thermal issue. I am guessing that the scheduler is just a bit overwhelmed. If that is the case, is there a way to restrict Handbrake to a specific number of threads? I tried settings the threads=1 option on the video settings tab but that made no difference. Or perhaps using VirtualBox to break it into 4 or 8 core machines could work, though I would think the overhead would not be worth it.

Tell us about your environment. What version of HandBrake? What version of Linux / Unix are you running. etc.
Lubuntu 17.10
Custom build (to add audio codecs) between 1.0.6 and 1.0.7

I don't think the logs are relevant, as nothing is broken, just behaving strangely.

Thanks
Deleted User 11865

Re: Strange performance on high core count machine

Post by Deleted User 11865 »

Doesn't nlmeans have some sort of tiny lookahead now (thus also some sort of buffering going on)? That could explain a behavior like this, if true (I don't know that part of the code, so it's just a guess).
mduell
Veteran User
Posts: 8187
Joined: Sat Apr 21, 2007 8:54 pm

Re: Strange performance on high core count machine

Post by mduell »

Try disabling HT.

Logs are always useful to confirm claims/assumptions in the post.
sirjorj
Posts: 7
Joined: Mon Nov 12, 2007 5:38 am

Re: Strange performance on high core count machine

Post by sirjorj »

I disabled HyperThreading and saw no difference.

Here is the log from a test run.

Code: Select all

Handbrake Version: 20170409202336-43b9078 (2017110801)
[19:10:37] gtkgui: Custom Preset: /custom
[19:10:37] 1 job(s) to process
[19:10:37] json job:
{
    "Audio": {
        "AudioList": [
            {
                "Bitrate": 384,
                "CompressionLevel": -1.0,
                "DRC": 0.0,
                "DitherMethod": "auto",
                "Encoder": "fdk_aac",
                "Gain": 0.0,
                "Mixdown": "dpl2",
                "NormalizeMixLevel": false,
                "PresetEncoder": "fdk_aac",
                "Quality": -3.0,
                "Samplerate": "auto",
                "Track": 0
            },
            {
                "Bitrate": 0,
                "DRC": 0.0,
                "Encoder": "copy:ac3",
                "Mixdown": "none",
                "PresetEncoder": "copy:ac3",
                "Quality": -3.0,
                "Samplerate": 0,
                "Track": 0
            },
            {
                "Bitrate": 64,
                "CompressionLevel": -1.0,
                "DRC": 0.0,
                "DitherMethod": "auto",
                "Encoder": "fdk_haac",
                "Gain": 0.0,
                "Mixdown": "stereo",
                "NormalizeMixLevel": false,
                "PresetEncoder": "fdk_haac",
                "Quality": -3.0,
                "Samplerate": "auto",
                "Track": 0
            }
        ],
        "CopyMask": [
            "copy:mp3",
            "copy:aac",
            "copy:ac3",
            "copy:dts",
            "copy:dtshd"
        ],
        "FallbackEncoder": "ac3"
    },
    "Destination": {
        "ChapterList": [
            {
                "Name": "Chapter 1"
            },
            {
                "Name": "Chapter 2"
            },
            {
                "Name": "Chapter 3"
            },
            {
                "Name": "Chapter 4"
            }
        ],
        "ChapterMarkers": false,
        "File": "/home/sirjorj/enc/out/s1e01.mp4",
        "Mp4Options": {
            "IpodAtom": false,
            "Mp4Optimize": true
        },
        "Mux": "m4v"
    },
    "Filters": {
        "FilterList": [
            {
                "ID": 2,
                "Settings": {
                    "plane": "0",
                    "skip-bottom": "4",
                    "skip-left": "1",
                    "skip-right": "1",
                    "skip-top": "4"
                }
            },
            {
                "ID": 3,
                "Settings": {
                    "block-height": "16",
                    "block-thresh": "40",
                    "block-width": "16",
                    "filter-mode": "2",
                    "mode": "3",
                    "motion-thresh": "1",
                    "spatial-metric": "2",
                    "spatial-thresh": "1"
                }
            },
            {
                "ID": 4,
                "Settings": {
                    "mode": "7"
                }
            },
            {
                "ID": 6,
                "Settings": {
                    "mode": 0
                }
            },
            {
                "ID": 9,
                "Settings": {
                    "cb-frame-count": 2,
                    "cb-origin-tune": 0.90000000000000002,
                    "cb-patch-size": 7,
                    "cb-prefilter": 0,
                    "cb-range": 3,
                    "cb-strength": 2.3999999999999999,
                    "y-frame-count": 2,
                    "y-origin-tune": 0.90000000000000002,
                    "y-patch-size": 7,
                    "y-prefilter": 0,
                    "y-range": 3,
                    "y-strength": 1.5
                }
            },
            {
                "ID": 11,
                "Settings": {
                    "crop-bottom": 60,
                    "crop-left": 2,
                    "crop-right": 2,
                    "crop-top": 64,
                    "height": 956,
                    "width": 1916
                }
            }
        ]
    },
    "Metadata": {
        "Name": "STAR WARS: THE CLONE WARS SEASON 1"
    },
    "PAR": {
        "Den": 1,
        "Num": 1
    },
    "SequenceID": 0,
    "Source": {
        "Angle": 0,
        "Path": "/home/sirjorj/enc/in/s1e01.mkv",
        "Range": {
            "End": 1,
            "Start": 1,
            "Type": "chapter"
        },
        "Title": 1
    },
    "Subtitle": {
        "Search": {
            "Burn": false,
            "Default": true,
            "Enable": true,
            "Forced": true
        },
        "SubtitleList": [
            {
                "Burn": true,
                "Default": false,
                "Forced": false,
                "Track": 0
            }
        ]
    },
    "Video": {
        "ColorMatrixCode": 0,
        "Encoder": "x264",
        "OpenCL": false,
        "Options": "ref=9:bframes=16:me=umh:subme=10:direct=auto:merange=64:b-adapt=2:deblock=-1,-1:partitions=all:trellis=2:psy-rd=1|0.15",
        "QSV": {
            "AsyncDepth": 4,
            "Decode": false
        },
        "Quality": 16.0,
        "Turbo": false,
        "TwoPass": false
    }
}
[19:10:37] CPU: Intel(R) Xeon(R) CPU           X7560  @ 2.27GHz
[19:10:37]  - logical processor count: 32
[19:10:37] hb_scan: path=/home/sirjorj/enc/in/s1e01.mkv, title_index=1
udfread ERROR: ECMA 167 Volume Recognition failed
disc.c:274: failed opening UDF image /home/sirjorj/enc/in/s1e01.mkv
disc.c:352: error opening file BDMV/index.bdmv
disc.c:352: error opening file BDMV/BACKUP/index.bdmv
[19:10:37] bd: not a bd - trying as a stream/file instead
libdvdnav: Using dvdnav version 5.0.1
libdvdread: Encrypted DVD support unavailable.
libdvdread:DVDOpenFileUDF:UDFFindFile /VIDEO_TS/VIDEO_TS.IFO failed
libdvdread:DVDOpenFileUDF:UDFFindFile /VIDEO_TS/VIDEO_TS.BUP failed
libdvdread: Can't open file VIDEO_TS.IFO.
libdvdnav: vm: failed to read VIDEO_TS.IFO
[19:10:37] dvd: not a dvd - trying as a stream/file instead
Input #0, matroska,webm, from '/home/sirjorj/enc/in/s1e01.mkv':
  Metadata:
    title           : STAR WARS: THE CLONE WARS SEASON 1
  Duration: 00:22:38.14, start: 0.000000, bitrate: N/A
    Chapter #0:0: start 0.000000, end 428.177750
    Metadata:
      title           : Chapter 01
    Chapter #0:1: start 428.177750, end 907.072833
    Metadata:
      title           : Chapter 02
    Chapter #0:2: start 907.072833, end 1317.065750
    Metadata:
      title           : Chapter 03
    Chapter #0:3: start 1317.065750, end 1358.144000
    Metadata:
      title           : Chapter 04
    Stream #0:0(eng): Video: vc1 (Advanced) [WVC1 / 0x31435657]
      yuv420p, bt709/bt709/bt709
      1920x1080 [PAR 1:1 DAR 16:9], PAR 1:1 DAR 16:9
      23.98 fps, 1k tbn
    Metadata:
      BPS-eng         : 10504949
      DURATION-eng    : 00:22:37.147458333
      NUMBER_OF_FRAMES-eng: 32539
      NUMBER_OF_BYTES-eng: 1782095031
      SOURCE_ID-eng   : 001011
      _STATISTICS_WRITING_APP-eng: MakeMKV v1.9.9 darwin(x86-release)
      _STATISTICS_WRITING_DATE_UTC-eng: 2016-01-19 00:59:03
      _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES SOURCE_ID
    Stream #0:1(eng): Audio: ac3
      48000 Hz, 5.1, fltp, 640 kb/s (default)
    Metadata:
      title           : Surround 5.1
      BPS-eng         : 640000
      DURATION-eng    : 00:22:38.176000000
      NUMBER_OF_FRAMES-eng: 42443
      NUMBER_OF_BYTES-eng: 108654080
      SOURCE_ID-eng   : 001100
      _STATISTICS_WRITING_APP-eng: MakeMKV v1.9.9 darwin(x86-release)
      _STATISTICS_WRITING_DATE_UTC-eng: 2016-01-19 00:59:03
      _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES SOURCE_ID
    Stream #0:2(eng): Subtitle: hdmv_pgs_subtitle
    Metadata:
      BPS-eng         : 37925
      DURATION-eng    : 00:22:16.272437500
      NUMBER_OF_FRAMES-eng: 504
      NUMBER_OF_BYTES-eng: 6334822
      SOURCE_ID-eng   : 001201
      _STATISTICS_WRITING_APP-eng: MakeMKV v1.9.9 darwin(x86-release)
      _STATISTICS_WRITING_DATE_UTC-eng: 2016-01-19 00:59:03
      _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES SOURCE_ID
[19:10:37] scan: decoding previews for title 1
[19:10:37] scan: audio 0x1: ac3, rate=48000Hz, bitrate=640000 English (AC3) (5.1 ch)
[19:10:38] scan: 10 previews, 1920x1080, 23.976 fps, autocrop = 132/132/0/0, aspect 16:9, PAR 1:1
[19:10:38] libhb: scan thread found 1 valid title(s)
[19:10:38] starting job
[19:10:38] decomb filter thread started for segment 1
[19:10:38] decomb filter thread started for segment 2
[19:10:38] decomb filter thread started for segment 0
[19:10:38] decomb filter thread started for segment 4
[19:10:38] decomb filter thread started for segment 3
[19:10:38] decomb filter thread started for segment 5
[19:10:38] decomb filter thread started for segment 6
[19:10:38] decomb filter thread started for segment 7
[19:10:38] decomb filter thread started for segment 8
[19:10:38] decomb filter thread started for segment 9
[19:10:38] decomb filter thread started for segment 10
[19:10:38] decomb filter thread started for segment 14
[19:10:38] decomb filter thread started for segment 15
[19:10:38] decomb filter thread started for segment 18
[19:10:38] decomb filter thread started for segment 11
[19:10:38] decomb filter thread started for segment 19
[19:10:38] decomb filter thread started for segment 13
[19:10:38] decomb filter thread started for segment 12
[19:10:38] decomb filter thread started for segment 16
[19:10:38] decomb filter thread started for segment 20
[19:10:38] decomb filter thread started for segment 22
[19:10:38] decomb filter thread started for segment 23
[19:10:38] decomb filter thread started for segment 26
[19:10:38] decomb filter thread started for segment 21
[19:10:38] decomb filter thread started for segment 24
[19:10:38] decomb check thread started for segment 1
[19:10:38] decomb check thread started for segment 2
[19:10:38] decomb check thread started for segment 4
[19:10:38] decomb filter thread started for segment 17
[19:10:38] decomb filter thread started for segment 27
[19:10:38] decomb check thread started for segment 7
[19:10:38] decomb check thread started for segment 10
[19:10:38] decomb check thread started for segment 12
[19:10:38] decomb check thread started for segment 13
[19:10:38] decomb check thread started for segment 14
[19:10:38] decomb check thread started for segment 16
[19:10:38] decomb check thread started for segment 6
[19:10:38] decomb check thread started for segment 5
[19:10:38] decomb check thread started for segment 19
[19:10:38] decomb check thread started for segment 23
[19:10:38] decomb check thread started for segment 24
[19:10:38] decomb filter thread started for segment 30
[19:10:38] decomb check thread started for segment 11
[19:10:38] decomb check thread started for segment 27
[19:10:38] decomb check thread started for segment 28
[19:10:38] decomb filter thread started for segment 28
[19:10:38] decomb filter thread started for segment 31
[19:10:38] decomb check thread started for segment 17
[19:10:38] mask filter thread started for segment 0
[19:10:38] decomb check thread started for segment 3
[19:10:38] mask filter thread started for segment 3
[19:10:38] decomb check thread started for segment 18
[19:10:38] mask filter thread started for segment 4
[19:10:38] decomb check thread started for segment 8
[19:10:38] decomb check thread started for segment 20
[19:10:38] mask filter thread started for segment 8
[19:10:38] mask filter thread started for segment 11
[19:10:38] mask filter thread started for segment 13
[19:10:38] decomb check thread started for segment 0
[19:10:38] mask filter thread started for segment 14
[19:10:38] mask filter thread started for segment 15
[19:10:38] decomb filter thread started for segment 29
[19:10:38] decomb check thread started for segment 25
[19:10:38] decomb check thread started for segment 15
[19:10:38] mask filter thread started for segment 19
[19:10:38] decomb check thread started for segment 31
[19:10:38] mask filter thread started for segment 21
[19:10:38] decomb filter thread started for segment 25
[19:10:38] mask filter thread started for segment 23
[19:10:38] mask filter thread started for segment 26
[19:10:38] mask filter thread started for segment 27
[19:10:38] mask filter thread started for segment 1
[19:10:38] mask filter thread started for segment 6
[19:10:38] mask filter thread started for segment 5
[19:10:38] mask erode thread started for segment 2
[19:10:38] mask erode thread started for segment 4
[19:10:38] mask erode thread started for segment 6
[19:10:38] mask erode thread started for segment 8
[19:10:38] mask filter thread started for segment 10
[19:10:38] decomb check thread started for segment 21
[19:10:38] mask erode thread started for segment 10
[19:10:38] mask erode thread started for segment 11
[19:10:38] mask filter thread started for segment 12
[19:10:38] mask erode thread started for segment 13
[19:10:38] mask filter thread started for segment 16
[19:10:38] mask erode thread started for segment 15
[19:10:38] mask erode thread started for segment 16
[19:10:38] mask erode thread started for segment 17
[19:10:38] mask erode thread started for segment 18
[19:10:38] decomb check thread started for segment 26
[19:10:38] mask erode thread started for segment 20
[19:10:38] mask filter thread started for segment 18
[19:10:38] mask erode thread started for segment 22
[19:10:38] mask erode thread started for segment 23
[19:10:38] decomb check thread started for segment 30
[19:10:38] mask filter thread started for segment 22
[19:10:38] mask erode thread started for segment 28
[19:10:38] mask erode thread started for segment 29
[19:10:38] mask filter thread started for segment 25
[19:10:38] mask dilate thread started for segment 1
[19:10:38] mask dilate thread started for segment 4
[19:10:38] mask dilate thread started for segment 5
[19:10:38] mask dilate thread started for segment 6
[19:10:38] mask erode thread started for segment 0
[19:10:38] mask erode thread started for segment 1
[19:10:38] mask erode thread started for segment 3
[19:10:38] mask dilate thread started for segment 9
[19:10:38] mask filter thread started for segment 7
[19:10:38] mask erode thread started for segment 5
[19:10:38] mask dilate thread started for segment 12
[19:10:38] mask erode thread started for segment 7
[19:10:38] mask dilate thread started for segment 14
[19:10:38] mask dilate thread started for segment 13
[19:10:38] decomb check thread started for segment 9
[19:10:38] mask dilate thread started for segment 19
[19:10:38] mask dilate thread started for segment 17
[19:10:38] mask erode thread started for segment 9
[19:10:38] mask erode thread started for segment 14
[19:10:38] decomb check thread started for segment 22
[19:10:38] mask erode thread started for segment 19
[19:10:38] mask erode thread started for segment 21
[19:10:38] mask dilate thread started for segment 27
[19:10:38] mask erode thread started for segment 24
[19:10:38] mask erode thread started for segment 25
[19:10:38] mask dilate thread started for segment 23
[19:10:38] mask erode thread started for segment 27
[19:10:38] yadif thread started for segment 1
[19:10:38] yadif thread started for segment 0
[19:10:38] mask filter thread started for segment 24
[19:10:38] mask erode thread started for segment 30
[19:10:38] mask erode thread started for segment 31
[19:10:38] mask dilate thread started for segment 0
[19:10:38] yadif thread started for segment 8
[19:10:38] mask dilate thread started for segment 2
[19:10:38] yadif thread started for segment 12
[19:10:38] mask dilate thread started for segment 3
[19:10:38] yadif thread started for segment 14
[19:10:38] mask filter thread started for segment 31
[19:10:38] mask dilate thread started for segment 7
[19:10:38] mask dilate thread started for segment 8
[19:10:38] yadif thread started for segment 15
[19:10:38] yadif thread started for segment 18
[19:10:38] yadif thread started for segment 19
[19:10:38] yadif thread started for segment 20
[19:10:38] decomb check thread started for segment 29
[19:10:38] yadif thread started for segment 3
[19:10:38] yadif thread started for segment 22
[19:10:38] yadif thread started for segment 24
[19:10:38] mask dilate thread started for segment 15
[19:10:38] yadif thread started for segment 25
[19:10:38] mask dilate thread started for segment 21
[19:10:38] mask dilate thread started for segment 18
[19:10:38] mask filter thread started for segment 17
[19:10:38] mask erode thread started for segment 12
[19:10:38] NLMeans using SSE2 optimizations
[19:10:38] mask dilate thread started for segment 25
[19:10:38] mask dilate thread started for segment 24
[19:10:38] NLMeans thread started for segment 6
[19:10:38] mask dilate thread started for segment 26
[19:10:38] NLMeans thread started for segment 5
[19:10:38] yadif thread started for segment 29
[19:10:38] NLMeans thread started for segment 9
[19:10:38] yadif thread started for segment 30
[19:10:38] NLMeans thread started for segment 10
[19:10:38] yadif thread started for segment 28
[19:10:38] NLMeans thread started for segment 11
[19:10:38] yadif thread started for segment 2
[19:10:38] mask dilate thread started for segment 31
[19:10:38] NLMeans thread started for segment 22
[19:10:38] mask filter thread started for segment 2
[19:10:38] NLMeans thread started for segment 25
[19:10:38] NLMeans thread started for segment 18
[19:10:38] NLMeans thread started for segment 21
[19:10:38] NLMeans thread started for segment 20
[19:10:38] mask filter thread started for segment 28
[19:10:38] NLMeans thread started for segment 28
[19:10:38] NLMeans thread started for segment 29
[19:10:38] mask filter thread started for segment 29
[19:10:38] job configuration:
[19:10:38]  * source
[19:10:38]    + /home/sirjorj/enc/in/s1e01.mkv
[19:10:38]    + title 1, chapter(s) 1 to 1
[19:10:38]    + container: matroska,webm
[19:10:38]  * destination
[19:10:38]    + /home/sirjorj/enc/out/s1e01.mp4
[19:10:38]    + container: MPEG-4 (libavformat)
[19:10:38]      + optimized for HTTP streaming (fast start)
[19:10:38]  * video track
[19:10:38]    + decoder: vc1
[19:10:38]    + filters
[19:10:38] NLMeans thread started for segment 31
[19:10:38] yadif thread started for segment 4
[19:10:38] yadif thread started for segment 5
[19:10:38] yadif thread started for segment 6
[19:10:38] yadif thread started for segment 9
[19:10:38] yadif thread started for segment 13
[19:10:38] yadif thread started for segment 16
[19:10:38] yadif thread started for segment 23
[19:10:38] mask dilate thread started for segment 11
[19:10:38] mask dilate thread started for segment 16
[19:10:38] mask filter thread started for segment 9
[19:10:38] yadif thread started for segment 26
[19:10:38] yadif thread started for segment 27
[19:10:38] mask dilate thread started for segment 20
[19:10:38] NLMeans thread started for segment 3
[19:10:38] mask filter thread started for segment 20
[19:10:38] mask dilate thread started for segment 29
[19:10:38] NLMeans thread started for segment 8
[19:10:38] NLMeans thread started for segment 2
[19:10:38] NLMeans thread started for segment 4
[19:10:38] NLMeans thread started for segment 7
[19:10:38] mask dilate thread started for segment 28
[19:10:38] yadif thread started for segment 31
[19:10:38] mask dilate thread started for segment 22
[19:10:38] NLMeans thread started for segment 0
[19:10:38] NLMeans thread started for segment 1
[19:10:38] mask dilate thread started for segment 30
[19:10:38] mask erode thread started for segment 26
[19:10:38] NLMeans thread started for segment 16
[19:10:38] NLMeans thread started for segment 17
[19:10:38] NLMeans thread started for segment 23
[19:10:38] NLMeans thread started for segment 24
[19:10:38] yadif thread started for segment 7
[19:10:38] NLMeans thread started for segment 19
[19:10:38] NLMeans thread started for segment 26
[19:10:38] NLMeans thread started for segment 27
[19:10:38] NLMeans thread started for segment 13
[19:10:38] NLMeans thread started for segment 14
[19:10:38] NLMeans thread started for segment 15
[19:10:38] yadif thread started for segment 11
[19:10:38] yadif thread started for segment 10
[19:10:38] NLMeans thread started for segment 12
[19:10:38] mask filter thread started for segment 30
[19:10:38] NLMeans thread started for segment 30
[19:10:38] yadif thread started for segment 17
[19:10:38] mask dilate thread started for segment 10
[19:10:38]      + Detelecine (pullup) (skip-left=1:skip-right=1:skip-top=4:skip-bottom=4:plane=0)
[19:10:38]      + Comb Detect (mode=3:spatial-metric=2:motion-thresh=1:spatial-thresh=1:filter-mode=2:block-thresh=40:block-width=16:block-height=16)
[19:10:38]      + Decomb (mode=39)
[19:10:38] yadif thread started for segment 21
[19:10:38]      + Framerate Shaper (mode=0)
[19:10:38]        + frame rate: same as source (around 23.976 fps)
[19:10:38]      + Denoise (nlmeans) (y-strength=1.5:y-origin-tune=0.9:y-patch-size=7:y-range=3:y-frame-count=2:y-prefilter=0:cb-strength=2.4:cb-origin-tune=0.9:cb-patch-size=7:cb-range=3:cb-frame-count=2:cb-prefilter=0)
[19:10:38]      + Crop and Scale (width=1916:height=956:crop-top=64:crop-bottom=60:crop-left=2:crop-right=2)
[19:10:38]        + source: 1920 * 1080, crop (64/60/2/2): 1916 * 956, scale: 1916 * 956
[19:10:38]    + Output geometry
[19:10:38]      + storage dimensions: 1916 x 956
[19:10:38]      + pixel aspect ratio: 1 : 1
[19:10:38]      + display dimensions: 1916 x 956
[19:10:38]  * Foreign Audio Search: Passthrough, Forced Only, Default
[19:10:38]    + subtitle, English [PGS] (track 0, id 0x2, Picture)
[19:10:38] sync: expecting 10265 video frames
[19:10:38] reader: end of chapter 1 (media 1) reached at media chapter 2
[19:10:38] reader: done. 1 scr changes
[19:10:38] work: average encoding speed for job is 0.000000 fps
[19:10:38] comb detect: heavy 0 | light 0 | uncombed 0 | total 0
[19:10:38] decomb: deinterlaced 0 | blended 0 | unfiltered 0 | total 0
[19:10:38] vfr: lost time: 0 (0 frames)
[19:10:38] vfr: gained time: 0 (0 frames) (0 not accounted for)
[19:10:39] vc1-decoder done: 0 frames, 0 decoder errors
[19:10:39] sync: got 0 frames, 10265 expected
[19:10:39] Subtitle track 0 (id 0x2) 'English [PGS]': 91 hits (0 forced)
[19:10:39] No candidate detected during subtitle scan
[19:10:39] starting job
[19:10:39] decomb filter thread started for segment 1
[19:10:39] decomb filter thread started for segment 0
[19:10:39] decomb filter thread started for segment 3
[19:10:39] decomb filter thread started for segment 2
[19:10:39] decomb filter thread started for segment 4
[19:10:39] decomb filter thread started for segment 5
[19:10:39] decomb filter thread started for segment 7
[19:10:39] decomb filter thread started for segment 6
[19:10:39] decomb filter thread started for segment 8
[19:10:39] decomb filter thread started for segment 9
[19:10:39] decomb filter thread started for segment 10
[19:10:39] decomb filter thread started for segment 12
[19:10:39] decomb filter thread started for segment 11
[19:10:39] decomb filter thread started for segment 13
[19:10:39] decomb filter thread started for segment 15
[19:10:39] decomb filter thread started for segment 14
[19:10:39] decomb filter thread started for segment 17
[19:10:39] decomb filter thread started for segment 16
[19:10:39] decomb filter thread started for segment 20
[19:10:39] decomb filter thread started for segment 19
[19:10:39] decomb filter thread started for segment 21
[19:10:39] decomb filter thread started for segment 22
[19:10:39] decomb filter thread started for segment 23
[19:10:39] decomb filter thread started for segment 18
[19:10:39] decomb filter thread started for segment 28
[19:10:39] decomb filter thread started for segment 25
[19:10:39] decomb filter thread started for segment 29
[19:10:39] decomb filter thread started for segment 27
[19:10:39] decomb filter thread started for segment 31
[19:10:39] decomb filter thread started for segment 30
[19:10:39] decomb filter thread started for segment 24
[19:10:39] decomb filter thread started for segment 26
[19:10:39] decomb check thread started for segment 2
[19:10:39] decomb check thread started for segment 4
[19:10:39] decomb check thread started for segment 0
[19:10:39] decomb check thread started for segment 6
[19:10:39] decomb check thread started for segment 1
[19:10:39] decomb check thread started for segment 3
[19:10:39] decomb check thread started for segment 5
[19:10:39] decomb check thread started for segment 8
[19:10:39] decomb check thread started for segment 7
[19:10:39] decomb check thread started for segment 11
[19:10:39] decomb check thread started for segment 9
[19:10:39] decomb check thread started for segment 10
[19:10:39] decomb check thread started for segment 12
[19:10:39] decomb check thread started for segment 13
[19:10:39] decomb check thread started for segment 19
[19:10:39] decomb check thread started for segment 16
[19:10:39] decomb check thread started for segment 18
[19:10:39] decomb check thread started for segment 15
[19:10:39] decomb check thread started for segment 17
[19:10:39] decomb check thread started for segment 25
[19:10:39] decomb check thread started for segment 24
[19:10:39] decomb check thread started for segment 14
[19:10:39] decomb check thread started for segment 21
[19:10:39] decomb check thread started for segment 26
[19:10:39] decomb check thread started for segment 20
[19:10:39] decomb check thread started for segment 27
[19:10:39] decomb check thread started for segment 28
[19:10:39] decomb check thread started for segment 29
[19:10:39] decomb check thread started for segment 30
[19:10:39] mask filter thread started for segment 0
[19:10:39] mask filter thread started for segment 2
[19:10:39] mask filter thread started for segment 1
[19:10:39] decomb check thread started for segment 31
[19:10:39] mask filter thread started for segment 3
[19:10:39] mask filter thread started for segment 4
[19:10:39] decomb check thread started for segment 23
[19:10:39] mask filter thread started for segment 12
[19:10:39] mask filter thread started for segment 11
[19:10:39] mask filter thread started for segment 9
[19:10:39] mask filter thread started for segment 7
[19:10:39] mask filter thread started for segment 15
[19:10:39] mask filter thread started for segment 5
[19:10:39] decomb check thread started for segment 22
[19:10:39] mask filter thread started for segment 14
[19:10:39] mask filter thread started for segment 6
[19:10:39] mask filter thread started for segment 10
[19:10:39] mask filter thread started for segment 13
[19:10:39] mask filter thread started for segment 8
[19:10:39] mask filter thread started for segment 16
[19:10:39] mask filter thread started for segment 17
[19:10:39] mask filter thread started for segment 18
[19:10:39] mask filter thread started for segment 20
[19:10:39] mask filter thread started for segment 19
[19:10:39] mask filter thread started for segment 21
[19:10:39] mask filter thread started for segment 22
[19:10:39] mask filter thread started for segment 23
[19:10:39] mask filter thread started for segment 24
[19:10:39] mask filter thread started for segment 25
[19:10:39] mask filter thread started for segment 27
[19:10:39] mask filter thread started for segment 26
[19:10:39] mask filter thread started for segment 28
[19:10:39] mask filter thread started for segment 29
[19:10:39] mask filter thread started for segment 30
[19:10:39] mask filter thread started for segment 31
[19:10:39] mask erode thread started for segment 0
[19:10:39] mask erode thread started for segment 1
[19:10:39] mask erode thread started for segment 3
[19:10:39] mask erode thread started for segment 2
[19:10:39] mask erode thread started for segment 6
[19:10:39] mask erode thread started for segment 7
[19:10:39] mask erode thread started for segment 4
[19:10:39] mask erode thread started for segment 8
[19:10:39] mask erode thread started for segment 10
[19:10:39] mask erode thread started for segment 11
[19:10:39] mask erode thread started for segment 5
[19:10:39] mask erode thread started for segment 12
[19:10:39] mask erode thread started for segment 13
[19:10:39] mask erode thread started for segment 14
[19:10:39] mask erode thread started for segment 15
[19:10:39] mask erode thread started for segment 9
[19:10:39] mask erode thread started for segment 16
[19:10:39] mask erode thread started for segment 17
[19:10:39] mask erode thread started for segment 19
[19:10:39] mask erode thread started for segment 18
[19:10:39] mask erode thread started for segment 20
[19:10:39] mask erode thread started for segment 21
[19:10:39] mask erode thread started for segment 22
[19:10:39] mask erode thread started for segment 24
[19:10:39] mask erode thread started for segment 23
[19:10:39] mask erode thread started for segment 29
[19:10:39] mask erode thread started for segment 30
[19:10:39] mask erode thread started for segment 31
[19:10:39] mask dilate thread started for segment 0
[19:10:39] mask erode thread started for segment 27
[19:10:39] mask erode thread started for segment 28
[19:10:39] mask dilate thread started for segment 1
[19:10:39] mask erode thread started for segment 26
[19:10:39] mask erode thread started for segment 25
[19:10:39] mask dilate thread started for segment 2
[19:10:39] mask dilate thread started for segment 3
[19:10:39] mask dilate thread started for segment 5
[19:10:39] mask dilate thread started for segment 6
[19:10:39] mask dilate thread started for segment 7
[19:10:39] mask dilate thread started for segment 4
[19:10:39] mask dilate thread started for segment 8
[19:10:39] mask dilate thread started for segment 10
[19:10:39] mask dilate thread started for segment 9
[19:10:39] mask dilate thread started for segment 12
[19:10:39] mask dilate thread started for segment 11
[19:10:39] mask dilate thread started for segment 13
[19:10:39] mask dilate thread started for segment 14
[19:10:39] mask dilate thread started for segment 15
[19:10:39] mask dilate thread started for segment 17
[19:10:39] mask dilate thread started for segment 16
[19:10:39] mask dilate thread started for segment 18
[19:10:39] mask dilate thread started for segment 19
[19:10:39] mask dilate thread started for segment 20
[19:10:39] mask dilate thread started for segment 21
[19:10:39] mask dilate thread started for segment 23
[19:10:39] mask dilate thread started for segment 22
[19:10:39] mask dilate thread started for segment 24
[19:10:39] mask dilate thread started for segment 26
[19:10:39] mask dilate thread started for segment 28
[19:10:39] mask dilate thread started for segment 27
[19:10:39] mask dilate thread started for segment 30
[19:10:39] mask dilate thread started for segment 29
[19:10:39] mask dilate thread started for segment 25
[19:10:39] yadif thread started for segment 0
[19:10:39] mask dilate thread started for segment 31
[19:10:39] yadif thread started for segment 1
[19:10:39] yadif thread started for segment 3
[19:10:39] yadif thread started for segment 4
[19:10:39] yadif thread started for segment 2
[19:10:39] yadif thread started for segment 5
[19:10:39] yadif thread started for segment 8
[19:10:39] yadif thread started for segment 7
[19:10:39] yadif thread started for segment 11
[19:10:39] yadif thread started for segment 6
[19:10:39] yadif thread started for segment 10
[19:10:39] yadif thread started for segment 9
[19:10:39] yadif thread started for segment 12
[19:10:39] yadif thread started for segment 13
[19:10:39] yadif thread started for segment 14
[19:10:39] yadif thread started for segment 18
[19:10:39] yadif thread started for segment 15
[19:10:39] yadif thread started for segment 16
[19:10:39] yadif thread started for segment 19
[19:10:39] yadif thread started for segment 17
[19:10:39] yadif thread started for segment 20
[19:10:39] yadif thread started for segment 21
[19:10:39] yadif thread started for segment 23
[19:10:39] yadif thread started for segment 22
[19:10:39] yadif thread started for segment 25
[19:10:39] yadif thread started for segment 24
[19:10:39] yadif thread started for segment 26
[19:10:39] yadif thread started for segment 27
[19:10:39] yadif thread started for segment 28
[19:10:39] NLMeans using SSE2 optimizations
[19:10:39] yadif thread started for segment 31
[19:10:39] yadif thread started for segment 30
[19:10:39] yadif thread started for segment 29
[19:10:39] NLMeans thread started for segment 0
[19:10:39] NLMeans thread started for segment 1
[19:10:39] NLMeans thread started for segment 4
[19:10:39] NLMeans thread started for segment 2
[19:10:39] NLMeans thread started for segment 5
[19:10:39] NLMeans thread started for segment 3
[19:10:39] NLMeans thread started for segment 6
[19:10:39] NLMeans thread started for segment 8
[19:10:39] NLMeans thread started for segment 7
[19:10:39] NLMeans thread started for segment 9
[19:10:39] NLMeans thread started for segment 10
[19:10:39] NLMeans thread started for segment 12
[19:10:39] NLMeans thread started for segment 11
[19:10:39] NLMeans thread started for segment 13
[19:10:39] NLMeans thread started for segment 14
[19:10:39] NLMeans thread started for segment 15
[19:10:39] NLMeans thread started for segment 16
[19:10:39] NLMeans thread started for segment 17
[19:10:39] NLMeans thread started for segment 18
[19:10:39] NLMeans thread started for segment 19
[19:10:39] NLMeans thread started for segment 20
[19:10:39] NLMeans thread started for segment 22
[19:10:39] NLMeans thread started for segment 23
[19:10:39] NLMeans thread started for segment 21
[19:10:39] NLMeans thread started for segment 24
[19:10:39] NLMeans thread started for segment 25
[19:10:39] NLMeans thread started for segment 29
[19:10:39] NLMeans thread started for segment 28
[19:10:39] NLMeans thread started for segment 31
[19:10:39] NLMeans thread started for segment 27
[19:10:39] job configuration:
[19:10:39]  * source
[19:10:39]    + /home/sirjorj/enc/in/s1e01.mkv
[19:10:39]    + title 1, chapter(s) 1 to 1
[19:10:39]    + container: matroska,webm
[19:10:39]  * destination
[19:10:39]    + /home/sirjorj/enc/out/s1e01.mp4
[19:10:39] NLMeans thread started for segment 30
[19:10:39] NLMeans thread started for segment 26
[19:10:39]    + container: MPEG-4 (libavformat)
[19:10:39]      + optimized for HTTP streaming (fast start)
[19:10:39]  * video track
[19:10:39]    + decoder: vc1
[19:10:39]    + filters
[19:10:39]      + Detelecine (pullup) (skip-left=1:skip-right=1:skip-top=4:skip-bottom=4:plane=0)
[19:10:39]      + Comb Detect (mode=3:spatial-metric=2:motion-thresh=1:spatial-thresh=1:filter-mode=2:block-thresh=40:block-width=16:block-height=16)
[19:10:39]      + Decomb (mode=39)
[19:10:39]      + Framerate Shaper (mode=0)
[19:10:39]        + frame rate: same as source (around 23.976 fps)
[19:10:39]      + Denoise (nlmeans) (y-strength=1.5:y-origin-tune=0.9:y-patch-size=7:y-range=3:y-frame-count=2:y-prefilter=0:cb-strength=2.4:cb-origin-tune=0.9:cb-patch-size=7:cb-range=3:cb-frame-count=2:cb-prefilter=0)
[19:10:39]      + Subtitle renderer ()
[19:10:39]      + Crop and Scale (width=1916:height=956:crop-top=64:crop-bottom=60:crop-left=2:crop-right=2)
[19:10:39]        + source: 1920 * 1080, crop (64/60/2/2): 1916 * 956, scale: 1916 * 956
[19:10:39]    + Output geometry
[19:10:39]      + storage dimensions: 1916 x 956
[19:10:39]      + pixel aspect ratio: 1 : 1
[19:10:39]      + display dimensions: 1916 x 956
[19:10:39]    + encoder: H.264 (libx264)
[19:10:39]      + options: ref=9:bframes=16:me=umh:subme=10:direct=auto:merange=64:b-adapt=2:deblock=-1,-1:partitions=all:trellis=2:psy-rd=1|0.15
[19:10:39]      + quality: 16.00 (RF)
[19:10:39]  * subtitle track 1, English [PGS] (track 0, id 0x2, Picture) -> Render/Burn-in
[19:10:39]  * audio track 1
[19:10:39]    + decoder: English (AC3) (5.1 ch) (track 1, id 0x1)
[19:10:39]      + bitrate: 640 kbps, samplerate: 48000 Hz
[19:10:39]    + mixdown: Dolby Pro Logic II
[19:10:39]    + dither: triangular
[19:10:39]    + encoder: AAC (libfdk_aac)
[19:10:39]      + bitrate: 384 kbps, samplerate: 48000 Hz
[19:10:39]  * audio track 2
[19:10:39]    + decoder: English (AC3) (5.1 ch) (track 1, id 0x1)
[19:10:39]      + bitrate: 640 kbps, samplerate: 48000 Hz
[19:10:39]    + AC3 Passthru
[19:10:39]  * audio track 3
[19:10:39]    + decoder: English (AC3) (5.1 ch) (track 1, id 0x1)
[19:10:39]      + bitrate: 640 kbps, samplerate: 48000 Hz
[19:10:39]    + mixdown: Stereo
[19:10:39]    + dither: triangular
[19:10:39]    + encoder: HE-AAC (libfdk_aac)
[19:10:39]      + bitrate: 64 kbps, samplerate: 48000 Hz
[19:10:39] sync: expecting 10265 video frames
[19:10:39] encx264: min-keyint: 24, keyint: 240
[19:10:39] encx264: encoding at constant RF 16.000000
[19:10:39] encx264: unparsed options: ref=9:bframes=16:me=umh:subme=10:direct=auto:merange=64:b-adapt=2:deblock=-1,-1:analyse=all:trellis=2:psy-rd=1,0.15
x264 [info]: using SAR=1/1
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2
x264 [info]: profile High, level 5.0
[19:10:39] sync: first pts video is 0
[19:10:39] sync: "Chapter 1" (1) at frame 1 time 0
[19:10:39] sync: first pts audio 0x1 is 0
[19:10:39] sync: first pts audio 0x1 is 0
[19:10:39] sync: first pts audio 0x1 is 0
[19:11:22] sync: first pts subtitle 0x2 is 1692900
[19:34:51] reader: end of chapter 1 (media 1) reached at media chapter 2
[19:34:54] reader: done. 1 scr changes
[19:35:32] work: average encoding speed for job is 7.007217 fps
[19:35:33] comb detect: heavy 978 | light 1573 | uncombed 7714 | total 10265
[19:35:33] decomb: deinterlaced 978 | blended 1573 | unfiltered 7714 | total 10265
[19:35:33] vfr: lost time: 7508 (0 frames)
[19:35:33] vfr: gained time: 7508 (8 frames) (0 not accounted for)
[19:35:33] ac3-decoder done: 13381 frames, 0 decoder errors
[19:35:33] ac3-decoder done: 13381 frames, 0 decoder errors
[19:35:33] ac3-decoder done: 13381 frames, 0 decoder errors
[19:35:33] vc1-decoder done: 10267 frames, 0 decoder errors
[19:35:33] sync: got 10267 frames, 10265 expected
[19:35:33] sync: framerate min 23.981 fps, max 23.981 fps, avg 23.976 fps
x264 [info]: frame I:80    Avg QP:10.52  size:220441
x264 [info]: frame P:3016  Avg QP:14.39  size: 49606
x264 [info]: frame B:7169  Avg QP:18.58  size: 16361
x264 [info]: consecutive B-frames:  7.2%  7.7% 16.1% 28.8% 12.1% 17.1%  3.8%  2.0%  0.8%  0.9%  0.2%  0.2%  0.3%  1.9%  0.3%  0.0%  0.5%
x264 [info]: mb I  I16..4: 19.8% 49.4% 30.9%
x264 [info]: mb P  I16..4:  3.7% 12.3%  2.8%  P16..4: 31.9% 13.8% 11.2%  0.5%  0.3%    skip:23.5%
x264 [info]: mb B  I16..4:  0.5%  1.2%  0.3%  B16..8: 29.3%  7.2%  1.5%  direct: 3.4%  skip:56.5%  L0:46.1% L1:43.5% BI:10.4%
x264 [info]: 8x8 transform intra:62.8% inter:53.6%
x264 [info]: direct mvs  spatial:99.5% temporal:0.5%
x264 [info]: coded y,uvDC,uvAC intra: 61.4% 63.0% 38.2% inter: 12.0% 11.8% 3.0%
x264 [info]: i16 v,h,dc,p: 38% 27%  6% 29%
x264 [info]: i8 v,h,dc,ddl,ddr,vr,hd,vl,hu: 11% 18% 20%  6%  9%  8% 11%  7% 11%
x264 [info]: i4 v,h,dc,ddl,ddr,vr,hd,vl,hu:  9% 31% 10%  6% 11%  8% 11%  6%  8%
x264 [info]: i8c dc,h,v,p: 41% 34% 15% 11%
x264 [info]: Weighted P-Frames: Y:0.6% UV:0.4%
x264 [info]: ref P L0: 54.7%  6.5% 15.7%  6.2%  5.0%  3.7%  3.4%  2.3%  2.2%  0.4%  0.0%
x264 [info]: ref B L0: 73.1% 11.6%  6.0%  3.2%  2.3%  1.9%  1.4%  0.5%
x264 [info]: ref B L1: 95.6%  4.4%
x264 [info]: kb/s:5315.78
[19:35:33] mux: track 0, 10265 frames, 284536598 bytes, 5315.72 kbps, fifo 512
[19:35:33] mux: track 1, 20073 frames, 20554753 bytes, 384.00 kbps, fifo 2048
[19:35:33] mux: track 2, 13381 frames, 34255360 bytes, 639.96 kbps, fifo 1024
[19:35:33] mux: track 3, 10038 frames, 3426379 bytes, 64.01 kbps, fifo 1024
[19:35:33] libhb: work result = 0
rollin_eng
Veteran User
Posts: 4840
Joined: Wed May 04, 2011 11:06 pm

Re: Strange performance on high core count machine

Post by rollin_eng »

It looks like you have a bunch of filters running which could affect performance.

Also your source and destination drive appear to be the same, this could also affect your encode speed.
sirjorj
Posts: 7
Joined: Mon Nov 12, 2007 5:38 am

Re: Strange performance on high core count machine

Post by sirjorj »

I am expecting a fairly low fps. I was not expecting the cpu idle time in bursts while it is encoding. I’m just curious where the bottleneck is.

The drive is a raid array. I have seen the same behavior on this machine when running from a ramdisk so i doubt the bottleneck is in the drives.
User avatar
s55
HandBrake Team
Posts: 10350
Joined: Sun Dec 24, 2006 1:05 pm

Re: Strange performance on high core count machine

Post by s55 »

Filtering is probably going to be the main cause. NLMeans will really slow things down. It's very complex operation so it's slow as a filter.

Do you really need all those filters on? It's a bit suspicious. Particularly decomb / detelecine. Are you sure the source is interlaced? If not turn those off.

NLMeans can't be sped up an awful lot. It's just slow so if you want quality denoising, that's the price you pay for that.
rollin_eng
Veteran User
Posts: 4840
Joined: Wed May 04, 2011 11:06 pm

Re: Strange performance on high core count machine

Post by rollin_eng »

Your best bet is to turn the filters on one at a time and see if/when you get a big performance hit.
User avatar
BradleyS
Moderator
Posts: 1860
Joined: Thu Aug 09, 2007 12:16 pm

Re: Strange performance on high core count machine

Post by BradleyS »

NLMeans is memory bound on most machines, so your CPU is probably waiting on IO.
User avatar
JohnAStebbins
HandBrake Team
Posts: 5712
Joined: Sat Feb 09, 2008 7:21 pm

Re: Strange performance on high core count machine

Post by JohnAStebbins »

The detelecine filter is single threaded. So that filter would be my guess for the source of this behaviour. Try disabling it.

The denoise filter queues up a collection of frames, then launches a parallel filter on all the frames. So if there is something that is even a little bit slower than denoise in the pipeline before it, it's input queue can run dry and show the behaviour you see.

Also, it's generally not a good idea to run the detelecine filter unless you *know* that your source is *hard* telecined. The video fps of 23.98 indicates the source is probably not telecined (or interlaced for that matter). I wouldn't run either detelecine or decomb in this case.
sirjorj
Posts: 7
Joined: Mon Nov 12, 2007 5:38 am

Re: Strange performance on high core count machine

Post by sirjorj »

Excellent info. There are some setting here that are probably more useful on old dvds than modern blurays. I will reevaluate some of these.

More importantly, i have a better idea of how the processing workflow goes so thank you much for that!
Woodstock
Veteran User
Posts: 4614
Joined: Tue Aug 27, 2013 6:39 am

Re: Strange performance on high core count machine

Post by Woodstock »

Just remember that there ARE some telecined, interlaced BD sources out there. Much of the catalog from NISAmerica is like that.

But those are the exception. My personal presets for BD sources have most filters turned off.
Post Reply