Question / Help Audio De-Sync After Last Patch

[PyrionFlax]

Hello there! I stream a lot on Twitch.tv and up til now the only issue I've had has been with Virgin Media throttling my connection after too much streaming (too much for them, anyway)...

Here is a log file from last night:

22:34:06: Open Broadcaster Software v0.624b - 64bit (　^ω^)
22:34:06: -------------------------------
22:34:06: CPU Name: Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
22:34:06: CPU Speed: 3202MHz
22:34:06: Physical Memory:  16325MB Total, 5898MB Free
22:34:06: stepping id: 7, model 45, family 6, type 0, extmodel 1, extfamily 0, HTT 1, logical cores 12, total cores 6
22:34:06: monitor 1: pos={0, 0}, size={1920, 1080}
22:34:06: monitor 2: pos={1920, 0}, size={1920, 1080}
22:34:06: Windows Version: 6.2 Build 9200
22:34:06: Aero is Enabled
22:34:06: -------------------------------
22:34:06: OBS Modules:
22:34:06: Base Address     Module
22:34:06: 0000000058810000 OBS.exe
22:34:06: 0000000096AE0000 OBSApi.dll
22:34:06: 0000000098AA0000 DShowPlugin.dll
22:34:06: 0000000098440000 GraphicsCapture.dll
22:34:06: 0000000098410000 NoiseGate.dll
22:34:06: 0000000098370000 PSVPlugin.dll
22:34:06: ------------------------------------------
22:34:06: Adapter 1
22:34:06:   Video Adapter: NVIDIA GeForce GTX 770
22:34:06:   Video Adapter Dedicated Video Memory: 4190949376
22:34:06:   Video Adapter Shared System Memory: 4264333312
22:34:06:   Video Adapter Output 1: pos={0, 0}, size={1920, 1080}, attached=true
22:34:06:   Video Adapter Output 2: pos={1920, 0}, size={1920, 1080}, attached=true
22:34:06: =====Stream Start: 2014-05-26, 22:34:06===============================================
22:34:06:   Multithreaded optimizations: On
22:34:06:   Base resolution: 1920x1080
22:34:06:   Output resolution: 1920x1080
22:34:06: ------------------------------------------
22:34:06: Loading up D3D10 on NVIDIA GeForce GTX 770 (Adapter 1)...
22:34:06: ------------------------------------------
22:34:06: Audio Format: 48000 Hz
22:34:06: ------------------------------------------
22:34:06: Audio Channels: 2 Ch
22:34:06: Playback device Default
22:34:06: ------------------------------------------
22:34:06: Using desktop audio input: Line Out (2- Scarlett 2i2 USB)
22:34:06: Global Audio time adjust: 0
22:34:06: ------------------------------------------
22:34:06: Using auxilary audio input: Line In (2- Scarlett 2i2 USB)
22:34:06: Mic time offset: 0
22:34:06: ------------------------------------------
22:34:06: Audio Encoding: AAC
22:34:06:     bitrate: 128
22:34:06: Using Window Capture
22:34:06: Scene buffering time set to 700
22:34:06: ------------------------------------------
22:34:06: Video Encoding: x264
22:34:06:     fps: 25
22:34:06:     width: 1920, height: 1080
22:34:06:     preset: veryfast
22:34:06:     profile: main
22:34:06:     keyint: 50
22:34:06:     CBR: yes
22:34:06:     CFR: yes
22:34:06:     max bitrate: 2000
22:34:06:     buffer size: 2000
22:34:06: ------------------------------------------
22:34:06: Audio timestamp for device 'Line In (2- Scarlett 2i2 USB)' was behind target timestamp by 1211616792
22:34:10: Using RTMP service: Twitch / Justin.tv
22:34:10:   Server selection: rtmp://live-lhr.justin.tv/app
22:34:10:   Interface: Intel(R) 82579V Gigabit Network Connection (ethernet, 1000 mbps)
22:34:10: Completed handshake with rtmp://live-lhr.justin.tv/app in 368 ms.
22:34:11: SO_SNDBUF was at 64512
22:34:11: SO_SNDBUF is now 65536
22:34:18: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 131072 (buffer: 0 / 272384)
22:42:11: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 262144 (buffer: 18624 / 272384)

---------------(CUT BY ME TO REDUCE LOG SIZE)-----------

23:03:29: Audio timestamp for device 'Line In (2- Scarlett 2i2 USB)' was behind target timestamp by 10
23:03:29: Audio timestamp for device 'Line In (2- Scarlett 2i2 USB)' was behind target timestamp by 10
23:03:31: Audio device 'Line Out (2- Scarlett 2i2 USB)' has been lost, attempting to reinitialize
23:03:32: Global Audio time adjust: 0
23:03:32: Device 'Speakers (Realtek High Definition Audio)' reacquired.
23:03:41: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 262144 (buffer: 0 / 272384)
23:03:46: Total frames encoded: 897, total frames duplicated: 248 (27.65%)
23:03:46: Total frames rendered: 640, number of late frames: 5 (0.78%) (it's okay for some frames to be late)
23:03:47: RTMPPublisher::SocketLoop: Graceful loop exit
23:03:47: Average send payload: 8340 bytes, average send interval: 32 ms
23:03:47: Number of times waited to send: 0, Waited for a total of 0 bytes
23:03:47: Number of b-frames dropped: 0 (0%), Number of p-frames dropped: 0 (0%), Total 0 (0%)
23:03:47: Number of bytes sent: 8340549
23:03:47:
23:03:47: Profiler time results:
23:03:47:
23:03:47: ==============================================================
23:03:47: video thread frame - [100%] [avg time: 21.026 ms] [children: 1.64%] [unaccounted: 98.4%]
23:03:47: | scene->Preprocess - [1.16%] [avg time: 0.243 ms]
23:03:47: | GPU download and conversion - [0.48%] [avg time: 0.101 ms] [children: 0.333%] [unaccounted: 0.147%]
23:03:47: | | flush - [0.252%] [avg time: 0.053 ms]
23:03:47: | | CopyResource - [0.0571%] [avg time: 0.012 ms]
23:03:47: | | conversion to 4:2:0 - [0.0238%] [avg time: 0.005 ms]
23:03:47: Convert444Threads - [100%] [avg time: 0.474 ms] [children: 99.2%] [unaccounted: 0.844%]
23:03:47: | Convert444toNV12 - [99.2%] [avg time: 0.47 ms]
23:03:47: encoder thread frame - [100%] [avg time: 1.895 ms] [children: 1.48%] [unaccounted: 98.5%]
23:03:47: | sending stuff out - [1.48%] [avg time: 0.028 ms]
23:03:47: ==============================================================
23:03:47:
23:03:47:
23:03:47: Profiler CPU results:
23:03:47:
23:03:47: ==============================================================
23:03:47: video thread frame - [cpu time: avg 20.507 ms, total 13125 ms] [avg calls per frame: 1]
23:03:47: | scene->Preprocess - [cpu time: avg 0 ms, total 0 ms] [avg calls per frame: 1]
23:03:47: | GPU download and conversion - [cpu time: avg 0.244 ms, total 156.25 ms] [avg calls per frame: 1]
23:03:47: | | flush - [cpu time: avg 0.122 ms, total 78.125 ms] [avg calls per frame: 1]
23:03:47: | | CopyResource - [cpu time: avg 0.048 ms, total 31.25 ms] [avg calls per frame: 1]
23:03:47: | | conversion to 4:2:0 - [cpu time: avg 0.048 ms, total 31.25 ms] [avg calls per frame: 1]
23:03:47: Convert444Threads - [cpu time: avg 0.551 ms, total 1406.25 ms] [avg calls per frame: 4]
23:03:47: | Convert444toNV12 - [cpu time: avg 0.544 ms, total 1390.63 ms] [avg calls per frame: 4]
23:03:47: encoder thread frame - [cpu time: avg 1.262 ms, total 1109.38 ms] [avg calls per frame: 1]
23:03:47: | sending stuff out - [cpu time: avg 0.035 ms, total 31.25 ms] [avg calls per frame: 1]
23:03:47: ==============================================================
23:03:47:
23:03:47: =====Stream End: 2014-05-26, 23:03:47=================================================


Last game capture log:
2014-05-09, 22:43:02: we're booting up:
22:43:02: CaptureThread: attached to process rogame.exe
22:43:02: D3D9 Present
22:43:02: (half life scientist) everything..  seems to be in order
22:43:16: D3D9EndScene called
22:43:16: D3DPRESENT_PARAMETERS {
22:43:16:     BackBufferWidth: 1920
22:43:16:     BackBufferHeight: 1080
22:43:16:     BackBufferFormat: D3DFMT_A8R8G8B8
22:43:16:     BackBufferCount: 1
22:43:16:     MultiSampleType: D3DMULTISAMPLE_NONE
22:43:16:     MultiSampleQuality: 0
22:43:16:     SwapEffect: D3DSWAPEFFECT_DISCARD
22:43:16:     hDeviceWindow: 2108080
22:43:16:     Windowed: false
22:43:16:     EnableAutoDepthStencil: false
22:43:16:     AutoDepthStencilFormat: D3DFMT_UNKNOWN
22:43:16:     Flags: D3DPRESENTFLAG_LOCKABLE_BACKBUFFER
22:43:16:     FullScreen_RefreshRateInHz: 60
22:43:16:     PresentationInterval: 2147483648
22:43:16: };
22:43:16: successfully set up d3d9 hooks
22:43:16: D3D9Present called
22:43:16: DoD3D9GPUHook: success
22:43:16: D3DSURFACE_DESC {
22:43:16:     Format: D3DFMT_A8R8G8B8
22:43:16:     Type: D3DRTYPE_SURFACE
22:43:16:     Usage: D3DUSAGE_RENDERTARGET
22:43:16:     Pool: D3DPOOL_DEFAULT
22:43:16:     MultiSampleType: D3DMULTISAMPLE_NONE
22:43:16:     MultiSampleQuality: 0
22:43:16:     Width: 1920
22:43:16:     Height: 1080
22:43:16: };
22:43:16: successfully capturing d3d9 frames via GPU
22:44:23: D3D9Reset called
22:44:23: ---------------------- Cleared D3D9 Capture ----------------------
22:44:24: successfully set up d3d9 hooks
22:44:32: D3D9EndScene called
22:44:32: D3D9Present called
22:44:32: DoD3D9GPUHook: success
22:44:35: D3DSURFACE_DESC {
22:44:35:     Format: D3DFMT_A8R8G8B8
22:44:35:     Type: D3DRTYPE_SURFACE
22:44:35:     Usage: D3DUSAGE_RENDERTARGET
22:44:35:     Pool: D3DPOOL_DEFAULT
22:44:35:     MultiSampleType: D3DMULTISAMPLE_NONE
22:44:35:     MultiSampleQuality: 0
22:44:35:     Width: 1920
22:44:35:     Height: 1080
22:44:35: };
22:44:35: successfully capturing d3d9 frames via GPU

I've had to remove the line:
Audio timestamp for device 'Line In (2- Scarlett 2i2 USB)' was behind target timestamp by 20
Since it occurred so many times in the logfile that it actually caused me problems posting it here (it was too large)

Any ideas? Viewers said the stream audio was out by around 2 or 3 seconds or so.

 

[pzlate]

Yeah not sure what's up with 0.624. I downgraded back to 0.622 and everything is in sync again.

Edit: Nevermind, at least for me, it was something hardware related. Nothing to do with 0.624. I was messing around with a new overclock and didn't revert everything back when I decided to go back to my old overclock. After fixing some voltages it seems to be in sync, not sure if that's what did it.

 

[PyrionFlax]

Hmm, in the changelog it says

"Fix potential audio/video sync issues that would happen with hardware encoders"

So I wonder if that's actually messed it up for some of us who didn't have issues? Either way, going to roll back to an older version, thanks for the tip.

 

[Vaughn Whiskey]

Had the same issue and did the following that Jim suggested. Seemed to fix it for now.

Actually desync shouldn't happen if you're just streaming computer games. First, try the "sync audio to video" option in advanced, see if that helps.

If not, then try this:
1.) Open a command prompt as administrator, and type in: bcdedit /set useplatformclock true
2.) Restart your computer, go to bios, and search for an option in there that says either 'HPET' or 'High Precision Event Timer', and enable it.
3.) Try again and see if it affects anything.

 

[Boildown]

You have a 3930k hexa-core and yet you're still getting this:

23:03:46: Total frames encoded: 897, total frames duplicated: 248 (27.65%)

Something is definitely very wrong, although I wish you'd let it stream for longer than a few seconds. What are you streaming that your CPU can't keep up with both the game and the stream? Do you have a ton of other stuff going on in the background too? Can you post a log file from 6.22b where its working properly? Longer than a few seconds, more like five minutes, would be best.