Skip to content

Conversation

nohwnd
Copy link
Member

@nohwnd nohwnd commented Nov 3, 2023

Description

We disabled pre-started testhosts in 17.6.0 because the waiting host could consume large amounts of CPU when data were waiting on the pipeline and there were no consumers on vstest.console side. This is easy to reproduce when you set VSTEST_HOSTPRESTART_COUNT = 1 or more, and enable diagnostic logs.

What happens is that we run init on the pre-started testhost and after we remove the CheckVersionWithHost subscriber, the diag log will push TestMesage: Logging TestHost Diagnostics in file... which will be wating on the wire and causing tight loop of notifications to subscriber that is not there.

In logs this shows up like this, with 0ms since the last poll, because the Poll returns immediately, and the notification as well, causing this tight loop:

TpTrace Verbose: 0 : 59440, 12, 2023/11/03, 12:18:50.769, 655225963354, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:59895 localEndPoint: 127.0.0.1:59892
TpTrace Verbose: 0 : 59440, 12, 2023/11/03, 12:18:50.769, 655225963520, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:59895 localEndPoint: 127.0.0.1:59892 after 0 ms

Instead of this we add a flag that will wait for the maximum of 1 second for a subscriber to subscribe to data reading, and if that does not happen we repeat the loop.

In log it shows like this:

TpTrace Verbose: 0 : 59440, 12, 2023/11/03, 12:18:50.769, 655225963354, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:59895 localEndPoint: 127.0.0.1:59892
TpTrace Verbose: 0 : 59440, 12, 2023/11/03, 12:18:51.769, 655225963520, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:59895 localEndPoint: 127.0.0.1:59892 after 1000 ms

Where we correctly wait for the subscriber to subscribe. We also return immediately when we are being cancelled.

There are probably other causes for this to happen, but this should solve all of them.

Related issue

Fix https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1896342
Fix https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1835463

@nohwnd
Copy link
Member Author

nohwnd commented Nov 3, 2023

@cvpoienaru Please fix the tests, and re-enable the PreStartCount to 2. 🙏🙇

MessageReceived.SafeInvoke(this, new MessageReceivedEventArgs { Data = data }, "LengthPrefixCommunicationChannel: MessageReceived");
}
else
{
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This message is unnecessary, and way too much detail. with prestart it is normal that client is waiting for his turn and this would just add yet another message to the log that would always repeat.

@nohwnd nohwnd changed the title Fix cpu usage by polling frequently when there is no subscriber Fix CPU is consumed by polling frequently when there is no subscriber Nov 3, 2023
@nohwnd
Copy link
Member Author

nohwnd commented Nov 7, 2023

/azp run

Copy link

Azure Pipelines successfully started running 1 pipeline(s).

@cvpoienaru cvpoienaru enabled auto-merge (squash) November 14, 2023 14:30
@cvpoienaru cvpoienaru merged commit 5d3d844 into microsoft:main Nov 14, 2023
This was referenced Sep 24, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants