貌似PageParser的大量调用,会导致大量的小size的dll、众多memory hole的出现。得到eparg的指教,越来越感觉是这个样子。据joycode老大说,只有2.0这个样子,只有特定的这一个app这个样子。
准备写一个.net 2的测试程序,看这个hole是不是确实很明显?
(详情等下文)
Session,Session,Session!(请耐心阅读………………)
地球人都知道,asp.net中有三种方式存放我们的session objects。In Proc模式,在cache中存放对象。StateServer在State Service中存放,最后一种是存放在SQL Server中。对于In Proc模式,太多的session对象,意味着高内存占用;对于后两者,意味着序列化和反序列化的性能损失。
Session存放的东西太多,不一定意味着性能的问题,但这依赖于你往session里面存放的东西。
让我们假设一个场景,你开发了一个网上商店,有很少的人在用,所以你只用了一台web server,使用了In Proc模式,你的程序对每个用户的订单,都存放了一些dataset。
突然,你的程序出名了!一个大公司来找你,于是,你增加了N台web server,同时把Session State也修改成了SQL Server模式。
问题来了!
asp.net进程,内存占用很好(800MB – 1GB),有时候会提示OutOfMemory异常,或者提示.net进程被recycled了。dump的大小为1,473,913 bytes,所以,大概就是1.4G。首先,我们看看托管堆上面都有些啥东西?
0:023> !eeheap -gc
Number of GC Heaps: 2
------------------------------
Heap 0 (0x000b7198)
generation 0 starts at 0x022104d4
generation 1 starts at 0x022037c0
generation 2 starts at 0x02170030
ephemeral segment allocation context: none
segment begin allocated size
0x2170000 0x2170030 0x224a4e0 0xda4b0(894,128)
Large object heap starts at 0x0a170030
segment begin allocated size
0x0a170000 0x0a170030 0x0acf0b20 0x00b80af0(12,061,424)
0x0d490000 0x0d490030 0x0e3d2450 0x00f42420(16,000,032)
0x12010000 0x12010030 0x12f52460 0x00f42430(16,000,048)
0x13010000 0x13010030 0x13f52460 0x00f42430(16,000,048)
0x15010000 0x15010030 0x15f52460 0x00f42430(16,000,048)
0x1a010000 0x1a010030 0x1af52460 0x00f42430(16,000,048)
…
0x71ca0000 0x71ca0030 0x72be2470 0x00f42440(16,000,064)
0x748b0000 0x748b0030 0x757f2470 0x00f42440(16,000,064)
0x7d0e0000 0x7d0e0030 0x7d881250 0x007a1220(8,000,032)
Heap Size 0x2d5b4e10(760,958,480)
------------------------------
Heap 1 (0x000ede88)
generation 0 starts at 0x06249b58
generation 1 starts at 0x0623e190
generation 2 starts at 0x06170030
ephemeral segment allocation context: none
segment begin allocated size
0x6170000 0x6170030 0x6283b64 0x113b34(1,129,268)
Large object heap starts at 0x0b170030
segment begin allocated size
0x0b170000 0x0b170030 0x0b9f1c90 0x00881c60(8,920,160)
0x0c3e0000 0x0c3e0030 0x0d322460 0x00f42430(16,000,048)
0x0e490000 0x0e490030 0x0f3d2460 0x00f42430(16,000,048)
0x11010000 0x11010030 0x11f52460 0x00f42430(16,000,048)
0x14010000 0x14010030 0x14f52450 0x00f42420(16,000,032)
0x16010000 0x16010030 0x16f52480 0x00f42450(16,000,080)
0x17010000 0x17010030 0x17b81b60 0x00b71b30(12,000,048)
0x18010000 0x18010030 0x18b81b60 0x00b71b30(12,000,048)
0x19010000 0x19010030 0x19f52460 0x00f42430(16,000,048)
0x1b010000 0x1b010030 0x1bf52460 0x00f42430(16,000,048)
…
0x61010000 0x61010030 0x61f52470 0x00f42440(16,000,064)
0x62db0000 0x62db0030 0x63cf2470 0x00f42440(16,000,064)
0x657e0000 0x657e0030 0x66722470 0x00f42440(16,000,064)
0x685c0000 0x685c0030 0x69502470 0x00f42440(16,000,064)
0x6e110000 0x6e110030 0x6ec81b70 0x00b71b40(12,000,064)
0x72ca0000 0x72ca0030 0x73be2470 0x00f42440(16,000,064)
0x77ff0000 0x77ff0030 0x78f32470 0x00f42440(16,000,064)
0x7e0e0000 0x7e0e0030 0x7f022470 0x00f42440(16,000,064)
Heap Size 0x286a4124(678,052,132)
------------------------------
GC Heap Size 0x55c58f34(1,439,010,612)
!eeheap –gc告诉我们两个事情:
a) the GC Heap大小在1.4G左右,和上面的总内存占用非常接近。这说明大部分内存占用,都在托管堆上。
b) 大部分内存占用都在LargeObjects上面(>85000bytes的东西)
很自然的,我们要看看在heap里面的LO到底都是啥东西?
0:023> !dumpheap -min 85000 -stat
Using our cache to search the heap.
Statistics:
MT Count TotalSize Class Name
0x000eda20 1 920,144 Free
0x01b2209c 33 132,000,528 System.Object[]
0x01b226b0 163 1,304,001,956 System.Int32[]
Total 197 objects, Total size: 1,436,922,628
大部分内存被Int32数组占用了,还有132M被一个对象数组占用了。注意啊!这里的132M和那个1.3G,都只是object本身的大小,而不包括存储在Object数组里面的对象的大小。如果要看详细情况,我们需要跑一下!objsize才可以。
0:023> !dumpheap -min 85000
Using our cache to search the heap.
Address MT Size Gen
0x0b170030 0x000eda20 920,144 -1 Free
0x0a920210 0x01b2209c 4,000,016 -1 System.Object[]
0x247b1250 0x01b2209c 4,000,016 -1 System.Object[]
0x277b1250 0x01b2209c 4,000,016 -1 System.Object[]
0x287b1250 0x01b2209c 4,000,016 -1 System.Object[]
…
0x51af0030 0x01b226b0 8,000,012 -1 System.Int32[]
0x52291250 0x01b226b0 8,000,012 -1 System.Int32[]
0x53b40950 0x01b226b0 8,000,012 -1 System.Int32[]
0x56620030 0x01b226b0 8,000,012 -1 System.Int32[]
0x57620030 0x01b226b0 8,000,012 -1 System.Int32[]
0x5a440030 0x01b226b0 8,000,012 -1 System.Int32[]
0x5abe1250 0x01b226b0 8,000,012 -1 System.Int32[]
0x5c660030 0x01b226b0 8,000,012 -1 System.Int32[]
0x5ce01250 0x01b226b0 8,000,012 -1 System.Int32[]
0x61010030 0x01b226b0 8,000,012 -1 System.Int32[]
0x617b1250 0x01b226b0 8,000,012 -1 System.Int32[]
0x62db0030 0x01b226b0 8,000,012 -1 System.Int32[]
0x63551250 0x01b226b0 8,000,012 -1 System.Int32[]
0x657e0030 0x01b226b0 8,000,012 -1 System.Int32[]
0x65f81250 0x01b226b0 8,000,012 -1 System.Int32[]
注意Gen这一列,这些object都没有被GC,为啥?随便找一个,看看吧!
0:023> !gcroot 0x72ca0030
Scan Thread 16 (0xbd8)
ESP:1a3f5e0:Root:0x6280d38(System.Web.HttpContext)->
0x62809ec(System.Web.Hosting.ISAPIWorkerRequestInProcForIIS6)->
0x61b7030(System.Web.HttpWorkerRequest/EndOfSendNotification)->
0x61b47d4(System.Web.HttpRuntime)->
0x61b4ca0(System.Web.Caching.CacheMultiple)->0x61b4cc4(System.Object[])->
0x61b4cdc(System.Web.Caching.CacheSingle)->
0x61b4dac(System.Web.Caching.CacheExpires)->0x61b4ff8(System.Object[])->
0x61b5ab8(System.Web.Caching.ExpiresBucket)->
0x222e63c(System.Web.Caching.ExpiresEntry[])->
0x220292c(System.Web.Caching.CacheEntry)->
0x22028fc(System.Web.SessionState.InProcSessionState)->
0x2202690(System.Web.SessionState.SessionDictionary)->
0x220273c(System.Collections.Hashtable)->
0x2202770(System.Collections.Hashtable/bucket[])->
0x2202810(System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry)->
0x72ca0030(System.Int32[])
Scan Thread 20 (0x89c)
Scan Thread 22 (0xa5c)
Scan HandleTable 0xdc9d8
Scan HandleTable 0xea6e8
Scan HandleTable 0x1531e8
看这条链,我们发现Int32被Cache root了(看GC的原理就知道这句话啥意思了),看上面的InProcSessionState,我们知道现在是InProc模式。
继续看……
0:023> !dumpaspnetcache -stat
Going to dump the ASP.NET Cache.
MT Count TotalSize Class Name
0x0211cc9c 1 20 System.Web.Security.FileSecurityDescriptorWrapper
0x020c242c 2 56 System.Web.UI.ParserCacheItem
0x0206c66c 5 260 System.Web.Configuration.HttpConfigurationRecord
0x0c2e7014 1 316 System.Web.Mobile.MobileCapabilities
0x79b94638 4 376 System.String
0x0c2eaeb4 151 7,248 System.Web.SessionState.InProcSessionState
Total 164 objects, Total size: 8,276
好,我们找到了151个Session对象。
0:023> .foreach (obj {!dumpheap -mt 0x0c2eaeb4 -short}){!objsize ${obj}}
sizeof(0x22028fc) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x2202a10) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x2202cfc) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x2202fe8) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x22032d4) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x22035c0) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x2203a38) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x2203d24) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x2204010) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
…
sizeof(0x6248080) = 12,000,772 (0xb71e04) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x6248334) = 12,000,772 (0xb71e04) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x62485e8) = 12,000,772 (0xb71e04) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x624a84c) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x624d7b8) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x6250724) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x6253690) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x62565fc) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x6259568) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x625c4d4) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x625f440) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x62623ac) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x6265318) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x6268284) = 8,000,812 (0x7a152c) bytes (System.Web.SessionState.InProcSessionState)
sizeof(0x626b1b8) = 12,000,772 (0xb71e04) bytes (System.Web.SessionState.InProcSessionState)
看到了!151个session对象,每个拿到了8-12M左右的数据。就是这个鸟玩意搞的内存有问题啦!
随便找一个,看看什么在里面???
0:023> !do 0x626b1b8
Name: System.Web.SessionState.InProcSessionState
MethodTable 0x0c2eaeb4
EEClass 0x0c1c5660
Size 48(0x30) bytes
GC Generation: 0
mdToken: 0x02000132 (c:\windows\assembly\gac\system.web\1.0.5000.0__b03f5f7f11d50a3a\system.web.dll)
FieldDesc*: 0x0c2eae0c
MT Field Offset Type Attr Value Name
0x0c2eaeb4 0x40009f2 0x4 CLASS instance 0x06269f74 dict
0x0c2eaeb4 0x40009f3 0x8 CLASS instance 0x00000000 staticObjects
0x0c2eaeb4 0x40009f4 0xc System.Int32 instance 20 timeout
0x0c2eaeb4 0x40009f5 0x18 System.Boolean instance 0 isCookieless
0x0c2eaeb4 0x40009f6 0x10 System.Int32 instance 0 streamLength
0x0c2eaeb4 0x40009f7 0x19 System.Boolean instance 0 locked
0x0c2eaeb4 0x40009f8 0x1c VALUETYPE instance start at 0x0626b1d4 utcLockDate
0x0c2eaeb4 0x40009f9 0x14 System.Int32 instance 1 lockCookie
0x0c2eaeb4 0x40009fa 0x24 VALUETYPE instance start at 0x0626b1dc spinLock
每个InProcSessionState对象都有一个叫做_entriesArray的dict成员,装有实际的session对象列表。就是上面偏移为0x04的那行。
0:023> !do 0x06269f74
Name: System.Web.SessionState.SessionDictionary
MethodTable 0x0c2e0c54
EEClass 0x0c1c1308
Size 44(0x2c) bytes
GC Generation: 0
mdToken: 0x0200013b (c:\windows\assembly\gac\system.web\1.0.5000.0__b03f5f7f11d50a3a\system.web.dll)
FieldDesc*: 0x0c2e0b30
MT Field Offset Type Attr Value Name
0x0206b338 0x4000a8b 0x24 System.Boolean instance 0 _readOnly
0x0206b338 0x4000a8c 0x4 CLASS instance 0x06269fb8 _entriesArray
0x0206b338 0x4000a8d 0x8 CLASS instance 0x06269fa0 _hashProvider
0x0206b338 0x4000a8e 0xc CLASS instance 0x06269fac _comparer
0x0206b338 0x4000a8f 0x10 CLASS instance 0x0626a020 _entriesTable
0x0206b338 0x4000a90 0x14 CLASS instance 0x00000000 _nullKeyEntry
0x0206b338 0x4000a91 0x18 CLASS instance 0x00000000 _keys
0x0206b338 0x4000a92 0x1c CLASS instance 0x00000000 _serializationInfo
0x0206b338 0x4000a93 0x20 System.Int32 instance 4 _version
0x0c2e0c54 0x4000a0f 0x25 System.Boolean instance 1 _dirty
0x0c2e0c54 0x4000a0e 0 CLASS shared static s_immutableTypes
>> Domain:Value 0x000dad08:NotInit 0x00104f30:0x021be0dc <<
同样,还是看_entriesArray,偏移为0x04的那行
0:023> !do 0x06269fb8
Name: System.Collections.ArrayList
MethodTable 0x79ba2ee4
EEClass 0x79ba3020
Size 24(0x18) bytes
GC Generation: 0
mdToken: 0x02000100 (c:\windows\microsoft.net\framework\v1.1.4322\mscorlib.dll)
FieldDesc*: 0x79ba3084
MT Field Offset Type Attr Value Name
0x79ba2ee4 0x4000362 0x4 CLASS instance 0x06269fd0 _items
0x79ba2ee4 0x4000363 0xc System.Int32 instance 3 _size
0x79ba2ee4 0x4000364 0x10 System.Int32 instance 3 _version
0x79ba2ee4 0x4000365 0x8 CLASS instance 0x00000000 _syncRoot
哦,Name是ArrayList,好,我们继续看0x04对应的那个_items吧!
0:023> !do -v 0x06269fd0
Name: System.Object[]
MethodTable 0x01b2209c
EEClass 0x01b22018
Size 80(0x50) bytes
GC Generation: 0
Array: Rank 1, Type CLASS
Element Type: System.Object
Content: 16 items
------ Will only dump out valid managed objects ----
Address MT Class Name
0x0626a81c 0x0206b784 System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry
0x0626a82c 0x0206b784 System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry
0x0626a83c 0x0206b784 System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry
----------
对于每个对象,我们打印出0x04位置的Name和0x08位置的Size。
0:023> .foreach (obj {!do -v 0x06269fd0 -short}){.echo ***;!do poi(${obj}+0x4);!do poi(${obj}+0x8);!objsize ${obj}}
***
String: somestring
String: this is a string i stored in session scope
sizeof(0x626a81c) = 160 ( 0xa0) bytes (System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry)
***
String: alargeintarray
Name: System.Int32[]
MethodTable 0x01b226b0
EEClass 0x01b22638
Size 8000012(0x7a120c) bytes
GC Generation: 3
Array: Rank 1, Type System.Int32
Element Type: System.Int32
Content: 2,000,000 items
sizeof(0x626a82c) = 8,000,076 (0x7a124c) bytes (System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry)
***
String: sometimesbig
Name: System.Object[]
MethodTable 0x01b2209c
EEClass 0x01b22018
Size 4000016(0x3d0910) bytes
GC Generation: 3
Array: Rank 1, Type CLASS
Element Type: System.Object
Content: 1,000,000 items
sizeof(0x626a83c) = 4,000,076 (0x3d094c) bytes (System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry)
到这里,我们看到,一个很小的字符串:this is a string i stored in session scope。在Session的 somestring里面。然后是在Session的alargeintarray有一个8M的Int32数组,最后,是一个4M的sometimesbig在session的sometimesbig。
下面如何解决?就看我们的业务逻辑和代码实现啦!和偶无关了,嗬嗬!
(序 & 跋)
此文及后面的系列,都是从tess老大那里翻译过来的。一直和GTEC的老牛们作CASE(此句有误,一直提CASE,等老牛们提供答案),算是粘到了一点仙气。偶一直比较懒,所以以前精心抄袭的文章,今天再次精心作序于此,希望对各位挣扎于现实与理想的各位,共享,共勉。tess老大的文章国内似乎有人翻译过,但偶个人观点,不看好,因为好东西都没了哦。
不是我不舍得,意思是,我的post里面基本上没有link,但是从google上都能搞到,如tess老大的系列debug文章。写程序的人,用好google应该是第一要素啊,哇哈哈哈!(百度除外,偶鄙视的公司)
每个post的题目都挺吓人,但是最终发现问题以及解决掉的方法,都异常简单。简单,产生丑陋。
问题描述:
程序慢的要死,CPU占用始终持续在70%-80%之间
解决步骤:
性能监视器。对于高CPU占用,一般的是这三个原因:
· 高的离谱的循环
· 太多的加载(比如,许多小的对象被频繁的处理)
· GC作了太多的事情
第一种情况,当你在恰当的时机抓到一个dump,就非常容易解决,一般而言,都是因为业务处理逻辑造成的。第二种情况,一般需要从硬件上考虑,scale up或者scale out,都行。
是否是GC的问题,我们需要看性能监视器里面的.NET CLR Memory计数器。这里面,最重要的是.net CLR Memory / % Time in GC. 这个值的阀值,可能是5%或者30%或者20%。实际上,没有一个准确的阀值存在的。当然,这个数字理论上应该接近于0%才对。
在GC里面,导致高CPU占用的原因,通常是因为过高的分配速率(对应到性能监视器里面的.net CLR Memory / allocated bytes/sec计数器。但实际上,如果所有的GC操作都在第0代上,则不会导致这个问题。真正的元凶,是大量的2代操作。如N多的对象在被移动到2代或者从2代中被释放。另一个原因就是我们熟知的大对象操作(LOH)
再强调一次,没有什么准确的指标,就告诉我们,超过了它就是出问题了,这是不可能的。包括微软给我们的大多数Practics Training,只有“尽量”、“尽可能”、“如果”等,而不是“一定”、“必须”。
如同我在那篇“浅谈GC中”讲到的一样,如果你搞了GC.Collect(2)或者GC.GetTotalMemory(true),那么也会导致大量的2代回收。
对于这个问题,我从性能监视器中抓到了这些数据:
% Time in GC ~40 % average
allocated bytes / sec 400 MB average
# Induced GC 0
# Gen 0 Collections 28.379
# Gen 1 Collections 28.378
# Gen 2 Collections 28.378
看第二行,真是让人晕倒!每秒分配400M字节!但实际上,我的代码中没有分配任何这么大的东西,有点太离谱了吧?!如果看最后面三行,也比较搞笑,0、1、2代的分配几乎完全相同。这实际上说明有LOH在压缩,或者有大量的对象冲进了第2代,然后又被立刻释放掉。
开始debug吧!
GC问题很难debug,因为:
1. 如果在GC中间过程中用adplus -hang模式抓了一个dump,基本上从dump里面看不到任何高CPU占用的原因。
2. 即时你通过性能监视器找到了GC的问题,也抓到了dump,但是很难分析。
实际上,通用的做法是每隔一小段时间,你就抓一次dump。如果看起来都差不多,那么有可能就能分析出哪里的问题了。
步骤1 - 我们在GC里面不?
如果我们的OS是server,那么每个CPU有一个GC线程(如果超线程的话,就是2个)。如果是非server的,那么只有一个GC线程。我们正在看到的这个dump,是在一个双核的、带有.NET2.0的机器上产生的。
如果我们不在GC过程中,那么我们会有两个线程(每个CPU一个):
18 Id: 134c.918 Suspend: 1 Teb: 7ffa8000 Unfrozen
ChildEBP RetAddr Args to Child
01e1fe68 7c822124 77e6baa8 00000398 00000000 ntdll!KiFastSystemCallRet
01e1fe6c 77e6baa8 00000398 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
01e1fedc 79e77fd1 00000398 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
01e1ff20 79e77f9a 00000398 ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199
01e1ff70 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
01e1ff80 79f3549b ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17
01e1ffa8 79f6ece3 00000000 b28c067c 01e1ffec mscorwks!SVR::gc_heap::gc_thread_function+0x2e
01e1ffb8 77e66063 000e7660 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x9b
01e1ffec 00000000 79f6ec79 000e7660 00000000 kernel32!BaseThreadStart+0x34
上面的代码表明,GC正在等着干活……在我抓到的dump中,GC看起来这个样子:
16 Id: f28.1150 Suspend: 1 Teb: fff82000 Unfrozen
ChildEBP RetAddr Args to Child
0248fd28 7d4d8c46 000002dc 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15
0248fd98 79e77fd1 000002dc ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
0248fddc 79e77f9a 000002dc ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199
0248fe2c 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
0248fe3c 79f35e1a ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17
0248fe54 7a0d5a3b 001afbf0 0000000d 00000002 mscorwks!SVR::t_join::join+0x61
0248ff54 79f391bf 00000002 001afbf0 00000000 mscorwks!SVR::gc_heap::plan_phase+0xd78
0248ff70 79f39954 00000002 ffffffff 001afbf0 mscorwks!SVR::gc_heap::gc1+0x57
0248ff88 79f35422 00000000 00000000 001afbf0 mscorwks!SVR::gc_heap::garbage_collect+0x37c
0248ffa8 79f6ece3 00000000 914b1904 0248ffec mscorwks!SVR::gc_heap::gc_thread_function+0x68
0248ffb8 7d4e0729 001afbf0 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x9b
0248ffec 00000000 79f6ec79 001afbf0 00000000 kernel32!BaseThreadStart+0x34
看上面的粗体,哦,正在Collect。就是说,我们闯到了GC的肚子里面。
步骤2 - GC为什么开始工作了?
先看一下,CPU都被谁用掉了?
0:029> !runaway
User Mode Time
Thread Time
14:11b8 0 days 0:00:55.687
16:1150 0 days 0:00:45.500
17:7a8 0 days 0:00:43.875
21:1244 0 days 0:00:23.140
0:ea0 0 days 0:00:00.046
29:fc8 0 days 0:00:00.000
28:11f0 0 days 0:00:00.000
0:021> .time
Debug session time: Tue Jun 20 09:46:04.000 2006 (GMT+2)
System Uptime: 4 days 6:36:51.031
Process Uptime: 0 days 0:16:53.000
Kernel time: 0 days 0:00:45.000
User time: 0 days 0:02:48.000
上面来看,大约有17分钟被程序用掉了。我们看一下14号在作什么?
14 Id: f28.11b8 Suspend: 1 Teb: fff88000 Unfrozen
ChildEBP RetAddr Args to Child
020afc8c 7d4d8c46 00000224 00000000 020afcd0 ntdll!ZwWaitForSingleObject+0x15
020afcfc 79e77fd1 00000224 00009c40 00000000 kernel32!WaitForSingleObjectEx+0xac
020afd40 79e77f9a 00000224 00009c40 00000000 mscorwks!PEImage::LoadImage+0x199
020afd90 79e77f50 00009c40 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
020afda0 79f5b69c 00009c40 00000000 00000000 mscorwks!CLREvent::Wait+0x17
020afe20 7a1121c3 001862f8 00009c40 00000000 mscorwks!ThreadpoolMgr::SafeWait+0x73
020afe94 79f71123 00000000 00000000 00000000 mscorwks!ThreadpoolMgr::WorkerThreadStart+0xf1
020affb8 7d4e0729 0019cab8 00000000 00000000 mscorwks!ThreadpoolMgr::intermediateThreadProc+0x49
020affec 00000000 79f710dd 0019cab8 00000000 kernel32!BaseThreadStart+0x34
哦,很清闲,什么都没干。但是,那17分钟中,有56秒在用着CPU,什么意思呢???我们继续看一下21号线程的托管堆。
0:021> !clrstack
OS Thread Id: 0x1244 (21)
ESP EIP
029ef1e8 7d61c824 [HelperMethodFrame: 029ef1e8]
029ef254 02920df3 LargeObjectHeap.GetLotsOfDatesXML(Int32)
029ef2a4 02920b20 LargeObjectHeap.Button1_Click(System.Object, System.EventArgs)
029ef2b4 6881bdc6 System.Web.UI.WebControls.Button.OnClick(System.EventArgs)
029ef2c8 6881bfbc System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)
029ef2dc 6881bf38 System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)
029ef2e0 687d91e0 System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)
029ef2e8 687d912a System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)
029ef2f8 687dcbbf System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
029ef4b0 687db521 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
029ef4e0 687db487 System.Web.UI.Page.ProcessRequest()
029ef518 687db3a7 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
029ef520 687db33a System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
029ef534 02920795 ASP.largeobjectheap_aspx.ProcessRequest(System.Web.HttpContext)
029ef538 686888df System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
029ef56c 6865a071 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
029ef5ac 6865a39b System.Web.HttpApplication.ResumeSteps(System.Exception)
029ef5f4 6865912d System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
029ef610 6865e0bd System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
029ef644 6865dd72 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
029ef650 6865c447 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
029ef800 79f1ef33 [ContextTransitionFrame: 029ef800]
029ef850 79f1ef33 [GCFrame: 029ef850]
029ef9a8 79f1ef33 [ComMethodFrame: 029ef9a8]
看上面的call stack,我们看到了LargeObjectHeap.GetLotsOfDatesXML(),这个咚咚触发了LOH的回收,然后按次序触发了2代、1代、0代。
但是只有一个大对象,并不会导致高CPU的占用啊!那我们看一下实际的代码吧!
String GetLotsOfDatesXML(int i)
{
String dates = "<Dates>";
for (int j = 0; j < i; j++)
{
DateTime dt = DateTime.Now.Add(new TimeSpan(j, 0, 0, 0));
dates += "<Date><Month>" + dt.Month + "</Month><Day>" + dt.Day + "</Day><DayOfWeek>" + dt.DayOfWeek + "</DayOfWeek><Date>";
dates += "<Date><Month>" + dt.Month + "</Month><Day>" + dt.Day + "</Day><DayOfWeek>" + dt.DayOfWeek + "</DayOfWeek><Date>";
}
dates += "</Dates>";
return dates;
}
如果外面传来的i小点还好,但是如果很大呢?对于确切地i是多少,我们需要一点一点地开始找。从callstack上面,我们看到是LargeObjectHeap.Button1_Click调用了GetLotsOfDatesXML方法。
protected void Button1_Click(object sender, EventArgs e)
{
String str = GetLotsOfDatesXML(Int32.Parse(txtNumIterations.Text));
}
在这里,txtNumIterations是一个textbox控件。下面,基本上都是!do和!dso的工作了。
0:021> !dso
OS Thread Id: 0x1244 (21)
ESP/REG Object Name
029ef0f0 0b1a2270 System.String <String is invalid or too large to print>
029ef1a8 0b1a2270 System.String <String is invalid or too large to print>
029ef1bc 0b1a2270 System.String <String is invalid or too large to print>
029ef228 06a759e4 System.String </DayOfWeek><Date>
029ef28c 06a76df0 ASP.largeobjectheap_aspx
029ef2b4 06a77b84 System.ComponentModel.EventHandlerList
029ef2bc 06a77a84 System.Web.UI.WebControls.Button
029ef2c8 06a76df0 ASP.largeobjectheap_aspx
029ef304 06a76880 System.Web.HttpContext
...
0:021> !do 06a76df0
Name: ASP.largeobjectheap_aspx
MethodTable: 02746ccc
EEClass: 028d24cc
Size: 380(0x17c) bytes
(C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\debuggersamples\e7443224\5232f845\App_Web_h0ctkxwz.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fa3e0 4001fe0 4 System.String 0 instance 02a7cba4 _id
790fa3e0 4001fe1 8 System.String 0 instance 00000000 _cachedUniqueID
68a2af44 4001fe2 c ...em.Web.UI.Control 0 instance 00000000 _parent
68a91070 4001fe3 2c System.Int32 0 instance 5 _controlState
68a85ea0 4001fe4 10 ...m.Web.UI.StateBag 0 instance 00000000 _viewState
68a2af44 4001fe5 14 ...em.Web.UI.Control 0 instance 00000000 _namingContainer
68a273d0 4001fe6 18 System.Web.UI.Page 0 instance 06a76df0 _page
...
68a7d910 4000004 16c ...ebControls.Button 0 instance 06a77a84 Button1
68a95f40 4000005 170 ...bControls.TextBox 0 instance 06a77be4 txtNumIterations
68a2bc80 4000006 174 ...Controls.HtmlForm 0 instance 06a77688 form1
好,继续看一下这个textbox。
0:021> !do 06a77be4
Name: System.Web.UI.WebControls.TextBox
MethodTable: 68a95f40
EEClass: 68a95ebc
Size: 80(0x50) bytes
(C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fa3e0 4001fe0 4 System.String 0 instance 02a85a04 _id
790fa3e0 4001fe1 8 System.String 0 instance 00000000 _cachedUniqueID
68a2af44 4001fe2 c ...em.Web.UI.Control 0 instance 06a77688 _parent
68a91070 4001fe3 2c System.Int32 0 instance 5 _controlState
68a85ea0 4001fe4 10 ...m.Web.UI.StateBag 0 instance 06a788f0 _viewState
68a2af44 4001fe5 14 ...em.Web.UI.Control 0 instance 06a76df0 _namingContainer
68a273d0 4001fe6 18 System.Web.UI.Page 0 instance 06a76df0 _page
68a92e2c 4001fe7 1c ...+OccasionalFields 0 instance 06a78974 _occasionalFields
68a2b378 4001fe8 20 ...I.TemplateControl 0 instance 00000000 _templateControl
...
0:021> !do 06a788f0
Name: System.Web.UI.StateBag
MethodTable: 68a85ea0
EEClass: 68a85e30
Size: 16(0x10) bytes
(C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79113dfc 400235f 4 ...tions.IDictionary 0 instance 06a78900 bag
79104f64 4002360 8 System.Boolean 0 instance 1 marked
79104f64 4002361 9 System.Boolean 0 instance 0 ignoreCase
0:021> !do 06a78900
Name: System.Collections.Specialized.HybridDictionary
MethodTable: 7a747ad4
EEClass: 7a7aa890
Size: 20(0x14) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
7a747bac 4001145 4 ...ed.ListDictionary 0 instance 06a78924 list
790fea70 4001146 8 ...ections.Hashtable 0 instance 00000000 hashtable
79104f64 4001147 c System.Boolean 0 instance 0 caseInsensitive
0:021> !do 06a78924
Name: System.Collections.Specialized.ListDictionary
MethodTable: 7a747bac
EEClass: 7a7aa918
Size: 28(0x1c) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
7a747c78 4001148 4 ...ry+DictionaryNode 0 instance 06a78940 head
790fed1c 4001149 10 System.Int32 0 instance 1 version
790fed1c 400114a 14 System.Int32 0 instance 1 count
791117c8 400114b 8 ...ections.IComparer 0 instance 00000000 comparer
790f9c18 400114c c System.Object 0 instance 00000000 _syncRoot
0:021> !do 06a78940
Name: System.Collections.Specialized.ListDictionary+DictionaryNode
MethodTable: 7a747c78
EEClass: 7a7aa9b8
Size: 20(0x14) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790f9c18 4001158 4 System.Object 0 instance 06a66bd8 key
790f9c18 4001159 8 System.Object 0 instance 06a78914 value
7a747c78 400115a c ...ry+DictionaryNode 0 instance 00000000 next
0:021> !do 06a66bd8
Name: System.String
MethodTable: 790fa3e0
EEClass: 790fa340
Size: 26(0x1a) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: Text
...
找到了Text属性,看看是多少?
0:021> !do 06a78914
Name: System.Web.UI.StateItem
MethodTable: 68a131b4
EEClass: 68a13144
Size: 16(0x10) bytes
(C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790f9c18 4002362 4 System.Object 0 instance 06a78184 value
79104f64 4002363 8 System.Boolean 0 instance 1 isDirty
0:021> !do 06a78184
Name: System.String
MethodTable: 790fa3e0
EEClass: 790fa340
Size: 28(0x1c) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: 40000
Fields:
MT Field Offset Type VT Attr Value Name
790fed1c 4000096 4 System.Int32 0 instance 6 m_arrayLength
790fed1c 4000097 8 System.Int32 0 instance 5 m_stringLength
790fbefc 4000098 c System.Char 0 instance 34 m_firstChar
790fa3e0 4000099 10 System.String 0 shared static Empty
>> Domain:Value 001a8868:790d6584 001ca990:790d6584 <<
79124670 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 001a8868:06a303f0 001ca990:06a34118 <<
靠,循环了4万次!
结论:
地球人都知道,用+=会产生3*n个对象,如果用StringBuilder,就不会有这个问题了。
上文中,我们解决了那个场景的死锁问题。这次,我们分析一下,为什么会死锁呢?再回顾一下两个sp的写法:
CREATE PROC p1 @p1 int AS
SELECT c2, c3 FROM t1 WHERE c2 BETWEEN @p1 AND @p1+1
GO
CREATE PROC p2 @p1 int AS
UPDATE t1 SET c2 = c2+1 WHERE c1 = @p1
UPDATE t1 SET c2 = c2-1 WHERE c1 = @p1
GO
很奇怪吧!p1没有insert,没有delete,没有update,只是一个select,p2才是update。这个和我们前面说过的,trans1里面updata A,update B;trans2里面upate B,update A,根本不贴边啊!
那么,什么导致了死锁?
需要从事件日志中,看sql的死锁信息:
Spid X is running this query (line 2 of proc [p1], inputbuffer “… EXEC p1 4 …”):
SELECT c2, c3 FROM t1 WHERE c2 BETWEEN @p1 AND @p1+1
Spid Y is running this query (line 2 of proc [p2], inputbuffer “EXEC p2 4”):
UPDATE t1 SET c2 = c2+1 WHERE c1 = @p1
The SELECT is waiting for a Shared KEY lock on index t1.cidx. The UPDATE holds a conflicting X lock.
The UPDATE is waiting for an eXclusive KEY lock on index t1.idx1. The SELECT holds a conflicting S lock.
首先,我们看看p1的执行计划。怎么看呢?可以执行set statistics profile on,这句就可以了。下面是p1的执行计划
SELECT c2, c3 FROM t1 WHERE c2 BETWEEN @p1 AND @p1+1
|--Nested Loops(Inner Join, OUTER REFERENCES:([Uniq1002], [t1].[c1]))
|--Index Seek(OBJECT:([t1].[idx1]), SEEK:([t1].[c2] >= [@p1] AND [t1].[c2] <= [@p1]+(1)) ORDERED FORWARD)
|--Clustered Index Seek(OBJECT:([t1].[cidx]), SEEK:([t1].[c1]=[t1].[c1] AND [Uniq1002]=[Uniq1002]) LOOKUP ORDERED FORWARD)
我们看到了一个nested loops,第一行,利用索引t1.c2来进行seek,seek出来的那个rowid,在第二行中,用来通过聚集索引来查找整行的数据。这是什么?就是bookmark lookup啊!为什么?因为我们需要的c2、c3不能完全的被索引t1.c1带出来,所以需要书签查找。
好,我们接着看p2的执行计划。
UPDATE t1 SET c2 = c2+1 WHERE c1 = @p1
|--Clustered Index Update(OBJECT:([t1].[cidx]), OBJECT:([t1].[idx1]), SET:([t1].[c2] = [Expr1004]))
|--Compute Scalar(DEFINE:([Expr1013]=[Expr1013]))
|--Compute Scalar(DEFINE:([Expr1004]=[t1].[c2]+(1), [Expr1013]=CASE WHEN CASE WHEN ...
|--Top(ROWCOUNT est 0)
|--Clustered Index Seek(OBJECT:([t1].[cidx]), SEEK:([t1].[c1]=[@p1]) ORDERED FORWARD)
通过聚集索引的seek找到了一行,然后开始更新。这里注意的是,update的时候,它会申请一个针对clustered index的X锁的。
实际上到这里,我们就明白了为什么update会对select产生死锁。update的时候,会申请一个针对clustered index的X锁,这样就阻塞住了(注意,不是死锁!)select里面最后的那个clustered index seek。死锁的另一半在哪里呢?注意我们的select语句,c2存在于索引idx1中,c1是一个聚集索引cidx。问题就在这里!我们在p2中更新了c2这个值,所以sqlserver会自动更新包含c2列的非聚集索引:idx1。而idx1在哪里?就在我们刚才的select语句中。而对这个索引列的更改,意味着索引集合的某个行或者某些行,需要重新排列,而重新排列,需要一个X锁。
SO………,问题就这样被发现了。
总结一下,就是说,某个query使用非聚集索引来select数据,那么它会在非聚集索引上持有一个S锁。当有一些select的列不在该索引上,它需要根据rowid找到对应的聚集索引的那行,然后找到其他数据。而此时,第二个的查询中,update正在聚集索引上忙乎:定位、加锁、修改等。但因为正在修改的某个列,是另外一个非聚集索引的某个列,所以此时,它需要同时更改那个非聚集索引的信息,这就需要在那个非聚集索引上,加第二个X锁。select开始等待update的X锁,update开始等待select的S锁,死锁,就这样发生鸟。
那么,为什么我们增加了一个非聚集索引,死锁就消失鸟?我们看一下,按照上文中自动增加的索引之后的执行计划:
SELECT c2, c3 FROM t1 WHERE c2 BETWEEN @p1 AND @p1+1
|--Index Seek(OBJECT:([deadlocktest].[dbo].[t1].[_dta_index_t1_7_2073058421__K2_K1_3]), SEEK:([deadlocktest].[dbo].[t1].[c2] >= [@p1] AND [deadlocktest].[dbo].[t1].[c2] <= [@p1]+(1)) ORDERED FORWARD)
哦,对于clustered index的需求没有了,因为增加的覆盖索引已经足够把所有的信息都select出来。就这么简单。
实际上,在sqlserver 2005中,如果用profiler来抓eventid:1222,那么会出现一个死锁的图,很直观的说。
下面的方法,有助于将死锁减至最少(详细情况,请看SQLServer联机帮助,搜索:将死锁减至最少即可。
- 按同一顺序访问对象。
- 避免事务中的用户交互。
- 保持事务简短并处于一个批处理中。
- 使用较低的隔离级别。
- 使用基于行版本控制的隔离级别。
- 将 READ_COMMITTED_SNAPSHOT 数据库选项设置为 ON,使得已提交读事务使用行版本控制。
- 使用快照隔离。
- 使用绑定连接。
死锁,简而言之,两个或者多个trans,同时请求对方正在请求的某个对象,导致双方互相等待。简单的例子如下:
trans1 trans2
------------------------------------------------------------------------
1.IDBConnection.BeginTransaction 1.IDBConnection.BeginTransaction
2.update table A 2.update table B
3.update table B 3.update table A
4.IDBConnection.Commit 4.IDBConnection.Commit
那么,很容易看到,如果trans1和trans2,分别到达了step3,那么trans1会请求对于B的X锁,trans2会请求对于A的X锁,而二者的锁在step2上已经被对方分别持有了。由于得不到锁,后面的Commit无法执行,这样双方开始死锁。
好,我们看一个简单的例子,来解释一下,应该如何解决死锁问题。
-- Batch #1
CREATE DATABASE deadlocktest
GO
USE deadlocktest
SET NOCOUNT ON
DBCC TRACEON (1222, -1)
-- 在SQL2005中,增加了一个新的dbcc参数,就是1222,原来在2000下,我们知道,可以执行dbcc
--traceon(1204,3605,-1)看到所有的死锁信息。SqlServer 2005中,对于1204进行了增强,这就是1222。
GO
IF OBJECT_ID ('t1') IS NOT NULL DROP TABLE t1
IF OBJECT_ID ('p1') IS NOT NULL DROP PROC p1
IF OBJECT_ID ('p2') IS NOT NULL DROP PROC p2
GO
CREATE TABLE t1 (c1 int, c2 int, c3 int, c4 char(5000))
GO
DECLARE @x int
SET @x = 1
WHILE (@x <= 1000) BEGIN
INSERT INTO t1 VALUES (@x*2, @x*2, @x*2, @x*2)
SET @x = @x + 1
END
GO
CREATE CLUSTERED INDEX cidx ON t1 (c1)
CREATE NONCLUSTERED INDEX idx1 ON t1 (c2)
GO
CREATE PROC p1 @p1 int AS SELECT c2, c3 FROM t1 WHERE c2 BETWEEN @p1 AND @p1+1
GO
CREATE PROC p2 @p1 int AS
UPDATE t1 SET c2 = c2+1 WHERE c1 = @p1
UPDATE t1 SET c2 = c2-1 WHERE c1 = @p1
GO
上述sql创建一个deadlock的示范数据库,插入了1000条数据,并在表t1上建立了c1列的聚集索引,和c2列的非聚集索引。另外创建了两个sp,分别是从t1中select数据和update数据。
好,打开一个新的查询窗口,我们开始执行下面的query:
-- Batch #2
USE deadlocktest
SET NOCOUNT ON
WHILE (1=1) EXEC p2 4
GO
开始执行后,然后我们打开第三个查询窗口,执行下面的query:
-- Batch #3
USE deadlocktest
SET NOCOUNT ON
CREATE TABLE #t1 (c2 int, c3 int)
GO
WHILE (1=1) BEGIN
INSERT INTO #t1 EXEC p1 4
TRUNCATE TABLE #t1
END
GO
开始执行,哈哈,很快,我们看到了这样的错误信息:
Msg 1205, Level 13, State 51, Procedure p1, Line 4
Transaction (Process ID 54) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
spid54发现了死锁。
那么,我们该如何解决它?
在SqlServer 2005中,我们可以这么做:
1.在trans3的窗口中,选择EXEC p1 4,然后right click,看到了菜单了吗?选择Analyse Query in Database Engine Tuning Advisor。
2.注意右面的窗口中,wordload有三个选择:负载文件、表、查询语句,因为我们选择了查询语句的方式,所以就不需要修改这个radio option了。
3.点左上角的Start Analysis按钮
4.抽根烟,回来后看结果吧!出现了一个分析结果窗口,其中,在Index Recommendations中,我们发现了一条信息:大意是,在表t1上增加一个非聚集索引索引:t2+t1。
5.在当前窗口的上方菜单上,选择Action菜单,选择Apply Recommendations,系统会自动创建这个索引。
重新运行batch #3,呵呵,死锁没有了。
这种方式,我们可以解决大部分的Sql Server死锁问题。那么,发生这个死锁的根本原因是什么呢?为什么增加一个non clustered index,问题就解决了呢?且听下文分解。
string bytecode = "73 01 00 00 06 28 4E 00 00 0A 2A";
上面这个string干什么的?加密后的代码?某种不可思议的数字?汇编语言?
如果按照CLR IL规范来解析,我们会得到一段常见的代码。
0000 : newobj instance void WindowsApplication3.MainForm::.ctor()
0005 : call System.Void System.Windows.Forms.Application::Run()
0010 : ret
简单吗?看起来是new一个MainForm,然后call Application的Run方法,最后return。
仔细想想,这就是我们常见的,每个winform程序中缺省方式下自动生成的代码。如下:
static void Main()
{
Application.Run(new MainForm());
}
实际上等同于:
static void Main()
{
MainForm mf = new MainForm();
Application.Run(mf);
}
那么,上面那个bytecode,是如何被翻译成上述代码的?
哦,bytecode的第一个字符,就是73。有一个神奇的表格,其中一行:
73 newobj <Method> N arguments o
我们看到了,73代表一个东西叫做newobj,并且,它是一个method。我们应该能猜测出来,C#代码中应该就是一个new关键字。
第二个数字01,我们还是查找那个表格:
01 break - - -
哦,怎么是break呢?我们代码里面,不大可能new了一个对象之后,立刻就break啊?实际上,第一句newobj之后,执行的代码是从0x05,就是0x28开始(第二句) 。为什么跳跃了5个字节呢?因为IL中,并不只是包含operator,还包含了其他数据。在CLR解析过程中,它发现0x73是一个method之后,会继续取得一个所谓的metadataToken。伪代码如下:
metadataToken = ReadInt32(il, ref position);
而ReadInt32代码,如下所示:
private int ReadInt32(byte[] _il, ref int position)
{
return (((il[position++] | (il[position++] << 8)) | (il[position++] << 0x10)) | (il[position++] << 0x18));
}
为什么会这么做???
暂且不表,我们继续。通过上面的ReadInt32,position增加了4,变成了5。所以要从bytecode第0个字节跳跃5个,直奔0x28。通过查表,我们知道,0x28代表着一个call:
28 call <Method> N arguments Ret.value。通过某种手段,我们可以得到当前0x28的call的方法名,是run。
那么首先,那个神奇的表格是什么呢?就是一个二维信息,从0x00到0xFE,每个字节分别对应着某个操作,如br,call,newobj等。这个表格,可以从《Inside Microsoft.NET IL Assembler eBook》中找到。
我们查表查找到operator之后,通过一系列的Read*方法,得到metadatatoken。针对这个token,分别进行resolve,得到最后的operand。如上所述,通过Read*系列方法,我们同时移动了bytecode中的offset,可以定位到正确的下一个operator。
这段解析代码,可以到codeproject上查找SDILReader,里面的Globals.cs、ILInstruction.cs、MethodBodyReader.cs,分别对应着全局operators、IL构造、方法转换等内容。
龟速查询
阻塞和索引问题,是常见的导致sql以龟速执行的罪魁。
阻塞
阻塞主要等待逻辑锁,如请求一个X锁。关于锁的信息,遍地都是,msdn或者google都可以。SQL Server 2005提供了125中等待类型(2000是76种)。
假设我们sp_who看到了一个block在56号上,那么通过这个可以看到详细信息
select * from sys.dm_os_waiting_tasks where session_id=56
(在2000下,你可以通过dbcc inputbuffer(56)来看当前执行的文本)
0x022A8898 56 0 1103500 LCK_M_S 0x03696820 0x022A8D48 53 NULL ridlock fileid=1 pageid=143 dbid=9 id=lock3667d00 mode=X associatedObjectId=72057594038321152
这里显示,56被53阻塞,并且等待了1103500毫秒了。
通过使用sys.dm_tran_locks,我们可以看到56被53以X模式锁住了,53持有1:143:3这个资源。
select request_session_id as spid, resource_type as rt, resource_database_id as rdb, (case resource_type WHEN 'OBJECT' then object_name(resource_associated_entity_id) WHEN 'DATABASE' then ' ' ELSE (select object_name(object_id) from sys.partitions where obt_id=resource_associated_entity_id) END) as objname, resource_description as rd, request_mode as rm, request_status as rs from sys.dm_tran_locks
输出如下
spid rt rdb objname rd rm rs
-----------------------------------------------------------------------------
56 DATABASE 9 S GRANT
53 DATABASE 9 S GRANT
56 PAGE 9 t_lock 1:143 IS GRANT
53 PAGE 9 t_lock 1:143 IX GRANT
53 PAGE 9 t_lock 1:153 IX GRANT
56 OBJECT 9 t_lock IS GRANT
53 OBJECT 9 t_lock IX GRANT
53 KEY 9 t_lock (a400c34cb X GRANT
53 RID 9 t_lock 1:143:3 X GRANT
56 RID 9 t_lock 1:143:3 S WAIT
而在SQL Server 2000里面,可以从sysprocesses看到。
select * from master..sysprocesses where blocked <> 0.
更详细的阻塞信息
2005中提供了一个新的DMV:Sys.dm_db_index_operational_stats,它提供了针对每个表、索引、分区的详细阻塞情况,如:访问历史、锁、阻塞、waits等。详细信息如下:
· 页/行等持有锁的个数
· 页/行等锁或waits的个数
· 页/行等锁或waits的时间
· 页闩的waits个数(闩与hotspot,就是所谓的热点有关,下同)
· 页闩的waits时间
· 页I/O闩的waits时间
除了阻塞的信息,还有一些索引的信息。
· 访问方式,如某个range,或者lookup
· 在叶子层的插入/更新/修改
· 叶子层之上的插入/更新/修改,就是索引维护。每个叶子页面的第一行,指向了该层的上一层。假如说在叶子上分配了一个新页面,那么上面那层的页面就包含一个指向该层第一行的指针信息。
在原文的附录B中,包含了一系列的索引信息相关的存储过程。下面是使用该sp的步骤
1. 使用init_index_operational_stats来初始化indexstats表
2. 使用insert_indexstats建立一个基线
3. 运行你的负载
4. 到合时的实际,使用insert_indexstats捕获索引状态的快照
5. 跑get_indexstats来分析索引状态。诸如很高的阻塞或者很高的waits,基本可以表明索引有问题。
这里列出了一些使用上述sp的例子。
· 所有数据库中,使用最多的前5个索引
exec get_indexstats @dbid=-1, @top='top 5', @columns='index, usage', @order='index usage'
· 锁增长最多的前5个索引
exec get_indexstats @dbid=-1, @top='top 5', @order='index lock promotions', @threshold='[index lock promotion attempts] > 0'
· 递减模式,前5个最大的行锁waits时间的索引状态
exec get_indexstats @dbid=-1, @top='top 5', @order='avg row lock wait ms'
· 前10个,在dbid=5的数据库中,所有阻塞率大于10%的索引状态
exec get_indexstats @dbid=-1, @top='top 10', @order='block %', @threshold='[block %] > 0.1'
注:sql2000没有提供任何关于对象或者索引使用状态
监视索引使用情况
2005中提供了一个非常有用的DMV:sys.dm_db_index_usage_stats,通过它我们可以找到哪些索引正在被当前query使用,或者没被使用。注意的是,这些数据仅保留在内存中,并没有被持久化存储。所以,如果sql发生down机了,这些数据就都丢掉了。当然,我们可以把这些save到表中,供日后分析。
索引上的操作分为两种:用户方式和系统方式。一个索引,通过dbid、对象id和索引id三列信息唯一标示。索引id为0的时候,代表一个heap table;1的时候,聚集索引;大于1的时候,非聚集索引。
2005下,seek/scan/lookup的规则与定义如下:
· SEEK: 使用B-tree结构访问数据的次数。
· SCAN: 不使用B-tree结构访问数据的次数。
· LOOKUP: 使用不合适的非聚集索引配合聚集索引来寻找数据,如2000中的书签查找。
下面这个DMV可以得到“当前”所有数据库所有对象的索引状态。
select object_id, index_id, user_seeks, user_scans, user_lookups from sys.dm_db_index_usage_stats order by object_id, index_id
假设是下面的结果
object_id index_id user_seeks user_scans user_lookups
------------ ------------- -------------- -------------- ----------- ------
521690298 1 0 251 123
521690298 2 123 0 0
该结果表明,有251次的聚集索引scan,123次的书签查找,123次的非聚集索引seek。
如果想知道从上次sql启动之后,到现在为止,某个表中没有被使用过的索引状况,执行下面的sql。
select i.name from sys.indexes i where i.object_id=object_id('<table_name>') and i.index_id NOT IN (select s.index_id from sys.dm_db_index_usage_stats s where s.object_id=i.object_id and i.index_id=s.index_id and database_id = <dbid> )
所有未被使用的索引:
select object_name(object_id), i.name from sys.indexes i where i.index_id NOT IN (select s.index_id from sys.dm_db_index_usage_stats s where s.object_id=i.object_id and i.index_id=s.index_id and database_id = <dbid> ) order by object_name(object_id) asc
结束了
原文后面有N多的sp,大家可以参考原文,在你的sql2005上跑一次。当然,能够在客户的生产环境中,用这些sp进行实际测试,会得到更好的体会。
我个人认为,更好的利用这些DMVs和sp的前提是,对于sql的基本概念要有所了解。索引、锁、阻塞、死锁等,为什么会产生,他们在SqlServer这种数据库下面是如何处理的,等等。否则,看着那些DMVs,很容易发懵。
TempDB
每个实例只有一个tempdb,所以这里很可能成为性能或者磁盘空间的瓶颈。
常见的tempdb问题如下:
· 把磁盘空间用光了
· 因为tempdb的瓶颈,导致I/O很差。参见第一部分。
· DDL带来的对系统表的瓶颈
· 内容分配
诊断问题之前,先看看tempdb是如何利用空间的。
用户对象
· 表和索引
· 全局临时表 (##t1)和索引
· 局部临时表和索引(#t1) and index.
· 当前连接的
· 存储过程内的
· 表变量(同上)
内部对象
· Work file (hash join)
· Sort run
· Work table (cursor, spool和临时大对象)
版本存储
2005新增的
空闲空间
tempdb暂时没有用到的磁盘剩余空间.
整个tempdb就是上述4个东西的和。
监视tempdb剩余空间很简单,监测这个指标即可。Free Space in tempdb (KB)。下面这个DMVs很强大的说,上面四个都能看到。
Select SUM (user_object_reserved_page_count)*8 as user_objects_kb, SUM (internal_object_reserved_page_count)*8 as internal_objects_kb, SUM (version_store_reserved_page_count)*8 as version_store_kb, SUM (unallocated_extent_page_count)*8 as freespace_kb From sys.dm_db_file_space_usage Where database_id = 2
这是一个输出结果(kb表示的)
user_objets_kb internal_objects_kb version_store_kb freespace_kb
---------------- -------------------- ------------------ ------------
8736 128 64 448
分析空间使用问题
用户对象
跑这个,能看出来到底谁干的。
DECLARE userobj_cursor CURSOR FOR
select sys.schemas.name + '.' + sys.objects.name from sys.objects, sys.schemas where object_id > 100 and type_desc = 'USER_TABLE'and sys.objects.schema_id = sys.schemas.schema_id
go
open userobj_cursor
go
declare @name varchar(256)
fetch userobj_cursor into @name
while (@@FETCH_STATUS = 0)
begin
exec sp_spaceused @objname = @name
fetch userobj_cursor into @name
end
close userobj_cursor
版本存储
select top 2 transaction_id, transaction_sequence_num, elapsed_time_seconds from sys.dm_tran_active_snapshot_database_transactions order by elapsed_time_seconds DESC
这里显示一个带有XSN3的事务(ID是8609),已经激活了6523秒。
transaction_id transaction_sequence_num elapsed_time_seconds
-------------------- ------------------------ --------------------
8609 3 6523
20156 25 783
Kill掉第一个trans,我们可以释放iding数量的version store。但是,没有办法能够估计出来,kill掉之后,究竟能释放多少。
内部对象
SQL Server 2005提供了两个DMVs: sys.dm_db_session_space_usage和 asys.dm_db_task_space_usage,用以跟踪sessions和tasks在tempdb中的空间变化。
select session_id, internal_objects_alloc_page_count, internal_objects_dealloc_page_count from sys.dm_db_session_space_usage order by internal_objects_alloc_page_count DESC
再如这个
SELECT t1.session_id, (t1.internal_objects_alloc_page_count + task_alloc) as allocated, (t1.internal_objects_dealloc_page_count + task_dealloc) as deallocated from sys.dm_db_session_space_usage as t1, (select session_id, sum(internal_objects_alloc_page_count) as task_alloc, sum (internal_objects_dealloc_page_count) as task_dealloc from sys.dm_db_task_space_usage group by session_id) as t2 where t1.session_id = t2.session_id and t1.session_id >50 order by allocated DESC
这里一个示例输出
session_id allocated deallocated
---------- -------------------- --------------------
52 5120 5136
51 16 0
对于tasks,可以执行下面的sql
select t1.session_id, t1.request_id, t1.task_alloc, t1.task_dealloc, t2.sql_handle, t2.statement_start_offset, t2.statement_end_offset, t2.plan_handle from (Select session_id, request_id, sum(internal_objects_alloc_page_count) as task_alloc, sum (internal_objects_dealloc_page_count) as task_dealloc from sys.dm_db_task_space_usage group by session_id, request_id) as t1, sys.dm_exec_requests as t2 where t1.session_id = t2.session_id and (t1.request_id = t2.request_id) order by t1.task_alloc DESC
session_id request_id task_alloc task_dealloc
---------------------------------------------------------
52 0 1024 1024
sql_handle statement_start_offset
----------------------------------------------------------------------- 0x02000000D490961BDD2A8BE3B0FB81ED67655EFEEB360172 356
statement_end_offset plan_handle
---------------------------------
-1 0x06000500D490961BA8C19503000000000000000000000000
然后通过sql_handle和plan_handle,就可以得到sql的语句
select text from sys.dm_exec_sql_text(@sql_handle)
select * from sys.dm_exec_query_plan(@plan_handle)
(第三部分,介绍大家最关心的sql调优)
名次解释
DMVs:dynamic management views
三个点
· 资源瓶颈: CPU、内存、I/O(这里面不考虑网络问题)
· Tempdb瓶颈:
· User query瓶颈,可能是统计信息的变化、不恰当的索引、阻塞或者死锁等
上述三点,可能是相互影响的。
资源瓶颈
工具
1. System Monitor (PerfMon):windows自带
2. SQL Server Profiler: 2005继续有
3. DBCC commands: 参考联机文档
4. DMVs: 见上名次解释
CPU瓶颈
CPU瓶颈,是突然并且不可预料的。一般来讲,没有优化的查询计划、系统低配置、设计不合理等,很容易导致这些问题。
在perfmon中,我们一般需要监视Processor:% Processor Time,如果每个CPU持续高于80%,CPU就是瓶颈了。当然,在强大的2005下我们也可监视sys.dm_os_schedulers ,如果有内容,表明有任务等待CPU来分配给它。如下面这个DMVs的查询:
select scheduler_id,current_tasks_count,runnable_tasks_count from sys.dm_os_schedulers where scheduler_id < 255
下面的查询,更高级点。分析方法是,看结果的number_of_statements,如果该值大于1,说明可能有问题,要进一步分析。
select top 50 sum(qs.total_worker_time) as total_cpu_time, sum(qs.execution_count) as total_execution_count,count(*) as number_of_statements, qs.plan_handle from sys.dm_exec_query_stats qs group by qs.plan_handle order by sum(qs.total_worker_time) desc
执行计划的编译与重新编译
在sql2005中的一个改进,就是对于某个sp,进行recompile的时候,只需要针对改变的部分进行编译,sql2000只能是全部都搞一遍。
Recompile的原因很多,如:
· Schema的变更 changed
· Statistics变更
· 延迟编译
· SET option的执行
· 临时表的变化
· Sp使用了RECOMPILE提示或者使用了OPTION (RECOMPILE)
诊断方法,老朋友了,继续使用perfmon或者sql profiler。
对于perfmon,监视下面的 计数器
· SQL Server: SQL Statistics: Batch Requests/sec
· SQL Server: SQL Statistics: SQL Compilations/sec
· SQL Server: SQL Statistics: SQL Recompilations/sec
对于profiler抓到的trace,分析这几个event:SP:Recompile / SQL:StmtRecompile / Showplan XML For Query Compile。如果我们抓到了trace,对于文件,可以这么做:
select spid,StartTime,Textdata,EventSubclass,ObjectID,SQLHandle from fn_trace_gettable ( 'e:\recompiletrace.trc' , 1) where EventClass in(37,75,166)
这里面,EventClass 37 = Sp:Recompile, 75 = CursorRecompile, 166=SQL:StmtRecompile
如果你事先保存到了 table jq中,那么把上面的from修改为from jq即可。
或者使用这个DMVs: sys.dm_exec_query_optimizer_info(注意一个技巧!多执行几次,看中间的差异)
select * from sys.dm_exec_query_optimizer_info
另外一个DMVs是:sys.dm_exec_query_stats,如执行这个sql:
select * from sys.dm_exec_query_stats CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS s2
另外, plan_generation_num标示出了被recompile的所有query。如下面这个
select top 25 sql_text.text,sql_handle,plan_generation_num, execution_count,dbid,objectid from sys.dm_exec_query_stats a cross apply sys.dm_exec_sql_text(sql_handle) as sql_text where plan_generation_num >1 order by plan_generation_num desc
解决办法
· 如果因为使用了Set option,那么通过profiler来观察是什么引起的变化。
· 如果因为临时表,那么尽量使用表变量,而不是临时表。(对于表变量的限制,请查看联机文档)另一个解决办法,使用KEEP PLAN查询提示,这会把临时表当作普通表一样对待,会进行statistics的跟踪
· 关闭对于索引或者索引视图上的状态自动更新(偶个人不建议)
· 对象名称写全了,如dbo.Table1
· 尽量少用延迟编译。如你的SP或者query里面,有N多的if/else之类的。
· 运行索引调优向导(sql2000里面就有)
· 看看sp是不是使用了WITH RECOMPILE来建立的,或者RECOMPILE查询提示。
弱智的查询计划
每个查询执行之前,sqlserver都会“试图”优化一个最快的查询计划出来。注意的是,这里的最快的,不代表I/O最小,也不代表CPU占用最小。它是一个权衡后的值。
对于Hash join或者sort等,它们都是与CPU密切相关的。对于nested loop,很可能会因为大量的index lookups,导致I/O迅速上涨。如果search的数据散落在各个pages里面,很可能会导致缓冲命中率下降。
诊断方法
使用这个DMVs: sys.dm_exec_query_stats,它可以有效地监视CPU的使用情况。
select highest_cpu_queries.plan_handle, highest_cpu_queries.total_worker_time,q.dbid,q.objectid,q.number,q.encrypted,q.[text] from (select top 50 qs.plan_handle, qs.total_worker_time from sys.dm_exec_query_stats qs order by qs.total_worker_time desc) as highest_cpu_queries cross apply sys.dm_exec_sql_text(plan_handle) as q order by highest_cpu_queries.total_worker_time desc
解决办法
· 使用优化向导调优
· 检查一下,WHERE条件是不是限制的足够好?
游标问题
强烈建议,尽量减少使用游标。可以使用perfmon监视SQL Server:Cursor Manager By Type – Cursor Requests/Sec。或者使用DMVs:
select cur.* from sys.dm_exec_connections con cross apply sys.dm_exec_cursors(con.session_id) as cur where cur.fetch_buffer_size = 1 and cur.properties LIKE 'API%'
如果使用profiler,可以监视sp_cursorfetch(前提是包含了RPC:Completed这个event class)
内存瓶颈
对于VAS和AWE概念,请自行查找MSDN。我印象中,M$的人强烈建议不要在32bit windows上面使用AWE或者3BG之类的东西。
检测内存问题
打开taskmgr看物理内存中的Avaiable,如果持续低于10M,恭喜你,系统内存压力太大!通过perfmon,监视Memory: Available Mbytes,一样的效果。
对于AWE使用,可以用这个DMVs来看:
select sum(awe_allocated_kb) / 1024 as [AWE allocated, Mb] from sys.dm_os_memory_clerks
对于虚拟内存等,可以观察Commit Charge中的Total,与limit的对比。如果两者很接近,虚拟内存可能不够了。如果你好奇,想看看sqlserver自己的内存分配,可以执行DBCC MEMORYSTATUS。具体内容,见联机文档。
对于内存问题,偶认为采用sql的默认设置,一般情况下足够了。
I/O瓶颈
除非操作系统能够,并且内存足够大,把你的db放到物理内存里,否则,I/O我们永远回避不过去。使用perfmon的话,可以监视
· PhysicalDisk Object: Avg. Disk Queue Length,如果经常性的大于2*磁盘个数,磁盘有性能问题。
· Avg. Disk Sec/Read,如果<10ms,很好。20以下,一般。50以下,密切观察。50以上,换硬盘吧!
· Avg. Disk Sec/Write,这个和上面的两个值,如果持续大于物理磁盘的指标的85%,说明磁盘已经到极限了。
· Physical Disk: %Disk Time,一般如果超过50%,I/O有瓶颈。
如果用了raid,采用下面这个公式来计算:
Raid 0 -- I/Os per disk = (reads + writes) / number of disks
Raid 1 -- I/Os per disk = [reads + (2 * writes)] / 2
Raid 5 -- I/Os per disk = [reads + (4 * writes)] / number of disks
Raid 10 -- I/Os per disk = [reads + (2 * writes)] / number of disks
如下面这个例子,2个磁盘,raid1,监测到的结果:
Disk Reads/sec 80
Disk Writes/sec 70
Avg. Disk Queue Length 5
那么I/O平均是80/2+70=110,队列长度上限是2*2=4
解决办法
· 检查sqlserver的内存配置
· 增加或者替换更快的硬盘,读写缓存越高越好
· 检查执行计划,找到I/O大的地方。如这个DMVs
select top 50 (total_logical_reads/execution_count) as avg_logical_reads, (total_logical_writes/execution_count) as avg_logical_writes, (total_physical_reads/execution_count) as avg_phys_reads, Execution_count, statement_start_offset as stmt_start_offset, sql_handle, s2.text plan_handle from sys.dm_exec_query_stats cross APPLY sys.dm_exec_sql_text(sql_handle) AS s2 order by (total_logical_reads + total_logical_writes) Desc
小TIP,如果要清除缓存的作用,执行这个:
checkpoint
dbcc freeproccache
dbcc dropcleanbuffers
(第二部分,介绍tempdb的优化)
(原文地址,点这里)
vista ultimate版本,sql2005,没有任何sp。安装后,连接本地实例,无论windows Authentication还是sqlserver authentication,都提示18456错误。
解决办法如下:
- 用admin或者run as administrator方式,运行sql mgr studio
- 展开security结点,到login,new login,在general里面起一个你自己的账户名字,假如叫juqiang,密码设置上。(注意!同时要把password的policy和expiration这两个东西uncheck掉)。然后到server rols里面,把sysadmin钩上。
- 没有了。
环境是Vistal ultimate+IE7,最近上csdn或者news.sina.com.cn,打开N个窗口后,IE突然就崩溃了,然后自动重新启动,甚是郁闷。
于是打开adplus,抓之:
adplus -crash -pn iexplore.exe -o d:\dumps
到了CSDN社区,看了两个帖子,哈哈,adplus开始create dump了。一会功夫,一共抓到了三个,分别是1st Chance AV mini,1st Chance Proc Shutdown,2nd Chance AV。
打开三个dump,1st Proc Shudown里面啥都没有,直接ret了,打开另外两个AV的。哦,看到东西了。
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(ff0.158): Access violation - code c0000005 (first/second chance not available)
eax=6ee500c2 ebx=00000000 ecx=0a10ef08 edx=0a10ef14 esi=1000ea7c edi=0782d1c0
eip=8bffdb10 esp=0a10eeec ebp=0a10ef0c iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00010246
8bffdb10 ?? ???
kb一下之后,看到这些:
0:019> kb 2000
ChildEBP RetAddr Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
0a10eee8 10003e1f 0782d1c0 1000ea7c 0a10ef08 0x8bffdb10
0a10ef0c 10003d46 0a94edc8 0a10f108 00dabd80 Jccatch!DllGetClassObject+0x28fc
0a10ef2c 100034c0 0a880d20 00dabd88 0a10f014 Jccatch!DllGetClassObject+0x2823
0a10ef60 705fecc2 0a880d20 00000103 70622ff4 Jccatch!DllGetClassObject+0x1f9d
0a10ef94 70624095 00dabd88 0a10f014 0a10f014 ieframe!EnumInvokeCallback+0x3c
0a10efb8 7062401a 00dabd88 0a10eff0 70623004 ieframe!EnumConnectionPointSinks+0x6c
0a10f004 70624af7 00122a84 0a10f014 00000003 ieframe!IConnectionPoint_InvokeIndirect+0x80
0a10f044 70624b7f 00122a84 00000103 0a10f108 ieframe!IConnectionPoint_InvokeWithCancel+0x3a
0a10f11c 70625069 0a905af0 00122a84 00000000 ieframe!DoInvokeParamHelper+0x8b
0a10f174 705f43d3 0a905af0 0a905af0 039cf310 ieframe!FireEvent_DocumentComplete+0xc2
0a10f194 705f4348 059c2620 039cf310 0a850bc0 ieframe!CBaseBrowser2::_FireDocumentComplete+0x46
0a10f1bc 6ebb8381 059c267c 0a850bc0 00000002 ieframe!CBaseBrowser2::FireDocumentComplete+0x52
0a10f1f0 6ebb3e49 00000000 0a9558ec 6ec05988 mshtml!CWebOCEvents::DocumentComplete+0x102
0a10f260 6eba036d 0a94edc8 0a94edd8 07800168 mshtml!CMarkup::OnLoadStatusDone+0x248
0a10f274 6ebb82ea 00000004 0a10f6f4 0000009d mshtml!CMarkup::OnLoadStatus+0x4c
0a10f6bc 6ebefdd7 0a62b500 00000000 0a10f700 mshtml!CProgSink::DoUpdate+0x533
0a10f6cc 6ec07a4a 0a62b500 0a62b500 00000000 mshtml!CProgSink::OnMethodCall+0xf
0a10f700 6ec014f2 0a10f79c 00008002 00000000 mshtml!GlobalWndOnMethodCall+0x101
0a10f720 75e81a10 0009066c 00000e5e 00000000 mshtml!GlobalWndProc+0x181
0a10f74c 75e81ae8 6ec01441 0009066c 00008002 user32!InternalCallWinProc+0x23
0a10f7c4 75e82a47 000b02c4 6ec01441 0009066c user32!UserCallWinProcCheckWow+0x14b
0a10f828 75e82a98 6ec01441 00000000 0a10f8a0 user32!DispatchMessageWorker+0x322
0a10f838 705fe5db 0a10f850 00000000 00000000 user32!DispatchMessageW+0xf
0a10f8a0 77303833 07753a58 0a10f8ec 775da9bd ieframe!CTabWindow::_TabWindowThreadProc+0x189
0a10f8ac 775da9bd 07618580 0a10680a 00000000 kernel32!BaseThreadInitThunk+0xe
0a10f8ec 00000000 705fe3a4 07618580 00000000 ntdll!_RtlUserThreadStart+0x23
ooh,jccatch!于是打开IE,tools-Managed Addin,看到了jccatch正在enabled。disable之后,貌似没有问题了。继续观察之………………(jccatch是jetcar就是网际快车的东西)
某个牛人说过,即使啥也不懂,用windbg也能看到系统的哪个dll出错了,:)
GC的几个误区,需要注意的地方(节选自偶从前写的《浅谈GC》)
说明:对于下面提到的“上一部分”、“第一部分”等,是整篇文章的前部分,我这里面只放了后面的编程注意事项。
1.1 万物皆可被回收
GC针对的仅仅是托管资源,对于非托管资源,GC不负责、也无法对其进行回收。对于File Handle、Mutex、Network Handle、Database Connection、Socket、GDI Object(如Brush、Font、Icon),调用者需要自己手动进行处理。究其根本原因在于,CLR无法识别这些非托管资源的正确类型,无法知道该如何对资源进行释放(虽然CLR可以跟踪到这些资源的生命周期)。而对于托管资源,Metadata(元数据),则给CLR提供了正确的对象引用信息以及释放资源的方法,这是GC算法的一个重要依据。
根据上面非托管对象回收的介绍,我们知道,只有提供了Finalize方法的对象,才可以被GC回收掉。否则,会造成内存泄漏。
1.2 手动垃圾回收可以提高性能
我们经常会看到手动垃圾回收在代码中的调用,如下面这段例子:
private void SomeCloseFunction( ){
// Some Close Function
GC.Collect();
// 或者如下调用代码:
GC.Collect(1);// 对generation 1进行回收
}
上述代码的目的是为了清理内存,提高程序的运行效率。但是事与愿违,绝大多数情况下,我们的代码会变慢,或者变得根本无法使用。原因如下:
- GC在Collect的时候,CLR会挂起当前正在运行的所有线程。
- GC会对generation 0/1/2所有的对象进行回收,这可能是一个非常耗时的工作。
- 如果GC.Collect在你的某个被调用频度很高的核心代码中,如数据库连接的关闭、某个字符串处理方法,频繁回收,将导致其他应用无法得到CPU的控制权,产生严重的性能问题。
这里面的根本原则就是,CLR知道何时进行GC,GC的最佳时机是CLR根据操作系统的运行状况动态决定的。当然,如果我们的代码中对于非托管资源有很多的占用,如一个GDI的应用,那么可以在应用程序关闭或者GDI处理完毕的时候,进行一次GC.Collect的调用。
1.3 Finalize会快速并准确地回收对象
Finalize方法在C#中无法被重写,取而代之的是一个非常容易让我们混淆的C++析构函数的写法,~SomeClassName()。在C++中,析构函数我们可以认为是一种确定性行为,对象的生命周期结束后,析构函数将立刻被调用。而在C#(或者其他的支持CLR的语言)中,由于GC的不确定性,上述析构方法被调用的时机我们无法确定。
第一部分我们讲过,只有对于非托管资源,我们才需要对其进行手动回收处理。常见的代码可能是这样:
private SomeUnmangedType sut;
private void MyClass( ){
sut = CreateSomeUnmanagedType();
sut.DoSomeThing();
}
~MyClass(){
sut.CloseSomeUnmanagedType();
}
对于非托管资源,一般来讲,上述的代码是正确的。如果我们用ildasm看这段代码的IL code,我们会发现代码实际上是类似于下面的样子:
~MyClass(){
try{
sut.CloseSomeUnmanagedType();
}
finally{
base.Finalize();
}
}
try/ finally对,是C#编译器自动生成的代码。在finally中,自动增加了对于base的Finalize方法的调用。
而对于托管资源,我们有N多的理由来反对使用Finalize方法:
- Finalize的被调用,是我们不能控制的,是由CLR决定的。
- 所有重写了Finalize方法的对象以及相关引用对象,在垃圾回收的时候,代龄可能会提高,增加不必要的内存负担。
- 所有重写了Finalize方法的对象,CLR会额外的建立一个链表来对其进行维护,GC将进行至少两次才能真正的释放对象。
- 致命的一点是,对于托管资源对象,如Database Connection,如果我们在Finalize方法中对其进行了Close的调用,那么将会发生不可预知的错误,根本原因就在于对于FReachable Queue的特殊线程处理,CLR不保证Finalize方法的执行顺序。如A包含了一个对于B的引用,那么A或者B的Finalize调用顺序是不可预知的。对此问题,可以参考如下的MSDN链接:http://msdn.microsoft.com/library/default.asp?url=/library/en-us/cpref/html/frlrfsystemdatasqlclientsqlconnectionclassclosetopic.asp
为了解决此问题,我们可以采用Dispose模式,即需要实现IDisposable接口。在C#中,也可以方便的使用using语法。对于Dispose模式,可以参考如下的MSDN示例:
class X: IDisposable{
public X(?…){
… initialize resources …
}
~X(){
?… release resources ?…
}
public void Dispose(){
// this is the same as calling ~X()
Finalize();
// no need to finalize later
System.GC.SuppressFinalize(this);
}
};
对于GC更多的资源,请参见MSDN相关文章:http://msdn.microsoft.com/library/default.asp?url=/library/en-us/cpguide/html/cpconProgrammingEssentialsForGarbageCollection.asp
1.4对于COM+之类的Wrapper会自动管理内存生命周期
首先需要澄清的是,COM+ Application或者COM+ Library,是长时间(如24*7)的run在客户的Server上的。只要24*7有组件不停的被调用,那么该Application或者Library就不会被自动释放或回收。
所以,虽然.NET提供了对于COM+的wrapper,我们仍需要手工的再作一些工作。
错误的代码示例如下:
MyComplusComponent mcc = new MyComplusComponent();
mcc.CallSomeFunction();
mcc = null;
这段代码之所以错误,是因为仅仅释放了mcc这个wrapper,而该对象本身的Reference却没有被release,导致该mcc所指向的Complus Compoent一直存在。修正代码如下:
MyComplusComponent mcc = new MyComplusComponent();
mcc.CallSomeFunction();
System.Runtime.InteropServices.Marshal.ReleaseComObject(mcc);//这句对于reference进行了-1的操作。
mcc = null;
总结一下就是说,OS自己能做的,CLR自己能做的,我们不要干预。尤其是对于Wrapper之类的东西,一定要小心谨慎。
SqlServer的性能问题,也是窗户纸,让偶道来!
先考虑一个问题,怎么判断SQL的执行效率是好是坏?也许,95%的人会回答,看执行时间。
错!
为什么?因为在一个稳定的DB中(稳定这个词,我是这样定义的:某个时间段内,如1周,大部分被SQL缓存的数据是几乎不变的,这意味着客户这段时间内的操作模式、数据变化,是平稳的),同样的sql执行,可能会因为缓存的变化,导致时间变化无常,或者因为一些诸如hot spot,也会导致这个问题。
既然要tuning,就要有一个调优的标准。标准是什么呢?最主要的,看I/O。
在一个稳定的DB中,执行同样的SQL,I/O基本是不变化的。同样的内存配置,你的台式机,客户的高级server,产生的I/O相差不大的。I/O分为两种,逻辑的,从内存读写;物理的,从磁盘读写。
SQL调优的最终目的,就是大幅度的降低I/O大小,减少阻塞,避免死锁。
有了这个目标之后,就可以开始干活了!
首先打开sql analysis(查询分析器),用sa连接到你的数据库,执行
dbcc traceon(1204,3605,-1),这一句保证任何的死锁信息都会被记录在sql log中。
然后打开sql profiler(事件探查器),在业务高峰期开始,抓里面的sql completed和sp completed,持续2-4个小时(看客户的实际情况而定)。
然后把profiler里面的数据save as到一个table中,加入叫做:jq(偶名字的缩写)。好,到此,成功1/3了!
再次打开查询分析器,执行类似的这条sql:
Select textdata, reads, duration from jq order by reads desc
这会把所有抓到的sql按照I/O从大到小的顺序排列,睁大你的眼睛,找出来那些I/O最大的,执行最频繁的sql,copy出来,在查询分析器的另一个窗口中,粘贴上。
哦,先不要急着Ctrl+E,要先执行这个语句!
Set statistics io on
然后按一下Ctrl+K(打开执行计划)
好了,执行你从jq里面抓到的那个最大的sql吧!仔细分析下面的执行计划,仔细看output中每个表的I/O。分析为什么index的走向不是你所期望的,分析为什么这么多nested loops,分析为什么有大量的worktable?等等,等等。
上面是对于普通sql调优的办法。而对于阻塞,可以参考msdn的文章,kbid是271509。
对于死锁,刚才说过了,只要dbcc traceon(1204,3605,-1)执行后,所有的deadlock都会记录在sql log中。这个日志,纯文本文件,一般会列举出,至少两个对象的当前状态。常见的,如:
KEY: 8:1653632984:2 (da00ce043a9e) CleanCnt:1 Mode: U Fl ags: 0x0
KEY: 8:1653632984:1 (2d018af70d80) CleanCnt:1 Mode: X Flags: 0x0
通过察看sysobjects中ID,和index,我们可以找到对应的deadlock的table,通过分析执行计划,我们可以看出死锁发生的原因。具体内容,参考msdn文章,KBID是832524。
补充一下,GTEC也作SQL的case,虽然收费不菲,哈哈!
(注,连续三篇随笔介绍的情况和方法,同样适用于Vista/SqlServer 2005等最新MS产品)
要想解决上文提到的几种常见情况,首先,代码开发人员都要提供相应的dll的symbols。什么叫symbols?就是符号表!有了它,我们可以根据dump,确切的看到问题代码的所处位置:源文件名、方法名、行号等。对于VC++和.NET程序,symbols就是后缀为.PDB的那个文件,对于Borland系列的,需要build出来一个.map文件,然后通过Map2Dbg来生成.DBG文件。
这是我们自己的symbols,其实,微软各种产品也有symbols。一部分叫做public的,一部分叫做private的。对于后者,我们拿不到。
symbols准备好了之后,还要下载一个工具,叫做windbg。下载地址,你可以到google.cn上search:debugging tools for windows,安装就可以了。
有了这两样,我们就可以开始干活了!
对于Memory Leak,发现现象之后,分析哪里产生了泄漏,这是一个很难的任务。这里推荐几款工具和文章:
l XiongLi的blog,http://www.cnblogs.com/lixiong。 这是GTEC的大牛,偶的哥们+偶像。
l UMDH工具,安装好上面的windbg,你会在同一个目录下发现这个文件。具体用法,看上面的blog。
l Debug Diag工具,在google中搜索:IIS Diagnostics,到msdn上下载即可。
尤其是debug diag,使用非常简单。你用它抓到dump之后,可以自动进行分析,产生格式友好的html文件。UMDH也可以分析,不过使用起来有些罗嗦。
对于CPU使用占100%的情况,解决办法是,restart出问题的进程,打开taskmgr,选择该进程,眼睛盯着该进程的CPU变化(注意!眼睛不要眨!!!)。如果CPU持续达到85%以上(经常是100%居多),好,这时候利用上面提到的windbg,打开命令行,运行
adplus –hang –p 1234 –o c:\dumps
具体参数,可以运行adplus来看帮助。
抓好dump之后,可以用debugdiag来分析,也可以用windbg来分析。如果你想锻炼一下windbg的使用,可以按照如下操作来做:
.load clr10\sos.dll
!runaway
敲完这两个命令后,看输出的前几行,记录下来thread id。然后分别用kb来察看,把其中的代码都复制到你的notepad里面。
Ok,等一段时间(你自己决定长短),如果该进程CPU还是持续100%,按照上面步骤,继续抓。这样抓好3组后,通过!runaway命令,看占用CPU最高的thread的call stack。如果内容都类似,说明我们抓到了导致hang的代码。下面的工作就是分析这些call stack了。
对于hang,还有一种情况,就是CPU和Memory都很低,但是客户端执行就是没有反映。这里举一个我们自己项目的例子:
0x4bc8f458 0x77f88f03 [FRAME: ECallMethodFrame] [DEFAULT] I4 System.Threading.WaitHandle.WaitMultiple(SZArray Class System.Threading.WaitHandle,I4,Boolean,Boolean)
0x4bc8f470 0x26547659 [DEFAULT] I4 System.Threading.WaitHandle.WaitAny(SZArray Class System.Threading.WaitHandle,I4,Boolean)
0x4bc8f484 0x26385470 [DEFAULT] [hasThis] Class System.Data.SqlClient.SqlInternalConnection System.Data.SqlClient.ConnectionPool.GetConnection(ByRef Boolean)
0x4bc8f4b8 0x2758fbad [DEFAULT] Class System.Data.SqlClient.SqlInternalConnection System.Data.SqlClient.SqlConnectionPoolManager.GetPooledConnection(Class System.Data.SqlClient.SqlConnectionString,ByRef Boolean)
0x4bc8f4f8 0x2758f6b9 [DEFAULT] [hasThis] Void System.Data.SqlClient.SqlConnection.Open()
0x4bc8f534 0x2fdd26bc [DEFAULT] [hasThis] Void Genersoft.Focus.Db.DataBase.Open()
at [+0x7c] [+0x37]
从最下面看,那个Database.Open是我们自己的db helper,然后看最上面的红色部分,由一个WaitAny。这个call stack就是我们实际项目中发生的。
通过看中间那个红色加粗部分,我们看到了.net自己的代码,ConnPool.GetConn。通过reflector看这段代码实现,我们知道了.NET的db conn是从pool里面得到的,而pool的大小是有限的。所以,我们猜测:程序中存在着db conn没有Close或者DataReader没有Close的问题。searchi一番,果然如此。修改后,问题解决。
对于Access Violation问题(简称AV,J),我们一般也使用adplus进行抓取。命令如下:
adplus –crash –p 1234 –o c:\dumps
AV或者Crash分析起来也比较麻烦。如果想偷懒,可以用debug diag自动分析。如果自己手工作,参考上面xiong li的blog,哈哈!
这里也举一个我以前做培训时候的例子。
char a[] = "hello";
a[0] = 'X';
printf("%s",a);
char *p = "world"; // 注意p指向常量字符串
p[0] = 'X'; // 编译器不能发现该错误
printf("%s",p);
此段代码取自林锐博士的“高质量C/C++编程”,运行后会crash,我们抓了dump之后,按alt+7切换到汇编代码中,发现如下语句:
0040dcac c60058 mov byte ptr [eax],0x58 ds:0023:0042201c=77
在windbg下面运行!address 0042201c,得到如下结果:
0:000> !address 0042201c
00400000 : 00422000 - 00002000
Type 01000000 MEM_IMAGE
Protect 00000002 PAGE_READONLY
State 00001000 MEM_COMMIT
Usage RegionUsageImage
FullPath
注意上面的protect属性,该页面是只读的,所以导致了AV错误,这是真正的原因。当然,表面上的解释是,char * p = “world”,这个world存放在.data segment,不能修改。
好,讲完了,窗户纸好捅破吧?哈哈!
慢着,如果你没用这种思路来考虑过问题,你一定会看晕的。因为我写的太粗略了,太简单了!这里面涉及到的概念如此之多,涉及到的工具如此之多,经常让我们回忆起操作系统课程的N多东西。
想摆脱这种恶梦吗?找GTEC吧,上CASE,那些牛人们会解决的。
根据我的经验,上述问题几乎每个项目都会有,但是没有一个人会重视。用C++的,也许对于AV/Crash,彻底麻木了。用.NET的,对于session state、recycled等,也彻底麻木了。“很简单,重新启动机器就好了嘛!”。
是啊!这也是一个解决之道………………
(下面接着来做SQL Server的Performance Tuning,待续)
每个人都有这种经历,我们N多人辛苦作出来的软件,放到客户那里,过了一段时间,随着业务数据的增加和在线用户的增加,就开始“衰老”了。症状,典型的有几种:
1. 内存由100M疯涨到了1700M,最终要频繁重启进程或者服务器。
2. CPU狂涨到了100%,你用taskmgr眼睁睁的看着你的某个w3wp.exe站在那里居高不下。
3. 你的Button点下去之后,服务器内存很平稳,CPU一直低于5%,但是你的程序就是没有响应。
4. 客户无意中发现,event logs里面有大量的诸如aspnet_wp被recycled、某个dllhost突然访问了某个不该访问的地址。
5. ==………………………………
当我们还是少年的时候,碰到这种事情,第一件事就是问候BillG的所有女性亲属,然后手足无措的低头挨训 - 老板的抑或客户的。
这些问题,从良心上讲,基本上和BillG没关系,99.9999%的可能性,和我们自己相关。对于这种问题,我们需要的是解决思路。而解决问题的通则之一,就是对现象就行分类(能否看到本质,还说不上,呵呵)。对于上面的4种情况,我们一般归纳为几种情况:
l Memory Leak,就是内存泄漏
l Hang,某个东西挂起了
l Access Violation,访问了你不该访问的东西
那么,第一个疑问,如何把上面的N个问题,对号到这三种情况?
答案是,工具!每台Windows Server上,都有下面这几个工具:task manager、performance monitor、Event Viewer,对应的命令行分别是:taskmgr、perfmon、eventvwr。
对于上面的问题1,我们可以先用taskmgr找出有问题的进程,然后restart该进程。然后打开perfmon,建立一个log,抓取的对象是:Process。等内存涨到你忍受不了的地步的时候,stop那个log。
OK!我们再次打开perfmon,打开刚才那个log(它的尺寸应该和你的虚拟内存+物理内存大小相当),添加Process里面我们自己的那个进程,添加Private Bytes这个计数器。如果我们发现,这个值一直增长,直到最后,也没有掉下来,那么就基本可以确认为是Memory Leak的问题。
对于Performance Monitor,里面的Process/Processor/Memory/Physical Disks/Networks/System,都是我们经常要观察的。具体的含义,可以看perfmon自己的帮助。
对于上面的问题2,用taskmgr也能判断,但是taskmgr的缺点是,它是实时的,我们看不到CPU的趋势。所以,用perfmon我们可以检测Process,分析里面的几个cpu计数器。
问题3,稍微棘手一些,通过taskmgr或者performance monitor,看到的CPU和内存都很低。解决办法,后面再说。
问题4,系统的事件察看器中,有一些Dllhost发生Crash的记录,也有一些aspnet_wp被回收的记录。对于前者,我们叫做Crash,这可能是Access Violation引起的;对于后者,大部分情况是Memory Leak,或者某个杀毒软件干的事。
通过几个系统自带的工具,我们能够把客户眼中的问题,归纳到我们画的圈子中,下一步,就是要通过另外的手段,来解决它了。
(待续)
看这个代码(VC6 + sp6)
void Test( void ){
unsigned int a = 1;
int b = -2;
printf("a+b>0 is ;%s", (a+b>0)?"true":"false");
}
结果是:true。理由很简单,int会向unsigned int靠拢,得到的是一个很大的unsigned int,所以是true。隐含在后面的事什么呢?看汇编:
10: printf("a+b>0 is %s", (a+b>0)?"true":"false");
00401036 mov eax,dword ptr [ebp-4]
00401039 add eax,dword ptr [ebp-8]
0040103C test eax,eax
0040103E jbe main+39h (00401049)
00401040 mov dword ptr [ebp-0Ch],offset string "true" (00422044)
00401047 jmp main+40h (00401050)
00401049 mov dword ptr [ebp-0Ch],offset string "false" (0042203c)
00401050 mov ecx,dword ptr [ebp-0Ch]
00401053 push ecx
00401054 push offset string "a+b>0 is %s" (0042202c)
00401059 call printf (004010a0)
0040105E add esp,8
注意看上面红色的部分,此时EAX=0XFFFFFFFF,test的结果ZF=0
那么,同样的代码,我们放在.NET中来做,显示结果是相反的:false
uint a = 1;
int b = -2;
Console.WriteLine((a + b > 0) ? "True" : "False");
看IL代码:
IL_0001: ldc.i4.1
IL_0002: stloc.0 //set a = 1;
IL_0003: ldc.i4.s -2 // push 一个-2(i4.s意味着当作一个int8,就是byte来处理)作为int32类型
IL_0005: stloc.1 // set b = -2
IL_0006: ldloc.0
IL_0007: conv.u8// convert变量a为一个unsigned int64
IL_0008: ldloc.1
IL_0009: conv.i8// convert变量b为一个int 64
IL_000a: add // 相加
IL_000b: ldc.i4.0
IL_000c: conv.i8// convert为一个int 64
native assembly我看不到,不知道怎么写的,单纯看上面的IL,看不出来,CLR为什么要这么处理。