Question / Help OBS just started skipping frames

TheMoatman

New Member
Hi,
I started up OBS today and I saw the red "WARNING: Taking too long to encode" alert when I was doing a preview to get the layout set up. I never had this problem until today, even though I was recording 1080p @ 60fps. I'm running a 4790k.
I've uploaded two logs, one from the 22nd (a working 1080p60 stream) and one from today. I'm more interested in why this would start happening than fixing it, but a fix would be nice, too.
e: It's skipping frames at 720p60, too. Relevant parts of the log are below.
Code:
05:58:18: Open Broadcaster Software v0.625b - 32bit (´・ω・`)
05:58:18: -------------------------------
05:58:18: CPU Name: Intel(R) Core(TM) i7-4790K CPU @ 4.00GHz
05:58:18: CPU Speed: 3991MHz
05:58:18: Physical Memory:  4095MB Total, 4095MB Free
05:58:18: stepping id: 3, model 60, family 6, type 0, extmodel 1, extfamily 0, HTT 1, logical cores 8, total cores 4
05:58:18: monitor 1: pos={0, 0}, size={1920, 1080}
05:58:18: Windows Version: 6.2 Build 9200
05:58:18: Aero is Enabled
05:58:18: -------------------------------
05:58:18: OBS Modules:
05:58:18: Base Address     Module
05:58:18: 013A0000         OBS.exe
05:58:18: 562C0000         OBSApi.dll
05:58:18: 649E0000         DShowPlugin.dll
05:58:18: 649B0000         GraphicsCapture.dll
05:58:18: 64980000         NoiseGate.dll
05:58:18: 64960000         PSVPlugin.dll
05:58:18: ------------------------------------------
05:58:18: Adapter 1
05:58:18:   Video Adapter: AMD Radeon R9 200 Series
05:58:18:   Video Adapter Dedicated Video Memory: 2128662528
05:58:18:   Video Adapter Shared System Memory: 2166239232
05:58:18:   Video Adapter Output 1: pos={0, 0}, size={1920, 1080}, attached=true
06:03:29: =====Stream Start: 2014-08-26, 06:03:29===============================================
06:03:29:   Multithreaded optimizations: On
06:03:29:   Base resolution: 1280x720
06:03:29:   Output resolution: 1280x720
06:03:29: ------------------------------------------
06:03:29: Loading up D3D10 on AMD Radeon R9 200 Series (Adapter 1)...
06:03:29: ------------------------------------------
06:03:29: Audio Format: 48000 Hz
06:03:29: ------------------------------------------
06:03:29: Audio Channels: 2 Ch
06:03:29: Playback device Default
06:03:29: ------------------------------------------
06:03:29: Using desktop audio input: Speakers (Realtek High Definition Audio)
06:03:29: Global Audio time adjust: 0
06:03:29: ------------------------------------------
06:03:29: Audio Encoding: AAC
06:03:29:     bitrate: 128
06:03:29: Using Window Capture
06:03:29: Scene buffering time set to 700
06:03:29: ------------------------------------------
06:03:29: Video Encoding: x264
06:03:29:     fps: 60
06:03:29:     width: 1280, height: 720
06:03:29:     preset: veryfast
06:03:29:     profile: main
06:03:29:     keyint: 120
06:03:29:     CBR: yes
06:03:29:     CFR: yes
06:03:29:     max bitrate: 3500
06:03:29:     buffer size: 3500
06:03:29: ------------------------------------------
06:03:31: Using RTMP service: Twitch / Justin.tv
06:03:31:   Server selection: rtmp://live.justin.tv/app
06:03:31:   Interface: Intel(R) Centrino(R) Advanced-N 6205 (802.11, 43 mbps)
06:03:31: Completed handshake with rtmp://live.justin.tv/app in 177 ms.
06:03:32: SO_SNDBUF was at 65536
06:03:33: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 131072 (buffer: 37976 / 463872)
06:03:37: RTMPPublisher::SocketLoop: Increasing send buffer to ISB 262144 (buffer: 0 / 463872)
06:05:29: Total frames encoded: 7145, total frames duplicated: 285 (3.99%)
06:05:29: Number of frames skipped due to encoder lag: 179 (2.51%)
06:05:29: Total frames rendered: 6975, number of late frames: 20 (0.29%) (it's okay for some frames to be late)
06:05:30: RTMPPublisher::SocketLoop: Graceful loop exit
06:05:31: Average send payload: 7683 bytes, average send interval: 16 ms
06:05:31: Number of times waited to send: 4, Waited for a total of 9258 bytes
06:05:31: Number of b-frames dropped: 0 (0%), Number of p-frames dropped: 0 (0%), Total 0 (0%)
06:05:31: Number of bytes sent: 53241392
06:05:31:
06:05:31: Profiler time results:
06:05:31:
06:05:31: ==============================================================
06:05:31: video thread frame - [100%] [avg time: 2.277 ms] [children: 46.6%] [unaccounted: 53.4%]
06:05:31: | scene->Preprocess - [30.3%] [avg time: 0.691 ms]
06:05:31: | GPU download and conversion - [16.2%] [avg time: 0.37 ms] [children: 14.4%] [unaccounted: 1.89%]
06:05:31: | | flush - [11.8%] [avg time: 0.269 ms]
06:05:31: | | CopyResource - [2.15%] [avg time: 0.049 ms]
06:05:31: | | conversion to 4:2:0 - [0.395%] [avg time: 0.009 ms]
06:05:31: Convert444Threads - [100%] [avg time: 2.114 ms] [children: 99.1%] [unaccounted: 0.899%]
06:05:31: | Convert444toNV12 - [99.1%] [avg time: 2.095 ms]
06:05:31: encoder thread frame - [100%] [avg time: 4.258 ms] [children: 2.18%] [unaccounted: 97.8%]
06:05:31: | sending stuff out - [2.18%] [avg time: 0.093 ms]
06:05:31: ==============================================================
06:05:31:
06:05:31:
06:05:31: Profiler CPU results:
06:05:31:
06:05:31: ==============================================================
06:05:31: video thread frame - [cpu time: avg 0.938 ms, total 6546.88 ms] [avg calls per frame: 1]
06:05:31: | scene->Preprocess - [cpu time: avg 0.051 ms, total 359.375 ms] [avg calls per frame: 1]
06:05:31: | GPU download and conversion - [cpu time: avg 0.226 ms, total 1578.13 ms] [avg calls per frame: 1]
06:05:31: | | flush - [cpu time: avg 0.161 ms, total 1125 ms] [avg calls per frame: 1]
06:05:31: | | CopyResource - [cpu time: avg 0.02 ms, total 140.625 ms] [avg calls per frame: 1]
06:05:31: | | conversion to 4:2:0 - [cpu time: avg 0.015 ms, total 109.375 ms] [avg calls per frame: 1]
06:05:31: Convert444Threads - [cpu time: avg 1.987 ms, total 27531.3 ms] [avg calls per frame: 2]
06:05:31: | Convert444toNV12 - [cpu time: avg 1.977 ms, total 27390.6 ms] [avg calls per frame: 2]
06:05:31: encoder thread frame - [cpu time: avg 3.07 ms, total 21875 ms] [avg calls per frame: 1]
06:05:31: | sending stuff out - [cpu time: avg 0.059 ms, total 421.875 ms] [avg calls per frame: 1]
06:05:31: ==============================================================
06:05:31:
06:05:31: =====Stream End: 2014-08-26, 06:05:31=================================================
 

Attachments

  • 2014-08-22-1348-00.log
    5.9 KB · Views: 33
  • 2014-08-26-0450-44.log
    20.3 KB · Views: 25
Last edited:

Lain

Forum Admin
Lain
Forum Moderator
Developer
I agree that it shouldn't be happening at 720p on that computer, even my old 2500k can do 720p 60fps without that issue. So I'm not entirely sure what's going on. Perhaps just general high CPU usage on the computer? It's probably something that you might have to investigate on your end, because it would usually imply general high CPU usage elsewhere on the computer (perhaps the game is eating it all up? Not sure).
 

TheMoatman

New Member
I'm afraid it might be a hardware issue, but I don't know what (maybe graphics card?). I've been having some trouble with framerate in games for a couple of days now.
I wanted to see how 1080p compared between the two logs, so I tried the same game as in the 8-22 log (Teslagrad) which actually uses more CPU than VVVVVV. Teslagrad normally hovers around several hundred FPS on my hardware, including when I was recording last week. Today, it frequently dropped sub-20. I had every program except the stream and game closed
BpT8oDG.png

This is a screenshot from MSI Afterburner's FPS monitor. The plateau at the end is above 600 fps, and was after I turned off the recording. The ones in the middle are ~200.
And logs of this:
Code:
11:48:35: Open Broadcaster Software v0.625b - 64bit ( ^ω^)
11:48:35: -------------------------------
11:48:35: CPU Name: Intel(R) Core(TM) i7-4790K CPU @ 4.00GHz
11:48:35: CPU Speed: 3991MHz
11:48:35: Physical Memory:  8113MB Total, 5214MB Free
11:48:35: stepping id: 3, model 60, family 6, type 0, extmodel 1, extfamily 0, HTT 1, logical cores 8, total cores 4
11:48:35: monitor 1: pos={0, 0}, size={1920, 1080}
11:48:35: Windows Version: 6.2 Build 9200
11:48:35: Aero is Enabled
11:48:35: -------------------------------
11:48:35: OBS Modules:
11:48:35: Base Address     Module
11:48:35: 000000004B090000 OBS.exe
11:48:35: 00000000D1DC0000 OBSApi.dll
11:48:35: 00000000D9390000 DShowPlugin.dll
11:48:35: 00000000DA2D0000 GraphicsCapture.dll
11:48:35: 00000000D8610000 NoiseGate.dll
11:48:35: 00000000D85E0000 PSVPlugin.dll
11:48:35: ------------------------------------------
11:48:35: Adapter 1
11:48:35:   Video Adapter: AMD Radeon R9 200 Series
11:48:35:   Video Adapter Dedicated Video Memory: 2128662528
11:48:35:   Video Adapter Shared System Memory: 4026531840
11:48:35:   Video Adapter Output 1: pos={0, 0}, size={1920, 1080}, attached=true
11:48:35: =====Stream Start: 2014-08-26, 11:48:35===============================================
11:48:35:   Multithreaded optimizations: On
11:48:35:   Base resolution: 1920x1080
11:48:35:   Output resolution: 1920x1080
11:48:35: ------------------------------------------
11:48:35: Loading up D3D10 on AMD Radeon R9 200 Series (Adapter 1)...
11:48:35: ------------------------------------------
11:48:35: Audio Format: 48000 Hz
11:48:35: ------------------------------------------
11:48:35: Audio Channels: 2 Ch
11:48:35: Playback device Default
11:48:35: ------------------------------------------
11:48:35: Using desktop audio input: Speakers (Realtek High Definition Audio)
11:48:35: Global Audio time adjust: 0
11:48:35: ------------------------------------------
11:48:35: Audio Encoding: AAC
11:48:35:     bitrate: 128
11:48:35: Using Window Capture
11:48:35: Scene buffering time set to 700
11:48:35: x264: MB rate (489600) > level limit (245760)
11:48:35: ------------------------------------------
11:48:35: Video Encoding: x264
11:48:35:     fps: 60
11:48:35:     width: 1920, height: 1080
11:48:35:     preset: veryfast
11:48:35:     profile: main
11:48:35:     keyint: 120
11:48:35:     CBR: yes
11:48:35:     CFR: yes
11:48:35:     max bitrate: 3500
11:48:35:     buffer size: 3500
11:48:35: ------------------------------------------
11:49:19: Total frames encoded: 2550, total frames duplicated: 400 (15.69%)
11:49:19: Number of frames skipped due to encoder lag: 364 (14.27%)
11:49:19: Total frames rendered: 2214, number of late frames: 10 (0.45%) (it's okay for some frames to be late)
11:49:19:
11:49:19: Profiler time results:
11:49:19:
11:49:19: ==============================================================
11:49:19: video thread frame - [100%] [avg time: 1.663 ms] [children: 52.7%] [unaccounted: 47.3%]
11:49:19: | scene->Preprocess - [32.4%] [avg time: 0.539 ms]
11:49:19: | GPU download and conversion - [20.3%] [avg time: 0.338 ms] [children: 17%] [unaccounted: 3.31%]
11:49:19: | | flush - [13.7%] [avg time: 0.227 ms]
11:49:19: | | CopyResource - [3.01%] [avg time: 0.05 ms]
11:49:19: | | conversion to 4:2:0 - [0.361%] [avg time: 0.006 ms]
11:49:19: Convert444Threads - [100%] [avg time: 2.194 ms] [children: 99.6%] [unaccounted: 0.41%]
11:49:19: | Convert444toNV12 - [99.6%] [avg time: 2.185 ms]
11:49:19: encoder thread frame - [100%] [avg time: 6.797 ms] [children: 0.25%] [unaccounted: 99.7%]
11:49:19: | sending stuff out - [0.25%] [avg time: 0.017 ms]
11:49:19: ==============================================================
11:49:19:
11:49:19:
11:49:19: Profiler CPU results:
11:49:19:
11:49:19: ==============================================================
11:49:19: video thread frame - [cpu time: avg 0.931 ms, total 2062.5 ms] [avg calls per frame: 1]
11:49:19: | scene->Preprocess - [cpu time: avg 0.063 ms, total 140.625 ms] [avg calls per frame: 1]
11:49:19: | GPU download and conversion - [cpu time: avg 0.218 ms, total 484.375 ms] [avg calls per frame: 1]
11:49:19: | | flush - [cpu time: avg 0.098 ms, total 218.75 ms] [avg calls per frame: 1]
11:49:19: | | CopyResource - [cpu time: avg 0.043 ms, total 93.75 ms] [avg calls per frame: 1]
11:49:19: | | conversion to 4:2:0 - [cpu time: avg 0.014 ms, total 31.25 ms] [avg calls per frame: 1]
11:49:19: Convert444Threads - [cpu time: avg 2.012 ms, total 8718.75 ms] [avg calls per frame: 2]
11:49:19: | Convert444toNV12 - [cpu time: avg 2.001 ms, total 8671.88 ms] [avg calls per frame: 2]
11:49:19: encoder thread frame - [cpu time: avg 4.627 ms, total 11703.1 ms] [avg calls per frame: 1]
11:49:19: | sending stuff out - [cpu time: avg 0.006 ms, total 15.625 ms] [avg calls per frame: 1]
11:49:19: ==============================================================
11:49:19:
11:49:19: =====Stream End: 2014-08-26, 11:49:19=================================================
11:49:36: =====Stream Start: 2014-08-26, 11:49:36===============================================
11:49:36:   Multithreaded optimizations: On
11:49:36:   Base resolution: 1920x1080
11:49:36:   Output resolution: 1920x1080
11:49:36: ------------------------------------------
11:49:36: Loading up D3D10 on AMD Radeon R9 200 Series (Adapter 1)...
11:49:36: ------------------------------------------
11:49:36: Audio Format: 48000 Hz
11:49:36: ------------------------------------------
11:49:36: Audio Channels: 2 Ch
11:49:36: Playback device Default
11:49:36: ------------------------------------------
11:49:36: Using desktop audio input: Speakers (Realtek High Definition Audio)
11:49:36: Global Audio time adjust: 0
11:49:36: ------------------------------------------
11:49:36: Audio Encoding: AAC
11:49:36:     bitrate: 128
11:49:36: Using Window Capture
11:49:36: Scene buffering time set to 700
11:49:36: x264: MB rate (489600) > level limit (245760)
11:49:36: ------------------------------------------
11:49:36: Video Encoding: x264
11:49:36:     fps: 60
11:49:36:     width: 1920, height: 1080
11:49:36:     preset: veryfast
11:49:36:     profile: main
11:49:36:     keyint: 120
11:49:36:     CBR: yes
11:49:36:     CFR: yes
11:49:36:     max bitrate: 3500
11:49:36:     buffer size: 3500
11:49:36: ------------------------------------------
11:55:18: Total frames encoded: 20438, total frames duplicated: 1192 (5.83%)
11:55:18: Number of frames skipped due to encoder lag: 1021 (5.00%)
11:55:18: Total frames rendered: 19442, number of late frames: 35 (0.18%) (it's okay for some frames to be late)
11:55:18:
11:55:18: Profiler time results:
11:55:18:
11:55:18: ==============================================================
11:55:18: video thread frame - [100%] [avg time: 0.939 ms] [children: 49.9%] [unaccounted: 50.1%]
11:55:18: | scene->Preprocess - [34.2%] [avg time: 0.321 ms]
11:55:18: | GPU download and conversion - [15.8%] [avg time: 0.148 ms] [children: 13.8%] [unaccounted: 1.92%]
11:55:18: | | flush - [11%] [avg time: 0.103 ms]
11:55:18: | | CopyResource - [2.56%] [avg time: 0.024 ms]
11:55:18: | | conversion to 4:2:0 - [0.319%] [avg time: 0.003 ms]
11:55:18: Convert444Threads - [100%] [avg time: 1.508 ms] [children: 99.6%] [unaccounted: 0.398%]
11:55:18: | Convert444toNV12 - [99.6%] [avg time: 1.502 ms]
11:55:18: encoder thread frame - [100%] [avg time: 3.702 ms] [children: 0.432%] [unaccounted: 99.6%]
11:55:18: | sending stuff out - [0.432%] [avg time: 0.016 ms]
11:55:18: ==============================================================
11:55:18:
11:55:18:
11:55:18: Profiler CPU results:
11:55:18:
11:55:18: ==============================================================
11:55:18: video thread frame - [cpu time: avg 0.189 ms, total 3687.5 ms] [avg calls per frame: 1]
11:55:18: | scene->Preprocess - [cpu time: avg 0.021 ms, total 421.875 ms] [avg calls per frame: 1]
11:55:18: | GPU download and conversion - [cpu time: avg 0.046 ms, total 906.25 ms] [avg calls per frame: 1]
11:55:18: | | flush - [cpu time: avg 0.03 ms, total 593.75 ms] [avg calls per frame: 1]
11:55:18: | | CopyResource - [cpu time: avg 0.01 ms, total 203.125 ms] [avg calls per frame: 1]
11:55:18: | | conversion to 4:2:0 - [cpu time: avg 0 ms, total 0 ms] [avg calls per frame: 1]
11:55:18: Convert444Threads - [cpu time: avg 1.414 ms, total 54875 ms] [avg calls per frame: 2]
11:55:18: | Convert444toNV12 - [cpu time: avg 1.408 ms, total 54640.6 ms] [avg calls per frame: 2]
11:55:18: encoder thread frame - [cpu time: avg 2.329 ms, total 47562.5 ms] [avg calls per frame: 1]
11:55:18: | sending stuff out - [cpu time: avg 0.009 ms, total 187.5 ms] [avg calls per frame: 1]
11:55:18: ==============================================================
11:55:18:
11:55:18: =====Stream End: 2014-08-26, 11:55:18=================================================
 
You tried another server in OBS? Sometimes it fixes the problem because servers are overloaded. I had this problem too. Changed from Frankfurt am Main (Germany) to Amsterdam (Germany too) and my frame drops are gone :)
 

TheMoatman

New Member
You tried another server in OBS? Sometimes it fixes the problem because servers are overloaded. I had this problem too. Changed from Frankfurt am Main (Germany) to Amsterdam (Germany too) and my frame drops are gone :)
The problem is it's not dropping frames on the network, it's skipping the render. This happens even when I only record locally
 
Top