Improved Memoryblock tracking #998

benaadams · 2016-07-20T11:03:10Z

Extending #991

In debug:

Adds leaser info.
Checks for double returns.
Forces finalizer to cause the finalizer check to trigger.

Also fixed 3 tests that weren't handling blocks properly.

Should resolve #988

Resolves #1012
Resolves #1013

/cc @halter73 @davidfowl @mikeharder

cesarblum · 2016-07-20T21:03:42Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/MemoryPool.cs

+        {
+            Debug.Assert(!_disposedValue, "Block being leased from disposed pool!");
+#else
+


Can you move this after the doc comments or does the compiler complain about the args?

benaadams · 2016-07-20T21:31:26Z

Turns out it doesn fix everything but it does give more info when it goes wrong, just got the following StackTrace

Unhandled Exception: System.Diagnostics.Debug+DebugAssertException: Block being garbage collected instead of returned to pool: IncomingStart, I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\SocketInput.cs, 65
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure.MemoryPool.Lease(String memberName, String sourceFilePath, Int32 sourceLineNumber) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Infrastructure\MemoryPool.cs:line 85
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.SocketInput.IncomingStart() in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\SocketInput.cs:line 65
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Connection.OnAlloc(UvStreamHandle handle, Int32 suggestedSize) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Connection.cs:line 199
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Connection.AllocCallback(UvStreamHandle handle, Int32 suggestedSize, Object state) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Connection.cs:line 194
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Connection.<>c.<.cctor>b__28_1(UvStreamHandle handle, Int32 suggestedsize, Object state) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Connection.cs:line 24
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvStreamHandle.UvAllocCb(IntPtr handle, Int32 suggested_size, uv_buf_t& buf) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvStreamHandle.cs:line 149
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvStreamHandle.<>c.<.cctor>b__24_1(IntPtr handle, Int32 suggested_size, uv_buf_t& buf) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvStreamHandle.cs:line 16
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.NativeMethods.uv_run(UvLoopHandle handle, Int32 mode)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.NativeMethods.uv_run(UvLoopHandle handle, Int32 mode)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.run(UvLoopHandle handle, Int32 mode) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\Libuv.cs:line 107
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvLoopHandle.Run(Int32 mode) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvLoopHandle.cs:line 28
   at Microsoft.AspNetCore.Server.Kestrel.Internal.KestrelThread.ThreadStart(Object parameter) in I:\Work\GitHub\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Infrastructure\KestrelThread.cs:line 232
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

benaadams · 2016-07-20T21:57:04Z

Hmm... got really upset with those changes?

benaadams · 2016-07-20T22:36:08Z

@davidfowl @CesarBS looks like it can always trigger the issue now...

Test is: Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.

Alloc stack trace is:

IncomingStart, C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\SocketInput.cs, 65 ***
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure.MemoryPool.Lease(String memberName, String sourceFilePath, Int32 sourceLineNumber) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Infrastructure\MemoryPool.cs:line 85
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.SocketInput.IncomingStart() in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\SocketInput.cs:line 65
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Connection.OnAlloc(UvStreamHandle handle, Int32 suggestedSize) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Connection.cs:line 199
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Connection.AllocCallback(UvStreamHandle handle, Int32 suggestedSize, Object state) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Connection.cs:line 194
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Connection.<>c.<.cctor>b__28_1(UvStreamHandle handle, Int32 suggestedsize, Object state) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Connection.cs:line 24
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvStreamHandle.UvAllocCb(IntPtr handle, Int32 suggested_size, uv_buf_t& buf) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvStreamHandle.cs:line 149
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvStreamHandle.<>c.<.cctor>b__24_1(IntPtr handle, Int32 suggested_size, uv_buf_t& buf) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvStreamHandle.cs:line 16
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.NativeMethods.uv_run(UvLoopHandle handle, Int32 mode)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.NativeMethods.uv_run(UvLoopHandle handle, Int32 mode)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.run(UvLoopHandle handle, Int32 mode) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\Libuv.cs:line 107
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvLoopHandle.Run(Int32 mode) in C:\projects\kestrelhttpserver\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvLoopHandle.cs:line 28
   at Microsoft.AspNetCore.Server.Kestrel.Internal.KestrelThread.ThreadStart(Object parameter) in

Also fixed 3 tests that weren't handling block properly

benaadams · 2016-07-21T00:36:37Z

False alarm on the block, that happens after test error - is a symptom not cause.

benaadams · 2016-07-21T00:40:50Z

@CesarBS Environment.StackTrace causes the MaxRequestBufferSizeTests to bomb; which then causes the block to finalize. Dropping the stack trace.

benaadams · 2016-07-21T00:53:50Z

AppVeyor unrelated #1002 WritesDontCompleteImmediatelyWhenTooManyBytesIncludingNonImmediateAreAlreadyPreCompleted

halter73 · 2016-07-25T17:49:54Z

Noticed the tests in the PR as no longer slow as molasses. Nice!

halter73 · 2016-07-25T17:50:39Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/MemoryPool.cs

+#if DEBUG
+        public MemoryPoolBlock Lease([CallerMemberName] string memberName = "",
+                             [CallerFilePath] string sourceFilePath = "",
+                             [CallerLineNumber] int sourceLineNumber = 0)


Is it the switching Environment.StackTrace to this that made the tests faster?

Another one of my super nits :) Put the first arg in its own line, and indent all args with 4 spaces only.

Environment.StackTrace caused the large response test to crash, which then caused a block to finalize. On the one hand it crashed; on the other it finalized a block - so may still be a circumstance...

dnfclas added the cla-already-signed label Jul 20, 2016

cesarblum reviewed Jul 20, 2016
View reviewed changes

benaadams force-pushed the more-block-collect-info branch from d3c1876 to cbdb37a Compare July 20, 2016 22:21

benaadams force-pushed the more-block-collect-info branch from cbdb37a to 415ab1f Compare July 20, 2016 22:39

benaadams added 2 commits July 21, 2016 01:13

Improved Memoryblock tracking

7b8abf5

Also fixed 3 tests that weren't handling block properly

Use Environment.NewLine and Environment.StackTrace

aa385a1

benaadams force-pushed the more-block-collect-info branch from 7f8e48f to 83cac5b Compare July 21, 2016 00:13

Remove Environment.StackTrace as crashing tests

f42316a

benaadams force-pushed the more-block-collect-info branch from 83cac5b to f42316a Compare July 21, 2016 00:44

benaadams closed this Jul 21, 2016

benaadams reopened this Jul 21, 2016

dnfclas added the cla-already-signed label Jul 21, 2016

This was referenced Jul 21, 2016

Assert "Block being garbage collected instead of returned to pool" on Travis/Linux #988

Closed

Two tests don't return blocks to the memory pool #1012

Closed

Test returns block to pool twice #1013

Closed

halter73 reviewed Jul 25, 2016
View reviewed changes

davidfowl assigned halter73 Jul 27, 2016

halter73 merged commit f42316a into aspnet:dev Jul 28, 2016

benaadams deleted the more-block-collect-info branch March 27, 2018 05:14

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Improved Memoryblock tracking #998

Improved Memoryblock tracking #998

Uh oh!

benaadams commented Jul 20, 2016 •

edited

Loading

Uh oh!

cesarblum Jul 20, 2016

Uh oh!

benaadams Jul 20, 2016

Uh oh!

benaadams commented Jul 20, 2016

Uh oh!

benaadams commented Jul 20, 2016

Uh oh!

benaadams commented Jul 20, 2016

Uh oh!

benaadams commented Jul 21, 2016

Uh oh!

benaadams commented Jul 21, 2016

Uh oh!

benaadams commented Jul 21, 2016

Uh oh!

halter73 commented Jul 25, 2016

Uh oh!

halter73 Jul 25, 2016

Uh oh!

cesarblum Jul 25, 2016

Uh oh!

benaadams Jul 25, 2016

Uh oh!

Uh oh!

Improved Memoryblock tracking #998

Improved Memoryblock tracking #998

Uh oh!

Conversation

benaadams commented Jul 20, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cesarblum Jul 20, 2016

Choose a reason for hiding this comment

Uh oh!

benaadams Jul 20, 2016

Choose a reason for hiding this comment

Uh oh!

benaadams commented Jul 20, 2016

Uh oh!

benaadams commented Jul 20, 2016

Uh oh!

benaadams commented Jul 20, 2016

Uh oh!

benaadams commented Jul 21, 2016

Uh oh!

benaadams commented Jul 21, 2016

Uh oh!

benaadams commented Jul 21, 2016

Uh oh!

halter73 commented Jul 25, 2016

Uh oh!

halter73 Jul 25, 2016

Choose a reason for hiding this comment

Uh oh!

cesarblum Jul 25, 2016

Choose a reason for hiding this comment

Uh oh!

benaadams Jul 25, 2016

Choose a reason for hiding this comment

Uh oh!

Uh oh!

benaadams commented Jul 20, 2016 •

edited

Loading