search

QubesOS / qubes-issues

The Qubes OS Project issue tracker
https://www.qubes-os.org/doc/issue-tracking/
536 stars 48 forks source link

Increasing CPU consumption of qga.exe with SAP GUI app #3418

Closed bb991 closed 1 year ago

bb991 commented 6 years ago

Qubes OS version:

R3.2

Affected TemplateVMs:

Windows 7 Home Premium SP1 build 7601 64bit Qubes Windows Tools 3.2.2.3 (showing in installed apps of VM)

Steps to reproduce the behavior:

After using system for around 30 min with SAP GUI (MFC app, stable software that is used in most corporate networks as frontend to log into SAP servers) qga.exe process CPU usage increases to 15-20% with every action and there is a visible effect of reloading every icon on the screen. Around 1-1.5 hour of work usage increases to 50% even when only switching between screens in any VM app or calc.exe.

I would really appreciate any hints with this. I can provide you with the details needed to identify the root cause of such behaviour.

Trace level set to 5 gives such messages after VM start...:

[20171222.090120.867-2080-I] LogInit: Log started, module name: qga [20171222.090120.867-2080-I] LogInit: Running as user: SYSTEM, process ID: 2076 [20171222.090120.867-2080-I] LogInit: Module version: 3.2.0.0 [20171222.090120.867-2080-I] LogInit: Session: 1 [20171222.090120.867-2080-I] LogInitDefault: Verbosity level set to 5 [20171222.090120.867-2080-D] ErrRegisterUEF: done [20171222.090120.867-2080-D] Init: start [20171222.090120.867-2080-D] CreateNamedEvent: Global\QGA_SHUTDOWN [20171222.090120.867-2080-I] Init: MaxFps: 0 [20171222.090120.867-2080-V] HideCursors: start [20171222.090120.867-2080-D] HideCursors: disabling cursors [20171222.090120.867-2080-D] DisableEffects: start [20171222.090120.867-2080-D] IncreaseProcessWorkingSetSize: New working set size: 262144 pages [20171222.090120.867-2080-D] QpsConnect: opening read pipe: \.\pipe\qubesdb.sock [20171222.090120.867-2080-D] QpsConnect: opening write pipe: \.\pipe\qubesdb.sock-2076-2 [20171222.090120.899-2080-D] GetDomainName: kk-win7-clone [20171222.090120.899-2080-I] Init: Fullscreen desktop name: kk-win7-clone [20171222.090120.899-2080-D] WatchForEvents: start [20171222.090120.899-2080-D] VchanInitServer: domain 0, port 6000, buffer 65536, timeout 300000 [20171222.090120.899-2080-D] CreateNamedEvent: QUBES_GUI_AGENT_FULLSCREEN_ON [20171222.090120.899-2080-D] CreateNamedEvent: QUBES_GUI_AGENT_FULLSCREEN_OFF [20171222.090120.899-2080-I] WatchForEvents: Awaiting for a vchan client, write buffer size: 65536 [20171222.090120.899-2080-I] WatchForEvents: A vchan client has connected [20171222.090120.899-2080-V] VchanSendBuffer: (0000000000223B80, version): 4 bytes (free: 65536) [20171222.090120.899-2080-V] HandleXconf: start [20171222.090120.899-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_xconf): 16 bytes (available: 0) [20171222.090120.899-2080-W] VchanReceiveBuffer: (0000000000223B80, msg_xconf): no data, blocking read [20171222.090120.914-2080-I] HandleXconf: host resolution: 1920x1080, mem: 8101, depth: 24 [20171222.090120.914-2080-I] SetVideoModeInternal: New resolution: 1920x1080@32 [20171222.090120.914-2080-V] AttachToInputDesktop: start [20171222.090120.914-2080-V] QvFindQubesDisplayDevice: start

... after longer time when system works slowly the same messages all the time...

[20171222.104449.519-2080-V] AttachToInputDesktop: start [20171222.104449.534-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104449.534-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104449.534-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104449.534-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104449.534-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_hdr): 12 bytes (available: 32) [20171222.104449.534-2080-V] HandleServerData: received message type 124 for 0x0 [20171222.104449.534-2080-V] HandleKeypress: 0x0 [20171222.104449.534-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_keypress): 20 bytes (available: 20) [20171222.104449.534-2080-D] SynthesizeKeycode: keycode: 0x36, scancode: 0x2e [20171222.104449.550-2080-V] AttachToInputDesktop: start [20171222.104449.566-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104449.566-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104449.566-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104449.566-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104449.566-2080-V] AttachToInputDesktop: start [20171222.104449.597-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104449.597-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104449.597-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104449.597-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104449.675-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_hdr): 12 bytes (available: 32) [20171222.104449.675-2080-V] HandleServerData: received message type 124 for 0x0 [20171222.104449.675-2080-V] HandleKeypress: 0x0 [20171222.104449.675-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_keypress): 20 bytes (available: 20) [20171222.104449.690-2080-D] SynthesizeKeycode: keycode: 0x36, scancode: 0x2e [20171222.104450.002-2080-V] AttachToInputDesktop: start [20171222.104450.034-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.034-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.034-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.034-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.034-2080-V] AttachToInputDesktop: start [20171222.104450.049-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.049-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.049-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.049-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.049-2080-V] AttachToInputDesktop: start [20171222.104450.080-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.080-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.080-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.080-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.080-2080-V] AttachToInputDesktop: start [20171222.104450.112-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.112-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.112-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.112-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.112-2080-V] AttachToInputDesktop: start [20171222.104450.127-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.127-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.127-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.127-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.127-2080-V] AttachToInputDesktop: start [20171222.104450.158-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.158-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.158-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.158-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.158-2080-V] AttachToInputDesktop: start [20171222.104450.190-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.190-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.190-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.190-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.190-2080-V] AttachToInputDesktop: start [20171222.104450.221-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.221-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.221-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.221-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.221-2080-V] AttachToInputDesktop: start [20171222.104450.236-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.236-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.236-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.236-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65536) [20171222.104450.252-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_hdr): 12 bytes (available: 32) [20171222.104450.252-2080-V] HandleServerData: received message type 124 for 0x0 [20171222.104450.252-2080-V] HandleKeypress: 0x0 [20171222.104450.252-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_keypress): 20 bytes (available: 20) [20171222.104450.252-2080-D] SynthesizeKeycode: keycode: 0x37, scancode: 0x2f [20171222.104450.252-2080-V] AttachToInputDesktop: start [20171222.104450.268-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.268-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.268-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.268-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.268-2080-V] AttachToInputDesktop: start [20171222.104450.299-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.299-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.299-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.299-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.299-2080-V] AttachToInputDesktop: start [20171222.104450.330-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.330-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.330-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.330-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65536) [20171222.104450.330-2080-V] AttachToInputDesktop: start [20171222.104450.346-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.346-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.346-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.346-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.361-2080-V] AttachToInputDesktop: start [20171222.104450.377-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.377-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.377-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.377-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.377-2080-V] AttachToInputDesktop: start [20171222.104450.408-2080-V] SendWindowDamageEvent: 0x0 (0,0)-(1920,1031) [20171222.104450.408-2080-V] VchanSendMessage: msg 0x88 (MSG_SHMIMAGE) for window 0x0, size 12 [20171222.104450.408-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 12 bytes (free: 65536) [20171222.104450.408-2080-V] VchanSendBuffer: (0000000000223B80, MSG_SHMIMAGE): 16 bytes (free: 65524) [20171222.104450.408-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_hdr): 12 bytes (available: 32) [20171222.104450.408-2080-V] HandleServerData: received message type 124 for 0x0 [20171222.104450.408-2080-V] HandleKeypress: 0x0 [20171222.104450.408-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_keypress): 20 bytes (available: 20) [20171222.104450.408-2080-D] SynthesizeKeycode: keycode: 0x37, scancode: 0x2f [20171222.104450.424-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_hdr): 12 bytes (available: 32) [20171222.104450.424-2080-V] HandleServerData: received message type 124 for 0x0 [20171222.104450.424-2080-V] HandleKeypress: 0x0 [20171222.104450.424-2080-V] VchanReceiveBuffer: (0000000000223B80, msg_keypress): 20 bytes (available: 20) [20171222.104450.424-2080-D] SynthesizeKeycode: keycode: 0x25, scancode: 0x1d

Expected behavior:

Actual behavior:

General notes:

Related issues:

tonsimple commented 6 years ago

Might be related (just linking this here in case these rather similarly looking issues have a common cause)

https://github.com/QubesOS/qubes-issues/issues/2678

bb991 commented 6 years ago

@tonsimple - the issue is similar to yours. Once I use "switch user" option performance returns to its original state. I did some more research on this yesterday via process explorer (sysinternals) tool and xperf (performance diagnostic tool) and there here are the results:

First I checked how stack looks like and in most cases thread that is working so hard stays here: ntoskrnl.exe!KeWaitForMultipleObjects+0xc0a ntoskrnl.exe!KeAcquireSpinLockAtDpcLevel+0x712 ntoskrnl.exe!KeWaitForSingleObject+0x19f ntoskrnl.exe!PoStartNextPowerIrp+0xbd4 ntoskrnl.exe!PoStartNextPowerIrp+0x187d ntoskrnl.exe!KeAcquireSpinLockAtDpcLevel+0x91d ntoskrnl.exe!KeWaitForMultipleObjects+0x26a ntoskrnl.exe!NtWaitForSingleObject+0x40f ntoskrnl.exe!NtWaitForSingleObject+0x77e ntoskrnl.exe!KeSynchronizeExecution+0x3a23 ntdll.dll!ZwWaitForMultipleObjects+0xa KERNELBASE.dll!GetCurrentProcess+0x40 kernel32.dll!WaitForMultipleObjects+0xb0 qga.exe+0x2b4a qga.exe+0x2d38 qga.exe+0x6979 kernel32.dll!BaseThreadInitThunk+0xd ntdll.dll!RtlUserThreadStart+0x21

So I checked DPC statistics via xperf tool (https://blogs.msdn.microsoft.com/peterwie/2008/10/06/measuring-dpc-time/) and the result is that there is no significant difference between work of drivers at the beginning and at the end when the load is so heavy only qga.exe works slower but without any increase memory consumption. Response time from the driver modules were similar in both cases.

The second thing I did was to read more about KeWaitForMultipleObjects: https://msdn.microsoft.com/en-us/library/windows/hardware/ff553324(v=vs.85).aspx

Then I looked into source code to investigate more how this function was called and the outcome is that probably via EnterCriticalSection call. So it seems that is waits for vchan or something else to release mutex.

That's why I tried my luck to decrease number of CPUs in VM and suddenly problem disappeared and qga.exe works much faster with single CPU than with two.

This has to be investigated in more details but at least there is some workaround for now so you can try to do the same and let me know :)

tonsimple commented 6 years ago

@bb991 Wow, that's impressive work!

The "reduce number of processors to 1" seems to sort of work for me too.

Of course, given my typical usage it causes other issues and is a bit of a "robbing peter to pay paul" situation, but it works.

Could attaching QGA exe and/or some other qubes-specific processes to a particular processor (via set affinity in task manager) have similar effect ?

tonsimple commented 6 years ago

So far, attaching all qubes-related processes I could find to CPU0 (out of 2 CPUs set available to this VM) via Set Affinity has been giving optimistic results... there is some slowdown (and QGA.exe CPU usage spikes up to 40%) but system was running for 12 hours, and lagging appears way less severe than it used to be...

Does it work for you, @bb991 ?

bb991 commented 6 years ago

I tried to assign QGA.exe to particular CPU and it works better than without this operation but also much slower than with one CPU. Reload of the buttons was visible but at least speed allowed to work.

tonsimple commented 6 years ago

@bb991 could you try assigning all qubes and xen related processes (easy to find since they are named intuitively), explorer.exe, and dwm.exe to CPU0 ?

This seems to work somewhat good-ish for me, but I am not smart enough to properly benchmark the difference between "single CPU" and "all these fine processes assigned to CPU0).

tonsimple commented 6 years ago

Hi @bb991 , just in case you are still interested in this issue, there seems to be a windows registry setting "MaxFPS" available for QGA, and if windows template VM (assuming your windows is template-based) has it set to something like 40, it further reduced the CPU load and lag with very little effect on visuals (40 FPS is frankly fine for most things)

andrewdavidwong commented 3 years ago

This bug report has seen no activity in a very long time, and it is not assigned to any current release milestone. It looks like it was left open by mistake, so I'm closing it now. However, if anyone is still affected by this bug on a currently-supported release, please leave a comment, and we'll be happy to reopen this. Thank you.

brendanhoar commented 3 years ago

I don't think QWT has been updated since this issue was opened and imho it seems unlikely that other qubes changes in the interim have addressed this. It's possible that particular applications or work processes are more likely to trigger the slowdowns. Would be nice to know what apps the original poster was using.

B

github-actions[bot] commented 1 year ago

This issue is being closed because:

If anyone believes that this issue should be reopened and reassigned to an active milestone, please leave a brief comment. (For example, if a bug still affects Qubes OS 4.1, then the comment "Affects 4.1" will suffice.)