search

Facepunch / sbox-issues

176 stars 12 forks source link

sbox-dev.exe random Vulkan crash #5562

Open UAVXP opened 4 months ago

UAVXP commented 4 months ago

Describe the bug

I'm experiencing an s&box Editor crash. It happens pretty randomly, but I cannot work normally cause of it. (s&box game is not crashing for me btw, at least not that often, and if it crashes - I think it's because of certain games)

GPU: AMD Radeon R7 360 2GB GPU driver version: 21.09.13.02-220802a-382934C-RadeonSoftware GPU software version: 2022.0802.1058.19750 Vulkan Driver version: 2.0.179 Vulkan API version: 1.2.170

s&box Steam build 14467697

To Reproduce

Unfortunately, there's no consistent reproduction for this, but it somewhat consistently happened to me a few times when I was trying to put mouse on a three dot button of my custom controller. Another time I caused a crash was when I tried to press on my Player object in a hierarchy

Expected behavior

No crash

Media/Files

Log.log vulkaninfo.txt

Additional context

I also noticed that script hotloading stops to work before crash. Don't know if it related

UAVXP commented 4 months ago

I enabled "Verbose Engine Logging" and I can see a bunch of engine/RenderSystem [63] CSwapChainVulkan::SwapBuffers(): the main thread is more than 3 frames ahead which means no swap queue images are available. Waiting for outstanding frames... The number in square brackets is increasing very rapidly

UAVXP commented 4 months ago

Part of crash log with "Verbose Engine Logging" enabled:

2024/05/23 17:02:27.1756    [engine/RenderSystem] CSwapChainVulkan::SwapBuffers(): the main thread is more than 3 frames ahead which means no swap queue images are available.  Waiting for outstanding frames...   
2024/05/23 17:02:27.2893    [engine/ResourceSystem] WARNING: Long resource system update - should have taken no more than 3271112ns, but took 0.0078s! (Frame #1252969) 
...
...
...
2024/05/23 17:02:55.5335    [engine/InputBindSystem] * Rehandling active codes  
2024/05/23 17:02:55.6263    [ControlWidget] Target Type: System.String  
2024/05/23 17:02:55.6263    [ControlWidget]  1. [1000]  Editor.StringControlWidget  
2024/05/23 17:02:55.6263    [ControlWidget] Target Type: Sandbox.GameTags   
2024/05/23 17:02:55.6263    [ControlWidget]  1. [100]   Editor.TagSetControlWidget  
2024/05/23 17:02:55.6418    [ControlWidget] Target Type: Vector3    
2024/05/23 17:02:55.6418    [ControlWidget]  1. [1000]  Editor.VectorControlWidget  
2024/05/23 17:02:55.6418    [ControlWidget] Target Type: Rotation   
2024/05/23 17:02:55.6418    [ControlWidget]  1. [1000]  Editor.RotationControlWidget    
2024/05/23 17:02:55.6418    [ControlWidget] Target Type: Angles 
2024/05/23 17:02:55.6418    [ControlWidget]  1. [1000]  Editor.AnglesControlWidget  
2024/05/23 17:02:55.6591    [ControlWidget] Target Type: Vector3    
2024/05/23 17:02:55.6591    [ControlWidget]  1. [1000]  Editor.VectorControlWidget  
2024/05/23 17:02:55.6591    [ControlWidget] Target Type: System.Boolean 
2024/05/23 17:02:55.6737    [ControlWidget]  1. [1000]  Editor.BoolControlWidget    
2024/05/23 17:02:55.6737    [ControlWidget] Target Type: System.Boolean 
2024/05/23 17:02:55.6737    [ControlWidget]  1. [1000]  Editor.BoolControlWidget    
2024/05/23 17:02:55.6737    [ControlWidget] Target Type: System.Boolean 
2024/05/23 17:02:55.6737    [ControlWidget]  1. [1000]  Editor.BoolControlWidget    
2024/05/23 17:02:55.6896    [ControlWidget] Target Type: System.Boolean 
2024/05/23 17:02:55.6896    [ControlWidget]  1. [1000]  Editor.BoolControlWidget    
2024/05/23 17:02:55.6896    [ControlWidget] Target Type: Sandbox.GameObject 
2024/05/23 17:02:55.6896    [ControlWidget]  1. [1000]  Editor.GameObjectControlWidget  
2024/05/23 17:02:55.6896    [ControlWidget] Target Type: Sandbox.CharacterController    
2024/05/23 17:02:55.6896    [ControlWidget]  1. [100]   Editor.ComponentControlWidget   
2024/05/23 17:02:55.7049    [ControlWidget] Target Type: Sandbox.Citizen.CitizenAnimationHelper 
2024/05/23 17:02:55.7049    [ControlWidget]  1. [100]   Editor.ComponentControlWidget   
2024/05/23 17:02:55.7049    [ControlWidget] Target Type: System.Single  
2024/05/23 17:02:55.7049    [ControlWidget]  1. [1000]  Editor.FloatControlWidget   
2024/05/23 17:02:55.7049    [ControlWidget] Target Type: System.Single  
2024/05/23 17:02:55.7049    [ControlWidget]  1. [1000]  Editor.FloatControlWidget   
2024/05/23 17:02:55.7214    [ControlWidget] Target Type: System.Single  
2024/05/23 17:02:55.7214    [ControlWidget]  1. [1000]  Editor.FloatControlWidget   
2024/05/23 17:02:55.7214    [ControlWidget] Target Type: Vector3    
2024/05/23 17:02:55.7214    [ControlWidget]  1. [1000]  Editor.VectorControlWidget  
2024/05/23 17:02:55.7368    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7368    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7368    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7368    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7540    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7540    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7540    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7540    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7676    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7676    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7676    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7676    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7676    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7841    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7841    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7841    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7841    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7976    [ControlWidget] Target Type: System.Threading.Tasks.Task    
2024/05/23 17:02:55.7976    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7976    [ControlWidget] Target Type: T  
2024/05/23 17:02:55.7976    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.7976    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.8163    [ControlWidget] Target Type: System.Text.Json.Nodes.JsonNode    
2024/05/23 17:02:55.8163    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.8163    [ControlWidget] Target Type: System.Void    
2024/05/23 17:02:55.9753    [engine/RenderSystem] CSwapChainVulkan::SwapBuffers(): the main thread is more than 3 frames ahead which means no swap queue images are available.  Waiting for outstanding frames...   
2024/05/23 17:02:55.9922    [engine/RenderSystem] TEXMAN: Deleting 7 textures   
2024/05/23 17:02:59.2225    [engine/SoundSystemLowLevel] Audio device starved 512 samples   
2024/05/23 17:02:59.2225    [engine/SoundSystemLowLevel] Audio device starved 512 samples   
2024/05/23 17:02:59.2889    [engine/RenderSystem] ERROR! VK call failed! result = VK_ERROR_DEVICE_LOST ( vkQueueSubmit( pQueue, 1, &submitInfo, pFence->Get() ) )

Here's the full Log.log

UAVXP commented 4 months ago

Here's a new Log.log

This time the editor surprised me as how consistent it was in terms of hotloading scripts after editing... But the issue appeared again, along with familiar "CSwapChainVulkan::SwapBuffers()" complains.

The first time I tested editor keeps working fine, until hotloading stops (compiling popups stops showing), I went to check an editor, hit Play - and the editor crashed. I then restart it, enabled "Verbose" and "Trace" logging, and captured aforementioned log.

I start to feel that it's some kind of hotloading-related issue

samzanemesis commented 4 months ago

Try now, I reworked how things work but I cannot reproduce the issue myself, hopefully it's sorted

UAVXP commented 4 months ago

Log.log This time issue appeared even faster after I played with a Game window placement.

After that I've verified game files integrity, it fixed 16 files. I ran Game Editor, played with windows a bit, opened a script for a component, decided to record my crash for you. Just after I closed VS and editor - it crashed: Log.log

Third run. This time I recorded this crash, here's the Log.log And a video: https://www.youtube.com/watch?v=Vr0CdwUOyk4

Then I ran the game itself and cleared "Unused Assets" in "Cache & Storage" few times. Here's the Log.log from that game run, just in case. Also, verified integrity of game files again (20 files failed to validate this time) and created a new project in s&box Editor. Well, you guessed it right - Editor crashed. Log.log https://www.youtube.com/watch?v=gTK2ybcvOnw

Don't know if this will help, but here's this "Vulkan Crash Project" from the last video: vulkan_crash_project.zip I forgot to save every second, so... It's just a default project unfortunately

UAVXP commented 4 months ago

Here's a new project: vulkan_crash_project.zip I managed to somewhat pinpoint a way to crash. You need to move windows around, like Game window, for example. Then try to move one box from a scene in a spastic way. Here's a Log.log, as usual

UPD: *Select all the boxes and try to move them

UAVXP commented 3 months ago

New portion of logs, I think there are some new messages, might be handy:

2024/06/16 13:59:18.6932    [engine/Engine] CSwapChainBase::QueuePresentAndWait() looped for 22 iterations without a present event. 
2024/06/16 13:59:18.6932    [engine/RenderSystem] CSwapChainVulkan::SwapBuffers(): the main thread is more than 3 frames ahead which means no swap queue images are available.  Waiting for outstanding frames...   
2024/06/16 13:59:18.7172    [engine/RenderSystem] FrameSync() - bailing out of vkWaitForFences( fenceCount = 1 ) after 0.250518 seconds, error = VK_TIMEOUT 
2024/06/16 13:59:18.9702    [engine/RenderSystem] FrameSync() - bailing out of vkWaitForFences( fenceCount = 2 ) after 0.250350 seconds, error = VK_TIMEOUT 
2024/06/16 13:59:21.9710    [engine/RenderSystem] ERROR! VK call failed! result = VK_TIMEOUT ( vkQueueWaitIdle( VulkanQueue() ) )   
2024/06/16 13:59:21.9710    [engine/RenderSystem] CSwapChainVulkan::SwapBuffers(): waited for 3.28 seconds  
2024/06/16 13:59:22.1875    [engine/RenderSystem] ERROR! VK call failed! result = VK_ERROR_DEVICE_LOST ( vkQueueSubmit( VulkanQueue(), 1, &submitInfo, presentFence.m_pFence ) )    
2024/06/16 13:59:22.1875    [engine/RenderSystem] CSwapChainVulkan::SwapBuffers(): the main thread is more than 3 frames ahead which means no swap queue images are available.  Waiting for outstanding frames...   
2024/06/16 13:59:22.1875    [engine/RenderSystem] ERROR! VK call failed! result = VK_ERROR_DEVICE_LOST ( vkQueueSubmit( pQueue, 1, &submitInfo, pFence->Get() ) )   
2024/06/16 13:59:27.2397    [engine/ToolsStallMonitor] Stall detected.

Log.log