Excessively large number of StringBuilder objects allocated in FormReader for big input data

[aspnet-hello]

From @yuwaMSFT on Friday, March 11, 2016 10:54:07 AM

In one stress run on Linux we hit OOM. During investigation, we saw excessive StringBuilder objects allocated in FormReader. The implementation will keep reading the stream until reaching a separator. In the test, we were posting faked large data ( > 16MB), which could cause the allocation of 2000 StringBuilder objects (8K chunk for each). If keep them all in memory we could only support very small number of clients. We probably can either reject big form or save data to temp cache file.

_### _OS Thread Id: 0xf462 (1)
        Child SP               IP Call Site
00007F27E6A441F0 00007F2862257CC9 [PrestubMethodFrame: 00007f27e6a441f0] System.Threading.Tasks.AwaitTaskContinuation.ThrowAsyncIfNecessary(System.Exception)
00007F27E6A448D0 00007F27E877FD9A System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
00007F27E6A46688 00007F286185E1CD [HelperMethodFrame: 00007f27e6a46688]
00007F27E6A46D40 00007F27E7DF7792 System.Text.StringBuilder.ExpandByABlock(Int32)
00007F27E6A46D80 00007F27E82BB29E System.Text.StringBuilder.Append(Char, Int32)
00007F27E6A46DB0 00007F27E7BF044B System.Text.StringBuilder.Append(Char)
00007F27E6A46DD0 00007F27E97AD3F9 Microsoft.AspNetCore.WebUtilities.FormReader+<ReadWordAsync>d__10.MoveNext()
00007F27E6A46E10 00007F27E7DFCB9A System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00007F27E6A46E60 00007F27E877FF42 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
00007F27E6A46EA0 00007F27E877FD65 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
00007F27E6A46ED0 00007F27E82B42D1 System.Threading.Tasks.Task.FinishContinuations()
00007F27E6A46F50 00007F27E878018F System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].TrySetResult(System.Threading.Tasks.VoidTaskResult)
00007F27E6A46F70 00007F27E87800AE System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetResult(System.Threading.Tasks.VoidTaskResult)
00007F27E6A46FB0 00007F27E82C7D09 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetResult(System.Threading.Tasks.Task`1<System.Threading.Tasks.VoidTaskResult>)
00007F27E6A46FD0 00007F27E97AD7C6 Microsoft.AspNetCore.WebUtilities.FormReader+<BufferAsync>d__13.MoveNext()
00007F27E6A47000 00007F27E7DFCB9A System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00007F27E6A47050 00007F27E877FF42 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
00007F27E6A47090 00007F27E877FD65 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
00007F27E6A470C0 00007F27E82B42D1 System.Threading.Tasks.Task.FinishContinuations()
00007F27E6A47140 00007F27E82B6E3C System.Threading.Tasks.Task`1[[System.Int32, mscorlib]].TrySetResult(Int32)
00007F27E6A47160 00007F27E877DAA6 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Int32, mscorlib]].SetResult(Int32)
00007F27E6A47190 00007F27E877CF35 System.IO.StreamReader+<ReadAsyncInternal>d__69.MoveNext()
00007F27E6A47230 00007F27E7DFCB9A System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00007F27E6A47280 00007F27E877FF42 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
00007F27E6A472C0 00007F27E877FD65 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
00007F27E6A472F0 00007F27E82B42D1 System.Threading.Tasks.Task.FinishContinuations()
00007F27E6A47370 00007F27E82B6E3C System.Threading.Tasks.Task`1[[System.Int32, mscorlib]].TrySetResult(Int32)
00007F27E6A47390 00007F27E877DAA6 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Int32, mscorlib]].SetResult(Int32)
00007F27E6A473C0 00007F27E877D724 System.IO.StreamReader+<ReadBufferAsync>d__102.MoveNext()
00007F27E6A47450 00007F27E7DFCB9A System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00007F27E6A474A0 00007F27E877FF42 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
00007F27E6A474E0 00007F27E877FD65 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
00007F27E6A47510 00007F27E82B42D1 System.Threading.Tasks.Task.FinishContinuations()
00007F27E6A47590 00007F27E82B6E3C System.Threading.Tasks.Task`1[[System.Int32, mscorlib]].TrySetResult(Int32)
00007F27E6A475B0 00007F27E877DAA6 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Int32, mscorlib]].SetResult(Int32)
00007F27E6A475E0 00007F27E97ADF19 Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream+<ReadAsync>d__24.MoveNext()
00007F27E6A47650 00007F27E7DFCB9A System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00007F27E6A476A0 00007F27E877FF42 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
00007F27E6A476E0 00007F27E877FD65 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
00007F27E6A47710 00007F27E82B42D1 System.Threading.Tasks.Task.FinishContinuations()
00007F27E6A47790 00007F27E82B34A8 System.Threading.Tasks.Task.Finish(Boolean)
00007F27E6A477D0 00007F27E7DFE091 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)
00007F27E6A47890 00007F27E7DFD873 System.Threading.Tasks.Task.ExecuteEntry(Boolean)
00007F27E6A478B0 00007F27E7E0F215 System.Threading.ThreadPoolWorkQueue.Dispatch()
00007F27E6A47C40 00007F286186EFA7 [DebuggerU2MCatchHandlerFrame: 00007f27e6a47c40]


(lldb) sos DumpObj 00007f27c361e368
Name:        System.Text.StringBuilder
MethodTable: 00007f27e7c4e480
EEClass:     00007f27e7c3d1b8
Size:        48(0x30) bytes
File:        /mnt/test/StarterMvc/bin/debug/dnxcore50/ubuntu.14.04-x64/mscorlib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007f27e7c29a08  4001616        8        System.Char[]  0 instance 00007f27cb23b8c0 m_ChunkChars
00007f27e7c4e480  4001617       10 ...ext.StringBuilder  0 instance 00007f27cb23f7c0 m_ChunkPrevious
00007f27e7c216a0  4001618       18         System.Int32  1 instance                0 m_ChunkLength
00007f27e7c216a0  4001619       1c         System.Int32  1 instance          4928192 m_ChunkOffset
00007f27e7c216a0  400161a       20         System.Int32  1 instance       2147483647 m_MaxCapacity_
_

Totally we had more than 10000 StringBuilder objects. 
_Statistics:
              MT    Count    TotalSize Class Name
00007f27e7c4e480    10539       505872 System.Text.StringBuilder
_

Statistics:
              MT    Count    TotalSize Class Name
00007f27e7c29a08    10690    166336624 System.Char[]

Copied from original issue: aspnet/HttpAbstractions#583

[aspnet-hello]

From @yuwaMSFT on Friday, March 11, 2016 10:58:15 AM

@halter73 @muratg @Tratcher @sivagms @sajayantony

[aspnet-hello]

From @muratg on Monday, March 14, 2016 12:06:29 PM

@yuwaMSFT Is this in Music Store?

[aspnet-hello]

From @yuwaMSFT on Monday, March 14, 2016 12:16:41 PM

@muratg It's not. It's a stress app

[aspnet-hello]

From @sajayantony on Monday, March 14, 2016 12:19:06 PM

@muratg @Eilon Do you want to mark this as label this as stress. FormReader is currently failing stress mix. So I've asked @yuwaMSFT to remove that scenario for now and see how far along it can progress.

[aspnet-hello]

From @Tratcher on Monday, March 14, 2016 12:23:36 PM

We can pool StringBuilders.

aspnet/HttpAbstractions#578 will help a little by removing the backing buffer. A workaround for large forms is using the WebUtilties libraries to read them in a streamed fashion without building up a large collection.

[aspnet-hello]

From @yuwaMSFT on Monday, March 14, 2016 12:45:08 PM

Also for large forms, they could stack up in Gen 2 quickly since the request takes time to finish. I ran the test for <5mins and disconnected all clients. Checked the StringBuilder objs in heap:
Total # of objs: 70643
Total # of objs in Gen 2: 19391
Total # of objs in Gen 1: 49650

[aspnet-hello]

From @Tratcher on Monday, March 14, 2016 12:46:53 PM

The string builders are only used in the initial parsing, they aren't held for the duration of the request are they?

[aspnet-hello]

From @yuwaMSFT on Monday, March 14, 2016 12:56:40 PM

From the code it's supposed to be cleared after we read the complete key/value pair...But if the form data is big it may take a while to finish reading I guess. Also since there are more allocations, we may do GC more frequently and push the objs to the next generate faster?

[aspnet-hello]

From @Tratcher on Monday, March 14, 2016 1:31:12 PM

What does your data look like? form-url-encoded? Lots of small keys/values, or large keys/values?

[aspnet-hello]

From @yuwaMSFT on Monday, March 14, 2016 2:00:47 PM

Yes, the default content type. It's a single pair with big value.
Maybe content with lots of small pairs is fine. I can add one in the test.

[aspnet-hello]

From @dougbu on Monday, March 14, 2016 2:08:39 PM

What is the difference between this bug and #561?

[aspnet-hello]

From @halter73 on Monday, March 14, 2016 3:59:41 PM

@dougbu Based on you dotpeek screenshots it looks like the strings from ResponseCookies.Append still get GC'd.

For some reason, @yuwaMSFT is seeing tens of thousands of StringBuilders (2000 per 16MB post and that's StringBuilders not strings) remaining in the heap leading to the process running out of memory and being killed by the Linux kernel.