protonscr

Look into semaphore error spam

vkd3dclosed
HansKristian-Work/vkd3d-proton#65 · opened 2020-03-30 by HansKristian-Work · updated 2020-03-31 · 2 comments · github
HHansKristian-Work 2020-03-30 github

Games like WoW have a lot of spam like:

fixme:d3d12_command_queue_Wait: Failed to acquire Vulkan semaphore for fence 0x7f2fd72ffc60, value 0x2ed9, completed value 0x2ed8.

It does not seem to affect rendering, but we should investigate if there is some underlying bug.

SSveSop 2020-03-30 github

Would/could things like this cause some kind of buffer to be filled, that eventually lead to a adapter reset you think? I do not run with logging enabled - i set VKD3D_DEBUG=none and WINEDEBUG=-all since it takes somewhat of a toll to do logging if not strictly necessary... so in theory atleast a wine/vkd3d log would not be created at all.

I know the nVidia driver is somewhat not 110% these days, but i have tested with a few. 440.43 (vulkan beta series), 440.66 (vulkan beta series) and 440.59 (release) and the problem is the same.

When playing WoW the GPU resets - that is, the picture freezes for like 3-4 seconds, then come alive again. The WoW log (gx.log) logs a "GxRestart".

3/29 19:21:31.511  LogOpen
3/29 19:21:32.130  Wine detected, skipping NvAPI/ADL loading
3/29 19:21:32.400  Adapter 0: "NVIDIA GeForce RTX 2070" vendor:0x10de device:0x1f07 driver(0xa0012, 0xd0fd4) dx11:true dx12:true
3/29 19:21:32.400  	Monitor 0 "\\.\DISPLAY1" (2560x1440)
3/29 19:21:32.440  D3d12 Device Create
3/29 19:21:32.685  Taking Adapter 0 by name: "NVIDIA GeForce RTX 2070"
3/29 19:21:32.685  Choosing adapter 0
3/29 19:21:32.861  AFR Groups: 1/1
3/29 19:21:32.861  Feature Level: DX=3, MTL=0
3/29 19:21:33.058  NotifyOnDeviceCreate
3/29 19:21:33.058  D3d12 Device Create Successful
3/29 19:21:33.058  <IsGPUDriverOutOfDate> No
3/29 19:21:33.145  CPU Processor Detection: 12 H/W threads
3/29 19:21:33.145  Memory Detection: 18866413568 bytes of physical memory available
3/29 19:21:33.145  Detected Graphics Defaults: 6 (CPU = 6, GPU = 6, MEM = 6)
3/29 19:21:33.224  RenderSettings::NotifyChanged
3/29 20:29:40.671  Error WaitForSingleObjectEx Timeout: Attempt to JOIN onto a JOINed drive. (0x8007008A).
3/29 20:29:40.679  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
- repeated number of times -
3/29 20:29:40.778  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
3/29 20:29:40.779  Device context was lost. Attempting recovery. Occurrence: 1
3/29 20:29:40.782  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
3/29 20:29:40.783  GxRestart
3/29 20:29:40.783  D3d12 Device Destroy
3/29 20:29:40.784  NotifyOnDeviceDestroy
3/29 20:29:41.279  D3d12 Device Create
3/29 20:29:41.494  Taking Adapter 0 by name: "NVIDIA GeForce RTX 2070"
3/29 20:29:41.494  Choosing adapter 0
3/29 20:29:41.631  AFR Groups: 1/1
3/29 20:29:41.631  Feature Level: DX=3, MTL=0
3/29 20:29:41.646  NotifyOnDeviceCreate
3/29 20:29:44.873  D3d12 Device Create Successful
3/29 20:29:44.873  <IsGPUDriverOutOfDate> No
3/29 21:24:50.835  Error WaitForSingleObjectEx Timeout: Attempt to JOIN onto a JOINed drive. (0x8007008A).
3/29 21:24:50.847  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
- repeated number of times -
3/29 21:24:50.917  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
3/29 21:24:50.928  Device context was lost. Attempting recovery. Occurrence: 2
3/29 21:24:50.931  GxRestart
3/29 21:24:50.931  D3d12 Device Destroy
3/29 21:24:50.931  NotifyOnDeviceDestroy
3/29 21:24:51.627  D3d12 Device Create
3/29 21:24:51.836  Taking Adapter 0 by name: "NVIDIA GeForce RTX 2070"
3/29 21:24:51.836  Choosing adapter 0
3/29 21:24:51.984  AFR Groups: 1/1
3/29 21:24:51.984  Feature Level: DX=3, MTL=0
3/29 21:24:52.000  NotifyOnDeviceCreate
3/29 21:24:55.179  D3d12 Device Create Successful
3/29 21:24:55.179  <IsGPUDriverOutOfDate> No
3/29 21:58:52.280  Error WaitForSingleObjectEx Timeout: Attempt to JOIN onto a JOINed drive. (0x8007008A).
3/29 21:58:52.293  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
- repeated number of times -
3/29 21:58:52.370  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
3/29 21:58:52.425  Device context was lost. Attempting recovery. Occurrence: 3
3/29 21:58:52.433  GxRestart
3/29 21:58:52.433  D3d12 Device Destroy
3/29 21:58:52.434  NotifyOnDeviceDestroy
3/29 21:58:53.195  D3d12 Device Create
3/29 21:58:53.415  Taking Adapter 0 by name: "NVIDIA GeForce RTX 2070"
3/29 21:58:53.415  Choosing adapter 0
3/29 21:58:53.559  AFR Groups: 1/1
3/29 21:58:53.559  Feature Level: DX=3, MTL=0
3/29 21:58:53.575  NotifyOnDeviceCreate
3/29 21:58:56.258  D3d12 Device Create Successful
3/29 21:58:56.258  <IsGPUDriverOutOfDate> No
3/29 23:28:11.970  Error WaitForSingleObjectEx Timeout: Attempt to JOIN onto a JOINed drive. (0x8007008A).
3/29 23:28:11.991  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
- repeated number of times -
3/29 23:28:12.019  GxTexCreate short-circuited due to no device context for texture "GxuFont" (128x128x1)
3/29 23:28:12.019  Device context was lost. Attempting recovery. Occurrence: 4
3/29 23:28:12.022  GxRestart
3/29 23:28:12.022  D3d12 Device Destroy
3/29 23:28:12.023  NotifyOnDeviceDestroy
3/29 23:28:12.888  D3d12 Device Create
3/29 23:28:13.125  Taking Adapter 0 by name: "NVIDIA GeForce RTX 2070"
3/29 23:28:13.125  Choosing adapter 0
3/29 23:28:13.267  AFR Groups: 1/1
3/29 23:28:13.267  Feature Level: DX=3, MTL=0
3/29 23:28:13.284  NotifyOnDeviceCreate
3/29 23:28:15.491  D3d12 Device Create Successful
3/29 23:28:15.491  <IsGPUDriverOutOfDate> No
3/29 23:55:58.677  D3d12 Device Destroy
3/29 23:55:58.677  NotifyOnDeviceDestroy
3/29 23:55:59.545  GxShutdown

The reason i ask about filling a buffer, is because this then seems to occur somewhat at regular intervals when "under load" (spell-effects and whatnot causing high gpu usage). I had a break without doing much other than hanging around town between 22'ish and 23:15'ish where i did a instance. The log is from a raid starting 19:30 and ending at 22. I "crashed" 3 times in the raid, and 1 time in the instance. If you look at the time, it seems that from start at 19:30, i crash 1 hour later at 20:29, then 1 hour after that at 21:24, and 30 minutes after that just before ending the raid at 21:58. 1.5 hours after that (when inside the instance) i had another crash. I did not experience any problems when just hanging around.

Far fetched maybe?

If one of those crashes happens (does not happen as often, but they DO happen) with DXVK, WoW will crash with a Error # 132 - memory could not be read and the client exits. With vkd3d, this "just" causes a gpu restart. The gx.log i think does not log the same error when WoW crashes with DXVK, as the client then aborts and wine exits before that happens.

If you feel this is totally unrelated, i could open a separate issue, or for that matter if it does not seem related to vkd3d ill just continue to do more testing.

HHansKristian-Work maintainer 2020-03-30 github

@SveSop not sure if this is related. Anyways, found the issue. Wow is first submitting a wait for a semaphore, and then that value gets signalled from CPU a bit later, which unblocks the GPU.

I think we'll need timeline semaphores to implement this correctly.

Launch options

Error codes