Re: [Qemu-discuss] Odd QXL performance issue with a Windows 7 Guest

[Brad Campbell]

On 1/9/19 21:28, Brad Campbell wrote:> G'day all,
> I have a box which has the sole purpose of running a Windows 7 VM. It's 
> an i7-3770K built in 2013 and happily runs a Windows 7 VM with 2 QXL 
> heads which are displayed remotely over a 1GB ethernet to a client 
> running the spicy spice-gtk client.

....

> CPU/FPU/Memory/Storage are all comparable. GDI performance is similar, 
> but when we get to the D2D test the Intel box runs at about ~50 FPS and 
> the AMD box runs ~5FPS. That explains the interactive issues when 
> running CAD in the guest.

....
 
> I've tried enabling simpletrace and run traces on both machines. Aside 
> from the intel machine time deltas for the commands being ~ half those 
> on the AMD box I really can spot anything strange.

Ok, so enabling tracing for the guest, ring and qxl_* tracepoints and I can now 
see an issue.

These traces are snapped out of a benchmark run when it's clearly demonstrating 
the issue. i7 ~ 60fps, Ryzen ~8fps.

This is a trace from the i7 box :

qxl/guest-0: 36633582382: qxldd: DrvCopyBits
30794@1567418204.460991:qxl_ring_cursor_check 0 native
30794@1567418204.461016:qxl_ring_command_check 0 native
30794@1567418204.465960:qxl_ring_cursor_check 0 native
30794@1567418204.465979:qxl_ring_command_check 0 native
30794@1567418204.465989:qxl_ring_cursor_check 0 native
30794@1567418204.465997:qxl_ring_command_check 0 native
30794@1567418204.469440:qxl_io_write 0 native addr=4 (QXL_IO_NOTIFY_OOM) val=0 
size=1 async=0
30794@1567418204.469466:qxl_spice_oom 0
30794@1567418204.469517:qxl_ring_command_check 0 native
30794@1567418204.469538:qxl_ring_res_push_rest 0 ring 1/8 [125,124]
30794@1567418204.469552:qxl_send_events 0 1
30794@1567418204.469568:qxl_ring_cursor_check 0 native
30794@1567418204.469577:qxl_ring_command_check 0 native
30794@1567418204.469587:qxl_ring_cursor_check 0 native
30794@1567418204.469595:qxl_ring_command_check 0 native
30794@1567418204.469604:qxl_ring_cursor_check 0 native
30794@1567418204.469611:qxl_ring_command_check 0 native
30794@1567418204.469622:qxl_io_write 0 native addr=3 (QXL_IO_UPDATE_IRQ) val=0 
size=1 async=0
30794@1567418204.469658:qxl_io_write 0 native addr=3 (QXL_IO_UPDATE_IRQ) val=0 
size=1 async=0
30794@1567418204.470821:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0
30794@1567418204.470888:qxl_ring_cursor_check 0 native
30794@1567418204.470904:qxl_ring_command_check 0 native
36647479204 qxl-0/cmd: cmd @ 0x10000000104b798 draw: surface_id 0 type copy 
effect opaque src 10000000348f840 (id 10ae0870780 type 0 flags 0 width 1920 
height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 
10000000348f870) area 1920x1080+0+0 rop 8
30794@1567418204.470967:qxl_ring_command_get 0 native
30794@1567418204.471014:qxl_ring_command_check 0 native
30794@1567418204.471026:qxl_ring_cursor_check 0 native
30794@1567418204.471034:qxl_ring_command_check 0 native
30794@1567418204.471042:qxl_ring_command_req_notification 0
30794@1567418204.471051:qxl_ring_cursor_check 0 native
30794@1567418204.471059:qxl_ring_command_check 0 native
30794@1567418204.471667:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 
async=0
30794@1567418204.471689:qxl_io_log 0 qxldd: DrvCopyBits

qxl/guest-0: 36648262127: qxldd: DrvCopyBits
30794@1567418204.475330:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0
30794@1567418204.475417:qxl_ring_cursor_check 0 native
30794@1567418204.475435:qxl_ring_command_check 0 native
36652010610 qxl-0/cmd: cmd @ 0x10000000104b498 draw: surface_id 0 type copy 
effect opaque src 100000001a0ff78 (id 10be0870780 type 0 flags 0 width 1920 
height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 
100000001a0ffa8) area 1920x1080+0+0 rop 8
30794@1567418204.475498:qxl_ring_command_get 0 native
30794@1567418204.475548:qxl_ring_command_check 0 native
30794@1567418204.475562:qxl_ring_cursor_check 0 native
30794@1567418204.475571:qxl_ring_command_check 0 native
30794@1567418204.475579:qxl_ring_command_req_notification 0
30794@1567418204.475587:qxl_ring_cursor_check 0 native
30794@1567418204.475596:qxl_ring_command_check 0 native
30794@1567418204.476111:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 
async=0
30794@1567418204.476133:qxl_io_log 0 qxldd: DrvCopyBits

qxl/guest-0: 36652705645: qxldd: DrvCopyBits
30794@1567418204.479788:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0
30794@1567418204.479863:qxl_ring_cursor_check 0 native
30794@1567418204.479881:qxl_ring_command_check 0 native
36656456294 qxl-0/cmd: cmd @ 0x10000000104b598 draw: surface_id 0 type copy 
effect opaque src 1000000037ba090 (id 10ce0870780 type 0 flags 0 width 1920 
height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 
1000000037ba0c0) area 1920x1080+0+0 rop 8
30794@1567418204.479944:qxl_ring_command_get 0 native
30794@1567418204.480000:qxl_ring_command_check 0 native
30794@1567418204.480014:qxl_ring_cursor_check 0 native
30794@1567418204.480022:qxl_ring_command_check 0 native
30794@1567418204.480030:qxl_ring_command_req_notification 0
30794@1567418204.480040:qxl_ring_cursor_check 0 native
30794@1567418204.480048:qxl_ring_command_check 0 native
30794@1567418204.480561:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 
async=0
30794@1567418204.480583:qxl_io_log 0 qxldd: DrvCopyBits


This is the equivalent trace from the Ryzen :

qxl/guest-0: 78354754028: qxldd: DrvCopyBits
11725@1567416624.988319:qxl_ring_cursor_check 0 native
11725@1567416624.988340:qxl_ring_command_check 0 native
11725@1567416625.003283:qxl_io_write 0 native addr=4 (QXL_IO_NOTIFY_OOM) val=0 
size=1 async=0
11725@1567416625.003315:qxl_spice_oom 0
11725@1567416625.003350:qxl_ring_command_check 0 native
11725@1567416625.003365:qxl_ring_res_push_rest 0 ring 1/8 [174,173]
11725@1567416625.003380:qxl_send_events 0 1
11725@1567416625.003396:qxl_ring_cursor_check 0 native
11725@1567416625.003406:qxl_ring_command_check 0 native
11725@1567416625.003414:qxl_io_write 0 native addr=3 (QXL_IO_UPDATE_IRQ) val=0 
size=1 async=0
11725@1567416625.003430:qxl_ring_cursor_check 0 native
11725@1567416625.003461:qxl_io_write 0 native addr=3 (QXL_IO_UPDATE_IRQ) val=0 
size=1 async=0
11725@1567416625.003462:qxl_ring_command_check 0 native
11725@1567416625.003494:qxl_ring_cursor_check 0 native
11725@1567416625.003504:qxl_ring_command_check 0 native
11725@1567416625.102653:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0
11725@1567416625.102701:qxl_ring_cursor_check 0 native
11725@1567416625.102717:qxl_ring_command_check 0 native
78472556666 qxl-0/cmd: cmd @ 0x10000000105a5b8 draw: surface_id 0 type copy 
effect opaque src 1000000026d3f70 (id dfe0870780 type 0 flags 0 width 1920 
height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 
1000000026d3fa0) a
rea 1920x1080+0+0 rop 8
11725@1567416625.102797:qxl_ring_command_get 0 native
11725@1567416625.102850:qxl_ring_command_check 0 native
11725@1567416625.102865:qxl_ring_cursor_check 0 native
11725@1567416625.102876:qxl_ring_command_check 0 native
11725@1567416625.102885:qxl_ring_command_req_notification 0
11725@1567416625.103593:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 
async=0
11725@1567416625.103628:qxl_io_log 0 qxldd: DrvCopyBits

qxl/guest-0: 78473464666: qxldd: DrvCopyBits
11725@1567416625.106778:qxl_ring_cursor_check 0 native
11725@1567416625.106801:qxl_ring_command_check 0 native
11725@1567416625.210516:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0
11725@1567416625.210591:qxl_ring_cursor_check 0 native
11725@1567416625.210609:qxl_ring_command_check 0 native
78580448134 qxl-0/cmd: cmd @ 0x10000000105a6b8 draw: surface_id 0 type copy 
effect opaque src 100000002ebe098 (id e0e0870780 type 0 flags 0 width 1920 
height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 
100000002ebe0c8) a
rea 1920x1080+0+0 rop 8
11725@1567416625.210676:qxl_ring_command_get 0 native
11725@1567416625.210729:qxl_ring_command_check 0 native
11725@1567416625.210742:qxl_ring_cursor_check 0 native
11725@1567416625.210750:qxl_ring_command_check 0 native
11725@1567416625.210759:qxl_ring_command_req_notification 0
11725@1567416625.211881:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 
async=0
11725@1567416625.211924:qxl_io_log 0 qxldd: DrvCopyBits

qxl/guest-0: 78581760527: qxldd: DrvCopyBits
11725@1567416625.214592:qxl_ring_cursor_check 0 native
11725@1567416625.214614:qxl_ring_command_check 0 native
11725@1567416625.318683:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0
11725@1567416625.318748:qxl_ring_cursor_check 0 native
11725@1567416625.318763:qxl_ring_command_check 0 native
78688600327 qxl-0/cmd: cmd @ 0x10000000105a7b8 draw: surface_id 0 type copy 
effect opaque src 1000000036a81c0 (id e1e0870780 type 0 flags 0 width 1920 
height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 
1000000036a81f0) area 1920x1080+0+0 rop 8
11725@1567416625.318828:qxl_ring_command_get 0 native
11725@1567416625.318878:qxl_ring_command_check 0 native
11725@1567416625.318890:qxl_ring_cursor_check 0 native
11725@1567416625.318899:qxl_ring_command_check 0 native
11725@1567416625.318907:qxl_ring_command_req_notification 0
11725@1567416625.319633:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 
async=0
11725@1567416625.319669:qxl_io_log 0 qxldd: DrvCopyBits

Here is the holdup :

11725@1567416625.003504:qxl_ring_command_check 0 native
11725@1567416625.102653:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 
size=1 async=0

~100ms delay prior to each logged QXL_IO_NOTIFY_CMD on the AMD box which 
explains the performance difference. Now I just need to figure out if that lies 
in the guest, the guest QXL driver, QEMU or SPICE and why it exhibits on the 
AMD box and not the i7.

To get to this point, I recompiled the kernel on the i7 box with both AMD and 
Intel KVM modules. Once that was running I cloned the drive and put it in the 
AMD box, so the OS, software stack and all dependencies are identical.

Anyone have any ideas?

Brad
--
An expert is a person who has found out by his own painful
experience all the mistakes that one can make in a very
narrow field. - Niels Bohr