Bug Report Weird New Log Entry: GetQPCTimeNS: WTF, clock went backwards

Boildown · Feb 4, 2014

Anyone know what this is? I run two instances of OBS with -multi and -portable, and have for a good half year now, and this is the first time I've seen this. I also saw it in someone else's log today (can't remember which thread). I think this is new as of 0.60b.

Code:

21:03:05: CUDA loaded successfully
21:03:05: 1 CUDA capable devices found
21:03:05: [ GPU #0 - < GeForce GTX 560 Ti > has Compute SM 2.1, NVENC Not Available ]
21:03:05: No NVENC capable devices found
21:04:29: Open Broadcaster Software v0.60b - 32bit (´・ω・｀)
21:04:29: -------------------------------
21:04:29: CPU Name: Intel(R) Core(TM) i7-2600K CPU @ 3.40GHz
21:04:29: CPU Speed: 3400MHz
21:04:29: Physical Memory:  4095MB Total, 4095MB Free
21:04:29: stepping id: 7, model 42, family 6, type 0, extmodel 1, extfamily 0, HTT 1, logical cores 8, total cores 4
21:04:29: monitor 1: pos={0, 0}, size={1680, 1050}
21:04:29: Windows Version: 6.1 Build 7601 S
21:04:29: Aero is Disabled
21:04:29: -------------------------------
21:04:29: OBS Modules:
21:04:29: Base Address     Module
21:04:29: 013C0000         OBS.exe
21:04:29: 74190000         OBSApi.dll
21:04:29: 73D60000         DatapathPlugin.dll
21:04:29: 73D00000         DShowPlugin.dll
21:04:29: 73CE0000         GraphicsCapture.dll
21:04:29: 73CC0000         NoiseGate.dll
21:04:29: 73CA0000         PSVPlugin.dll
21:04:29: ------------------------------------------
21:04:29: Adapter 1
21:04:29:   Video Adapter: NVIDIA GeForce GTX 560 Ti  
21:04:29:   Video Adapter Dedicated Video Memory: 1025966080
21:04:29:   Video Adapter Shared System Memory: 3220779008
21:04:29:   Video Adapter Output 1: pos={0, 0}, size={1680, 1050}, attached=true
21:04:29: =====Stream Start: 2014-02-03, 21:04:29===============================================
21:04:29:   Multithreaded optimizations: On
21:04:29:   Base resolution: 1920x1080
21:04:29:   Output resolution: 1920x1080
21:04:29: ------------------------------------------
21:04:29: Loading up D3D10 on NVIDIA GeForce GTX 560 Ti (Adapter 1)...
21:04:29: ------------------------------------------
21:04:29: Audio Format: 44100hz
21:04:29: Playback device Default
21:04:29: ------------------------------------------
21:04:29: Using desktop audio input: Speakers (Creative SB X-Fi)
21:04:29: ------------------------------------------
21:04:29: Using auxilary audio input: Microphone (3- USB Audio Device)
21:04:29: ------------------------------------------
21:04:29: Audio Encoding: AAC
21:04:29:     bitrate: 192
21:04:30: Scene buffering time set to 700
21:04:30: Using custom x264 settings: "opencl=true qp=24"
21:04:30: x264: VBV maxrate specified, but no bufsize, ignored
21:04:30: ------------------------------------------
21:04:30: Video Encoding: x264
21:04:30:     fps: 60
21:04:30:     width: 1920, height: 1080
21:04:30:     preset: superfast
21:04:30:     profile: high
21:04:30:     keyint: 250
21:04:30:     CBR: no
21:04:30:     CFR: yes
21:04:30:     max bitrate: 1000
21:04:30:     buffer size: 0
21:04:30:     quality: 10
21:04:30: ------------------------------------------
21:24:24: GetQPCTimeNS: WTF, clock went backwards! 4489441071 < 4489441080
21:28:16: GetQPCTimeNS: WTF, clock went backwards! 5259550827 < 5259550835
21:42:58: GetQPCTimeNS: WTF, clock went backwards! 8187657554 < 8187657564
21:47:13: GetQPCTimeNS: WTF, clock went backwards! 9033914694 < 9033914704
22:29:10: GetQPCTimeNS: WTF, clock went backwards! 17392609720 < 17392609721
22:49:34: GetQPCTimeNS: WTF, clock went backwards! 21454964831 < 21454964841
00:25:07: Total frames encoded: 722215, total frames duplicated: 23 (0.00%)
00:25:07: Total frames rendered: 722222, number of late frames: 0 (0.00%) (it's okay for some frames to be late)
00:25:10: 
00:25:10: Profiler time results:
00:25:10: 
00:25:10: ==============================================================
00:25:10: video thread frame - [100%] [avg time: 0.975 ms] [children: 4.41%] [unaccounted: 95.6%]
00:25:10: | scene->Preprocess - [0.103%] [avg time: 0.001 ms]
00:25:10: | GPU download and conversion - [4.31%] [avg time: 0.042 ms] [children: 3.69%] [unaccounted: 0.615%]
00:25:10: | | flush - [1.95%] [avg time: 0.019 ms]
00:25:10: | | CopyResource - [1.54%] [avg time: 0.015 ms]
00:25:10: | | conversion to 4:2:0 - [0.205%] [avg time: 0.002 ms]
00:25:10: Convert444Threads - [100%] [avg time: 6.974 ms] [children: 14.6%] [unaccounted: 85.4%]
00:25:10: | Convert444toNV12 - [14.6%] [avg time: 1.019 ms]
00:25:10: encoder thread frame - [100%] [avg time: 1.38 ms]
00:25:10: ==============================================================
00:25:10: 
00:25:10: 
00:25:10: Profiler CPU results:
00:25:10: 
00:25:10: ==============================================================
00:25:10: video thread frame - [cpu time: avg 0.554 ms, total 400656 ms] [avg calls per frame: 1]
00:25:10: | scene->Preprocess - [cpu time: avg 0 ms, total 0 ms] [avg calls per frame: 1]
00:25:10: | GPU download and conversion - [cpu time: avg 0.021 ms, total 15718.8 ms] [avg calls per frame: 1]
00:25:10: | | flush - [cpu time: avg 0.009 ms, total 7187.5 ms] [avg calls per frame: 1]
00:25:10: | | CopyResource - [cpu time: avg 0.008 ms, total 6265.63 ms] [avg calls per frame: 1]
00:25:10: | | conversion to 4:2:0 - [cpu time: avg 0.001 ms, total 781.25 ms] [avg calls per frame: 1]
00:25:10: Convert444Threads - [cpu time: avg 0.985 ms, total 1.42352e+006 ms] [avg calls per frame: 2]
00:25:10: | Convert444toNV12 - [cpu time: avg 0.981 ms, total 1.41731e+006 ms] [avg calls per frame: 2]
00:25:10: encoder thread frame - [cpu time: avg 1.049 ms, total 757609 ms] [avg calls per frame: 1]
00:25:10: ==============================================================
00:25:10: 
00:25:10: =====Stream End: 2014-02-04, 00:25:10=================================================
00:25:38: Memory Leaks Were Detected.
00:25:38:

Code:

21:04:23: Open Broadcaster Software v0.60b - 32bit (´・ω・｀)
21:04:23: -------------------------------
21:04:23: CPU Name: Intel(R) Core(TM) i7-2600K CPU @ 3.40GHz
21:04:23: CPU Speed: 3400MHz
21:04:23: Physical Memory:  4095MB Total, 4095MB Free
21:04:23: stepping id: 7, model 42, family 6, type 0, extmodel 1, extfamily 0, HTT 1, logical cores 8, total cores 4
21:04:23: monitor 1: pos={0, 0}, size={1680, 1050}
21:04:23: Windows Version: 6.1 Build 7601 S
21:04:23: Aero is Disabled
21:04:23: -------------------------------
21:04:23: OBS Modules:
21:04:23: Base Address     Module
21:04:23: 01210000         OBS.exe
21:04:23: 738C0000         OBSApi.dll
21:04:23: 73C70000         DatapathPlugin.dll
21:04:23: 73C40000         DShowPlugin.dll
21:04:23: 73C20000         GraphicsCapture.dll
21:04:23: 73C00000         NoiseGate.dll
21:04:23: 73BE0000         PSVPlugin.dll
21:04:23: ------------------------------------------
21:04:23: Adapter 1
21:04:23:   Video Adapter: NVIDIA GeForce GTX 560 Ti  
21:04:23:   Video Adapter Dedicated Video Memory: 1025966080
21:04:23:   Video Adapter Shared System Memory: 3220779008
21:04:23:   Video Adapter Output 1: pos={0, 0}, size={1680, 1050}, attached=true
21:04:23: =====Stream Start: 2014-02-03, 21:04:23===============================================
21:04:23:   Multithreaded optimizations: On
21:04:23:   Base resolution: 1920x1080
21:04:23:   Output resolution: 1280x720
21:04:23: ------------------------------------------
21:04:23: Loading up D3D10 on NVIDIA GeForce GTX 560 Ti (Adapter 1)...
21:04:23: ------------------------------------------
21:04:23: Audio Format: 44100hz
21:04:23: Playback device Default
21:04:23: ------------------------------------------
21:04:23: Using desktop audio input: Speakers (Creative SB X-Fi)
21:04:23: ------------------------------------------
21:04:23: Using auxilary audio input: Microphone (3- USB Audio Device)
21:04:23: ------------------------------------------
21:04:23: Audio Encoding: AAC
21:04:23:     bitrate: 160
21:04:23: Scene buffering time set to 700
21:04:23: Using custom x264 settings: "opencl=true"
21:04:23: ------------------------------------------
21:04:23: Video Encoding: x264
21:04:23:     fps: 30
21:04:23:     width: 1280, height: 720
21:04:23:     preset: fast
21:04:23:     profile: main
21:04:23:     keyint: 60
21:04:23:     CBR: yes
21:04:23:     CFR: yes
21:04:23:     max bitrate: 3000
21:04:23:     buffer size: 2000
21:04:23: ------------------------------------------
21:04:23: Audio timestamp for device 'Microphone (3- USB Audio Device)' was behind target timestamp by 150519
21:19:26: Using RTMP service: Twitch / Justin.tv
21:19:26:   Server selection: rtmp://live-iad.justin.tv/app
21:19:26:   Interface: Intel(R) 82579V Gigabit Network Connection (ethernet, 1000 mbps)
21:19:26: Completed handshake with rtmp://live-iad.justin.tv/app in 264 ms.
21:19:27: SO_SNDBUF was at 8192
21:19:27: SO_SNDBUF is now 65536
21:19:28: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 131072 (buffer: 6064 / 404480)
22:42:07: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 262144 (buffer: 0 / 404480)
22:50:01: GetQPCTimeNS: WTF, clock went backwards! 21547357985 < 21547357993
23:26:03: GetQPCTimeNS: WTF, clock went backwards! 28723540535 < 28723540544
00:25:07: Total frames encoded: 361313, total frames duplicated: 85 (0.02%)
00:25:07: Total frames rendered: 361316, number of late frames: 0 (0.00%) (it's okay for some frames to be late)
00:40:09: RTMPPublisher::SocketLoop: Graceful loop exit
00:40:09: Average send payload: 8587 bytes, average send interval: 21 ms
00:40:09: Number of times waited to send: 0, Waited for a total of 0 bytes
00:40:09: Number of b-frames dropped: 0 (0%), Number of p-frames dropped: 0 (0%), Total 0 (0%)
00:40:09: Number of bytes sent: 4766931997
00:40:09: 
00:40:09: Profiler time results:
00:40:09: 
00:40:09: ==============================================================
00:40:09: video thread frame - [100%] [avg time: 1.64 ms] [children: 3.11%] [unaccounted: 96.9%]
00:40:09: | scene->Preprocess - [0.061%] [avg time: 0.001 ms]
00:40:09: | GPU download and conversion - [3.05%] [avg time: 0.05 ms] [children: 2.56%] [unaccounted: 0.488%]
00:40:09: | | flush - [1.46%] [avg time: 0.024 ms]
00:40:09: | | CopyResource - [0.976%] [avg time: 0.016 ms]
00:40:09: | | conversion to 4:2:0 - [0.122%] [avg time: 0.002 ms]
00:40:09: Convert444Threads - [100%] [avg time: 24.185 ms] [children: 1.67%] [unaccounted: 98.3%]
00:40:09: | Convert444toNV12 - [1.67%] [avg time: 0.404 ms]
00:40:09: encoder thread frame - [100%] [avg time: 1.688 ms]
00:40:09: ==============================================================
00:40:09: 
00:40:09: 
00:40:09: Profiler CPU results:
00:40:09: 
00:40:09: ==============================================================
00:40:09: video thread frame - [cpu time: avg 1.197 ms, total 432828 ms] [avg calls per frame: 1]
00:40:09: | scene->Preprocess - [cpu time: avg 0 ms, total 0 ms] [avg calls per frame: 1]
00:40:09: | GPU download and conversion - [cpu time: avg 0.04 ms, total 14750 ms] [avg calls per frame: 1]
00:40:09: | | flush - [cpu time: avg 0.019 ms, total 7031.25 ms] [avg calls per frame: 1]
00:40:09: | | CopyResource - [cpu time: avg 0.014 ms, total 5234.38 ms] [avg calls per frame: 1]
00:40:09: | | conversion to 4:2:0 - [cpu time: avg 0.002 ms, total 781.25 ms] [avg calls per frame: 1]
00:40:09: Convert444Threads - [cpu time: avg 0.344 ms, total 248891 ms] [avg calls per frame: 2]
00:40:09: | Convert444toNV12 - [cpu time: avg 0.342 ms, total 247828 ms] [avg calls per frame: 2]
00:40:09: encoder thread frame - [cpu time: avg 1.075 ms, total 388422 ms] [avg calls per frame: 1]
00:40:09: ==============================================================
00:40:09: 
00:40:09: =====Stream End: 2014-02-04, 00:40:09=================================================
00:41:36: Memory Leaks Were Detected.
00:41:36:

Parts in question:

21:24:24: GetQPCTimeNS: WTF, clock went backwards! 4489441071 < 4489441080
21:28:16: GetQPCTimeNS: WTF, clock went backwards! 5259550827 < 5259550835
21:42:58: GetQPCTimeNS: WTF, clock went backwards! 8187657554 < 8187657564
21:47:13: GetQPCTimeNS: WTF, clock went backwards! 9033914694 < 9033914704
22:29:10: GetQPCTimeNS: WTF, clock went backwards! 17392609720 < 17392609721
22:49:34: GetQPCTimeNS: WTF, clock went backwards! 21454964831 < 21454964841

22:50:01: GetQPCTimeNS: WTF, clock went backwards! 21547357985 < 21547357993
23:26:03: GetQPCTimeNS: WTF, clock went backwards! 28723540535 < 28723540544

I haven't seen this error before. What does it mean?

Krazy · Feb 4, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

It has to do with some of the new audio changes, it's some new logging info. Are you noticing any audio problems?

R1CH · Feb 4, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

Are you overclocking or using anything weird like "useplatformclock" in your boot loader? (run bcdedit at an admin cmd prompt to check).

Boildown · Feb 4, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

R1CH said:
Are you overclocking or using anything weird like "useplatformclock" in your boot loader? (run bcdedit at an admin cmd prompt to check).

Yes, overclocking, to 4.3Ghz. No strangeness in bootloader. Haven't yet listened to the recording to look for audio problems, at least there's timestamps, its 3.5 hours long, not looking forward to it.

R1CH · Feb 4, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

It's in the order of nanoseconds, you probably won't notice it. The issue with backwards timestamps is the video thread may deadlock if an integer underflow occurs. Maybe the counter is thread-safe.

Lain · Feb 5, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

It's fine if you see that in the log, we put it in to check to see if it was actually occurring. At this point in time it doesn't seem to affect anyone, we were looking for big jumps more than anything. Should probably put a threshold on it or something. I actually made sure it clamps now just in case as well.

Boildown · Feb 5, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

Ok, thanks, good to know. However, check this log out, its a pretty severe case and says the mp4s won't play:

viewtopic.php?f=6&t=11210

vbdkv · Feb 7, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

I'm getting these as well and noticed that my sound card was messing up the channels, making it impossible to tell where the audio is coming from (left, right, front, back etc). It seems to happen a lot when I'm streaming in 1080p, which is why I'm not streaming in 1080p :)

Also getting "failed loading cuda dll", not sure what that's about.

Code:

01:49:20: Failed loading CUDA dll
02:01:46: Settings::Video: Disabling Aero
02:03:26: Open Broadcaster Software v0.60b - 64bit (　^ω^)
02:03:26: -------------------------------
02:03:26: CPU Name: AMD FX(tm)-8320 Eight-Core Processor
02:03:26: CPU Speed: 4013MHz
02:03:26: Physical Memory:  12189MB Total, 10207MB Free
02:03:26: stepping id: 0, model 2, family 21, type 0, extmodel 0, extfamily 3, HTT 1, logical cores 8, total cores 4
02:03:26: monitor 1: pos={0, 0}, size={1920, 1080}
02:03:26: Windows Version: 6.1 Build 7601 S
02:03:26: Aero is Disabled
02:03:26: -------------------------------
02:03:26: OBS Modules:
02:03:26: Base Address     Module
02:03:26: 000000003F520000 OBS.exe
02:03:26: 00000000F11A0000 OBSApi.dll
02:03:26: 00000000F8D70000 DShowPlugin.dll
02:03:26: 00000000F9960000 GraphicsCapture.dll
02:03:26: 00000000F8D50000 NoiseGate.dll
02:03:26: 00000000F8D30000 PSVPlugin.dll
02:03:26: ------------------------------------------
02:03:26: Adapter 1
02:03:26:   Video Adapter: AMD Radeon R9 200 Series
02:03:26:   Video Adapter Dedicated Video Memory: 2124460032
02:03:26:   Video Adapter Shared System Memory: 1827211264
02:03:26:   Video Adapter Output 1: pos={0, 0}, size={1920, 1080}, attached=true
02:03:26: =====Stream Start: 2014-02-07, 02:03:26===============================================
02:03:26:   Multithreaded optimizations: On
02:03:26:   Base resolution: 1280x720
02:03:26:   Output resolution: 1280x720
02:03:26: ------------------------------------------
02:03:26: Loading up D3D10 on AMD Radeon R9 200 Series (Adapter 1)...
02:03:26: ------------------------------------------
02:03:26: Audio Format: 48000hz
02:03:26: Playback device Default
02:03:26: ------------------------------------------
02:03:26: Using desktop audio input: Speakers (2- Sound Blaster Z)
02:03:26: Using 5.1 speaker setup
02:03:26: ------------------------------------------
02:03:26: Audio Encoding: AAC
02:03:26:     bitrate: 96
02:03:26: Using graphics capture
02:03:26: Scene buffering time set to 400
02:03:26: ------------------------------------------
02:03:26: Video Encoding: x264
02:03:26:     fps: 60
02:03:26:     width: 1280, height: 720
02:03:26:     preset: veryfast
02:03:26:     profile: main
02:03:26:     keyint: 120
02:03:26:     CBR: yes
02:03:26:     CFR: yes
02:03:26:     max bitrate: 3000
02:03:26:     buffer size: 3000
02:03:26: ------------------------------------------
02:03:26: SharedTexCapture hooked
02:03:27: Using RTMP service: Twitch / Justin.tv
02:03:27:   Server selection: rtmp://live-ams.justin.tv/app
02:03:28:   Interface: Intel(R) PRO/1000 GT Desktop Adapter (ethernet, 1000 mbps)
02:03:28: Completed handshake with rtmp://live-ams.justin.tv/app in 379 ms.
02:03:29: SO_SNDBUF was at 8192
02:03:29: SO_SNDBUF is now 65536
02:03:32: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 262144 (buffer: 0 / 396288)
02:03:55: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 524288 (buffer: 0 / 396288)
02:12:05: GetQPCTimeNS: WTF, clock went backwards! 7823301482 < 7823301515
02:26:19: GetQPCTimeNS: WTF, clock went backwards! 10752213553 < 10752213566
02:52:22: GetQPCTimeNS: WTF, clock went backwards! 16110621372 < 16110621405
03:02:47: GetQPCTimeNS: WTF, clock went backwards! 18256490255 < 18256490268
03:09:36: Total frames encoded: 238135, total frames duplicated: 98 (0.04%)
03:09:36: Total frames rendered: 238100, number of late frames: 13 (0.01%) (it's okay for some frames to be late)
03:09:36: RTMPPublisher::SocketLoop: Graceful loop exit
03:09:36: Average send payload: 5956 bytes, average send interval: 15 ms
03:09:36: Number of times waited to send: 0, Waited for a total of 0 bytes
03:09:36: Number of b-frames dropped: 0 (0%), Number of p-frames dropped: 0 (0%), Total 0 (0%)
03:09:36: Number of bytes sent: 1539931806
03:09:36: 
03:09:36: Profiler time results:
03:09:36: 
03:09:36: ==============================================================
03:09:36: video thread frame - [100%] [avg time: 0.865 ms] [children: 51.3%] [unaccounted: 48.7%]
03:09:36: | scene->Preprocess - [0.116%] [avg time: 0.001 ms]
03:09:36: | GPU download and conversion - [51.2%] [avg time: 0.443 ms] [children: 49.5%] [unaccounted: 1.73%]
03:09:36: | | flush - [47.9%] [avg time: 0.414 ms]
03:09:36: | | CopyResource - [1.16%] [avg time: 0.01 ms]
03:09:36: | | conversion to 4:2:0 - [0.462%] [avg time: 0.004 ms]
03:09:36: Convert444Threads - [100%] [avg time: 0.755 ms] [children: 99.3%] [unaccounted: 0.662%]
03:09:36: | Convert444toNV12 - [99.3%] [avg time: 0.75 ms]
03:09:36: encoder thread frame - [100%] [avg time: 1.273 ms]
03:09:36: ==============================================================
03:09:36: 
03:09:36: 
03:09:36: Profiler CPU results:
03:09:36: 
03:09:36: ==============================================================
03:09:36: video thread frame - [cpu time: avg 0.077 ms, total 18548.5 ms] [avg calls per frame: 1]
03:09:36: | scene->Preprocess - [cpu time: avg 0 ms, total 31.201 ms] [avg calls per frame: 1]
03:09:36: | GPU download and conversion - [cpu time: avg 0.044 ms, total 10670.5 ms] [avg calls per frame: 1]
03:09:36: | | flush - [cpu time: avg 0.039 ms, total 9422.47 ms] [avg calls per frame: 1]
03:09:36: | | CopyResource - [cpu time: avg 0.001 ms, total 405.604 ms] [avg calls per frame: 1]
03:09:36: | | conversion to 4:2:0 - [cpu time: avg 0 ms, total 234.002 ms] [avg calls per frame: 1]
03:09:36: Convert444Threads - [cpu time: avg 0.749 ms, total 356977 ms] [avg calls per frame: 2]
03:09:36: | Convert444toNV12 - [cpu time: avg 0.746 ms, total 355526 ms] [avg calls per frame: 2]
03:09:36: encoder thread frame - [cpu time: avg 0.981 ms, total 233690 ms] [avg calls per frame: 1]
03:09:36: ==============================================================
03:09:36: 
03:09:36: =====Stream End: 2014-02-07, 03:09:36=================================================

Also I usually stream with aero enabled and in 1080p base resolution and downscale to 720p just for the record. This was just a test to see if audio was messing up which it did after about 30 mins.

vbdkv · Feb 8, 2014

Re: Weird New Log Entry: GetQPCTimeNS: WTF, clock went backw

Enabling HPET in Windows and bios fixed it, no more "WTF" errors so timers must be completely in sync, but it didn't help with the awful Creative drivers, still getting some crazy audio issues when capturing in 1080p.

So I disabled it again in bios and windows.

Bug Report Weird New Log Entry: GetQPCTimeNS: WTF, clock went backwards

Boildown

Active Member

Krazy

Town drunk

R1CH

Boildown

Active Member

R1CH

Lain

Boildown

Active Member

vbdkv

Member

vbdkv

Member