Async multi packet fixes #3534
Async multi packet fixes #3534
Conversation
|
@ErikEJ this might reduce memory usage for string reads. It might be worth benching the artifacts if the CI runs green. |
|
/azp run |
|
Azure Pipelines successfully started running 2 pipeline(s). |
|
I've added an additional fix which is the same as the 0 length left in terminator case and which occurs on the varchar not nvarchar read path. |
|
/azp run |
|
Azure Pipelines successfully started running 2 pipeline(s). |
|
@dotnet/sqlclientdevteam can I get a CI run on this please. I've added a new commit which forces process sni mode to compatibility mode (and by extension, disabled async-continue mode) and adds in a fix for the pending read counter imbalance that we discussed and that @rhuijben has been assisting with tracking down today. This is a possible stable current codebase state to evaluate. |
|
/azp run |
|
Azure Pipelines successfully started running 2 pipeline(s). |
|
I've aligned the appcontext switch test with the new defaults. Can i get another run please @dotnet/sqlclientdevteam |
|
/azp run |
|
Azure Pipelines successfully started running 2 pipeline(s). |
src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs
Outdated
Show resolved
Hide resolved
|
@Wraith2 when I run the testcase from the other issue against this branch I get in DEBUG mode In release mode the test passes. |
|
multitasking here, can you link me to the exact repro you're talking about? |
The testcase from I'm currently trying to get things reproduced against a docker instance of sqlserver 2019 so we can look at the same thing (and maybe even test this on github actions, like I do in the RepoDB project) |
|
This case rhuijben@1964bc1 fails for me on this docker setup. Too bad it is not the error I'm seeing myself, but it is still a valid testcase. Trying to extend this to include my case. It fails on the first (smallest) packetsize of 512. |
Debug.Assert(TdsEnums.HEADER_LEN + Packet.GetDataLengthFromHeader(buffer) == read, "partially read packets cannot be appended to the snapshot");read=512 503+8 = 511, so mismatch. Looks like the first byte of the next package is already in the buffer here. |
|
That assert will fire periodically when packet multiplexing is disabled. We should add in the context switch to the assertion. That might be correct. I saw something similar while looking at the multipart xml reads with a weird packet size. If the packet status does not include the last packet bit, and the requiredlength is less than the total packet as long as the transferred data amount is the same as the buffer size it's technically correct, I think. I'm referring to this as padded packets. I hadn't seen them before 2 weeks ago but the spec doesn't preclude them. When i saw them the remaining data space in the packet buffer was filled with FF. This is part of the reason that i added the DumpPackets and DumpInBuff functions to my debug branch. |
|
With packet size configured as 512 I see 511 byte packets (which fail these tests), but also one really large packet (>= 60 KB). Not sure if the debug assert does the right thing. It looks like the demultiplexer handles these cases just fine. With this packet code you also always have to handle short-reads caused by network security and TCP packets. There are standard proxies for that last case so you can always get small (or large) packets from the network layer. The DotNet core project uses fuzzing with that to catch http errors, as do a lot of other libraries. Looks like these asserts are on the wrong layer... as from the network you can have much smaller or larger packets than the TDS packets (smaller when processing really fast, and much longer when the network already delivered more data than a single packet... Which can also happen on slow networks when one packet got lost and is re-delivered, while others are already in the queue. |
|
With the multiplexer active every packet which is appended to the snapshot is required to have a correct header and be a complete packet. If you look at the locations where packets are assigned to _inBuff from the snapshot you'll see that it gets the status and data length from the packet, that requires a correct packet header. With the multiplexer inactive, which is ProcessSni compatibility mode those requirements no longer hold. So the correct things to do is to change the asserts to be: In terms of packet lengths I refer to the TDS definition of a packet which is that all packets are of the communicated packetsize unless they are the last packet in a stream. Even though it's possible in network terms to receive any length of bytes up to the buffer size that was passed to the function we will generally find that there are full packets unless your server is quite slow. Unfortunately the slow case is very hard to replicate in a reliable way so there have been holes in the code. The demultiplexer current does not handle padded packets (physical length > logical length) correctly. I need to get some example packets with padding and then write some new test infra for the multiplexer to make sure that CurrentLength and RequiredLength are used correctly. |
|
On https://github.com/rhuijben/SqlClient/tree/test/repro-1 (your branch + 1 commit) I now have (with Running the tests against a docker with a clean sqlserver 2019 container. (Create script is in that commit) (Don't look at the timings. My laptop is in silent mode, which is very slow with todays weather) |
|
Token packet, last packet of stream. No idea what the content is supposed to represent. This would silently fail in release mode because all that diagnostic output is a #DEBUG block |
Not sure if I read this correctly but looks like: |
src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderTest.cs
Show resolved
Hide resolved
Yes. That was my interpretation. Since I've no idea what the bytes that have been read were a part of I have no way to tell if the extra bytes are meaningful or not. It seems likely that they should be. If you've got my additional logging enabled from the -dev branch then you could look at the output of DumpLog() and see what operation consumed those bytes. |
|
/azp run |
|
FYI, we're having issues with macos tests at the moment, separate from this PR |
|
Any specific thing blocking merging? |
|
Waiting on #3597 to fix our macOS CI issues. One that merges, you can re-merge main and we can kick off another CI run. |
fix 0 length read at the start of a packe in plp stream returning 0 when continuing handle char array sizing better change existing test to use multiple packet sizes
|
that pr to fix the ci merged, rebased this pr. please run the CI. |
|
/azp run |
|
Azure Pipelines successfully started running 2 pipeline(s). |
|
So to take it to 11, what do I need to do with the latest main artifact? (Planning to share the simplest possible approach in a blog post) |
|
This makes main stable. It doesn't contain the speed improvements because this code can never enter an async-continue state. If you want to use this PR artifact for the sake of being on main and getting stability then that's fine, but that seems like a small use-case given that we have 6.1.1 which is stable. I have some work in a branch which will add the speed improvements back in. I'll get started on that this evening. |
|
@Wraith2 will that be opt-in via a switch then? |
|
Yes. |
Fixes #3519
Fixes: #3572
Fix 1:
When reading multi packet strings it is possible for multiple strings to happen in a single row. When reading asynchronously a snapshot is used which contains a linked list of packets. The current codebase has logic which keeps a cleared spare linked list node when the snapshot is cleared. The logic to clear the spare packet was faulty and did not clear all the fields leaving the data length in the node. In specific circumstances it is possible to re-use the spare linked list node containing an old data value as the first packet in a new linked list of packets. When this happens in a read which reaches the continue stage (3 or more packets) the size calculation is incorrect and various errors can occur.
The spare packet functionality is not very useful because it can store a single node. It doesn't retain the byte[] buffer so the memory saving is tiny. I have removed it and changed the linked list node fields to be readonly. This resolves the bug.
Fix 2:
When reading a multi packet string the plp chunks are read from each packet and the end is signalled by a terminator. It is possible for the data to align such that the contents of a string complete exactly at the end of a packet and the terminator is in the next packet. In this case some pre-existing logic checks for a 0 chars remaining and exists early.
This logic needed to be updated so that in when continuing it returns the entire existing length read and not a 0 value.
Fix 3:
While debugging the first two issues the buffer sizes and calculations were confusing me. I eventually realised that the code was directly using _longlenleft which is measured in bytes to size a char array, meaning that all char arrays were twice as long as needed. I have updated the code to handle that and use smaller appropriately sized arrays.
I have updated the existing test to iterate from 512 (minimum packet size) to 2048 bytes in size. This can cause lots of interesting alignments in the data testing the paths through the string reading code more effectively. The range could be increased but I considered that the runtime needed to be low enough to not timeout CI runs, most higher packet size will be similar to lower sized runs due to factoring.
Thanks to @erenes and @Suchiman for their help finding the reproduction that worked on my machine, without that I would have been unable to fix anything
@dotnet/sqlclientdevteam can I get a CI run please.
/cc @Jakimar
Edits:
Fixes 3572.
When reading data sequentially and calling GetFieldValueAsync it is possible for the call to TryReadColumnInternal to fail because there is not enough data. When this happens an async read has been started so we should wait for it to return but the code does not do this and instead falls through to attempting a call to TryReadColumnValue. Under a debugger it's clear that there is a problem because you hit an assert but at runtime this was silently failing which could cause data loss as an async read collided with a sync read.. The fix is to prevent the fallthrough and queue the wait for the next packet.