转载:
https://blog.csdn.net/riverlau/article/details/8742325
https://blog.csdn.net/AloneSword/article/details/3696839
最近在看相关内容,作者写的相当不错,自己随手学习了一下,非常棒,顺便也锻炼一下自己的翻译能力(好久没有处理相关内容了,能力直线下降啊)
原文地址:
http://blogs.msdn.com/johan/archive/2007/11/13/getting-started-with-windbg-part-i.aspx
Getting started with windbg - part I
Ok,在此之前随便写了一些帖子,关于“如何设置 windbg”和“如何查找OutOfMemoryException”。我的重新复习一些基础内容,为了更好的使用这些特殊的工具。
windbg基础配置:
1、 将sos.dll 从 framework 安装目录拷贝到 windbg 的安装目录。请确保 sos.dll 文件的版本和即将要分析的版本一致。如果正同时使用 1.1 和 2.0 版本,可以重新命名文件为 sos.dll 为 sos11.dll 和 sos20.dll ,或则将 sos.dll 单独放置到不同的目录;
2、 创建缓存符号文件夹。比如: c:/symbols
3、 启动 windbg,打开配置对话框(File -> Open Symbol Path,快捷键 Ctrl + S)
4、 输入符号文件夹位置。使用如下语法缓存缺失的符号文件(符号文件夹位置: c:/symbols public)
srv*[cache path]*[symbols path]
推荐输入如下内容:
Srv*c:/symbols public*http://msdl.microsoft.com/download/symbols
经过上述步骤后,即可打开已经存储的 dump 文件或附加进程,进行调试分析。
常用命令
以下实例基于 IIS6 的dump文件【标记1】 。
首先做的就是加载 sos 扩展功能dll。使用的是 load 命令,命令比较简单,语法如下:
.load [extension filename]
所以想加载未修改名称的sos.dll 文件,只需要简单的输入:
.load sos.dll
等加载成功后,即可使用sos 扩展的非常酷的命令,就像windbg 的默认命令一样。扩展命令通常都是以 “!” 开头。如果想运行 help 命令,只需要输入:
!help
即可显示当前扩展的帮助命令。
如果使用多个标识扩展命令,可使用 ![extension name].[command] 进行区分,例如:
!sos.help 【标记2】
Ok,到这里我们知道了如何运行扩展命令,尝试输入 !help 回车,可以看到如下结果:
0:000> !help *New* Use !CLRUsage to see how much memory .NET is actually using, including reserved memory. To see more tips, run !tip. ------------------------------------------------------------------------------- SOS is a debugger extension DLL designed to aid in the debugging of managed programs. Functions are listed by category, then roughly in order of importance. Shortcut names for popular functions are listed in parenthesis. Type "!help <functionname>" for detailed info on that function. Object Inspection Examining code and stacks ----------------------------- ----------------------------- DumpObj (do) Threads (t) DumpAllExceptions (dae) CLRStack DumpStackObjects (dso) IP2MD DumpHeap (dh) U DumpVC DumpStack GCRoot EEStack ObjSize GCInfo FinalizeQueue COMState DumpDynamicAssemblies (dda) X DumpField (df) SearchStack TraverseHeap (th) GCRef Examining CLR data structures Diagnostic Utilities ----------------------------- ----------------------------- DumpDomain VerifyHeap (vh) EEHeap DumpLog Name2EE FindAppDomain SyncBlk SaveModule DumpASPNETCache (dac) SaveAllModules (sam) DumpMT GCHandles DumpClass GCHandleLeaks DumpMD FindDebugTrue Token2EE FindDebugModules EEVersion Bp DumpSig ProcInfo DumpModule StopOnException (soe) ThreadPool (tp) TD ConvertTicksToDate (ctd) Analysis ConvertVTDateToDate (cvtdd) Bl RWLock CheckCurrentException (cce) DumpConfig CurrentExceptionName (cen) DumpHttpRuntime ExceptionBp DumpSessionStateConfig FindTable DumpBuckets LoadCache DumpHistoryTable SaveCache DumpRequestTable ASPXPages DumpCollection (dc) DumpGCNotInProgress DumpDataTables CLRUsage GetWorkItems DumpLargeObjectSegments (dl) DumpModule DumpAssembly Other DumpMethodSig ----------------------------- DumpRuntimeTypes FAQ PrintIPAddress DumpHttpContext DumpXmlDocument (dxd) |
如果想查找某个命令更多详细的内容,输入 !help [command name] 即可,例如:
0:000> !help eeversion *New* Use !DumpDataTables to see interesting information about System.Data.DataTables. To see more tips, run !tip. ------------------------------------------------------------------------------- !EEVersion This prints the Common Language Runtime Version. It also tells you if the code is running in "Workstation" or "Server" mode, a distinction which affects the garbage collector. The most apparent difference in the debugger is that in "Server" mode there is one dedicated garbage collector thread per CPU. A handy supplement to this function is to also run "lm v m mscorwks". That will provide more details about the CLR, including where mscorwks.dll is loaded from. |
.time
这个不是 sos 命令。很明显该命令不是以 ! 开头。.time 命令显示与时间有关的信息,比如系统运行时间、处理器运行时间、内核总运行时间和用户模式处理时间。
0:000> .time Debug session time: Fri Jan 2 14:57:48.000 2009 (GMT+8) System Uptime: 2 days 6:25:27.664 Process Uptime: 1 days 15:51:25.000 Kernel time: 0 days 1:04:32.000 User time: 0 days 16:55:49.000 |
如你所见,系统已运行2天,处理器运行 1天16小时左右,CPU累计运行18小时(kernel time + user time),根据这些信息,可以推测出CPU平均使用率为44%左右。
!threadpool
可以使用 !threadpool 命令精确的查找出,dump文件时cpu的使用情况。同时可以得到其他的有用的信息,例如:等待请求队列的数量,已完成的线程和时间【标注3】
0:000> !threadpool |
根据上述信息,可以看出cpu正100%的使用,下一个要运行的命令。
!runaway
这是一个非常棒的命令,可以列出当前正在运行的线程和cpu使用情况。如果正在检查cpu 高使用率的相关内容时,它更是你不可分离的好帮手。
0:000> !runaway |
如你所见,时间总和和前面通过.time 命令获得的cpu时间不一致。是因为线程可以被反复使用和回收,即:一个线程使用cpu总量可以分开为多个页请求。【标注4】
!threads
为了获取更多的关于线程的信息,可以使用 !threads 命令。该命令将列表显示出应用程序所有正在运行的线程,当前应用程序域中后台正在运行的程序,等等线程相关内容。输出如下:
0:000> !threads ThreadCount: 8 UnstartedThread: 0 BackgroundThread: 2 PendingThread: 0 DeadThread: 5 PreEmptive GC Alloc Lock ID ThreadOBJ State GC Context Domain Count APT Exception 0 0xfc4 0x00143348 0x20 Enabled 0x00000000:0x00000000 0x0015c3b8 0 Ukn 2 0xff8 0x001619c0 0xb220 Enabled 0x00000000:0x00000000 0x0015c3b8 0 MTA (Finalizer) XXX 0 0x001887b0 0x1820 Enabled 0x00000000:0x00000000 0x0015c3b8 0 Ukn XXX 0 0x00188b28 0x1820 Enabled 0x00000000:0x00000000 0x0015c3b8 0 Ukn XXX 0 0x001ac540 0x1820 Enabled 0x00000000:0x00000000 0x0015c3b8 0 MTA 10 0x13b4 0x00186df8 0x1800220 Enabled 0x00000000:0x00000000 0x0015c3b8 0 MTA (Threadpool Worker) XXX 0 0x00187c48 0x1800820 Enabled 0x00000000:0x00000000 0x0015c3b8 0 Ukn (Threadpool Worker) XXX 0 0x0785b490 0x1800820 Enabled 0x00000000:0x00000000 0x0015c3b8 0 Ukn (Threadpool Worker) |
如果线程ID列值为 XXXX ,则表示该线程已经终止,正等待被回收。终止线程Finalizer thread 的ID为2。如果在2号线程上有不正常的活动,运行 !threads 命令就可以知道终止线程相关的事件。
线程间的切换
为了切换到特定的线程上查看相关内容,可以使用 ~[thread id]s 命令。譬如,想切换到finalizer thread ,可以使用如下命令:
0:002> ~2s
现在我们就切换到了2号线程中了,在此基础上就可以继续使用其他的有用命令。
!clrstack
这个超强的命令可以列出当前线程中的调用栈信息。如果想查看额外的信息,添加 “-p”选项,该选项将同时显示相关参数和本地变量。
如下是在线程 10 上运行 clrstack 的清单表:
0:010> !clrstack Thread 10 ESP EIP 0x0d0ff5f8 0x7c90e4f4 [FRAME: NDirectMethodFrameStandalone] [DEFAULT] I4 System.Data.OracleClient.UnsafeNativeMethods.OCIStmtFetch(ValueClass System.Runtime.InteropServices.HandleRef,ValueClass System.Runtime.InteropServices.HandleRef,I4,ValueClass FETCH,ValueClass MODE) 0x0d0ff608 0x05081deb [DEFAULT] I4 System.Data.OracleClient.TracedNativeMethods.OCIStmtFetch(Class System.Data.OracleClient.OciHandle,Class System.Data.OracleClient.OciHandle,I4,ValueClass FETCH,ValueClass MODE) 0x0d0ff644 0x050817c9 [DEFAULT] [hasThis] Boolean System.Data.OracleClient.OracleDataReader.ReadInternal() 0x0d0ff664 0x05081673 [DEFAULT] [hasThis] Boolean System.Data.OracleClient.OracleDataReader.Read() 0x0d0ff66c 0x05081618 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillLoadDataRow(Class System.Data.Common.SchemaMapping) 0x0d0ff6a4 0x00c1ecb0 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillFromReader(Object,String,Class System.Data.IDataReader,I4,I4,Class System.Data.DataColumn,Object) 0x0d0ff6f8 0x00c1eb2a [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet,String,Class System.Data.IDataReader,I4,I4) 0x0d0ff71c 0x00c1b51a [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillFromCommand(Object,I4,I4,String,Class System.Data.IDbCommand,ValueClass System.Data.CommandBehavior) 0x0d0ff76c 0x00c1b3ce [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet,I4,I4,String,Class System.Data.IDbCommand,ValueClass System.Data.CommandBehavior) 0x0d0ff794 0x00c1b1ff [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet) 0x0d0ff7a0 0x00c1a54c [DEFAULT] [hasThis] Class System.Data.DataSet Dba.Wrapper.OracleWrapper.QueryDataSet(String,SZArray Class Dba.Parameter) at [+0x7c] [+0x29] 0x0d0ff7b4 0x00c170b0 [DEFAULT] Class System.Data.DataTable Sample.Access.Base.DataAccess.DbUtil.QueryDataTable(Class Dba.IDBWrapper,String) at [+0xc0] [+0x2b] 0x0d0ff804 0x0093660e [DEFAULT] Class System.Data.DataTable Sample.Access.Dao.ConConfigQuery.GetAllCalItemsInfo(Class Dba.IDBWrapper,I8,String,Boolean,Boolean) at [+0x176] [+0x8d] 0x0d0ff858 0x00935814 [DEFAULT] [hasThis] Void Sample.Business.Contract.Template.EvaluatorParameter.LoadEvaluatorParameter(String,Boolean,Boolean) at [+0x74] [+0x29] 0x0d0ff8a4 0x009351c5 [DEFAULT] [hasThis] Void Sample.Business.Contract.Template.TemplateEvaluator.StartAllCalTread() at [+0x15d] [+0xa5] 0x0d0ff8f0 0x05086a13 [DEFAULT] [hasThis] Boolean Sample.Business.Contract.MaterialConf.GenerateMaterialMng.RefreshMaterial(Class Dba.IDBWrapper,String,Boolean,String,String,Boolean) at [+0xe3] [+0x46] 0x0d0ff944 0x00c11a48 [DEFAULT] [hasThis] Void Sample.UI.Win.Service.MaterialManager.RefreshMaterial() at [+0x2c0] [+0x132] 0x0d0ff9d0 0x00c1175d [DEFAULT] [hasThis] Void Sample.UI.Win.Service.MaterialManager.tm_Elapsed(Object,Class System.Timers.ElapsedEventArgs) at [+0x1d] [+0xd] 0x0d0ff9e8 0x7b29984d [DEFAULT] [hasThis] Void System.Timers.Timer.MyTimerCallback(Object) |
如果运行 !clrstack –p将得到如下结果:
0:010> !clrstack -p Thread 10 ESP EIP 0x0d0ff5f8 0x7c90e4f4 [FRAME: NDirectMethodFrameStandalone] [DEFAULT] I4 System.Data.OracleClient.UnsafeNativeMethods.OCIStmtFetch(ValueClass System.Runtime.InteropServices.HandleRef,ValueClass System.Runtime.InteropServices.HandleRef,I4,ValueClass FETCH,ValueClass MODE) 0x0d0ff608 0x05081deb [DEFAULT] I4 System.Data.OracleClient.TracedNativeMethods.OCIStmtFetch(Class System.Data.OracleClient.OciHandle,Class System.Data.OracleClient.OciHandle,I4,ValueClass FETCH,ValueClass MODE) 0x0d0ff644 0x050817c9 [DEFAULT] [hasThis] Boolean System.Data.OracleClient.OracleDataReader.ReadInternal() 0x0d0ff664 0x05081673 [DEFAULT] [hasThis] Boolean System.Data.OracleClient.OracleDataReader.Read() 0x0d0ff66c 0x05081618 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillLoadDataRow(Class System.Data.Common.SchemaMapping) 0x0d0ff6a4 0x00c1ecb0 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillFromReader(Object,String,Class System.Data.IDataReader,I4,I4,Class System.Data.DataColumn,Object) 0x0d0ff6f8 0x00c1eb2a [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet,String,Class System.Data.IDataReader,I4,I4) 0x0d0ff71c 0x00c1b51a [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillFromCommand(Object,I4,I4,String,Class System.Data.IDbCommand,ValueClass System.Data.CommandBehavior) 0x0d0ff76c 0x00c1b3ce [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet,I4,I4,String,Class System.Data.IDbCommand,ValueClass System.Data.CommandBehavior) 0x0d0ff794 0x00c1b1ff [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet) 0x0d0ff7a0 0x00c1a54c [DEFAULT] [hasThis] Class System.Data.DataSet Dba.Wrapper.OracleWrapper.QueryDataSet(String,SZArray Class Dba.Parameter) at [+0x7c] [+0x29] 0x0d0ff7b4 0x00c170b0 [DEFAULT] Class System.Data.DataTable Sample.Access.Base.DataAccess.DbUtil.QueryDataTable(Class Dba.IDBWrapper,String) at [+0xc0] [+0x2b] PARAM: class Dba.IDBWrapper wrapper: 0x3b9599e8 PARAM: class System.String sql: 0x1d004690 (System.String) 0x0d0ff804 0x0093660e [DEFAULT] Class System.Data.DataTable Sample.Access.Dao.ConConfigQuery.GetAllCalItemsInfo(Class Dba.IDBWrapper,I8,String,Boolean,Boolean) at [+0x176] [+0x8d] PARAM: class Dba.IDBWrapper dbWrapper: 0x3b9599e8 PARAM: int64 contract_header_id: 3052226 PARAM: class System.String RegionCode: 0x00f67850 (System.String) PARAM: bool isDiff: false PARAM: bool genMaterial: true 0x0d0ff858 0x00935814 [DEFAULT] [hasThis] Void Sample.Business.Contract.Template.EvaluatorParameter.LoadEvaluatorParameter(String,Boolean,Boolean) at [+0x74] [+0x29] PARAM: this: 0x1cfff894 (Sample.Business.Contract.Template.EvaluatorParameter) PARAM: class System.String contractID: 0x3b95be28 (System.String) PARAM: bool isDiff: false PARAM: bool genMaterial: true 0x0d0ff8a4 0x009351c5 [DEFAULT] [hasThis] Void Sample.Business.Contract.Template.TemplateEvaluator.StartAllCalTread() at [+0x15d] [+0xa5] PARAM: this: 0x1cfff848 (Sample.Business.Contract.Template.TemplateEvaluator) 0x0d0ff8f0 0x05086a13 [DEFAULT] [hasThis] Boolean Sample.Business.Contract.MaterialConf.GenerateMaterialMng.RefreshMaterial(Class Dba.IDBWrapper,String,Boolean,String,String,Boolean) at [+0xe3] [+0x46] PARAM: this: 0x3b959a8c (Sample.Business.Contract.MaterialConf.GenerateMaterialMng) PARAM: class Dba.IDBWrapper dbWrappe: 0x3b9599e8 PARAM: class System.String contractID: 0x3b95be28 (System.String) PARAM: bool isDiff: false PARAM: class System.String contractNumber: 0x3b95a7cc (System.String) PARAM: class System.String email: 0x00f311f4 (System.String) PARAM: bool isOld: false 0x0d0ff944 0x00c11a48 [DEFAULT] [hasThis] Void Sample.UI.Win.Service.MaterialManager.RefreshMaterial() at [+0x2c0] [+0x132] PARAM: this: 0x00f569f8 (Sample.UI.Win.Service.MaterialManager) 0x0d0ff9d0 0x00c1175d [DEFAULT] [hasThis] Void Sample.UI.Win.Service.MaterialManager.tm_Elapsed(Object,Class System.Timers.ElapsedEventArgs) at [+0x1d] [+0xd] PARAM: this: 0x00f569f8 (Sample.UI.Win.Service.MaterialManager) PARAM: class System.Object sender: 0x00f56b8c (System.Timers.Timer) PARAM: 0x0d0ff9e8 0x7b29984d [DEFAULT] [hasThis] Void System.Timers.Timer.MyTimerCallback(Object) |
使用该命令我们可以查看相关参数。如上所述,将Sample.UI.Win.Service.MaterialManager作为Sample.UI.Win.Service.MaterialManager.tm_Elapsed的参数Object 进行传递,如果想得到更多的内容,就需要继续往下使用下个命令.
!dumpobject【标注5】 (!do 为简写)
这是另一个至关重要的命令。Dumpobj 显示指定地址对象的内容,只需要指定需要观察对象的地址即可,如下:
0:000> !dumpobj 0xf32fcc Name: System.Collections.Hashtable/bucket[] MethodTable 0x00822c28 EEClass 0x00822ba4 Size 144(0x90) bytes GC Generation: 2 Array: Rank 1, Type VALUETYPE Element Type: System.Collections.Hashtable/bucket Content: 11 items |
Ok,看到了什么?是的,0xf32fcc 是一个 System.Collections.Hashtable/bucket[] 对象,该对象有11个对象或属性,如果想继续查看对象的值,只需要继续使用 !dumpobj 或查询 MSDN 关于 Hashtable 类的说明即可,一下是该对象的更详细的内容:
0:000> !dumpobj -v 0xf32fcc Name: System.Collections.Hashtable/bucket[] MethodTable 0x00822c28 EEClass 0x00822ba4 Size 144(0x90) bytes GC Generation: 2 Array: Rank 1, Type VALUETYPE Element Type: System.Collections.Hashtable/bucket Content: 11 items 【标注6 ???】 Address MT Class Name key: 0x00f6709c 0x00f6709c 0x79b946b0 System.String val: 0x00f670b8 0x00f670b8 0x79baaff0 System.Int32 key: 0x00f54720 0x00f54720 0x79b946b0 System.String val: 0x00f5473c 0x00f5473c 0x79baaff0 System.Int32 |
根据上述内容,为了更加了解key中存储的是何内容,只需要继续使用 !dumpobj 即可。
0:000> !dumpobj 0x00f6709c String: zh-cn |
Ok,这样我们就找到了,上述hastable的一个key为 zh-CN ,value 为 23
0:000> !dumpobj 0x00f670b8 Name: System.Int32 MethodTable 0x79baaff0 EEClass 0x79bab17c Size 12(0xc) bytes GC Generation: 2 mdToken: 0x0200009a (c:/windows/microsoft.net/framework/v1.1.4322/mscorlib.dll) FieldDesc*: 0x79bab1f4 MT Field Offset Type Attr Value Name 0x79baaff0 0x40001e9 0x4 System.Int32 instance 23 m_value |
对于其他的托管堆中的对象,只要不停的使用 !dumpobj 即可找到最终的数据。
在接下来的文章中,我将继续使用 !dumpobj 命令来查找 w3wp 进程的内容,并介绍一下其他的非常棒的命令,敬请期待。
(未完待续)
原文:johan
翻译:AloneSword (部分内容在原有文章基础上做了修改)
【标记1】:由于没有拿到 iis6 下的 dmp 文件,翻译时是使用的xp sp3 中的一个应用程序的dmp 文件进行;
【标记2】: 在做这个命令时,一开始老是不正确。当输入 !sos.help 时,提示如下:
0:000> !sos.help The call to LoadLibrary(sos) failed, Win32 error 0n2 "The system cannot find the file specified." Please check your debugger configuration and/or network access. |
不知道为啥,最后再看 load 命令的帮助(命令行下输入: .hh load)时,才知道需要输入sos.dll 的绝对路径(或相对路径)才可以,而我将 sos.dll 放到了 windbg/clr10 目录下,所以需要输入 !clr10/sos.help ,终于见到了熟悉的面孔了。
【标注3】:由于是app 的dump 没有多线程的实例,所以当输入 !threadpool 时,显示如下:
0:000> !threadpool Loaded Son of Strike data table Version 5 from "C:/WINDOWS/Microsoft.NET/Framework/v1.1.4322/mscorwks.dll" CPU utilization 80% Worker Thread: Total: 1 Running: 1 Idle: 0 MaxLimit: 25 MinLimit: 1 Work Request in Queue: 0 -------------------------------------- Number of Timers: 0 -------------------------------------- Completion Port Thread: Total: 0 Free: 0 MaxFree: 2 CurrentLimit: 0 MaxLimit: 1000 MinLimit: 1 |
【标注4】:大脑在此处转不过来玩了,搞不明白了。被分配为多个了,咋时间还少了呢?
【标注5】:原文档中说是 !dumpobject 命令,但是使用 !help 找到的命令为 !dumpobj ,没有 !dumpobject ,相信是作者的笔误。
【标注6】:为啥这里显示的条目内容只有2条 Key-value ,但!dumpobj 时显示11,为啥呢?
原文:
Getting started with windbg - part I
http://blogs.msdn.com/b/johan/archive/2007/11/13/getting-started-with-windbg-part-i.aspx
Okay, I've previously written some random posts about how to set up windbg and how to troubleshoot OutOfMemoryExceptions. I thought I'd take a few steps back and review some of the basics in order to help you get started on using this fantastic tool.
Basic Configuration
- Copy sos.dll from the framework directory to the folder where you installed windbg. Make sure you copy it from the same Framework version as the one you wish to investigate. If you'll be working with both 1.1 and 2.0 you can rename the SOS.dlls to SOS11.dll and SOS20.dll or put them in separate folders.
- Create a folder where you want to cache all the symbol files. For example: "C:Symbols".
- Start windbg and open the dialogue to configure the symbol path by clicking File -> Symbol File Path.
- Enter the path, as well as the address from which you'll want to download missing symbols using the following syntax:
srv*[cache path]*[symbols path]
I'd recommend the following path:
srv*c:symbolspublic*http://msdl.microsoft.com/download/symbols
You should now be set to go. You're now ready to open up a saved dump, or attach to a process
Useful commands
I'll be using a dump from an IIS6-server to demonstrate some useful commands.
The first thing you'll want to do is load SOS. You'll do this using the .load command. The syntax is simple. .load [extension filename]. So if you want to load sos and haven't renamed the .dll you'd simply write:
You'll now have all the cool commands from the SOS-extension at your disposal as well as the default windbg ones. Commands from extensions are always preceded by a "!", so if you want to run the help-command for sos you'd write
If you should happen to have two extensions with an identically named command you can always separate them by typing ![extension name].[command] Example:
Okay, now that we know how to run the commands from the extension, try running !help. It should give you the following result.
-------------------------------------------------------------------------------
SOS is a debugger extension DLL designed to aid in the debugging of managed
programs. Functions are listed by category, then roughly in order of
importance. Shortcut names for popular functions are listed in parenthesis.
Type "!help " for detailed info on that function.
Object Inspection Examining code and stacks
----------------------------- -----------------------------
DumpObj (do) Threads
DumpArray (da) CLRStack
DumpStackObjects (dso) IP2MD
DumpHeap U
DumpVC DumpStack
GCRoot EEStack
ObjSize GCInfo
FinalizeQueue EHInfo
PrintException (pe) COMState
TraverseHeap BPMD
Examining CLR data structures Diagnostic Utilities
----------------------------- -----------------------------
DumpDomain VerifyHeap
EEHeap DumpLog
Name2EE FindAppDomain
SyncBlk SaveModule
DumpMT GCHandles
DumpClass GCHandleLeaks
DumpMD VMMap
Token2EE VMStat
EEVersion ProcInfo
DumpModule StopOnException (soe)
ThreadPool MinidumpMode
DumpAssembly
DumpMethodSig Other
DumpRuntimeTypes -----------------------------
DumpSig FAQ
RCWCleanupList
DumpIL
For more documentation on a specific command, type !help [name of command]
.time
This is not an SOS-command, which is evident by the command not beginning with a "!". Running the .Time command will show you relevant info about the time, as well as system uptime, process uptime and the amount of time spent in kernel & user mode.
Debug session time: Tue Oct 23 08:38:35.000 2007 (GMT+1)
System Uptime: 4 days 17:48:01.906
Process Uptime: 0 days 0:24:37.000
Kernel time: 0 days 0:04:23.000
User time: 0 days 0:03:28.000
As you can see the system has been up for over 4 days. The process has been running for 24½ minutes and has an accumulated CPU-time of about 8 minutes total. This would give us an average CPU-usage for the process of around 32,5%
!threadpool
We can then use the !Threadpool-command to find out exactly what the CPU-usage was at the time the dump was taken. We'll also get some useful information like the number of work requests in the queue, completion port threads and timers.
CPU utilization 100%
Worker Thread: Total: 5 Running: 4 Idle: 1 MaxLimit: 200 MinLimit: 2
Work Request in Queue: 16
Unknown Function: 6a2d945d Context: 023ede30
Unknown Function: 6a2d945d Context: 023ee1e8
AsyncTimerCallbackCompletion TimerInfo@11b53760
Unknown Function: 6a2d945d Context: 023ee3a8
Unknown Function: 6a2d945d Context: 023e3040
Unknown Function: 6a2d945d Context: 023ee178
Unknown Function: 6a2d945d Context: 023edfb0
AsyncTimerCallbackCompletion TimerInfo@11b36428
AsyncTimerCallbackCompletion TimerInfo@11b53868
Unknown Function: 6a2d945d Context: 023ee060
Unknown Function: 6a2d945d Context: 023ee290
Unknown Function: 6a2d945d Context: 023eded0
Unknown Function: 6a2d945d Context: 023edd88
Unknown Function: 6a2d945d Context: 023ede98
Unknown Function: 6a2d945d Context: 023ee258
Unknown Function: 6a2d945d Context: 023edfe8
--------------------------------------
Number of Timers: 9
--------------------------------------
Completion Port Thread:Total: 3 Free: 3 MaxFree: 4 CurrentLimit: 2 MaxLimit: 200 MinLimit: 2
So we can see that currently we're using 100% of the CPU, which leads us to the next command.
!runaway
This is a nice command that will list all running threads and their CPU-usage. It's your best friend when troubleshooting a high CPU hang issue.
User Mode Time
Thread Time
25:1a94 0 days 0:00:39.937
16:1bc0 0 days 0:00:38.390
50:1e8c 0 days 0:00:08.859
52:1e40 0 days 0:00:08.687
20:1c2c 0 days 0:00:08.234
51:1340 0 days 0:00:08.171
21:1bcc 0 days 0:00:06.953
26:13ec 0 days 0:00:06.671
44:131c 0 days 0:00:03.906
22:d8c 0 days 0:00:03.375
33:78c 0 days 0:00:02.656
34:1a8c 0 days 0:00:00.906
29:1f5c 0 days 0:00:00.828
6:e28 0 days 0:00:00.625
5:1c78 0 days 0:00:00.546
23:14a4 0 days 0:00:00.484
4:5ac 0 days 0:00:00.437
45:5dc 0 days 0:00:00.421
3:13b4 0 days 0:00:00.421
47:19c8 0 days 0:00:00.375
28:1b6c 0 days 0:00:00.250
46:1dac 0 days 0:00:00.156
7:1dd8 0 days 0:00:00.109
48:cdc 0 days 0:00:00.093
49:1eac 0 days 0:00:00.062
15:1a64 0 days 0:00:00.062
0:1804 0 days 0:00:00.046
36:4a4 0 days 0:00:00.031
11:1eb4 0 days 0:00:00.031
1:10b4 0 days 0:00:00.031
31:16ac 0 days 0:00:00.015
14:4ac 0 days 0:00:00.015
2:186c 0 days 0:00:00.015
59:590 0 days 0:00:00.000
58:294 0 days 0:00:00.000
57:16d0 0 days 0:00:00.000
56:1578 0 days 0:00:00.000
55:1428 0 days 0:00:00.000
54:16d8 0 days 0:00:00.000
53:fd8 0 days 0:00:00.000
43:1b8c 0 days 0:00:00.000
42:1c24 0 days 0:00:00.000
41:1e2c 0 days 0:00:00.000
40:11b0 0 days 0:00:00.000
39:edc 0 days 0:00:00.000
38:1a08 0 days 0:00:00.000
37:171c 0 days 0:00:00.000
35:1254 0 days 0:00:00.000
32:1f9c 0 days 0:00:00.000
30:1ae8 0 days 0:00:00.000
27:190c 0 days 0:00:00.000
24:1d2c 0 days 0:00:00.000
19:1e38 0 days 0:00:00.000
18:ee4 0 days 0:00:00.000
17:fb8 0 days 0:00:00.000
13:1b54 0 days 0:00:00.000
12:1a48 0 days 0:00:00.000
10:f64 0 days 0:00:00.000
9:1024 0 days 0:00:00.000
8:1b78 0 days 0:00:00.000
As you can see the total amount of time does not match the total CPU utilization time that we got from the .time command. That's simply because threads get reused and recycled. This means that the total amount of CPU time used by a thread may have been split up over several page requests.
!threads
To get more information about the running threads we can run the !Threads-command. This will list all managed threads in the application, what application domain the thread is currently executing under, etc. The output will look like this:
ThreadCount: 48
UnstartedThread: 0
BackgroundThread: 29
PendingThread: 0
DeadThread: 19
Hosted Runtime: no
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
16 1 1bc0 001fccd0 1808220 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
22 2 d8c 002016f0 b220 Enabled 00000000:00000000 0019daf0 0 MTA (Finalizer)
14 4 4ac 00242e58 880a220 Enabled 00000000:00000000 0019daf0 0 MTA (Threadpool Completion Port)
23 5 14a4 11b39f18 80a220 Enabled 00000000:00000000 0019daf0 0 MTA (Threadpool Completion Port)
24 6 1d2c 11b41ad8 1220 Enabled 00000000:00000000 0019daf0 0 Ukn
25 7 1a94 11b46c70 180b220 Enabled 27240c98:27241fd8 11b42540 1 MTA (Threadpool Worker)
26 9 13ec 12ce2888 200b220 Enabled 2a9f1434:2a9f33c0 11b42540 0 MTA
27 a 190c 12d85eb8 200b220 Enabled 00000000:00000000 11b42540 0 MTA
29 b 1f5c 13df6a50 200b220 Enabled 2ab1da6c:2ab1f1c0 11b42540 0 MTA
30 c 1ae8 12d44a58 b220 Enabled 00000000:00000000 11b42540 0 MTA
31 d 16ac 12e2e008 200b220 Enabled 2a81348c:2a8153c0 11b42540 1 MTA
5 e 1c78 12da2160 220 Enabled 00000000:00000000 0019daf0 0 Ukn
33 8 78c 11b674c8 200b220 Enabled 2707b818:2707c1d8 11b42540 0 MTA
34 12 1a8c 13f163c8 220 Enabled 00000000:00000000 0019daf0 0 Ukn
36 13 4a4 13eef718 200b220 Enabled 2a7db4a4:2a7dd3c0 11b42540 0 MTA
4 14 5ac 13ef2008 220 Enabled 00000000:00000000 0019daf0 0 Ukn
42 10 1c24 13f0e950 880b220 Enabled 00000000:00000000 0019daf0 0 MTA (Threadpool Completion Port)
6 11 e28 13f16008 220 Enabled 00000000:00000000 0019daf0 0 Ukn
3 f 13b4 13eba008 220 Enabled 00000000:00000000 0019daf0 0 Ukn
43 15 1b8c 140db008 880b220 Enabled 00000000:00000000 0019daf0 0 MTA (Threadpool Completion Port)
44 17 131c 140ceb28 200b220 Enabled 272288c8:27229fd8 11b42540 0 MTA
45 1d 5dc 140cd0a0 220 Enabled 00000000:00000000 0019daf0 0 Ukn
47 20 19c8 1651a008 220 Enabled 00000000:00000000 0019daf0 0 Ukn
XXXX 24 0 16468880 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
46 1f 1dac 1650ab48 220 Enabled 00000000:00000000 0019daf0 0 Ukn
XXXX 1a 0 140d5008 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 16 0 140c5008 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
50 3 1e8c 14064420 180b220 Enabled 27246f54:27247fd8 11b42540 1 MTA (Threadpool Worker)
XXXX 35 0 1406e800 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
51 36 1340 140df008 180b220 Enabled 2adec9cc:2aded1c0 11b42540 1 MTA (Threadpool Worker)
XXXX 37 0 16566868 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
48 38 cdc 16578840 220 Enabled 00000000:00000000 0019daf0 0 Ukn
XXXX 39 0 16566c28 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 3b 0 1646b8b0 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 3c 0 16674008 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 3d 0 16676418 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 3e 0 16676fb8 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 3f 0 16674d48 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 40 0 1667de10 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 41 0 16680050 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 42 0 166812e8 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 43 0 16683e60 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
52 44 1e40 165259e8 180b220 Enabled 2adf126c:2adf31c0 11b42540 1 MTA (Threadpool Worker)
XXXX 45 0 165b7c08 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 46 0 165aa3d8 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 47 0 165242c8 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
XXXX 48 0 165e9500 1801820 Enabled 00000000:00000000 0019daf0 0 Ukn (Threadpool Worker)
49 3a 1eac 165676f0 220 Enabled 00000000:00000000 0019daf0 0 Ukn
The threads with an ID of XXXX have ended and are waiting to be recycled. We can also see that the finalizer thread has an ID of 22. So if we'd seen an unhealthy amount of activity on thread 22 when we ran the !runaway-command we would now have known that we had a finalizer-issue on our hands.
Switching to a specific thread
To go to a specific thread we use the ~-command. The syntax is as follows: ~[number of thread]s. So to switch to thread 50 we would type the following:
We have then switched to thread 50, and can use a lot of other useful commands.
!clrstack
This great command will list the callstack for the current thread. If you want additional information you can add the "-p" switch which will show you parameters and local variables as well.
Below is a sample listing of the clrstack for thread 50.
OS Thread Id: 0x1e8c (50)
ESP EIP
17a9e750 7d61c828 [NDirectMethodFrameSlim: 17a9e750] System.DirectoryServices.Protocols.Wldap32.ldap_bind_s(IntPtr, System.String, System.DirectoryServices.Protocols.SEC_WINNT_AUTH_IDENTITY_EX, System.DirectoryServices.Protocols.BindMethod)
17a9e768 14df70f9 System.DirectoryServices.Protocols.LdapConnection.BindHelper(System.Net.NetworkCredential, Boolean)
17a9e794 14df6de0 System.DirectoryServices.Protocols.LdapConnection.Bind()
17a9e79c 14df59e9 System.DirectoryServices.Protocols.LdapConnection.SendRequestHelper(System.DirectoryServices.Protocols.DirectoryRequest, Int32 ByRef)
17a9e8b8 14df56e8 System.DirectoryServices.Protocols.LdapConnection.SendRequest(System.DirectoryServices.Protocols.DirectoryRequest, System.TimeSpan)
17a9e8bc 14df5657 [InlinedCallFrame: 17a9e8bc]
So, reading from the bottom up we can see that an LdapConnection called the SendRequest method, which in turn called the SendRequestHelper method, which called the Bind method, and so on.
If we run !clrstack -p we get the following:
OS Thread Id: 0x1e8c (50)
ESP EIP
17a9e750 7d61c828 [NDirectMethodFrameSlim: 17a9e750] System.DirectoryServices.Protocols.Wldap32.ldap_bind_s(IntPtr, System.String, System.DirectoryServices.Protocols.SEC_WINNT_AUTH_IDENTITY_EX, System.DirectoryServices.Protocols.BindMethod)
17a9e768 14df70f9 System.DirectoryServices.Protocols.LdapConnection.BindHelper(System.Net.NetworkCredential, Boolean)
PARAMETERS:
this = 0x271fdfe0
newCredential =
needSetCredential =
17a9e794 14df6de0 System.DirectoryServices.Protocols.LdapConnection.Bind()
PARAMETERS:
this =
17a9e79c 14df59e9 System.DirectoryServices.Protocols.LdapConnection.SendRequestHelper(System.DirectoryServices.Protocols.DirectoryRequest, Int32 ByRef)
PARAMETERS:
this = 0x271fdfe0
request = 0x27246e38
messageID = 0x17a9e8ec
17a9e8b8 14df56e8 System.DirectoryServices.Protocols.LdapConnection.SendRequest(System.DirectoryServices.Protocols.DirectoryRequest, System.TimeSpan)
PARAMETERS:
this = 0x271fdfe0
request = 0x27246e38
requestTimeout =
17a9e8bc 14df5657 [InlinedCallFrame: 17a9e8bc]
We can now look at the parameters, like the DirectoryRequest that was sent to the SendRequest and SendRequestHelper methods. To do this we simply copy the address of the request, (0x27246e38) and use it as an argument for our next command.
!dumpobject (!do)
This is another crucial command. Dumpobject will dump the object at the specified address, so if we send the address of the request as a parameter we will get the request dumped to screen.:
Name: System.DirectoryServices.Protocols.SearchRequest
MethodTable: 14b394c4
EEClass: 14d97ce0
Size: 52(0x34) bytes
GC Generation: 0
(C:WINDOWSassemblyGAC_MSILSystem.DirectoryServices.Protocols2.0.0.0__b03f5f7f11d50a3aSystem.DirectoryServices.Protocols.dll)
Fields:
MT Field Offset Type VT Attr Value Name
02c39310 4000102 4 System.String 0 instance 00000000 directoryRequestID
14b398bc 4000103 8 ...ControlCollection 0 instance 27246e90 directoryControlCollection
02c39310 4000111 c System.String 0 instance 27246d00 dn
12579f5c 4000112 10 ....StringCollection 0 instance 27246eb4 directoryAttributes
02c36ca0 4000113 14 System.Object 0 instance 27246ddc directoryFilter
14b39344 4000114 18 System.Int32 1 instance 1 directoryScope
14b393fc 4000115 1c System.Int32 1 instance 0 directoryRefAlias
0fd3da00 4000116 20 System.Int32 1 instance 0 directorySizeLimit
1202af88 4000117 28 System.TimeSpan 1 instance 27246e60 directoryTimeLimit
120261c8 4000118 24 System.Boolean 1 instance 0 directoryTypesOnly
Okay, so what's this? Well, it's a System.DirectoryServices.Protocols.SearchRequest object. This means that it has various properties defined by the System.DirectoryServices.Protocols.SearchRequest class. If you want to know more about these properties I suggest you look up the SearchRequest class in msdn. We have the RequestId, the Scope, the DistinguishedName, etc.
So, let's say we want to know what the distinguished name is for this particular request. We boldly assume that the dn-property we see in the listing above is what is called DistinguishedName by MSDN. Simply copy the address of the dn-property (27246d00) and use !dumpobject again. We can see that the property is a System.String, so the output should be pretty clear.
Name: System.String
MethodTable: 02c39310
EEClass: 0fb610ac
Size: 112(0x70) bytes
GC Generation: 0
(C:WINDOWSassemblyGAC_32mscorlib2.0.0.0__b77a5c561934e089mscorlib.dll)
String: CN=Dummy,CN=Accounts,CN=useradm,DC=dummy,DC=net
Fields:
MT Field Offset Type VT Attr Value Name
0fd3da00 4000096 4 System.Int32 1 instance 48 m_arrayLength
0fd3da00 4000097 8 System.Int32 1 instance 47 m_stringLength
0fb80010 4000098 c System.Char 1 instance 43 m_firstChar
02c39310 4000099 10 System.String 0 shared static Empty
>> Domain:Value 0019daf0:03380310 11b42540:03380310 <<
0fb86d44 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 0019daf0:03380324 11b42540:033855bc <<
Apparently, the distinguished name used was "CN=Dummy,CN=Accounts,CN=useradm,DC=dummy,DC=net". If we want to find out more we simply continue using !dumpobject to examine the objects and their respective values.
In my next post I thought I'd continue using the !dumpobject-command to probe through the w3wp-process, and introduce a couple of other great commands.
To be continued...
/ Johan