Archive for the ‘WinDbg’ Category

En overraskelse og 1000+ doubles

Friday, July 23rd, 2010

Dette indlæg rummer egentlig ingen ny viden, men på trods af at jeg efterhånden har brugt lang tid på finurlige detaljer omkring .NETs afviklingsmiljø, er jeg først nu stødt på denne detalje, så set i det lys vil jeg tillade mig at betegne emnet for dette indlæg som esoterisk og gentage noget, der muligvis ikke er nyt for alle.

Som det forhåbentlig er kendt for læserne af denne blog, foregår dynamisk allokering af hukommelse i .NET enten i generation 0 af heapen eller på Large Object Heap (LOH) i fald den allokerede instans er på 85.000 bytes eller mere.

Derfor vil small pege på et array allokeret i generation 0 og large pege på et array allokeret på LOH i nedenstående eksempel.

var small = new byte[1000];
var large = new byte[85000];

Det kan vi verificere via WinDbg eller ved at kalde GC.GetGeneration(), der som forventet returnerer henholdsvis 0 og 2 for de to referencer (bemærk, at metoden ikke skelner mellem generation 2 og LOH, da de i forhold til garbage collection behandles i samme ombæring). Bruger vi debuggeren, får vi lidt mere nøjagtig information, og her kan vi se, at large faktisk peger på en instans på LOH.

Gentager vi øvelsen for double[], burde vi igen kunne forudsige placeringen af de enkelte instanser. En double fylder 8 bytes, så for at komme over den magiske grænse, skal vi have et array med lidt over 10.000 elementer, lad os bare sige 11.000. Med det in mente burde vi altså kunne konkludere at small og large endnu en gang peger på instanser i henholdsvis generation 0 og på LOH.

var small = new double[1000];
var large = new double[11000];

Det er bare ikke sådan det forholder sig. Begge arrays bliver allokeret på LOH!

CLRen benytter nemlig en forholdsvis esoterisk optimering i dette tilfælde. Arrays af double med 1000 eller flere elementer bliver mod forventning altid allokeret på LOH. Det er nyt for mig, men hvis man nærlæser kommentarerne til dette gamle blogindlæg, kan man se, at det er ”by design”. Det er altså ikke en fejl, det er en feature.

Argumentationen er, at objekter på LOH altid ligger på 8 bytes skel, og derfor giver bedre performance ved opslag af elementerne. Jeg har ikke kunne finde nogen forklaring på, hvorfor grænsen på 1000 elementer er valgt, men sådan forholder det sig nu engang.

Det er fristende at prøve, om vi kan eftervise effekten af denne optimering, men det er ikke let i praksis, da vi har meget begrænset kontrol over og indsigt i allokering og adresselæsninger i managed code, så derfor må vi tage Microsofts ord for pålydende her.

Konsekvenserne af denne optimering kan være mange og ikke alle nødvendigvis til vores fordel. Hvis vi antager, at optimeringen har sin berettigelse, så må vi gå ud fra, at læsning af elementerne i et double[], nyder gavn af den gunstige placering i hukommelsen.

Til gengæld er disse arrays pludselig dyrere at allokere, eftersom allokering på LOH benytter en free list, hvilket kan være mange gange langsommere end den simple pointeroperation, der skal til ved allokering i generation 0. Ligeledes vil levetiden af disse arrays stige markant. Er der tale om midlertidige arrays, går de fra hurtig oprydning i generation 0 til en lang levetid på LOH. Det kan have indflydelse på hvor stor belastning garbage collection lægger på applikationen, ligesom det kan give yderligere problemer i form af fragmentering af LOH.

Konsekvenserne afhænger af den konkrete applikations forbrug af hukommelse, men givet er det, at det kan være en særdeles vigtig detalje i nogle scenarier. Så med mange års forsinkelse gør jeg hermed mit til at udbrede kendskabet til en godt bevaret hemmelighed.

Debugging adplus.exe

Tuesday, July 20th, 2010

Nej, der mangler ikke et “med” i overskriften. Dette indlæg handler om en fejl, jeg fandt i ADPlus.

I den seneste version af Debugging Tools for Windows er det gamle ADPlus vb-script blevet udskiftet med en exe-fil. ADPlus er blevet genimplementeret som en managed applikation (det gamle script er stadig tilgængelig under navnet adplus_old.vbs).

Ifølge det medfølgende Word-dokument er dette gjort for bedre at kunne udvide ADPlus med ny funktionalitet, og der er allerede kommet et par yderligere muligheder som f.eks. –pmn, der overvåger alle processer med et bestemt navn.

Det er dog ikke det, vi skal se på i dette indlæg. Ligesom sin forgænger understøtter adplus.exe, at vi kan få debuggeren til at starte vores applikation via –sc. Desværre er denne feature ikke implementeret særlig elegant i den nye version.

I forbindelse med en debugging-opgave havde jeg brug for at starte min applikation via –sc, men uanset hvad jeg gjorde, fik jeg nedenstående fejlmeddelelse:

Spawning c:\dev2010\testapp\testapp\bin\release\testapp.exe
!!! ERROR !!!
The system cannot find the file specified
   at System.Diagnostics.Process.StartWithShellExecuteEx(ProcessStartInfo startInfo)
   at System.Diagnostics.Process.Start(ProcessStartInfo startInfo)
   at ADPlus.AdplusEngine.SpawnProcess(String SpawnCommand)
   at ADPlus.AdplusApl.TryAttachSelectedProcesses()
   at ADPlus.AdplusApl.TryRun()
!!!ERROR - ADPlus failed to run

Det fik mig til at tro, at ADPlus af en eller anden grund ikke kunne finde min applikation, men det er faktisk ikke det, fejlmeddelelsen angiver.

I mangel på bedre fyrede jeg op under WinDbg for at finde ud af, hvorfor denne fejl opstod.

adplus.exe er som sagt en managed applikation, og den er bygget til CLR version 2 og AnyCPU, så vores runtime hedder mscorwks, og vi skal have fat i 64 bit versionen af WinDbg på trods af, at vi ønsker at debugge den version, der kommer med 32 bit versionen af Debugging Tools for Windows.

Via Open Executable-dialogen kan vi udvælge adplus.exe og angive de relevante opstartsparametre. Herefter starter WinDbg adplus.exe, men stopper udførelsen, så snart processen er i luften. På dette tidspunkt er CLRen ikke startet endnu, så vi får ikke noget ud af at forsøge at indlæse SOS. I stedet kan vi sætte et event filter så eksekveringen stopper, når CLRen indlæses og derefter indlæse SOS. Det kan gøres som følger:

sxe -c ".loadby sos mscorwks" ld mscorwks

Herefter kører vi videre, indtil vi rammer vores event filter og får indlæst SOS.

0:000> g
ModLoad: 000007fe`efd10000 000007fe`f06be000   C:\Windows\Microsoft.NET\Framework64\v2.0.50727\mscorwks.dll
ntdll!ZwMapViewOfSection+0xa:
00000000`77b9ffda c3              ret

Vi ved fra fejludskriften, at der bliver smidt en exception, så lad os sætte et event filter for managed exceptions.

0:000> sxe -c "!clrstack; !pe" clr

Ovenstående stopper i tilfælde af en managed exception og udskriver derefter kaldestak for den aktuelle tråd samt detaljerne om vores exception. Og så kører vi igen:

0:000> g
(14c4.13fc): CLR exception - code e0434f4d (first chance)
OS Thread Id: 0x13fc (0)
*** WARNING: Unable to verify checksum for C:\Windows\assembly\NativeImages_v2.0.50727_64\System\247913fa7ae6fcf04ea33d28d24ab611\System.ni.dll
Child-SP         RetAddr          Call Site
00000000002eec30 000007feefa406bc System.Diagnostics.Process.StartWithShellExecuteEx(System.Diagnostics.ProcessStartInfo)
00000000002eed30 000007ff00198597 System.Diagnostics.Process.Start(System.Diagnostics.ProcessStartInfo)
00000000002eed70 000007ff00197ef0 ADPlus.AdplusEngine.SpawnProcess(System.String)
00000000002eedc0 000007ff001942ce ADPlus.AdplusApl.TryAttachSelectedProcesses()
00000000002eee50 000007ff00191d98 ADPlus.AdplusApl.TryRun()
00000000002eeec0 000007ff0019026e ADPlus.AdplusApl.TryExecute(System.String[])
00000000002eef00 000007feeffdd502 ADPlus.Program.Main(System.String[])
Exception object: 000000000265fe10
Exception type: System.ComponentModel.Win32Exception
Message: The system cannot find the file specified
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80004005
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
KERNELBASE!RaiseException+0x39:
000007fe`fdb6aa7d 4881c4c8000000  add     rsp,0C8h

Debuggeren er stoppet som følge af en exception. Det ser ud til at passe meget godt med vores fejlsituation, så nu skal vi blot finde ud af, hvad det er for en fil, der ikke kan lokaliseres (tænk på hvor meget lettere alt ville være, hvis vi bare kunne læse det ud af vores exception).

Via kaldestakken kan vi se, at StartWithShellExecuteEx bliver kaldt med en instans af ProcessStartInfo. Hvis vi er heldige, er der en reference til denne på stakken. På 64 bit Windows overføres de fire første argumenter altid i registre, så vi kan ikke regne med at finde noget på stakken. I visse situationen opretter compileren dog lokale referencer på stakken, så det er vores første forsøg:

0:000> !dso
OS Thread Id: 0x13fc (0)
RSP/REG          Object           Name
00000000002eea30 000000000265fef8 System.Text.StringBuilder
00000000002eea68 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eea70 00000000025a7b48 System.String
00000000002eea80 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eeaa0 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eeaf0 000000000265ff20 System.String
00000000002eeb00 0000000002660140 System.String
00000000002eeb70 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eeb78 00000000025a7b48 System.String
00000000002eeb80 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eebd8 00000000025a7b48 System.String
00000000002eebe0 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eec10 000000000265fdf0 System.Diagnostics.ShellExecuteHelper
00000000002eec20 000000000265fe10 System.ComponentModel.Win32Exception
00000000002eec60 000000000265fbb8 System.Diagnostics.Process
00000000002eec68 00000000025a7b48 System.String
00000000002eec70 000000000265f238 System.Diagnostics.ProcessStartInfo
00000000002eece0 000000000265fcc8 Microsoft.Win32.NativeMethods+ShellExecuteInfo
00000000002eed10 000000000265f238 System.Diagnostics.ProcessStartInfo
00000000002eed18 00000000025a7a98 ADPlus.AdplusEngine
00000000002eed20 000000000265fbb8 System.Diagnostics.Process
00000000002eed30 000000000265fbb8 System.Diagnostics.Process
00000000002eed38 000000000265f238 System.Diagnostics.ProcessStartInfo
00000000002eed50 00000000025a7b48 System.String
00000000002eed58 000000000265f238 System.Diagnostics.ProcessStartInfo
00000000002eed60 000000000265f130 System.String
...

Jeg har forkortet listen en smule, men som vi kan se, er der faktisk en reference til en instans af ProcessStartInfo. Heldigt, så behøver vi ikke grave videre. Lad os se nærmere på instansen.

0:000> !do 000000000265f238
Name: System.Diagnostics.ProcessStartInfo
MethodTable: 000007feefb3ce18
EEClass: 000007feef39dcb8
Size: 128(0x80) bytes
 (C:\Windows\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feee37ec90  4003376        8        System.String  0 instance 00000000025a7b48 fileName
000007feee37ec90  4003377       10        System.String  0 instance 000000000265f130 arguments
000007feee37ec90  4003378       18        System.String  0 instance 0000000000000000 directory
000007feee37ec90  4003379       20        System.String  0 instance 0000000000000000 verb
000007feefb0ace0  400337a       68         System.Int32  1 instance                2 windowStyle
000007feee37de60  400337b       6c       System.Boolean  1 instance                0 errorDialog
000007feee381698  400337c       60        System.IntPtr  1 instance                0 errorDialogParentHandle
000007feee37de60  400337d       6d       System.Boolean  1 instance                1 useShellExecute
000007feee37ec90  400337e       28        System.String  0 instance 0000000000000000 userName
000007feee37ec90  400337f       30        System.String  0 instance 0000000000000000 domain
000007feeeb78b50  4003380       38 ...rity.SecureString  0 instance 0000000000000000 password
000007feee37de60  4003381       6e       System.Boolean  1 instance                0 loadUserProfile
000007feee37de60  4003382       6f       System.Boolean  1 instance                0 redirectStandardInput
000007feee37de60  4003383       70       System.Boolean  1 instance                0 redirectStandardOutput
000007feee37de60  4003384       71       System.Boolean  1 instance                0 redirectStandardError
000007feee386ae0  4003385       40 System.Text.Encoding  0 instance 0000000000000000 standardOutputEncoding
000007feee386ae0  4003386       48 System.Text.Encoding  0 instance 0000000000000000 standardErrorEncoding
000007feee37de60  4003387       72       System.Boolean  1 instance                0 createNoWindow
000007feee377a90  4003388       50 System.WeakReference  0 instance 0000000000000000 weakParentProcess
000007feef5d5d68  4003389       58 ....StringDictionary  0 instance 0000000000000000 environmentVariables

Læg mærke til det første felt ved navn fileName. Det må vi hellere se nærmere på:

0:000> !do 00000000025a7b48
Name: System.String
MethodTable: 000007feee37ec90
EEClass: 000007feedf8b038
Size: 40(0x28) bytes
 (C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: cdb.exe
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feee385f00  4000096        8         System.Int32  1 instance                8 m_arrayLength
000007feee385f00  4000097        c         System.Int32  1 instance                7 m_stringLength
000007feee3806d8  4000098       10          System.Char  1 instance               63 m_firstChar
000007feee37ec90  4000099       20        System.String  0   shared           static Empty
                                 >> Domain:Value  00000000003d0390:00000000025a1308 <<
000007feee380588  400009a       28        System.Char[]  0   shared           static WhitespaceChars
                                 >> Domain:Value  00000000003d0390:00000000025a1a38 <<

Hmm, det indeholder cdb.exe. Så det er altså der, skoen trykker. Det er ikke fordi adplus.exe ikke kan finde min applikation, men fordi den ikke kan finde cdb.exe.

Det er jo underligt, for de andre kommandoer har ingen problemer med at finde cdb.exe. Det betyder selvfølgelig, at vi kan løse problemet ved blot at tilføje det relevante directory til vores path, men nu er der faktisk en grund til, at jeg ikke har Debugging Tools for Windows i min path. Jeg har tre versioner installeret (nyeste version i 32 og 64 bit samt en 32 bit udgave af 6.7.5), og jeg vil selv kunne bestemme hvilken en jeg får fat i, og derfor har jeg ingen af disse i min path.

Det oplagte spørgsmål er: Hvorfor fejler –sc, når de andre kommandoer virker uden path? Kaldestakken fortæller os, at den relevante metode i ADPlus er SpawnProcess. Denne metode viser sig at være en instansmetode på typen AdplusEngineadplus.exe er jo en managed applikation, så vi kan inspicere koden ved hjælp af Reflector.

Hvis vi kan kalde SpawnProcess, må der være en instans af AdplusEngine på heapen. Går vi tilbage til ovenstående liste af stakreferencer, finder vi faktisk en reference til en sådan instans. Lad os se nærmere på den.

0:000> !do 00000000025a7a98
Name: ADPlus.AdplusEngine
MethodTable: 000007ff00054068
EEClass: 000007ff00182688
Size: 176(0xb0) bytes
 (C:\dbg32\adplus.exe)
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
0000000000000000  4000009        8                       0 instance 00000000025ab618 m_KeyWords
0000000000000000  400000a       10                       0 instance 00000000025ab500 m_KeyWordsCustom
0000000000000000  400000b       18                       0 instance 00000000025ac580 m_Exceptions
0000000000000000  400000c       20                       0 instance 00000000025ae0f0 m_Breakpoints
000007feee37ec90  400000d       28        System.String  0 instance 00000000025a8c90 m_HangConfiguration
000007feee37de60  400000e       9c       System.Boolean  1 instance                0 m_HangConfigurationChanged
0000000000000000  400000f       30                       0 instance 00000000025ae080 m_PreCommands
0000000000000000  4000010       38                       0 instance 00000000025ae0c8 m_PostCommands
0000000000000000  4000011       40                       0 instance 00000000025ae138 m_NotilyList
000007feee37ec90  4000012       48        System.String  0 instance 00000000025a32a8 m_OutputDir
000007feee37ec90  4000013       50        System.String  0 instance 00000000025b1680 m_OutputDumpDir
000007ff00053f10  4000014       98         System.Int32  1 instance                1 m_RunMode
000007feee37ec90  4000015       58        System.String  0 instance 00000000025ad9a0 m_DateTimeStamp
000007feee37ec90  4000016       60        System.String  0 instance 00000000025a1308 m_Sympath
000007feee37de60  4000017       9d       System.Boolean  1 instance                1 m_SympathSet
000007feee37ec90  4000018       68        System.String  0 instance 00000000025a1308 m_MssLocalCache
000007feee37de60  4000019       9e       System.Boolean  1 instance                0 m_AddMss
000007feee37ec90  400001a       70        System.String  0 instance 00000000025a1308 m_LastScriptCommand
000007feee37ec90  400001b       78        System.String  0 instance 00000000025a7b48 m_Debugger
000007feee37de60  400001c       9f       System.Boolean  1 instance                0 m_ExtensionInteraction
000007feee37de60  400001d       a0       System.Boolean  1 instance                0 m_ExtensionDebug
000007feee37ec90  400001e       80        System.String  0 instance 00000000025ab408 m_AdplusPath
000007feee37ec90  400001f       88        System.String  0 instance 00000000025a1308 m_DebuggersPath
000007ff00053808  4000020       90     ADPlus.AdplusApl  0 instance 00000000025a77c0 m_AdplusApl
000007feee37ec90  4000005        8        System.String  0   static 00000000025a6af0 m_Version
000007feee37ec90  4000006       10        System.String  0   static 00000000025a6b20 m_VersionDate
000007feee374748  4000007       18      System.Object[]  0   static 00000000025a6b90 m_LineSeparator
000007feee374748  4000008       20      System.Object[]  0   static 00000000025a6bb8 m_KWSeparator

Læg mærke til m_AdplusPath. Lad os se, hvad den indeholder.

0:000> !do 00000000025ab408
Name: System.String
MethodTable: 000007feee37ec90
EEClass: 000007feedf8b038
Size: 44(0x2c) bytes
 (C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: C:\dbg32\
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feee385f00  4000096        8         System.Int32  1 instance               10 m_arrayLength
000007feee385f00  4000097        c         System.Int32  1 instance                9 m_stringLength
000007feee3806d8  4000098       10          System.Char  1 instance               43 m_firstChar
000007feee37ec90  4000099       20        System.String  0   shared           static Empty
                                 >> Domain:Value  00000000003d0390:00000000025a1308 <<
000007feee380588  400009a       28        System.Char[]  0   shared           static WhitespaceChars
                                 >> Domain:Value  00000000003d0390:00000000025a1a38 <<

Den indeholder c:\dbg32, som er en junction til min 32 bit installation af Debugging Tools for Windows.

ADPlus har altså de nødvendige oplysninger til rådighed, men glemmer åbenbart at bruge dem. Lad os se på implementeringen af SpawnProcess:

public void SpawnProcess(string SpawnCommand)
{
   Logger.LogAndOut("Spawning " + SpawnCommand);
   string debugger = this.m_Debugger;
   string arguments = ("-c $<\"" + this.OutputDumpDir + "\\DebuggerScript.txt\" ") + SpawnCommand;
   Process.Start(new ProcessStartInfo(debugger, arguments) { WindowStyle = ProcessWindowStyle.Minimized });
}

ProcessStartInfo oprettes blot med indholdet af m_Debugger, og får således ikke m_AdplusPath med, og der har vi altså problemet.

Nu skal jeg bare vente på, at Microsoft får rettet fejlen.

Justering af referencer i ubrugte objekter

Monday, July 5th, 2010

Dette indlæg omhandler forholdsvis eksotiske detaljer omkring implementeringen af garbage collection i .NET. Det vil næppe være relevant i ret mange tilfælde, men at kortlægge disse detaljer var en underholdende og lærerig øvelse, så dette indlæg er i realiteten mere et vidnesbyrd om, hvad vi kan lære om .NETs afviklingsmiljø ved hjælp af WinDbg og SOS.

En kollega kom for nogle dage siden forbi og spurgte, om jeg vidste noget om en funktion ved navn gc_heap::relocate_in_large_objects. Det gjorde jeg tilfældigvis, for jeg var selv stødt på denne lidt spøjst navngivne funktion i anden sammenhæng. Navnet kan jo få en til at tro, at objekter på Large Object Heap (LOH) bliver flyttet, hvilket jo som bekendt ikke er tilfældet. Funktionen står derimod for at justere referencer i objekter på LOH.

Betragt nedenstående figur.

LOH før garbage collection og compaction

Her har vi et array på LOH med referencer til objekter på den almindelige heap. Oprydning af sidstnævnte kan føre til at objekterne bliver rykket sammen for at forhindre fragmentering. Hvis dette sker, skal referencerne i vores array justeres, så de igen peger på de faktiske instanser. Efter en oprydning, sammenrykning og justering kan billedet se ud som følger:

LOH efter garbage collection og compaction

Det er der næppe noget nyt eller overraskende i, men min kollega synes at have observeret, at justering af referencer også skete, hvis den omtalte array ikke længere var i brug.

Kunne det være tilfældet?

Tænk lidt over det: Bliver referencer virkelig justeret for objekter, der ikke længere er i brug af applikationen?

Mit første svar var forkert. Jeg var overbevist om, at der ikke var nogen grund til at justere disse referencer i fald vores array ikke længere var i brug, men i stedet for at lade det komme an på, hvad jeg troede, satte jeg mig for at undersøge det.

Til formålet lavede jeg en lille testapplikation som angivet nedenfor:

sealed class SomeType {
   public int X { get; set; }
   public int Y { get; set; }

   public SomeType(int x, int y) {
      X = x;
      Y = y;
   }
}

sealed class Program {
   static void GenerateRandomObjects() {
      string s = null;
      for (int i = 0; i < 1000; i++) {
         s += i.ToString();
      }
      Console.WriteLine(s.Length);
   }

   static void Main() {
      Console.WriteLine("Press Enter to begin");
      Console.ReadLine();

      GenerateRandomObjects();
      var smallbuffer = new SomeType[100];
      var largebuffer = new SomeType[85000];

      for (int i = 0; i < smallbuffer.Length; i++) {
         var st = new SomeType(1, 2);
         smallbuffer[i] = st;
         largebuffer[i] = st;
      }

      Trace.WriteLine("Buffers filled");
      Debugger.Break();

      Trace.WriteLine(string.Format("smallbuffer is in gen{0}", GC.GetGeneration(smallbuffer)));

      Trace.WriteLine("Nulling root to largebuffer");
      largebuffer = new SomeType[200];
      Debugger.Break();

      Trace.WriteLine(string.Format("smallbuffer is in gen{0}", GC.GetGeneration(smallbuffer)));

      Trace.WriteLine("Collecting ...");
      GC.Collect(1);
      Trace.WriteLine(string.Format("smallbuffer is in gen{0}", GC.GetGeneration(smallbuffer)));
      GenerateRandomObjects();

      Trace.WriteLine("After GC");
      Debugger.Break();

      Console.WriteLine(smallbuffer.Length);
      Console.WriteLine(largebuffer.Length);
   }
}

Applikationen gør som følger:

  • Først opretter den et array, der er stort nok til, at det ryger på LOH.
  • Dette array sættes til at pege på et antal objekter allokeret på den almindelige heap. For at gøre det lettere at spore disse objekter, lader jeg også et mindre array referere disse.
  • Det næste skridt er, at sørge for at det store array ikke længere er refereret. Det er ikke helt så let, som det lyder. Det er ofte utilstrækkeligt at sætte den lokale reference til null. I mange tilfælde vil vi nemlig stadig have en gyldig reference på stakken eller i et register. Derfor er den bedste fremgangsmåde, at lade referencen pege på en ny instans. Det sikrer, at vi få overskrevet eventuelle gemte referencer.
  • Dernæst skal jeg iværksætte en garbage collection, der også laver compaction, så objekterne bliver flyttet på heapen. Dette er også mere tricky end som så, da vi ikke har mulighed for at angive, at der skal foretages compaction ved kald til GC.Collect(). Ergo, var jeg nødt til at prøve mig frem. Ved at lave en del tilfældige objekter rundt om mit lille array (og de refererede objekter) og derefter lave et kald til GC.Collect(1), fik jeg sat gang i den nødvendige oprydning. Så langt så godt.

For at undersøge om referencerne faktisk blev justeret i det store array, gjorde jeg følgende:

Ved første break brugte jeg !dumpheap til at finde mine arrays. Det mindste array har plads til 100 referencer, så jeg filtrerede listen, så jeg kun fik instanser på mere end 400 bytes.

0:004> g
Buffers filled
(1bdc.1918): Break instruction exception - code 80000003 (first chance)
eax=00000000 ebx=00000000 ecx=0000a020 edx=0030f230 esi=00687048 edi=00000064
eip=761d22a1 esp=0030f1a0 ebp=0030f23c iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
KERNELBASE!DebugBreak+0x2:
761d22a1 cc              int     3
0:000> !dumpheap -type Object[] -min 400
 Address       MT     Size
02427060 64cf6c28     8208
026dfc7c 64cf6c28      416
026f9758 64cf6c28      528
03421010 64cf6c28     4096
03422020 64cf6c28      528
03422240 64cf6c28     4096
03423250 64cf6c28     8176
03425250 64cf6c28   340016
total 0 objects
Statistics:
      MT    Count    TotalSize Class Name
64cf6c28        8       366064 System.Object[]
Total 8 objects

De to interessante instanser var henholdsvis 026dfc7c (smallbuffer) og 03425250 (largebuffer).

For at verificere, at de begge pegede på samme elementer, udskrev jeg første element i hver array.

Først smallbuffer:

0:000> !da -details -length 1 026dfc7c
Name:        LOHRoots.SomeType[]
MethodTable: 64cf6c28
EEClass:     64a79698
Size:        416(0x1a0) bytes
Array:       Rank 1, Number of elements 100, Type CLASS
Element Methodtable: 001638cc
[0] 026dfe1c
    Name:        LOHRoots.SomeType
    MethodTable: 001638cc
    EEClass:     001614e4
    Size:        16(0x10) bytes
    File:        C:\dev2010\LOHRoots\LOHRoots\bin\Release\LOHRoots.exe
    Fields:
              MT    Field   Offset                 Type VT     Attr    Value Name
        64d42978  4000001        4             System.Int32      1     instance            1     <X>k__BackingField
        64d42978  4000002        8             System.Int32      1     instance            2     <Y>k__BackingField

Og derefter largebuffer:

0:000> !da -details -length 1 03425250
Name:        LOHRoots.SomeType[]
MethodTable: 64cf6c28
EEClass:     64a79698
Size:        340016(0x53030) bytes
Array:       Rank 1, Number of elements 85000, Type CLASS
Element Methodtable: 001638cc
[0] 026dfe1c
    Name:        LOHRoots.SomeType
    MethodTable: 001638cc
    EEClass:     001614e4
    Size:        16(0x10) bytes
    File:        C:\dev2010\LOHRoots\LOHRoots\bin\Release\LOHRoots.exe
    Fields:
              MT    Field   Offset                 Type VT     Attr    Value Name
        64d42978  4000001        4             System.Int32      1     instance            1     <X>k__BackingField
        64d42978  4000002        8             System.Int32      1     instance            2     <Y>k__BackingField

Læg mærke til, at begge elementer peger på 026dfe1c. Så langt så godt.

Herefter kørte jeg videre til det punkt, hvor referencen til largebuffer overskrives:

0:000> g
smallbuffer is in gen0
Nulling root to largebuffer
(1bdc.1918): Break instruction exception - code 80000003 (first chance)
eax=00000000 ebx=00000000 ecx=0000a020 edx=0030f230 esi=00687048 edi=0242b3f8
eip=761d22a1 esp=0030f1a0 ebp=0030f23c iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
KERNELBASE!DebugBreak+0x2:
761d22a1 cc              int     3

Herefter verificerede jeg, at applikationen ikke længere havde roots til largebuffer.

0:000> !gcroot 03425250
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 1918
Scan Thread 2 OSTHread 1d34

Ingen roots, så den instans largebuffer peger på, kan ryddes op på dette tidspunkt. Videre til næste stop.

0:000> g
smallbuffer is in gen0
Collecting ...
smallbuffer is in gen1
After GC
(1bdc.1918): Break instruction exception - code 80000003 (first chance)
eax=00000000 ebx=00000000 ecx=0000a020 edx=0030f230 esi=00687048 edi=0242865c
eip=761d22a1 esp=0030f1a0 ebp=0030f23c iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
KERNELBASE!DebugBreak+0x2:
761d22a1 cc              int     3

På dette tidspunkt har der netop været en garbage collection. Vi ved endnu ikke, om der også har været compaction. For at undersøge dette kan vi se, om vores arrays er blevet flyttet.

0:000> !dumpheap -type Object[] -min 400
 Address       MT     Size
0242566c 64cf6c28     8208
0242a3d0 64cf6c28      416
0243fb64 64cf6c28      816
03421010 64cf6c28     4096
03422020 64cf6c28      528
03422240 64cf6c28     4096
03423250 64cf6c28     8176
03425250 64cf6c28   340016
total 0 objects
Statistics:
      MT    Count    TotalSize Class Name
64cf6c28        8       366352 System.Object[]
Total 8 objects

Læg mærke til, at vores lille array er flyttet fra 026dfc7c til 0242a3d0, mens vores store array stadig befinder sig på 03425250. Der har altså været compaction i forbindelse med denne garbage collection.

Det interessante er således at finde ud af, om referencerne i vores store (og ubrugte) array er blevet justeret. Lad os se på det lille array:

0:000> !da -details -length 1 0242a3d0
Name:        LOHRoots.SomeType[]
MethodTable: 64cf6c28
EEClass:     64a79698
Size:        416(0x1a0) bytes
Array:       Rank 1, Number of elements 100, Type CLASS
Element Methodtable: 001638cc
[0] 0242a570
    Name:        LOHRoots.SomeType
    MethodTable: 001638cc
    EEClass:     001614e4
    Size:        16(0x10) bytes
    File:        C:\dev2010\LOHRoots\LOHRoots\bin\Release\LOHRoots.exe
    Fields:
              MT    Field   Offset                 Type VT     Attr    Value Name
        64d42978  4000001        4             System.Int32      1     instance            1     <X>k__BackingField
        64d42978  4000002        8             System.Int32      1     instance            2     <Y>k__BackingField

Og derefter det store:

0:000> !da -details -length 1 03425250
Name:        LOHRoots.SomeType[]
MethodTable: 64cf6c28
EEClass:     64a79698
Size:        340016(0x53030) bytes
Array:       Rank 1, Number of elements 85000, Type CLASS
Element Methodtable: 001638cc
[0] 0242a570
    Name:        LOHRoots.SomeType
    MethodTable: 001638cc
    EEClass:     001614e4
    Size:        16(0x10) bytes
    File:        C:\dev2010\LOHRoots\LOHRoots\bin\Release\LOHRoots.exe
    Fields:
              MT    Field   Offset                 Type VT     Attr    Value Name
        64d42978  4000001        4             System.Int32      1     instance            1     <X>k__BackingField
        64d42978  4000002        8             System.Int32      1     instance            2     <Y>k__BackingField

Læg mærke til at begge arrays peger på samme element. Referencen i det store array er således rettet fra 026dfe1c til 0242a570, og dermed kan vi konkludere, at det store array er blevet opdateret på trods af, at applikationen ikke længere har nogen gældende reference til dette array.

Hvordan kan det være?

Tænker vi lidt over, hvad der sker under en garbage collection, giver det faktisk god mening, men det er måske ikke så intuitivt ved første øjekast.

En garbage collection lægger ud med at lave en analyse af hvilke objekter på den aktuelle del af heapen, der stadig er i brug. Disse markeres som værende i brug. Alle andre objekter kan ryddes op. Nøgleordet her er den aktuelle del af heapen. I og med at testprogrammet kører en GC.Collect(1) foretages denne analyse således kun for objekter der ligger i generation 0 og 1. Vores store array ligger på LOH, og er således ikke berørt af denne analyse.

Da oprydningen også iværksætter en flytning af objekterne i dette tilfælde, er garbage collection-rutinen nødt til at opdatere referencerne til de flyttede objekter, men da den på dette tidspunkt ikke ved, at vores store array ikke længere er i brug, er den nødt til at opdatere disse referencer.

Disponeringen giver god mening, hvis analysen af aktive rødder er mere omfattende end justering af referencerne. Skønt det optimale ville være at springe opdateringen over, kan det sagtens give mening at udføre denne – i teorien – overflødige handling, hvis disse forhold er til stede. Den analyse har jeg svært ved at lave, men jeg har været i kontakt med en af de ansvarlige udviklere, og Microsoft kender til problematikken, og derfor har jeg tillid til, at de har lavet de nødvendige analyser og undersøgelser.

Ændrer vi testapplikationen så den kalder GC.Collect(2) i stedet (eller blot GC.Collect(), der ligeledes laver en komplet oprydning), laver garbage collection-rutinen en fuld analyse af heapen og finder således ud af, at det store array ikke længere er i brug. I det tilfælde opdateres referencerne naturligvis ikke, da den nødvendige viden er tilgængelig i dette tilfælde.

Som nævnt tror jeg ikke, at dette er et reelt problem i nogen væsentlig udstrækning. For at denne situation skal have indflydelse på afviklingen, skal applikationen have mange midlertidige objekter på LOH, disse skal i stor udstrækning referere objekter på den almindelige heap, og compaction skal foretages jævnligt. I det tilfælde vil man muligvis kunne spore en effekt, men det er i realiteten et afledt problem af at have mange midlertidige objekter på LOH. Det er af flere grunde en dårlig ide, og dette er således kun en af flere uheldige konsekvenser af den situation.

Slides fra MOW2010

Monday, April 19th, 2010

Jeg har lagt min præsentation for Miracle Open World til download her på siden.

Der er desværre ikke indsamlet evalueringer for præsentationen, men jeg har fået flere meget positive tilbagemeldinger, så jeg er glad. Yderligere kommentarer modtages gerne!

Miracle Open World 2010 – Advanced .NET Debugging

Tuesday, April 13th, 2010

Miracle Open WorldJeg er ved at lægge sidste hånd på min WinDbg-præsentation til Miracle Open World 2010, og det er næppe et øjeblik for tidligt. Jeg har godt nok holdt lignende præsentationer flere gange før, men der er sket rigtig meget siden min seneste optræden.

PSSCOR2 er netop blevet frigivet. Langt hen ad vejen kan vi betragte den som en overbygning til SOS, men den er endnu ikke kompatibel med CLR4 og så mangler den desværre også DML. Til gengæld tilføjer den et væld af kommandoer, der især retter sig mod debugging af ASP.NET. Derudover rummer den mange gode forberinger til eksisterende SOS-kommandoer.

Version 4 af SOSEX blev frigivet i går. Den er ligeledes blevet opdateret med nye kommandoer og fungerer både på CLR 2 og 4.

Sidst men ikke mindst, tager jeg denne gang fat på problematikken omkring debugging af 32 versus 64 bit processer samt 32 bit processer afviklet under Wow64.

Det giver en del opdateringer, så i stedet for at rette hist og her, har jeg lavet en helt ny præsentation.

WinDbg Q&A: Returværdier i WinDbg (anden del)

Friday, March 12th, 2010

I forrige indlæg viste jeg, hvordan vi får returværdien fra en metode ved hjælp af WinDbg. Denne gang skal vi se på en lidt mere kompliceret situation. Hvordan finder vi returværdien fra en anonym metode?

Givet nedenstående kode:

Func<int, int> f = x => x + 1;
Console.WriteLine(f.Invoke(1));

Hvordan finder vi returværdien for den metode, f repræsenterer?

Faktisk er problemstillingen ikke så kompliceret, så man måske skulle tro. Anonyme metoder er nemlig ikke spor anonyme, når det kommer til stykket. De er blot pakket ind i lidt compilerhekseri, så den første opgave er, at finde ud af hvilket navn den anonyme metode gemmer sig under.

Det kan vi læse ud af IL-koden, så lad os se nærmere på den for den omsluttende metode. I det her tilfælde er det Main(), så lad os se på den. For at se på IL-koden via WinDbg, har vi brug for Main()s MethodDesc. Den kan vi finde med !name2ee:

0:000> !name2ee * TestBench.Program.Main
Module: 6db11000 (mscorlib.dll)
--------------------------------------
Module: 00162c5c (TestBench.exe)
Token: 0x06000001
MethodDesc: 00163010
Name: TestBench.Program.Main()
JITTED Code Address: 00270070

MethodDesc for Main() er altså 00163010. Lad os se på IL for metoden.

0:000> !dumpil 00163010
ilAddr = 013c2064
IL_0000: nop
IL_0001: ldstr "press enter"
IL_0006: call System.Console::WriteLine
IL_000b: nop
IL_000c: call System.Console::ReadLine
IL_0011: pop
IL_0012: ldsfld TestBench.Program::CS$<>9__CachedAnonymousMethodDelegate1
IL_0017: brtrue.s IL_002c
IL_0019: ldnull
IL_001a: ldftn TestBench.Program::<Main>b__0
IL_0020: newobj class [System.Core]System.Func`2<int32,int32>::.ctor
IL_0025: stsfld TestBench.Program::CS$<>9__CachedAnonymousMethodDelegate1
IL_002a: br.s IL_002c
IL_002c: ldsfld TestBench.Program::CS$<>9__CachedAnonymousMethodDelegate1
IL_0031: stloc.0
IL_0032: ldloc.0
IL_0033: ldc.i4.1
IL_0034: callvirt class [System.Core]System.Func`2<int32,int32>::Invoke
IL_0039: call System.Console::WriteLine
IL_003e: nop
IL_003f: ret

Læg mærke til de spøjse navne. Det er navnene på henholdsvis den generede delegate type og den faktiske metode, der implementerer vores anonyme metode. Vores metode hedder altså TestBench.Program::

b__0. Lad os se nærmere på den:

0:000> !name2ee * TestBench.Program.<Main>b__0
Module: 6db11000 (mscorlib.dll)
--------------------------------------
Module: 00152c5c (TestBench.exe)
Token: 0x06000003
MethodDesc: 00153024
Name: TestBench.Program.<Main>b__0(Int32)
Not JITTED yet. Use !bpmd -md 00153024 to break on run.

Som det fremgår, er den endnu ikke oversat, så vi er nødt til at gå via et breakpoint på MD som foreslået i udskriften.

 0:000> !bpmd -md 00153024
MethodDesc = 00153024
Adding pending breakpoints...

Så er det blot at køre videre, til vi rammer vores breakpoint.

0:000> g
(1ad0.ecc): CLR notification exception - code e0444143 (first chance)
JITTED TestBench!TestBench.Program.<Main>b__0(Int32)
Setting breakpoint: bp 00260118 [TestBench.Program.<Main>b__0(Int32)]
Breakpoint 0 hit
eax=00153024 ebx=0038efdc ecx=00000001 edx=00000001 esi=006255f0 edi=00000000
eip=00260118 esp=0038efa0 ebp=0038efb0 iopl=0         nv up ei pl nz na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000206
00260118 55              push    ebp

Metoden er JIT-oversat, og vi er stoppet i begyndelsen af den. Som i første eksempel skal vi altså blot køre til slutningen og inspicere det korrekte register.

0:000> g $ra
eax=00000002 ebx=0038efdc ecx=00000001 edx=00000000 esi=006255f0 edi=00000000
eip=002600f0 esp=0038efa4 ebp=0038efb0 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
002600f0 8945fc          mov     dword ptr [ebp-4],eax ss:002b:0038efac=0038f1d8

0:000> ? $retreg
Evaluate expression: 2 = 00000002

Og der har vi vores returværdi. Havde metoden returneret long i stedet for int, skulle vi blot bruge $retreg64 i stedet.

WinDbg Q&A: Returværdier i WinDbg (første del)

Friday, March 12th, 2010

Et tilbagevendende spørgsmål fra min sidemand er ”hvordan ser man returværdien fra en funktion under debugging?” og kort tid efter kommer kommentaren, ”det kunne man da i C++”. Derefter følger lidt mumlen og banden.

Desværre er der ingen let måde at gøre det på, når det kommer til managed code. I hvert fald ikke fra Visual Studio. I WinDbg er det derimod ikke så svært, så lad os se på hvad, der skal til.

Returværdier afleveres i et register. Desværre er dette platformafhængig, men til alt held har WinDbg et såkaldt pseudoregister, der indkapsler denne forskellighed (faktisk er der to, et til 32 bit værdier og et til 64 bit værdier). For at se returværdien skal vi altså blot inspicere dette register på det rette tidspunkt.

Det relevante register sættes lige inden funktionen returnerer, og derfor er vi nødt til at stoppe afviklingen på dette tidspunkt. Heldigvis er der endnu et pseudoregister, der kan hjælpe os i den situation. Lad os se på et eksempel.

Betragt nedenstående klasse. Vi har en instansmetode, SomeMethod(), der returnerer en string eller mere specifikt en reference til en instans af string.

public sealed class SomeType {
   public string SomeMethod() {
      var date = DateTime.Now.ToShortDateString();
      var buffer = new StringBuilder();
      var line = new string('-', date.Length);
      buffer.AppendLine(line);
      buffer.AppendLine(date);
      buffer.AppendLine(line);
      return buffer.ToString();
   }
}

Vi desuden har følgende kode:

var st = new SomeType();
Console.WriteLine(st.SomeMethod());

og vi er interesseret i, at finde ud af hvad SomeMethod() returnerer. Lad os sætte WinDbg på sagen, og lad os desuden sige, at vi endnu ikke har kørt SomeMethod() andetsteds i koden, så den er endnu ikke blevet JIT-oversat.

Det første, vi skal gøre, er at finde method tabel (MT) for SomeType. Det kan vi gøre !name2ee eller via !dumpheap -type. Sidstnævnte kræver lidt mindre tastearbejde, så den snupper jeg.

0:003> !dumpheap -type SomeType
 Address       MT     Size
02652a78 002a3080       12
total 1 objects
Statistics:
      MT    Count    TotalSize Class Name
002a3080        1           12 TestBench.SomeType
Total 1 objects

Som forventet finder vi en instans. Af ovenstående kan vi se, at den relevante MT er 002a3080. Via den kan vi se metoder på vores type.

0:003> !dumpmt -md 002a3080
EEClass: 002a138c
Module: 002a2c5c
Name: TestBench.SomeType
mdToken: 02000004  (C:\dev\TestBench\TestBench\bin\x86\Debug\TestBench.exe)
BaseSize: 0xc
ComponentSize: 0x0
Number of IFaces in IFaceMap: 0
Slots in VTable: 6
--------------------------------------
MethodDesc Table
   Entry MethodDesc      JIT Name
6dcd6a90   6db51248   PreJIT System.Object.ToString()
6dcd6ab0   6db51250   PreJIT System.Object.Equals(System.Object)
6dcd6b20   6db51280   PreJIT System.Object.GetHashCode()
6dd474c0   6db512a4   PreJIT System.Object.Finalize()
003e00d8   002a3078      JIT TestBench.SomeType..ctor()
002ac03d   002a306c     NONE TestBench.SomeType.SomeMethod()

Der har vi SomeMethod(). Bemærk, at JIT-kolonnen siger NONE, hvilket vil sige, at metoden ikke er blevet JIT-oversat. Det kan skyldes, at den enten ikke har været kaldt endnu eller at den er blevet inlined. I vores tilfælde er det fordi den endnu ikke er blevet kaldt, og derfor er den ikke blevet oversat.

Læg mærke til Entry og MethodDesc-kolonnerne. Hvis metoden er oversat, står adressen på den oversatte version i Entry-kolonnen. Er den ikke oversat, skal vi i stedet sætte et breakpoint via MethodDesc. Da vores metode ikke er oversat, er det fremgangsmåden i dette tilfælde. Det gøres som følger:

0:003> !bpmd -md 002a306c
MethodDesc = 002a306c
Adding pending breakpoints...

Herefter kører vi videre, indtil vi rammer vores breakpoint.

0:003> g
(1638.fc4): CLR notification exception - code e0444143 (first chance)
JITTED TestBench!TestBench.SomeType.SomeMethod()
Setting breakpoint: bp 003E0110 [TestBench.SomeType.SomeMethod()]
Breakpoint 0 hit
eax=002a306c ebx=001af3ac ecx=02652a78 edx=00000000 esi=005855f0 edi=00000000
eip=003e0110 esp=001af370 ebp=001af380 iopl=0         nv up ei pl nz na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000206
003e0110 55              push    ebp

Applikationen er nu stoppet ved indgangen til SomeMethod(), og hvis vi kører !dumpmt igen som ovenfor, kan vi se, at metoden ganske rigtig er blevet JIT-oversat.

Hvis vi blot er interesseret i returværdien, er det eneste, vi behøver at gøre, at fortsætte afviklingen til vi rammer returadressen. Herefter vil vores returværdi være i det relevante register.

Vi kan fortsætte afviklingen og stoppe ved returadressen via g-kommandoen og pseudoregisteret $ra, som indeholder returadressen. Altså:

0:000> g $ra
C:\Windows\assembly\NativeImages_v2.0.50727_32\mscorlib\8c1770d45c63cf5c462eeb945ef9aa5d\mscorlib.ni.dll
eax=02655d04 ebx=001af3ac ecx=00000001 edx=00000000 esi=005855f0 edi=00000000
eip=003e00b7 esp=001af374 ebp=001af380 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
003e00b7 8945f4          mov     dword ptr [ebp-0Ch],eax ss:002b:001af374=001af390

Så er vi ved udgangen af metoden, og skal altså blot udskrive returværdien. Vi ved, at det er en string, så returværdien er en reference til et objekt. Lad os skrive det ud:

0:000> !do $retreg
Name: System.String
MethodTable: 6dd788c0
EEClass: 6db3a498
Size: 146(0x92) bytes
 (C:\Windows\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: ----------
12-03-2010
----------

Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
6dd7ab0c  4000096        4         System.Int32  1 instance       65 m_arrayLength
6dd7ab0c  4000097        8         System.Int32  1 instance       36 m_stringLength
6dd795a0  4000098        c          System.Char  1 instance       2d m_firstChar
6dd788c0  4000099       10        System.String  0   shared   static Empty
    >> Domain:Value  00582618:02651198 <<
6dd794f0  400009a       14        System.Char[]  0   shared   static WhitespaceChars
    >> Domain:Value  00582618:02651768 <<

Voila! Et styk string fra vores metode.