Skip to content
This repository was archived by the owner on Aug 2, 2023. It is now read-only.

[WIP] Fix RIO Thread #1420

Closed
wants to merge 8 commits into from
Closed

Conversation

KodrAus
Copy link
Contributor

@KodrAus KodrAus commented Apr 4, 2017

There's an issue with the RIO code calling _buffer.FlushAsync() in ReceiveEndComplete after it's been reallocated put back in a writable state by ReceiveBeginComplete.

To work around this I've just removed the ReceiveEndComplete method and am flushing before updating the shared input buffer.

I haven't removed any of the notify infrastructure in RioThread, even though it currently does nothing, because I thought we could work out what to do with it here. Maybe it can just be deleted, or some other work could be shifted onto the notify thread. Not sure.

The test is blocked on by-ref stuff, but this same code change worked fine pre-2.0 so it should work once that's sorted.

CC: @davidfowl @benaadams @aL3891

var task = PongServer(connection);
}

server.Stop();
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Is this a race with PongServer, which isn't awaited? I didn't get any issues running this, but it could still be sketchy...

@benaadams
Copy link
Member

The issue is RIO isn't backed by winsock buffers and FlushAsync may take time so you need to submit another receive before it else the NIC will drop the next packet and you'll hit a TCP re-transmit instead; which is fine if FlushAsync is actually blocking but not good if it just takes a little time (i.e isn't dispatched to a different thread).

_input.Writer.Complete();
}
else
// REVIEW: Why was there special behaviour for bytesTransferred = 0?
Copy link
Member

@benaadams benaadams Apr 4, 2017

Choose a reason for hiding this comment

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

bytesTransferred == 0 is end of data/pipe complete

@benaadams
Copy link
Member

benaadams commented Apr 4, 2017

I haven't removed any of the notify infrastructure in RioThread, even though it currently does nothing,

Isn't it the thing that's triggering the recieve completes?

(edit) maybe not; might need to see what the code is doing agian

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 4, 2017

Ok so I've updated this based on our chat on gitter. I couldn't confirm it though on current tooling because I broke my environment updating to 2.0... And we can't run the test yet with the new Span.

I might shelve this until we can run the tests and confirm it all works.

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 4, 2017

Turned out the Span error wasn't a big deal... but calling Alloc before flushing throws because the buffer is already in the writing state.

I don't think we'll be able to get away with deferring the flush. Looks like it has to happen before Alloc.

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 4, 2017

@benaadams This works:

public void ReceiveBeginComplete(uint bytesTransferred)
{
    if (bytesTransferred == 0)
    {
        _buffer.FlushAsync();
        _input.Writer.Complete();
    }
    else
    {
        _buffer.Advance((int)bytesTransferred);
        _buffer.Commit();
        _buffer.FlushAsync();

        ProcessReceives();
    }
}

public void ReceiveEndComplete()
{
    
}

I'm wondering if the issue of potentially blocking on FlushAsync is a bit overstated, since it doesn't seem to be performing io, just updating states and cursors.

@benaadams
Copy link
Member

I'm wondering if the issue of potentially blocking on FlushAsync is a bit overstated, since it doesn't seem to be performing io, just updating states and cursors.

Its the TrySchedule(_readerScheduler, awaitable); line where it notifies the reader that's the issue
https://github.com/dotnet/corefxlab/blob/master/src/System.IO.Pipelines/Pipe.cs#L325-L342

Which can be a synchronous execution of everything upstream of the pipe

@ahsonkhan
Copy link
Contributor

03:23:28 Ping: 500; Pong: 500; Time: 27ms 03:23:29 Unhandled Exception: System.InvalidOperationException: Already writing. 03:23:29 Unhandled Exception: System.InvalidOperationException: Already writing. at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource, String location) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\ThrowHelper.cs:line 37 03:23:29 Unhandled Exception: System.InvalidOperationException: Already writing. at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource, String location) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\ThrowHelper.cs:line 37 at System.IO.Pipelines.PipeOperationState.Begin(ExceptionResource exception) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\PipeOperationState.cs:line 21 03:23:29 Unhandled Exception: System.InvalidOperationException: Already writing. at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource, String location) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\ThrowHelper.cs:line 37 at System.IO.Pipelines.PipeOperationState.Begin(ExceptionResource exception) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\PipeOperationState.cs:line 21 at System.IO.Pipelines.Pipe.System.IO.Pipelines.IPipeWriter.Alloc(Int32 minimumSize) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\Pipe.cs:line 114 03:23:29 Unhandled Exception: System.InvalidOperationException: Already writing. at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource, String location) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\ThrowHelper.cs:line 37 at System.IO.Pipelines.PipeOperationState.Begin(ExceptionResource exception) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\PipeOperationState.cs:line 21 at System.IO.Pipelines.Pipe.System.IO.Pipelines.IPipeWriter.Alloc(Int32 minimumSize) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\Pipe.cs:line 114 at System.IO.Pipelines.Networking.Windows.RIO.RioTcpConnection.ReceiveBeginComplete(UInt32 bytesTransferred) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\RioTcpConnection.cs:line 209 03:23:29 ThrowInvalidOperationException(ExceptionResource resource, String location) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\ThrowHelper.cs:line 37 at System.IO.Pipelines.PipeOperationState.Begin(ExceptionResource exception) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\PipeOperationState.cs:line 21 at System.IO.Pipelines.Pipe.System.IO.Pipelines.IPipeWriter.Alloc(Int32 minimumSize) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\Pipe.cs:line 114 at System.IO.Pipelines.Networking.Windows.RIO.RioTcpConnection.ReceiveBeginComplete(UInt32 bytesTransferred) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\RioTcpConnection.cs:line 209 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.Complete(RioRequestResult* results, UInt32 count, RioTcpConnection[] connectionsToSignal) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 396 03:23:29 xceptionResource exception) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\PipeOperationState.cs:line 21 at System.IO.Pipelines.Pipe.System.IO.Pipelines.IPipeWriter.Alloc(Int32 minimumSize) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\Pipe.cs:line 114 at System.IO.Pipelines.Networking.Windows.RIO.RioTcpConnection.ReceiveBeginComplete(UInt32 bytesTransferred) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\RioTcpConnection.cs:line 209 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.Complete(RioRequestResult* results, UInt32 count, RioTcpConnection[] connectionsToSignal) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 396 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.ProcessPhysicalCompletions() in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 441 03:23:29 pace\Debug_prtestf5b6dea6\src\System.IO.Pipelines\Pipe.cs:line 114 at System.IO.Pipelines.Networking.Windows.RIO.RioTcpConnection.ReceiveBeginComplete(UInt32 bytesTransferred) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\RioTcpConnection.cs:line 209 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.Complete(RioRequestResult* results, UInt32 count, RioTcpConnection[] connectionsToSignal) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 396 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.ProcessPhysicalCompletions() in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 441 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.RunPhysicalCompletions(Object state) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 224 03:23:29 ipelines.Networking.Windows.RIO.RioTcpConnection.ReceiveBeginComplete(UInt32 bytesTransferred) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\RioTcpConnection.cs:line 209 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.Complete(RioRequestResult* results, UInt32 count, RioTcpConnection[] connectionsToSignal) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 396 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.ProcessPhysicalCompletions() in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 441 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.RunPhysicalCompletions(Object state) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 224 at System.Threading.Thread.ThreadMain_ParameterizedThreadStart(Object parameter) 03:23:29 _prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\RioTcpConnection.cs:line 209 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.Complete(RioRequestResult* results, UInt32 count, RioTcpConnection[] connectionsToSignal) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 396 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.ProcessPhysicalCompletions() in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 441 at System.IO.Pipelines.Networking.Windows.RIO.Internal.RioThread.RunPhysicalCompletions(Object state) in D:\j\workspace\Debug_prtestf5b6dea6\src\System.IO.Pipelines.Networking.Windows.RIO\Internal\RioThread.cs:line 224 at System.Threading.Thread.ThreadMain_ParameterizedThreadStart(Object parameter) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) 03:23:29 The active test run was aborted. Reason: Unable to communicate with test host process.

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 4, 2017

@ahsonkhan Yeh that's the failstack. We haven't got the state transitions right.

@benaadams Oh I see. Is that synchronous at the scheduling level, or at the underlying IO? Could we look at an alternative scheduler for the reader?

Otherwise I don't really see an alternative without changes to pipelines.

@ahsonkhan
Copy link
Contributor

@dotnet-bot test this please

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 6, 2017

@ahsonkhan:

19:05:10 Unhandled Exception: System.IO.Pipelines.Networking.Libuv.Interop.UvException: Error -4082 EBUSY resource busy or locked
19:05:10 Unhandled Exception: System.IO.Pipelines.Networking.Libuv.Interop.UvException: Error -4082 EBUSY resource busy or locked   at System.IO.Pipelines.Networking.Libuv.Interop.Uv.ThrowError(Int32 statusCode) in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\Uv.cs:line 80
19:05:10 Unhandled Exception: System.IO.Pipelines.Networking.Libuv.Interop.UvException: Error -4082 EBUSY resource busy or locked   at System.IO.Pipelines.Networking.Libuv.Interop.Uv.ThrowError(Int32 statusCode) in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\Uv.cs:line 80   at System.IO.Pipelines.Networking.Libuv.Interop.UvLoopHandle.ReleaseHandle() in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\UvLoopHandle.cs:line 44
19:05:10 Unhandled Exception: System.IO.Pipelines.Networking.Libuv.Interop.UvException: Error -4082 EBUSY resource busy or locked   at System.IO.Pipelines.Networking.Libuv.Interop.Uv.ThrowError(Int32 statusCode) in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\Uv.cs:line 80   at System.IO.Pipelines.Networking.Libuv.Interop.UvLoopHandle.ReleaseHandle() in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\UvLoopHandle.cs:line 44   at System.Runtime.InteropServices.SafeHandle.InternalDispose()
19:05:10 Unhandled Exception: System.IO.Pipelines.Networking.Libuv.Interop.UvException: Error -4082 EBUSY resource busy or locked   at System.IO.Pipelines.Networking.Libuv.Interop.Uv.ThrowError(Int32 statusCode) in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\Uv.cs:line 80   at System.IO.Pipelines.Networking.Libuv.Interop.UvLoopHandle.ReleaseHandle() in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\UvLoopHandle.cs:line 44   at System.Runtime.InteropServices.SafeHandle.InternalDispose()   at System.Threading.Thread.ThreadMain_ParameterizedThreadStart(Object parameter)
19:05:10 Unhandled Exception: System.IO.Pipelines.Networking.Libuv.Interop.UvException: Error -4082 EBUSY resource busy or locked   at System.IO.Pipelines.Networking.Libuv.Interop.Uv.ThrowError(Int32 statusCode) in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\Uv.cs:line 80   at System.IO.Pipelines.Networking.Libuv.Interop.UvLoopHandle.ReleaseHandle() in D:\j\workspace\Release_prtest58035862\src\System.IO.Pipelines.Networking.Libuv\Interop\UvLoopHandle.cs:line 44   at System.Runtime.InteropServices.SafeHandle.InternalDispose()   at System.Threading.Thread.ThreadMain_ParameterizedThreadStart(Object parameter)   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

That's kind of weird, it's trying to dispose the libuv loop while it's still busy doing io, and I haven't directly touched any libuv code in this PR.

If #1432 passes I'll just rebase on that and use its approach to SocketFacts. It's probably not worth a lot of effort here because I think @benaadams will come along soon and pave this code anyways.

@ahsonkhan
Copy link
Contributor

If #1432 passes I'll just rebase on that and use its approach to SocketFacts.

Sounds good. @shiftylogic will work on resolving the issue with #1432.

@ahsonkhan
Copy link
Contributor

@KodrAus, please resolve the conflict.

@davidfowl, review?

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 19, 2017

@benaadams Do you have some new code in Kestrel that works around this? If so it's probably best for me to just close this and we can port that over. Otherwise I'll fix the conflict and remove dead code.

@benaadams
Copy link
Member

Yeah aspnet/KestrelHttpServer#1630 but its quite a change as moved to threadpool and events rather than completion ports; would go with this change. Still haven't resolved the flushing completely as the read flushing needs some seperation

@KodrAus
Copy link
Contributor Author

KodrAus commented Apr 19, 2017

Ok I'll polish it up today then and ping when it's ready for review 👍

@davidfowl davidfowl closed this Apr 20, 2017
@davidfowl
Copy link
Member

@KodrAus open a new PR when ready

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants