Unit tests for Microsoft.Data.SqlClient.SqlClientEventSource

[winseros]

Hi, @DavoudEshtehari. I added the tests that check the event-counters functionality. I managed to cover most of the counters.

Also, I changed the places where the SqlClientEventSource.Log.ActiveConnectionPoolGroupRequest(false) and SqlClientEventSource.Log.ActiveConnectionPoolGroupRequest(false) calls are made, so the calls are invoked in a more "reusable" manner - closer to the place where the actual logic lives.

As there are lots of tests running in the same session and lots of the tests does affect the event-counters when run, I had to call the DbConnectionFactory.PruneConnectionPoolGroups() and DbConnectionFactory.ClearAllPools() before each test to get the underlying pooling infrastructure reset and tests reproducible. Those are internal methods, so I used reflection for that. But as an alternative, it could be done by allowing the [Microsoft.Data.SqlClient.ManualTesting.Tests] assembly members to access the [Microsoft.Data.SqlClient] internals.

I'm looking forward to your feedback and suggestions.

[karinazhou]

Hi @winseros ,

The [Microsoft.Data.SqlClient.ManualTesting.Tests] assembly members are not supposed to access Microsoft.Data.SqlClient's internal methods. If you need to call those internal functions from the tests, using reflection is acceptable.

And according to the following comment, can we use reflection to access the counters directly instead of using EventListener?
dotnet#719 (comment)

Thanks,

[winseros]

Hi, @karinazhou

The current implementation of the SqlClientEventSource has a check for an active EventListener:

SqlClient/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlClientEventSource.NetCoreApp.cs

Lines 337 to 350 in 7ec5012

	private void Request(ref long counter, bool increment)
	{
	if (IsEnabled())
	{
	if (increment)
	{
	Interlocked.Increment(ref counter);
	}
	else
	{
	Interlocked.Decrement(ref counter);
	}
	}
	}

I see two options here:

1. Use reflection in tests and remove the check
2. Keep using EventListener in tests

What's your opinion?

[karinazhou]

@winseros Yes, you are right. To use reflections, this IsEnabled() condition needs to be removed. Otherwise, no points to use reflection if we need the EventListener to enable the events for counters.
@DavoudEshtehari Do you have any thoughts on this one?

[DavoudEshtehari]

If we remove the IsEnabled() condition, the counters will be calculated all the time even when we don't want to collect them. The diagnostic tools like Event Counters should have the lowest perf impact and this is the aim of this function and I don't recommend removing it.

[DavoudEshtehari]

After consultations with other teams, there are some perf benefits of removing the If statement at CPU micro-instruction level just in this case. So, go ahead and remove the IsEnabled() methods where counters are going to increment or decrement.

Note: Avoid any checking before counters' manipulation, and remove the Request() method too.

[karinazhou]

@DavoudEshtehari OK. I will push the changes shortly.
@winseros Can you change the tests to use reflections instead of event listener?

[karinazhou]

@winseros I tested the unit tests locally but it failed at EventCounter_HardConnectionsCounters_Functional and EventCounter_SoftConnectionsCounters_Functional

Failed Microsoft.Data.SqlClient.ManualTesting.Tests.EventCounterTest.EventCounter_HardConnectionsCounters_Functional [7 ms]
  Error Message:
   Assert.Equal() Failure
Expected: 0
Actual:   1
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.EventCounterTest.EventCounter_HardConnectionsCounters_Functional() in \EventCounterTest\src\Microsoft.Data.SqlClient\tests\ManualTests\TracingTests\EventCounterTest.cs:line 33

  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.EventCounterTest.EventCounter_SoftConnectionsCounters_Functional [< 1 ms]
  Error Message:
   Assert.Equal() Failure
Expected: 0
Actual:   1
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.EventCounterTest.EventCounter_SoftConnectionsCounters_Functional() in \EventCounterTest\src\Microsoft.Data.SqlClient\tests\ManualTests\TracingTests\EventCounterTest.cs:line 58

---

It looks like a single run of either EventCounter_HardConnectionsCounters_Functional or EventCounter_SoftConnectionsCounters_Functional passing as expected 🤔

[winseros]

@karinazhou I still work on that. After we removed the IsEnabled() check, other tests started affecting counters. The EventCounterTest tries to do a cleanup before a run, but the cleanup won't help if any test left a dangling open SqlConnection.

Currently, I'm looking for tests that do leave open SqlConnection and deal with them - mostly wrap them into using.

[karinazhou]

@winseros It sounds good. Please let me know if you need any help on this. I can look into this too.

[karinazhou]

Hi @winseros ,

Here are somethings needed to be updated before we can give this PR a final review:

1. The using statements you added are not supported in the language version we use. This creates a lot of building errors. Please change it to the old using block style.

2. The last commit doesn't seem to solve the dangling connection from other tests. Since we are going to keep some of the SqlConnections without explicitly calling Close() or Dispose() methods such as ReclaimEmancipatedOnOpenTest, it cannot guarantee the exact number of some of the counters even we call SqlConnection.ClearAllPools() and PruneConnectionPoolGroups().

One workaround is to compare the counters before and after SqlConnection.Open() or SqlConnection.Close(). The expected behavior will be to increase / decrease the counter by 1. This can eliminate the impact from other tests running before EventCounterTest.

3. Please revert the changes in ReclaimEmancipatedOnOpenTest according to my comments.

4. Please add the following code back in src/Microsoft.Data.SqlClient/tests/ManualTests/DataCommon/DataTestUtility.cs

if (TracingEnabled)	
{	
                TraceListener = new TraceEventListener();
}

5. Please revert the TraceEventListener change in this PR which is not relevant to EventCounterTest. You can create a separate PR in SqlClient/master branch to include this change.

Thanks,

[winseros]

Hi, @karinazhou.

The current status:

1. Done. I reverted the using statements to the classic form. I hope I did not miss anyone.
2. I'll share my thoughts on this one below.
3. Done. Reverted the ReclaimEmancipatedOnOpenTest
4. Done. Reverted the DataTestUtility
5. Done. Reverted the TraceListener

Regarding the dangling connections.

When I started to work on tests, I tried to remember event counters' state before a test and check the changes after. The approach was working until I began to check the connection-pool related stuff. The connection pool counters appeared to be too unpredictable and depend on the pool state at the moment of the test. So the only way I see to get the EventCountersTest reproducible - is to have the dangling connections killed by one means or another.

So far, the EventCounterTest works fine (at least on my env) with all the tests except two. Those two are ConnectionPoolTest (its ReclaimEmancipatedOnOpenTest method) and ConnectionResiliencySPIDTest.

I think at this moment I'll ask for @DavoudEshtehari `s help. I'm not sure how the internals should work, but I feel those two tests strike event counters out of balance.

1. The ReclaimEmancipatedOnOpenTest makes a previous SqlConnection be collected by the GC and a new one to take its resources. But when the first SqlConnection gets GC'ed, the counters don't decrement, and when a new one opens, counters do increment, what looks superfluous.
2. The ConnectionResiliencySPIDTest triggers the DbConnectionPool.ReplaceConnection(). I'm not sure I can provide the precise info right now, but it seems that counters are out of balance after this call.

@DavoudEshtehari could you please have a look and share your thoughts on those two?

[DavoudEshtehari]

That's right @winseros, we don't apply the GC effect on the connection pool because that would eliminate the benefits of having a pooler by causing another round trip to the server.
The _reclaimedConnectionsCounter correctly shows the number of reclaimed connections in total. We reclaim any released objects that were not closed before creating any new objects. Some of the event counters may show an inaccurate number for an unknown duration before reclaiming those objects, and we shouldn't increment a counter if we didn't decrease it earlier.

Generally, to have more precise tests and avoid conflicts with other running tests, the following solutions would be useful:

• Enforce the tests to run sequentially instead of parallel by xUnit.
• Isolate the running tests by using one or more separate app domains.

Related links:

• Remove connections
• AppDomain

PS: Default xUnit's behaviour has set to run sequentially per assembly by a single thread.

[winseros]

@DavoudEshtehari I'm not sure AppDomain will work, assuming all the stuff runs on .Net Core. As far as I know, AppDomains are out of support there.

I found only two options that really work:

1. Move the EventCounterTest to a dedicated project. This way xUnit runs it isolated from the other tests.
2. Make the EventCounterTest run before the others. It will require a custom xUnit TestCaseOrderer added to the test project, at the assembly level. (Here is the default orderer, by the way). Apparently that will change the current run order of all the tests, and I can't say right now what and how much it will affect.

[DavoudEshtehari]

@winseros Could you explain more about the approach of studying the variation of counters values' problem by adding some samples you encountered with them to more examine before choosing other options?

[winseros]

Hi, @DavoudEshtehari, sorry for answering with such a delay.

I hope I understood the right way what you mean and giving a meaningful reply.

Here is what I'm doing to reproduce the issue.

1. Ensure the EventCounterTest works alone. Select it in the TestExplorer and run. Here is the result - the test passes:
   
2. Now run the test together with the ConnectionPoolTest. The ConnectionPoolTest runs first due to the xUnit default ordering strategy and the EventCounterTests fails after.
   
   Putting breakpoints at the failing assertions will give a picture of what exactly went wrong. and putting breakpoints inside the SqlClientEventSource which way did it happen.
3. Repeat the experiment, now with the ConnectionResiliencySPIDTest, and see the similar results.
   
   Now breakpoints inside the DbConnectionPool.ReplaceConnection() would be useful to understand what happens.

Please let me know if I can provide anything else that would help.

[karinazhou]

@winseros Thank you for showing the issue in detail. I think what @DavoudEshtehari says is about why this method doesn't work in your case:

When I started to work on tests, I tried to remember event counters' state before a test and check the changes after. The approach was working until I began to check the connection-pool related stuff. The connection pool counters appeared to be too unpredictable and depend on the pool state at the moment of the test.

Since you have cleared the connection pools before running these three event counter test cases and the xunit runs the tests sequentially based on our setting, we are expecting the before-after check to reflect the changes correctly. Any reason we can't do it in this way?

[DavoudEshtehari]

Hi @winseros, thank you for the answer.
I made a quick check to see the effect of checking the differentiation of values in EventCounter_SoftConnectionsCounters_Functional.
You can find its result here:

1. Store the counter values before opening a connection:
   

2. Study the expected values according to the stored values in the first step:

• After open a connection:
  
• After close the connection:
  
• After open the second connection:
  

[winseros]

@DavoudEshtehari I rewrote the tests as you pointed, and they started working! Thanks a lot!

[DavoudEshtehari]

Thank you @winseros, for the contribution.