WT slow to return to idle CPU usage

[vefatica]

Environment

Windows build number: [run `[Environment]::OSVersion` for powershell, or `ver` for cmd]
Windows Terminal version (if applicable):

Microsoft Windows 10 Pro for Workstations
10.0.19042.685 (2009, 20H2)
WindowsTerminalPreview_1.5.3242.0_x64

Any other software?

Steps to reproduce

Monitor WT's CPU usage (VBScript to do so included). See that it's low after startup, idling, with a single (also idling) shell. Open/clode several tabs ... return to idle state with one idle shell. Observe that it takes a long time (30 min in my experiment) for WT to return to idle (i.e., almost no) CPU usage.

Expected behavior

(Naively) I'd expect it to return to low CPU usage quickly.

Actual behavior

It doesn't happen quickly.

I'm not complaining or suggesting that something's wrong. But the behavior described below is odd and I'm curious about it.

Using a script (far below), outside WT, I monitored the total CPU use of WT. Here's the output of of the monitoring process together with my play-by-play.

v:> cscript //nologo wtmonitor.vbs
17:57:31 Total CPU: 0.53125 s
17:58:31 Total CPU: 0.53125 s
17:59:31 Total CPU: 0.53125 s

That's a newly started WT with one tab; both WT and the shell are idle. WT is using very little CPU. In the next minute I will open (+) and close (X) a new tab 10 times.

18:00:31 Total CPU: 4.5 s

That used a little CPU. WT is back to one tab; it and the shell are idle. Now I'll do nothing ... back to the monitoring ...

18:01:31 Total CPU: 8.015625 s
18:02:31 Total CPU: 10.375 s
18:03:31 Total CPU: 11.5625 s
18:04:31 Total CPU: 12.078125 s
18:05:31 Total CPU: 13.859375 s
18:06:31 Total CPU: 17.5625 s
18:07:31 Total CPU: 19.890625 s
18:08:31 Total CPU: 20.140625 s
18:09:31 Total CPU: 22.875 s
18:10:32 Total CPU: 23.96875 s
18:11:32 Total CPU: 24.21875 s
18:12:32 Total CPU: 26.46875 s
18:13:32 Total CPU: 30.171875 s
18:14:32 Total CPU: 33.859375 s
18:15:32 Total CPU: 37.484375 s
18:16:32 Total CPU: 38.4375 s
18:17:32 Total CPU: 39.09375 s
18:18:32 Total CPU: 42.5625 s
18:19:32 Total CPU: 45.0625 s
18:20:32 Total CPU: 48.125 s
18:21:32 Total CPU: 50.34375 s
18:22:32 Total CPU: 50.96875 s
18:23:32 Total CPU: 52.71875 s
18:24:32 Total CPU: 54.65625 s
18:25:32 Total CPU: 55.59375 s
18:26:32 Total CPU: 59.203125 s
18:27:32 Total CPU: 62.90625 s
18:28:32 Total CPU: 66.703125 s
18:29:32 Total CPU: 68.828125 s
18:30:32 Total CPU: 72.15625 s
18:31:32 Total CPU: 72.15625 s
18:32:32 Total CPU: 72.15625 s

It finally calmed down. And as long as WT is idle, it continues to use almost no CPU. But during that 30 minutes it was using, on the average, a little more than 2 seconds CPU per minute. That's over 3.3% which is non-trivial. From here it looked like WT was idling. What was it doing?

Here's the VB script I used (outside WT) to momitor the CPU usage.

Set iWMI = GetObject("winmgmts:\.\root\CIMV2")
For i=1 to 2 step 0
Set colItems = iWMI.ExecQuery("SELECT KernelModeTime,UserModeTime FROM Win32_Process where Name = 'windowsterminal.exe'")
For Each objItem in colItems
kt = CLng(objItem.KernelModeTime)
ut = CLng(objItem.UserModeTime)
total = (kt + ut) / 10000000
Wscript.Echo Time() & " Total CPU: " & total & " s"
Next
Wscript.Sleep 60000
Next

[zadjii-msft]

I dunno, I think there's gotta be something weird going on in your machine. This, combined with #7748 - which I don't think anyone on the team has any sort of repro for. Heck, just spinning up the Terminal and doing the same thing on my machine:

If you're willing to build the Terminal locally, we might be able to get a better beat on what is exactly causing this high idle usage on your machine. If you could build a Release build of CascadiaPackage from this repo, then you could get a perf trace with VS. That would give us the actual methods and threads that are responsible.

[vefatica]

Even yours looks fishy showing .3 ... .4 ... .7 when idling. Here, a new WT shows a rock-steady 0 when idling. You can add the "CPU Time" column to TaskMgr and see the accumulation over time. What TaskMgr shows agrees with the VB script I posted.

Here are the 4 busiest processes on my machine. WT will overtake DWM.EXE this afternoon.

Start  Time            Pid   PPid       CPU(s)    WS(MB)  Name
--------------------------------------------------------------------------------
12/17  11:06:52.231      4      0      900.828       5.5  System
12/19  23:51:26.896   4752   5624     2207.484      89.2  WindowsTerminal.exe
12/17  11:06:54.286   1280   1012     2547.094     100.1  dwm.exe
12/17  11:06:52.231      0      0   344906.863       0.0  System Idle Process

I'm quite willling to build WT here. I got sources in early summer and DevStudio said it needed more stuff. I didn't want to mess with DevStudio so I went no further. I'll get newer sources and try again. Can I get the source for the current preview? That's the one I'm using. I might need help getting DevStudio up to the task.

[vefatica]

I get this just loading the SLN. What does it mean? I have the latest version of VS Community.

[vefatica]

And then these. I accepted the default.

[vefatica]

Not having much luck.

[vefatica]

Let's look at it another way, a comparison of two instances of WT.

Process 9280 was started last night. It got no special treatment and it's the instance I've been using interactively, last night and today.

Process 8220 was started about 2 hours ago. I caused it to open and close a new tab ... 50 times. Then I minimized it (idling, one tab, shell also idling) and left it in that state. Right after minimizing 8220, things looked like this.

v:\> tl /f term
Start  Time            Pid   PPid       CPU(s)    WS(MB)  Name
--------------------------------------------------------------------------------
12/23  23:25:54.540   9280   9384       14.672      72.7  WindowsTerminal.exe
12/24  11:21:49.611   8220   6364        9.500      76.8  WindowsTerminal.exe
--------------------------------------------------------------------------------
35 non-service processes (2 shown)
68 service processes (77 services)
103 processes at 2020-12-24 11:23:55

Now, almost 2 hours later, things look like this.

v:\> tl /f term
Start  Time            Pid   PPid       CPU(s)    WS(MB)  Name
--------------------------------------------------------------------------------
12/23  23:25:54.540   9280   9384       38.000      75.2  WindowsTerminal.exe
12/24  11:21:49.611   8220   6364      450.484      74.5  WindowsTerminal.exe
--------------------------------------------------------------------------------
41 non-service processes (2 shown)
67 service processes (76 services)
108 processes at 2020-12-24 13:10:31

You can see the difference in TaskMgr, too. Both processes are idle.

[vefatica]

Here's a much simpler test.

Enable the "CPU Time" column in TaskMgr's "Details" tab.

Start a new, simple, one-tab, one-shell instance of WT and immediately minimize it (process 5448 below). Start another simple, one-tab, one-shell instance of WT ... open a second tab/shell, close the first one, and minimize it (process 8316 below). Now we have two minimized instances of WT, each with one idle shell. TaskMgr shows something like this.

I'd expect the two to behave similarly. But wait a while ... After 10 minutes, TaskMgr shows this.

And after another 10 minutes ...

In fact, process 5448 is behaving quite efficiently. WMI reports CPU time in 100-nanosecond units and shows that process 5448 has used 0 CPU time in what's now almost 30 minutes. I don't know what process 8316 is doing.

[vefatica]

Again ... here are two that were started at the same time and have been minimized, with an idle CMD.EXE in the only tab, for about 28 hours. The only difference between then is that the second one (PID 9088) momentarily had a second tab open before I minimized it.

Start  Time            Pid   PPid       CPU(s)    WS(MB)  Name
--------------------------------------------------------------------------------
01/03  13:29:25.821   3744   7604        1.203      69.8  WindowsTerminal.exe
01/03  13:29:26.066   5608   3744        0.016       8.9  OpenConsole.exe
01/03  13:29:26.070   8104   3744        0.000       4.0  cmd.exe
01/03  13:29:30.903   9088   5352     1385.547      74.5  WindowsTerminal.exe
01/03  13:29:31.136   7584   9088        0.016       8.9  OpenConsole.exe
01/03  13:29:31.140   5820   9088        0.000       4.0  cmd.exe

[Don-Vito]

@vefatica - this is highly unlikely.. but given the overall weirdness can you please do the same check with TabSwitcher disabled (from the very beginning)..

[vefatica]

"useTabSwitcher": false,
It's in the global section. It has been that way since at least 12/14.

[Don-Vito]

"useTabSwitcher": false,
It's in the global section. It has been that way since at least 12/14.

I see.. this was a nice theory 😄

[vefatica]

The release version does it too. Has anyone actually tried (and failed) to repro this. I'd be surprised. It never fails here.

Microsoft Windows 10 Pro for Workstations
10.0.19042.685 (2009, 20H2)
WindowsTerminal_1.4.3243.0_x64

[zadjii-msft]

LOOK WHAT I FOUND:

microsoft/microsoft-ui-xaml#3597

Maybe this has something to do with it. I know that's memory-related, but maybe XAML's walking the tree trying to free the tabs but isn't, and that's what's driving the CPU? Can't be sure.

[vefatica]

Thanks for the update. Please keep me informed.

[vefatica]

Any more on this? ProcessExplorer (Sysinternals) is pretty good at showing a difference. Here's a new WT with one tab after idling for 5 minutes.

And here's the same instance of WT after opening/closing a second tab and letting it idle for 5 minutes.

If I then open/close a new tab 20 times and let it idle for 5 minutes, I see this.

If I go to extremes ... open/close a new tab 100 times (automated) ... let it idle 5 minutes ...

Though WT returns to the 1-tab state, CPU use just keeps climbing (logarithmically would be my guess). The culprit seems to be WT's main (?) thread, 4396. From here it looks like something is not getting cleaned up.

[zadjii-msft]

Nope, no one has had a chance to come back around on this. The problems you're having with building the solution earlier are certainly weird - you can probably ignore all the errors about the WpfTerminalControl, or anything dealing with .NET. As far as the .wapproj build error though, that's strange. VS should have prompted you to install the missing dependencies when you first opened the solution. That should have installed the sdks for building a package. Did that not work?

[vefatica]

I let VS install whatever it wanted. Bottom line:

========== Build: 7 succeeded, 60 failed, 0 up-to-date, 2 skipped ==========

I'm trying to build p:\terminal-main\OpenConsole.sln in the IDE. I get tons of these:

P:\terminal-main\src\inc\LibraryIncludes.h(52,10): fatal error C1083: Cannot open include file: 'wil/Common.h': No such file or directory

[zadjii-msft]

https://github.com/microsoft/terminal#building-the-code

This repository uses git submodules for some of its dependencies. To make sure submodules are restored or updated, be sure to run the following prior to building:

git submodule update --init --recursive

[vefatica]

The only git I can find is /usr/bin/git.

[DHowett]

It really seems like you're trying to make our lives harder.

[vefatica]

It really seems like you're trying to make our lives harder.

I'm not trying and I'm sorry if that's what's happening. When it comes to building WT I have no clue what I'm doing. And I'm even doubtful that succeeding at it would eventually help with this issue, WT's increased CPU use as more tabs are opened/closed. Have you (collectively) really tried and failed to reproduce what I have reported.

[zadjii-msft]

To be honest, no, I haven't tried that hard. I saw something once that looked vaguely similar, thought "Huh, that must be what vefatica was talking about", and tossed it on the backlog. Frankly, we've just got other priorities that prevent us from digging in super deep on each and every report we get, immediately when we get them. This seems like it might be a real issue, but it's just not a super high priority one to us right now.

That being said, it does seem like it's a higher priority for you. Hence why I'm trying to help you build the code and investigate the root cause. If you could say "This function right here - that's being called in a loop when the UI should be idle", now that's something far more actionable. That's a lot lower cost. If you could help us get there, then we'd probably make progress on this bug faster. As is though, it'll probably just sit on the backlog for a while.

[vefatica]

It's not really of high priority. It just seems wrong and that bugs me. Here's one that has been running for 3 hours and has used over 30 minutes of CPU.

Start  Time            Pid   PPid       CPU(s)     WS(M)  Name
--------------------------------------------------------------------------------
02/26  14:53:18.198  10916   3236     1884.156     104.7  WindowsTerminal.exe
--------------------------------------------------------------------------------
 41 non-service processes (1 shown)
 67 service processes (76 services)
108 processes at 2021-02-26 16:53:25

I tried building with razzle.cmd and bcz. That was a little tidier (but it failed and left 12 instances of MSBuild running!). I still need to get terminal-main\dep\wil\ populated. Your comment about git seemed cryptic since my only "git" is in Ubuntu. I'm not sure building it myself will help. I'm pretty lost whan I look at the source. How about a hint on where to look to see what's done when a new tab is created and destroyed?