protonscr

Vsync strange behaviour in d3d11-triangle

dxvkclosed
doitsujin/dxvk#1039 · opened 2019-04-30 by pchome · updated 2019-04-30 · 7 comments · github
3 matching comments, n / p to jump
Ppchome 2019-04-30 github

High CPU usage when Vsync enabled.

  1. Vsync on
    • GPU usage: 9%
    • CPU usage: high (one random core: 100%, the rest: minimum)
  2. Vsync off
    • GPU usage: 97%
    • CPU usage: medium (1st core higher than others, ~80%, the rest: medium)
  3. Vsync on + FPS limiter
    • GPU usage: 9%
    • CPU usage: minimum (~3%)

While "Vsync off" variant looks ok, "Vsync on" variant looks weird.

Suspects:

  1. I don't know how how VK_PRESENT_MODE_MAILBOX_KHR should work, because Nvidia blob have no "mailbox" support on Linux (like previously "immediate" mode on Windows, but now it in vulkan beta for Windows ), but I rather expect such behaviour is ok for "mailbox", not for VK_PRESENT_MODE_FIFO_KHR.
  2. I don't used d3d11-triangle test for a long time, but previously Vsync mode was ok (or I just not used it too often to notice). Used it to test 981ea547f946c092e4ac6c166b6720c704bdaf8e, 81f6ccb1bec0b22fb871d09a63beeb1f37e65c09, 4cc35da3b277537486cfaedeb36b66617f474684, if this is something I asked about in #861 (part 2). Well, the only thing I can tell : there is no noticeable difference after those commits with dxgi.numBackBuffers set to 2, 3 or 4 (or whatever).
  3. d3d11-triangle itself, or winelib, or GCC, or my setup ...

I hope this d3d11-triangle behaviour is reproducible, don't tested other apps yet.

Software information

d3d11-triangle.exe.so
default settings / dxgi.syncInterval = 0

System information

  • GPU: GeForce GTX 750 Ti
  • Driver: 418.52.05
  • Wine version: 4.6
  • DXVK version: master, winelib

Apitrace file(s)

--

Log files

Ddoitsujin maintainer 2019-04-30 github

d3d11-triangle.exe has like 3% CPU utilization on one core on my system. Can you check what's eating all the CPU time on your end (sudo perf top)?

Ppchome 2019-04-30 github

Probably I should build DXVK w/ debug symbols, I'll do this if needed.
But here is what perf top -p <d3d11-triangle pid> currently shows:

Vsync on
   PerfTop:    3946 irqs/sec  kernel:48.3%  exact:  0.0% [4000Hz cycles],  (target_pid: 31936)
------------------------------------------------------------------------------------------------------------------------------------------------------

     7.18%  [kernel]                       [k] native_sched_clock
     6.93%  [kernel]                       [k] entry_SYSCALL_64
     6.23%  [vdso]                         [.] 0x0000000000000663
     3.53%  [kernel]                       [k] update_curr
     3.51%  [kernel]                       [k] __schedule
     3.41%  [kernel]                       [k] pick_next_entity
     3.14%  [kernel]                       [k] yield_task_fair
     2.93%  libc-2.29.so                   [.] __sched_yield
     2.86%  [kernel]                       [k] pick_next_task_fair
     2.59%  libpthread-2.29.so             [.] __pthread_mutex_unlock_usercnt
     2.44%  libc-2.29.so                   [.] __clock_gettime
     2.37%  [kernel]                       [k] syscall_return_via_sysret
     2.01%  libpthread-2.29.so             [.] __pthread_mutex_lock
     1.94%  [kernel]                       [k] do_syscall_64
     1.94%  [vdso]                         [.] 0x0000000000000617
     1.74%  d3d11.dll.so                   [.] 0x00000000000c5cc3
     1.68%  libpthread-2.29.so             [.] __pthread_mutex_unlock
     1.46%  [kernel]                       [k] __rcu_read_unlock
     1.36%  [vdso]                         [.] 0x0000000000000619
     1.29%  d3d11.dll.so                   [.] 0x00000000000c5cdc
     1.19%  [kernel]                       [k] __calc_delta
     1.11%  [kernel]                       [k] rcu_note_context_switch
     1.09%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa0c0
     1.05%  [kernel]                       [k] cgroup_rstat_updated
     1.00%  [kernel]                       [k] update_min_vruntime
     0.99%  [kernel]                       [k] _raw_spin_lock
     0.85%  [kernel]                       [k] do_sched_yield
     0.84%  d3d11.dll.so                   [.] 0x00000000000c5c36
     0.74%  libstdc++.so.6.0.25            [.] std::chrono::_V2::system_clock::now
     0.71%  [kernel]                       [k] cpuacct_charge
     0.68%  [kernel]                       [k] schedule
     0.64%  [kernel]                       [k] clear_buddies
     0.54%  [vdso]                         [.] __vdso_clock_gettime
     0.53%  [vdso]                         [.] 0x0000000000000643
     0.49%  [kernel]                       [k] _raw_spin_unlock_irq
     0.46%  [vdso]                         [.] 0x000000000000063b
     0.44%  d3d11.dll.so                   [.] 0x000000000008c38d
     0.44%  [kernel]                       [k] __rcu_read_lock
     0.40%  d3d11-triangle.exe.so          [.] WinMain
     0.38%  [kernel]                       [k] update_rq_clock.part.88
     0.37%  [kernel]                       [k] sched_clock_cpu
     0.33%  [kernel]                       [k] check_cfs_rq_runtime
     0.31%  d3d11.dll.so                   [.] 0x00000000000664b3
     0.29%  [vdso]                         [.] 0x000000000000067b
     0.29%  d3d11.dll.so                   [.] 0x000000000008c388
     0.27%  [kernel]                       [k] __ia32_sys_sched_yield
     0.27%  [kernel]                       [k] rcu_preempt_deferred_qs
     0.24%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be0e7
     0.24%  [kernel]                       [k] cgroup_base_stat_cputime_account_end.isra.7
     0.22%  [vdso]                         [.] 0x000000000000066c
     0.21%  d3d11.dll.so                   [.] 0x0000000000066401
     0.20%  d3d11.dll.so                   [.] 0x000000000008c481
     0.19%  d3d11.dll.so                   [.] 0x00000000000c5bc6
     0.19%  d3d11.dll.so                   [.] 0x00000000000d384d
     0.18%  d3d11.dll.so                   [.] 0x00000000000c5bbe
     0.18%  d3d11.dll.so                   [.] 0x00000000000c5c3c
     0.18%  [kernel]                       [k] __cgroup_account_cputime
     0.18%  d3d11.dll.so                   [.] 0x00000000000c5af8
     0.16%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa102
     0.16%  d3d11.dll.so                   [.] 0x00000000000c5b53
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be114
     0.16%  [kernel]                       [k] _raw_spin_unlock
     0.16%  d3d11.dll.so                   [.] 0x0000000000066419
     0.15%  d3d11.dll.so                   [.] 0x00000000000c5ac3
     0.15%  d3d11.dll.so                   [.] 0x00000000000c5cc6
     0.15%  [vdso]                         [.] 0x0000000000000674
     0.15%  d3d11.dll.so                   [.] 0x00000000000c5add
     0.14%  d3d11.dll.so                   [.] 0x0000000000024500
     0.14%  d3d11.dll.so                   [.] 0x00000000000c5cbb
     0.14%  [vdso]                         [.] 0x000000000000061c
     0.14%  d3d11.dll.so                   [.] 0x00000000000c5c42
     0.14%  d3d11.dll.so                   [.] 0x00000000000c5cdf
Vsync off
   PerfTop:    5289 irqs/sec  kernel:30.6%  exact:  0.0% [4000Hz cycles],  (target_pid: 31590)
------------------------------------------------------------------------------------------------------------------------------------------------------

     2.92%  [kernel]                       [k] native_sched_clock
     2.25%  [kernel]                       [k] entry_SYSCALL_64
     1.75%  [vdso]                         [.] 0x0000000000000663
     1.52%  [kernel]                       [k] update_curr
     1.42%  [kernel]                       [k] __schedule
     1.35%  libc-2.29.so                   [.] __sched_yield
     1.10%  [kernel]                       [k] pick_next_task_fair
     1.04%  libpthread-2.29.so             [.] __pthread_mutex_lock
     0.99%  [kernel]                       [k] yield_task_fair
     0.90%  [kernel]                       [k] do_syscall_64
     0.89%  [kernel]                       [k] pick_next_entity
     0.84%  [kernel]                       [k] __update_load_avg_cfs_rq
     0.82%  [kernel]                       [k] syscall_return_via_sysret
     0.78%  [kernel]                       [k] __rcu_read_unlock
     0.75%  [nvidia]                       [k] _nv020236rm
     0.73%  [kernel]                       [k] update_min_vruntime
     0.69%  [kernel]                       [k] update_blocked_averages
     0.68%  d3d11.dll.so                   [.] 0x00000000000d50e4
     0.66%  libpthread-2.29.so             [.] __pthread_mutex_unlock_usercnt
     0.66%  libpthread-2.29.so             [.] __pthread_mutex_unlock
     0.61%  [vdso]                         [.] 0x0000000000000617
     0.56%  [kernel]                       [k] __calc_delta
     0.55%  d3d11.dll.so                   [.] 0x00000000000c5cc3
     0.52%  libstdc++.so.6.0.25            [.] __dynamic_cast
     0.51%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa0c0
     0.50%  libc-2.29.so                   [.] __clock_gettime
     0.43%  libstdc++.so.6.0.25            [.] __cxxabiv1::__vmi_class_type_info::__do_dyncast
     0.42%  [vdso]                         [.] 0x0000000000000619
     0.39%  [kernel]                       [k] cgroup_rstat_updated
     0.36%  [kernel]                       [k] rcu_note_context_switch
     0.34%  d3d11.dll.so                   [.] 0x00000000000c5cdc
     0.31%  d3d11.dll.so                   [.] 0x00000000000d4d45
     0.30%  [kernel]                       [k] do_sched_yield
     0.30%  [kernel]                       [k] __fget
     0.29%  d3d11.dll.so                   [.] 0x00000000000d5113
     0.29%  [kernel]                       [k] __update_load_avg_se
     0.29%  [kernel]                       [k] cpuacct_charge
     0.28%  [kernel]                       [k] _raw_spin_lock
     0.28%  [kernel]                       [k] clear_buddies
     0.27%  d3d11-triangle.exe.so          [.] WinMain
     0.27%  [kernel]                       [k] enqueue_entity
     0.26%  libstdc++.so.6.0.25            [.] std::chrono::_V2::system_clock::now
     0.26%  d3d11.dll.so                   [.] 0x00000000000d5214
     0.25%  [kernel]                       [k] schedule
     0.25%  [kernel]                       [k] pci_conf1_read
     0.25%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011b5804
     0.25%  libstdc++.so.6.0.25            [.] __cxxabiv1::__si_class_type_info::__do_dyncast
     0.24%  [kernel]                       [k] try_to_wake_up
     0.24%  d3d11.dll.so                   [.] 0x00000000000d4d6d
     0.24%  [vdso]                         [.] __vdso_clock_gettime
     0.23%  d3d11.dll.so                   [.] 0x00000000000d50db
     0.22%  ntdll.dll.so                   [.] RtlAllocateHeap
     0.22%  libpthread-2.29.so             [.] pthread_cond_wait@@GLIBC_2.3.2
     0.21%  [kernel]                       [k] psi_task_change
     0.21%  libc-2.29.so                   [.] malloc
     0.21%  [kernel]                       [k] __rcu_read_lock
     0.20%  libc-2.29.so                   [.] memcpy
     0.20%  d3d11.dll.so                   [.] 0x00000000000d507e
     0.20%  d3d11.dll.so                   [.] 0x00000000000d4d11
     0.19%  d3d11.dll.so                   [.] 0x00000000000d5059
     0.18%  [kernel]                       [k] dequeue_entity
     0.18%  d3d11.dll.so                   [.] 0x00000000000d5220
     0.18%  d3d11.dll.so                   [.] 0x00000000000d4df0
     0.18%  [kernel]                       [k] unix_stream_read_generic
     0.17%  [kernel]                       [k] futex_wake
     0.17%  [kernel]                       [k] update_cfs_group
     0.17%  [vdso]                         [.] 0x0000000000000643
     0.17%  libstdc++.so.6.0.25            [.] std::basic_streambuf<char, std::char_traits<char> >::xsputn
     0.17%  [kernel]                       [k] sched_clock_cpu
     0.16%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aee34
     0.16%  libstdc++.so.6.0.25            [.] std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow
     0.16%  [kernel]                       [k] _raw_spin_unlock_irq
Ppchome 2019-04-30 github
     8.19%  d3d11.dll.so                   [.] dxvk::D3D11ImmediateContext::GetData
     6.47%  [kernel]                       [k] native_sched_clock
     6.15%  [vdso]                         [.] 0x0000000000000663

vs

     3.25%  d3d11.dll.so                   [.] dxvk::hud::HudFps::renderFrametimeGraph
     2.93%  [kernel]                       [k] native_sched_clock
     2.46%  [kernel]                       [k] entry_SYSCALL_64
Ppchome 2019-04-30 github
Disabled kernel calls and DXVK_HUD
   PerfTop:    4111 irqs/sec  kernel:50.8%  exact:  0.0% [4000Hz cycles],  (target_pid: 16188)
------------------------------------------------------------------------------------------------------------------------------------------------------

    17.47%  d3d11.dll.so                   [.] dxvk::D3D11ImmediateContext::GetData
    11.74%  [vdso]                         [.] 0x0000000000000663
     6.29%  d3d11.dll.so                   [.] dxvk::D3D11ImmediateContext::Flush
     5.36%  libc-2.29.so                   [.] __sched_yield
     4.81%  libpthread-2.29.so             [.] __pthread_mutex_unlock_usercnt
     4.35%  d3d11.dll.so                   [.] dxvk::D3D11ImmediateContext::SynchronizeCsThread
     3.77%  libpthread-2.29.so             [.] __pthread_mutex_lock
     3.77%  d3d11.dll.so                   [.] dxvk::D3D11Query::GetDataSize
     3.15%  [vdso]                         [.] 0x0000000000000617
     2.99%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa0c0
     2.78%  d3d11.dll.so                   [.] dxvk::D3D11ImmediateContext::FlushImplicit
     2.64%  libc-2.29.so                   [.] __clock_gettime
     2.64%  [vdso]                         [.] 0x0000000000000619
     2.26%  d3d11.dll.so                   [.] dxvk::DxvkGpuQuery::getDataForHandle
     1.39%  libpthread-2.29.so             [.] __pthread_mutex_unlock
     1.30%  libstdc++.so.6.0.25            [.] std::chrono::_V2::system_clock::now
     1.12%  [vdso]                         [.] __vdso_clock_gettime
     1.05%  [vdso]                         [.] 0x0000000000000643
     0.79%  [vdso]                         [.] 0x000000000000063b
     0.79%  d3d11-triangle.exe.so          [.] WinMain
     0.55%  [vdso]                         [.] 0x000000000000067b
     0.48%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be0e7
     0.40%  [vdso]                         [.] 0x000000000000066c
     0.34%  [vdso]                         [.] 0x00000000000005f6
     0.34%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa102
     0.31%  [vdso]                         [.] 0x000000000000061c
     0.30%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be137
     0.29%  [vdso]                         [.] 0x0000000000000674
     0.27%  libnvidia-glcore.so.418.52.05  [.] 0x0000000001175531
     0.26%  [vdso]                         [.] 0x00000000000005e0
     0.25%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be114
     0.25%  [vdso]                         [.] 0x0000000000000600
     0.24%  [vdso]                         [.] 0x0000000000000627
     0.24%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be05d
     0.24%  [vdso]                         [.] 0x00000000000005eb
     0.24%  libnvidia-glcore.so.418.52.05  [.] 0x0000000001173138
     0.23%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be03b
     0.23%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011754fe
     0.23%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011bdfd7
     0.23%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011aaed1
     0.22%  [vdso]                         [.] 0x0000000000000614
     0.22%  d3d11.dll.so                   [.] pthread_mutex_lock@plt
     0.21%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be031
     0.21%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be11f
     0.21%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011aaec1
     0.21%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011aadb6
     0.20%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011755c0
     0.20%  [vdso]                         [.] 0x0000000000000633
     0.20%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be07b
     0.20%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be00c
     0.19%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be10a
     0.19%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa0f2
     0.18%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011bdfea
     0.18%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa5c2
     0.18%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011754c7
     0.17%  libnvidia-glcore.so.418.52.05  [.] 0x000000000117550e
     0.17%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011755e1
     0.17%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be0f4
     0.17%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011754ad
     0.17%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011663b3
     0.17%  d3d11-triangle.exe.so          [.] sched_yield@plt
     0.16%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa0cc
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011754e4
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011754dd
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011a4890
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011755ca
     0.16%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa5a5
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011a4899
     0.16%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011aad75
     0.16%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa595
     0.15%  libnvidia-glcore.so.418.52.05  [.] 0x00000000011be053
     0.15%  libGLX_nvidia.so.418.52.05     [.] 0x00000000000aa0e3
Ddoitsujin maintainer 2019-04-30 github

Ah yeah, that kind of makes sense actually, depending on when Present happens.

Thing is, the triangle demo is incredibly stupid, it doesn't just render six triangles, it also blocks on an occlusion query immediately after Present, which causes a CPU<>GPU sync (which is implemented by calling GetData until it returns S_OK). Depending on when the command buffer gets executed, this can take quite a while, I wouldn't read too much into it.

Ppchome 2019-04-30 github

Ok then. Hope there is no much "incredibly stupid" games in the wild ;) .

Ddoitsujin maintainer 2019-04-30 github

cough Unreal Engine 4. It's literally the reason why I rewrote the entire query implementation for DXVK 1.1, to reduce these stalls in actual games. It's not quite as bad as in the d3d11-triangle sample, but it still waits for the GPU a fair amount.

Launch options

DLLs