Feature Request: Handbrake-style logging

Musicvid wrote on 2/6/2017, 3:15 PM

Verbose, but human readable. As I and now jd have discovered, they can be quite a troubleshooting tool in the hands of experienced others.

Comments

john_dennis wrote on 2/6/2017, 4:16 PM

I agree that human readable logs can make complicated debug transactions go quicker. Usually, one can't get me to look at a log any more because, for me, it's like taking a time machine back to the 1970s. Once you get me to open one, I bore-in like a tick and you can't pull me out without me losing my head.

This weekend, I was very impressed with how quickly an experienced user identified my issue and how easy it was for me to identify different encoding settings and finish my benchmark. I was doing a benchmark for my new i7-6850K machine and all renders from Vegas Pro showed improvement except Vegas2Handbrake. In the version changes from the old machine to the new machine, the Handbrake presets changed significantly. Analysis of the logs by someone familiar with the program exposed the differences right away.

If you're vaguely interested in the difference between an i7-3770K and an i7-6850K or log analysis the link to the thread is here.

NickHope wrote on 2/6/2017, 9:08 PM

Verbose, but human readable. As I and now jd have discovered, they can be quite a troubleshooting tool in the hands of experienced others.

Can you post an example please?

john_dennis wrote on 2/6/2017, 9:15 PM

HandBrake 1.0.2 (2017012200) - 64bit
OS: Microsoft Windows NT 6.1.7601 Service Pack 1 - 64bit
CPU: Intel(R) Core(TM) i7-6850K CPU @ 3.60GHz
Ram: 16294 MB,
GPU Information:
  Radeon (TM) RX 480 Graphics - 21.19.407.0
Screen: 1680x1050
Temp Dir: C:\Users\John\AppData\Local\Temp\
Install Dir: C:\Program Files\HandBrake
Data Dir: C:\Users\John\AppData\Roaming\HandBrake Team\HandBrake\1.0.2.0

-------------------------------------------


# Starting Encode ...

[16:08:27] hb_init: starting libhb thread
[16:08:28] 1 job(s) to process
[16:08:28] json job:
{
  "Audio": {
    "AudioList": [
      {
        "Bitrate": 384,
        "DRC": 0.0,
        "Encoder": 65536,
        "Gain": 0.0,
        "Mixdown": 4,
        "NormalizeMixLevel": false,
        "Samplerate": 0,
        "Track": 0,
        "DitherMethod": 0
      }
    ],
    "CopyMask": [
      1073807360,
      1073743872,
      1074003968,
      1073750016,
      1090519040,
      1074790400,
      1074266112,
      1107296256
    ],
    "FallbackEncoder": 65536
  },
  "Destination": {
    "ChapterList": [
      {
        "Name": "Chapter 1"
      }
    ],
    "ChapterMarkers": true,
    "File": "E:\\2017-01-31 Buddy\\Rendered Output\\2017-01-31 Buddy.mp4",
    "Mp4Options": {
      "IpodAtom": false,
      "Mp4Optimize": true
    },
    "Mux": 131072
  },
  "Filters": {
    "FilterList": [
      {
        "ID": 7,
        "Settings": {
          "qp": "5"
        }
      },
      {
        "ID": 11,
        "Settings": {
          "crop-bottom": "0",
          "crop-left": "0",
          "crop-right": "0",
          "crop-top": "0",
          "height": "1080",
          "width": "1920"
        }
      },
      {
        "ID": 6,
        "Settings": {
          "mode": "1",
          "rate": "27000000/1126125"
        }
      }
    ]
  },
  "PAR": {
    "Num": 1,
    "Den": 1
  },
  "Metadata": {},
  "SequenceID": 0,
  "Source": {
    "Angle": 1,
    "Range": {
      "Type": "chapter",
      "Start": 1,
      "End": 1
    },
    "Title": 1,
    "Path": "C:\\Volumes\\vegas.avs\\vegas.avi"
  },
  "Subtitle": {
    "Search": {
      "Burn": false,
      "Default": false,
      "Enable": false,
      "Forced": false
    },
    "SubtitleList": []
  },
  "Video": {
    "Encoder": 65536,
    "Level": "4.0",
    "TwoPass": false,
    "Turbo": false,
    "ColorMatrixCode": 0,
    "Options": "ref=5:bframes=5",
    "Preset": "veryslow",
    "Profile": "high",
    "Quality": 18.0,
    "OpenCL": false,
    "HWDecode": false,
    "QSV": {
      "Decode": false,
      "AsyncDepth": 0
    }
  }
}
[16:08:28] CPU: Intel(R) Core(TM) i7-6850K CPU @ 3.60GHz
[16:08:28]  - Intel microarchitecture Broadwell
[16:08:28]  - logical processor count: 12
[16:08:28] Intel Quick Sync Video support: no
[16:08:28] hb_scan: path=C:\Volumes\vegas.avs\vegas.avi, title_index=1
udfread ERROR: ECMA 167 Volume Recognition failed
src/libbluray/disc/disc.c:274: failed opening UDF image C:\Volumes\vegas.avs\vegas.avi
src/libbluray/disc/disc.c:352: error opening file BDMV\index.bdmv
src/libbluray/disc/disc.c:352: error opening file BDMV\BACKUP\index.bdmv
[16:08:28] 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
[16:08:28] dvd: not a dvd - trying as a stream/file instead
Input #0, avi, from 'C:\Volumes\vegas.avs\vegas.avi':
  Duration: 00:03:22.28, start: 0.000000, bitrate: 796943 kb/s
    Stream #0:0: Video: rawvideo [YUY2 / 0x32595559]
      yuyv422, 1920x1080
      23.98 fps, 23.98 tbn
    Stream #0:1: Audio: pcm_s16le [[1][0][0][0] / 0x0001]
      44100 Hz, 2 channels, s16, 1411 kb/s
[16:08:28] scan: decoding previews for title 1
[16:08:28] scan: audio 0x1: pcm_s16le, rate=44100Hz, bitrate=1411200 Unknown (pcm_s16le) (2.0 ch)
[16:08:29] scan: 10 previews, 1920x1080, 23.976 fps, autocrop = 0/0/0/0, aspect 16:9, PAR 1:1
[16:08:29] libhb: scan thread found 1 valid title(s)
[16:08:29] starting job
[16:08:29] work: track 1, dithering not supported by codec
[16:08:29] work: only 1 chapter, disabling chapter markers
[16:08:29] job configuration:
[16:08:29]  * source
[16:08:29]    + C:\Volumes\vegas.avs\vegas.avi
[16:08:29]    + title 1, chapter(s) 1 to 1
[16:08:29]    + container: avi
[16:08:29]    + data rate: 796943 kbps
[16:08:29]  * destination
[16:08:29]    + E:\2017-01-31 Buddy\Rendered Output\2017-01-31 Buddy.mp4
[16:08:29]    + container: MPEG-4 (libavformat)
[16:08:29]      + optimized for HTTP streaming (fast start)
[16:08:29]  * video track
[16:08:29]    + decoder: rawvideo
[16:08:29]    + filters
[16:08:29]      + Framerate Shaper (mode=1:rate=27000000/1126125)
[16:08:29]        + frame rate: 23.976 fps -> constant 23.976 fps
[16:08:29]      + Deblock (pp7) (qp=5)
[16:08:29]      + Crop and Scale (width=1920:height=1080:crop-top=0:crop-bottom=0:crop-left=0:crop-right=0)
[16:08:29]        + source: 1920 * 1080, crop (0/0/0/0): 1920 * 1080, scale: 1920 * 1080
[16:08:29]    + Output geometry
[16:08:29]      + storage dimensions: 1920 x 1080
[16:08:29]      + pixel aspect ratio: 1 : 1
[16:08:29]      + display dimensions: 1920 x 1080
[16:08:29]    + encoder: H.264 (libx264)
[16:08:29]      + preset:  veryslow
[16:08:29]      + options: ref=5:bframes=5
[16:08:29]      + profile: high
[16:08:29]      + level:   4.0
[16:08:29]      + quality: 18.00 (RF)
[16:08:29]  * audio track 1
[16:08:29]    + decoder: Unknown (pcm_s16le) (2.0 ch) (track 1, id 0x1)
[16:08:29]      + bitrate: 1411 kbps, samplerate: 44100 Hz
[16:08:29]    + mixdown: Stereo
[16:08:29]    + encoder: AAC (libavcodec)
[16:08:29]      + bitrate: 384 kbps, samplerate: 44100 Hz
[16:08:29] sync: expecting 4850 video frames
[16:08:29] encx264: min-keyint: 24, keyint: 240
[16:08:29] encx264: encoding at constant RF 18.000000
[16:08:29] encx264: unparsed options: direct=auto:ref=4:analyse=all:bframes=5:b-adapt=2:trellis=2:level=4.0:me=umh:merange=24:subme=10:vbv-bufsize=31250:vbv-maxrate=25000:rc-lookahead=60
x264 [info]: using SAR=1/1
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 AVX2 LZCNT BMI2
x264 [info]: profile High, level 4.0
[16:08:29] sync: first pts video is 0
[16:08:29] sync: "Chapter 1" (1) at frame 1 time 0
[16:08:29] sync: first pts audio 0x1 is 0
[16:17:06] reader: done. 1 scr changes
[16:17:14] work: average encoding speed for job is 9.278342 fps
[16:17:15] vfr: 4850 frames output, 0 dropped and 0 duped for CFR/PFR
[16:17:15] vfr: lost time: 0 (0 frames)
[16:17:15] vfr: gained time: 0 (0 frames) (0 not accounted for)
[16:17:15] pcm_s16le-decoder done: 9698 frames, 0 decoder errors
[16:17:15] rawvideo-decoder done: 4850 frames, 0 decoder errors
[16:17:15] sync: got 4850 frames, 4850 expected
[16:17:15] sync: framerate min 23.974 fps, max 23.981 fps, avg 23.976 fps
x264 [info]: frame I:21    Avg QP:15.71  size:193155
x264 [info]: frame P:930   Avg QP:18.96  size: 80488
x264 [info]: frame B:3899  Avg QP:21.82  size: 24676
x264 [info]: consecutive B-frames:  0.7%  0.4%  1.7% 17.0% 15.7% 64.6%
x264 [info]: mb I  I16..4: 12.5% 68.5% 19.0%
x264 [info]: mb P  I16..4:  2.6% 11.7%  1.5%  P16..4: 48.7% 20.1% 11.7%  0.3%  0.1%    skip: 3.4%
x264 [info]: mb B  I16..4:  0.4%  1.4%  0.1%  B16..8: 37.3%  9.3%  1.8%  direct:15.7%  skip:34.0%  L0:44.7% L1:40.7% BI:14.5%
x264 [info]: 8x8 transform intra:72.9% inter:67.8%
x264 [info]: direct mvs  spatial:99.4% temporal:0.6%
x264 [info]: coded y,uvDC,uvAC intra: 68.3% 74.6% 21.3% inter: 26.2% 42.7% 1.2%
x264 [info]: i16 v,h,dc,p: 15% 10%  5% 70%
x264 [info]: i8 v,h,dc,ddl,ddr,vr,hd,vl,hu: 13% 15%  7%  7% 11% 12% 13% 10% 13%
x264 [info]: i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 14% 12%  3%  8% 15% 14% 14%  9% 11%
x264 [info]: i8c dc,h,v,p: 27% 29% 18% 26%
x264 [info]: Weighted P-Frames: Y:6.0% UV:4.8%
x264 [info]: ref P L0: 43.8% 10.8% 30.9% 14.4%  0.2%  0.0%
x264 [info]: ref B L0: 76.5% 18.6%  4.9%
x264 [info]: ref B L1: 90.8%  9.2%
x264 [info]: kb/s:6925.70
[16:17:15] mux: track 0, 4850 frames, 175120077 bytes, 6924.24 kbps, fifo 512
[16:17:15] mux: track 1, 8712 frames, 9729225 bytes, 384.69 kbps, fifo 1024
[16:17:15] libhb: work result = 0

# Encode Completed ...

Musicvid wrote on 2/7/2017, 5:26 AM

Certain source information in the encode log is threshed from the scan log, which otherwise isn't very interesting.

Musicvid wrote on 5/11/2017, 9:40 PM

Is Magix any closer to implementation of verbose encode logging?

This goes beyond a feature request - - for now consider it a missed opportunity for peer and consumer support.

The first thing one must do in order to get out of a hole is to stop digging.

 

 

Grazie wrote on 5/12/2017, 12:29 AM

Is Magix any closer to implementation of verbose encode logging? ......The first thing one must do in order to get out of a hole is to stop digging.

MV, I laughed, and a pragmatic reply too. Is this thread going to be moved to Off Topic?

Musicvid wrote on 5/12/2017, 7:53 AM

The thing I've learned from the Handbrake forum, where logs are required for troubleshooting support, is that most user problem reports and descriptions are full of misinformation. If we must dig, let us do it in the right place.

Musicvid wrote on 2/4/2019, 2:54 PM

Magix, we all need this, especially those trying to assist your new users, who change everything they can find, and then blame the world for their unrequited expectations.

You are missing an opportunity to facilitate improved technical service and peer support.

j-v wrote on 2/4/2019, 3:22 PM

Not all "your new users" are serious video editing users, as there are a lot of only gameplayers a.s.o.
A lot are not using a registered version of the software as I saw as moderator and developer on our own Dutch forum and therefore we made special rules for our users.
I think we must not make it too easy for those to use the forum and/or the program.

met vriendelijke groet
Marten

Camera : Pan X900, GoPro Hero7 Hero Black, DJI Osmo Pocket, Samsung Galaxy A8
Desktop :MB Gigabyte Z390M, W11 home version 24H2, i7 9700 4.7Ghz,16 DDR4 GB RAM, Gef. GTX 1660 Ti with driver
566.14 Studiodriver and Intel HD graphics 630 with driver 31.0.101.2130
Laptop  :Asus ROG Str G712L, W11 home version 23H2, CPU i7-10875H, 16 GB RAM, NVIDIA GeForce RTX 2070 with Studiodriver 576.02 and Intel UHD Graphics 630 with driver 31.0.101.2130
Vegas software: VP 10 to 22 and VMS(pl) 10,12 to 17.
TV      :LG 4K 55EG960V

My slogan is: BE OR BECOME A STEM CELL DONOR!!! (because it saved my life in 2016)