Felsökning av ASP.NET minnesläcka som i slutändan va ett trådproblem

Sedan en tid tillbaka så har vi haft problem med att vår W3WP får konstiga fel när den ska försöka allokera resurser till objekt i runtime.

Första felet får vi när vi ska skapa upp ett nytt TransactionScope och anropar databasen...


Exception Type: System.Transactions.TransactionException
Message: The operation is not valid for the state of the transaction.

Exception Type: System.TimeoutException
Message: Transaction Timeout



Andra konstiga felet vi fick var...



Type: System.Data.SqlClient.SqlException
Message: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.



Så min första misstanke var att vi läcker SQLConnections från ConnectionPoolen. När jag tog upp perfmon och kontrollerade antal öppna sqlanlustningar var endast 3 anslutningar aktiva. Därmed kunde jag utesluta att vi läckte SQLConnections.

Eftersom vi inte hade förberett produktion server med ADPlus, så kunde jag inte ta en minnesdump för senare analys. Då system används av stora internationella kunder och med finnasiellainstrument var prio ett att få upp systemet så snabbt som möjligt. Där med döda vi W3WP processen som då släpper alla allokerade resurser.

För några dagar sedan hände det igen, men denna gång var jag föreberedd och hade installerat ADPlus i produktion. Jag logga snabbt in och körde ADPlus för att få en minnesdump av systemet.

Windbg:

Först kollade jag vad som låg på heapen (!DumpHeap -stat) och hitta inget anmärkningsvärt. Så här såg det ut...



65245d88 2428 8297936 System.Data.RBTree`1+Node[[System.Data.DataRow, System.Data]][]
65245048 197605 12646720 System.Data.DataRow
7933335c 40896 16573616 System.Byte[]
793040bc 104067 20629120 System.Object[]
000e0798 618 37587828 Free
793308ec 1201107 108431696 System.String



Det enda man skulle kunna tycka är lite anmärkningsvärt är att vi allokerar 108mb i strängar, varför?

Jag listade alla objekt av typen System.String som va över 8,5mb i storlek och hittade 78 objekt. Vad är det då som håller dessa objekt kvar i minnet?

Efter lite letande (.foreach(myVariable {!dumpheap -mt 793308ec -min 85000 -short}){!do myVariable;.echo *************}) kunde jag se att många objekt innehåller data som jag vet tillhör speciella trådar i systemet. Men trådarna ska inte leva längre än någon sekund varför?

Jag titta igenom alla trådar som har en .NET stack (~*e !CLRStack), där hittar jag 6 trådar som har samma callstack. Men trådarna väntar på en Join() varför går inte anropet igenom?



25d1e32c 7c82860c [HelperMethodFrame_1OBJ: 25d1e32c] System.Threading.Thread.JoinInternal()
25d1e384 7974cd45
System.Threading.Thread.Join()
25d1e388 22d59e0f XXXXXXXXXXXXXXX.CheckForTradingNeedsAndCreateLocates.Run()
25d1e3dc 792d6cf6 System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
25d1e3e8 792f5611 System.Threading.ExecutionContext.runTryCode(System.Object)
25d1e818 79e71b4c [HelperMethodFrame_PROTECTOBJ: 25d1e818] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)
25d1e880 792f5507 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
25d1e89c 792e0175 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
25d1e8b4 792d6c74 System.Threading.ThreadHelper.ThreadStart()
25d1eae0 79e71b4c [GCFrame: 25d1eae0]
25d1edd0 79e71b4c [ContextTransitionFrame: 25d1edd0]
OS Thread Id: 0x2040 (49)



Jag byter till tråden ” OS Thread Id: 0x2040 (49) ” (~49s) och tittar närmare på callstacken och dess parametrar (!CLRStack –p)


0:049> !CLRStack -p
OS Thread Id: 0x2040 (49)
ESP EIP
25c4ed2c 7c82860c [HelperMethodFrame_1OBJ: 25c4ed2c] System.Threading.Thread.JoinInternal()
25c4ed84 7974cd45 System.Threading.Thread.Join()
PARAMETERS:
this =

25c4ed88 XXXXXXXXXXXXX.CheckForTradingNeedsAndCreateLocates.Run()
PARAMETERS:
this = 0x037fce9c

25c4eddc 792d6cf6 System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
PARAMETERS:
state =

25c4ede8 792f5611 System.Threading.ExecutionContext.runTryCode(System.Object)
PARAMETERS:
userData =

25c4f218 79e71b4c [HelperMethodFrame_PROTECTOBJ: 25c4f218] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)
25c4f280 792f5507 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
PARAMETERS:
executionContext =
callback =
state =

25c4f29c 792e0175 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
PARAMETERS:
executionContext =
callback =
state =

25c4f2b4 792d6c74 System.Threading.ThreadHelper.ThreadStart()
PARAMETERS:
this =

25c4f4e0 79e71b4c [GCFrame: 25c4f4e0]
25c4f7d0 79e71b4c [ContextTransitionFrame: 25c4f7d0]



För att se vilken tråd som objektet XXXXXXXXXXXXXXX försöker göra en Join() på dumpar jag ut parametern som tråden använders sig av.



0:049> !do 0x037fce9c
Name: XXXXXXXXXXXXXXXXXXXX.CheckForTradingNeedsAndCreateLocates
MethodTable: 01eb9eb0
EEClass: 22c83184
Size: 24(0x18) bytes
(C:\WINNT\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Fields:
MT Field Offset Type VT Attr Value Name
79328f08 40000f6 4 ...l.WindowsIdentity 0 instance 037fcec8 _applicationIdentity
79330ec0 40000f7 8 ....Threading.Thread 0 instance 0eab25a4 _callingThread
79332b38 40000f8 c System.Int32 1 instance XXXXXX _clientFileId
793043b8 40000f9 10 System.Boolean 1 instance 1 _okToRun



Efter det så dumpar jag _callingThread


0:049> !do 0eab25a4
Name: System.Threading.Thread
MethodTable: 79330ec0
EEClass: 790ed984
Size: 56(0x38) bytes
(C:\WINNT\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79321cd0 400063f 4 ....Contexts.Context 0 instance 10a94e70 m_Context
7932d5e0 4000640 8 ....ExecutionContext 0 instance 00000000 m_ExecutionContext
793308ec 4000641 c System.String 0 instance 00000000 m_Name
79330d50 4000642 10 System.Delegate 0 instance 00000000 m_Delegate
79329fe8 4000643 14 System.Object[][] 0 instance 06ace0f4 m_ThreadStaticsBuckets
79332a88 4000644 18 System.Int32[] 0 instance 06ace198 m_ThreadStaticsBits
793334e8 4000645 1c ...ation.CultureInfo 0 instance 00000000 m_CurrentCulture
793334e8 4000646 20 ...ation.CultureInfo 0 instance 00000000 m_CurrentUICulture
79330508 4000647 24 System.Object 0 instance 00000000 m_ThreadStartArg
793331b4 4000648 28 System.IntPtr 1 instance 13cdd8 DONT_USE_InternalThread
79332b38 4000649 2c System.Int32 1 instance 2 m_Priority
79332b38 400064a 30 System.Int32 1 instance 10
m_ManagedThreadId
79309508 400064b 16c ...LocalDataStoreMgr 0 shared static s_LocalDataStoreMgr
>> Domain:Value 000d6488:00000000 00108fd8:0ee05db8 1e635008:0adc3d1c
79330508 400064c 170 System.Object 0 shared static s_SyncObject
>> Domain:Value 000d6488:10a92328 00108fd8:10a9e578 1e635008:0ab12a84


Det intressanta här är m_ ManagedThreadId variabeln som har värde 10. Vi vet alltså nu att tråden som kör Join() I metoden CheckForTradingNeedsAndCreateLocates.Run(). Gör en Join() på tråd id 10. Var är då tråd 10 för tråd och varför disposas den inte?

Vi byter till tråd 10 och se vad den pysslar med (~10s)



0:049> ~10s
eax=000000c0 ebx=00000000 ecx=012cfc20 edx=7ffde000 esi=00000000 edi=00000001
eip=7c82860c esp=012cfcf0 ebp=012cffb8 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
ntdll!KiFastSystemCallRet:
7c82860c c3 ret
0:010> !CLRStack
OS Thread Id: 0x4840 (10)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process



Detta är konstigt. Tråd 10 är inte en .Net tråd. Hur kan det komma sig att tråd 10 som körde CheckForTradingNeedsAndCreateLocates.Run() inte är en .NET tråd. Är inte alla trådar som kör efter MTA tråden .NET i ASP.NET?

Låt oss kolla ungmanage callstack på tråden.



:010> k 2000
ChildEBP RetAddr
011cff24 7c8277f9 ntdll!KiFastSystemCallRet
011cff28 77e5bea2 ntdll!NtRemoveIoCompletion+0xc
011cff54 5a30248e kernel32!GetQueuedCompletionStatus+0x29
011cff8c 5a3026ac w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x33
011cffa0 5a301da9 w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x24
011cffb8 77e6482f w3tp!THREAD_MANAGER::ThreadManagerThread+0x39
011cffec 00000000 kernel32!BaseThreadStart+0x34




Detta är intressant! Tråden som körde vår kod är en tråd som tillhör W3WP processens trådpool. Finnessen med en trådpool är att trådar inte dör efter de är klara. Istället återanvänds trådarna för att spara prestanda då det kostar en hel del att skapa upp nya trådar.

Slutsats:
Eftersom applikationen körs i ASP.NET så vet vi med hjälp av informationen ovan att externa anrop kommer in i systemet via en trådpool som ägs av W3WP processen. Och eftersom trådarna tillhör en trådpool så kan vi inte förlita oss på att tråden kommer att disposas. Alltså kommer Join() anropet hänga tills W3WP processen startas om. Eftersom trådarna ligger kvar i minnen i så kommer dess resurser att ”läcka” minne.

Lösning:
1, Skriva om systemet så den inte kräver att kallande tråd disposas innan systemet går vidare med sina beräkningar.


2, Alltid se till att anrop som kommer från ASP.NET wrappas in i en ny tråd som vi själva kan hantera och disposa när anropet är klart. Och bibehålla logiken som kräver att kallande tråd disposas innan beräkningarna körs.

Slutord:

Trådning kan se lätt ut på ytan, efter att jobbat med trådar i 8 år inser jag hur lätt det är att gå vilse i pannkakassmeten. Så använd trådar så sparsamt du kan.


//Johan

Visningar: 151

Kommentera

Du måste vara medlem i SweNug för att lägga till kommentarer!

Gå med i SweNug

Kommentar av Tiberiu Covaci den 4 Maj 2010 kl. 17.13
Varför inte nu på fredag på dotNet4ever!?

/T
Kommentar av Johan Spännare den 4 Maj 2010 kl. 13.41
Tack Tibi!
Dock så måste vi köra trådar i detta fall, vid nästa pub-runda ska jag förklara varför :)
Kommentar av Tiberiu Covaci den 4 Maj 2010 kl. 11.41
Eller upgradera till .NET 4, och försök köra tasks. :) Men, det är rekomenderat att man låter bli och använder trådar i ASP.NET. Prova med asyncrona sidor istället.

© 2018   Created by Jarle Skogheim.   Drivs med tekniken bakom

Emblem  |  Rapportera en händelse  |  Användarvillkor