如何使用oracle提供的SQL_TRACE來(lái)跟蹤sql的執行情況(2)

　　線(xiàn)程阻塞是我們在 java 多線(xiàn)程編程中經(jīng)常遇到的問(wèn)題。由于對后端有限資源的爭用以及過(guò)度同步等問(wèn)題，經(jīng)常會(huì )發(fā)現 Java dump 中某個(gè)資源(鎖對象)下有太多的線(xiàn)程處于等待狀態(tài)，這時(shí)候我們通常需要從以下三個(gè)方面去診斷這個(gè)問(wèn)題：

　　這個(gè)鎖存在的目的是什么?有沒(méi)有可能去掉這個(gè)鎖或者縮小這個(gè)鎖保護的范圍，從而減少線(xiàn)程等待問(wèn)題發(fā)生的幾率。

　　有哪些線(xiàn)程需要用到這個(gè)鎖，有沒(méi)有可能改用其它更好的替代方案。

　　當前哪個(gè)線(xiàn)程正在持有這個(gè)鎖，持有的時(shí)間是多長(cháng)，有沒(méi)有可能縮短持有的時(shí)間。

　　下面通過(guò)實(shí)際測試中的dump文件來(lái)談?wù)勅绾巫x懂一個(gè)dump文件。

　　可以看到一共有4種線(xiàn)程的狀態(tài)，WAITING，RUNNABLE，TIMED_WAITING (sleeping)，BLOCKED。線(xiàn)程阻塞就是BLOCKED。搜索文件中BLOCKED的部分，我們可以看到其中一個(gè)：

　　"[ACTIVE] ExecuteThread: '91' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaae8181000 nid=0x4849 waiting for monitor entry [0x0000000047d4d000]

　　java.lang.Thread.State: BLOCKED (on object monitor)

　　* 線(xiàn)程名稱(chēng)：

　　* 線(xiàn)程類(lèi)型：daemon

　　* 優(yōu)先級：10，默認是5

　　* jvm線(xiàn)程id：jvm內部線(xiàn)程的唯一標識,0x00002aaae8181000

　　* 對應系統線(xiàn)程id：和top命令查看的pid對應，不過(guò)一個(gè)是10進(jìn)制，一個(gè)是16 進(jìn)制。0x4849

　　* 線(xiàn)程狀態(tài)：BLOCKED

　　* 起始棧地址：

　　可以看到很多線(xiàn)程狀態(tài)都是BLOCKED，表示當前線(xiàn)程A正要進(jìn)入一個(gè)同步塊，但是被另外一個(gè)線(xiàn)程B持有該鎖，于是需要等待B，釋放鎖才有機會(huì )重新獲取。

　　用一種輕松的方式來(lái)思考鎖，其實(shí)挺簡(jiǎn)單的。數據庫中也存在這樣的鎖。為什么會(huì )有鎖，打個(gè)比喻，一個(gè)java對象就像一個(gè)大房子，大門(mén)永遠打開(kāi)。房子里有很多房間(方法)。這些房間有上鎖的和不上鎖之分。房門(mén)口只放著(zhù)一把鑰匙，這把鑰匙可以打開(kāi)所有上鎖的房間。把所有想調用該對象方法的線(xiàn)程比喻成想進(jìn)入這房子某個(gè)房間的人。試想如果只有一個(gè)人，肯定是不存在等待別人使用完鑰匙歸還的時(shí)候。如果要是很多人，勢必會(huì )需要等這把鑰匙歸還，等鑰匙還回來(lái)以后，就會(huì )有一個(gè)人優(yōu)先得到鑰匙。

　　由此可以看到，鎖是不可避免的，要想正確獲取對象的狀態(tài)，或者修改對象的狀態(tài)，必須存在這樣一種lock。也就意味著(zhù)，鎖的持有時(shí)間越久，對性能的影響也就越大，直接結果是大并發(fā)情況下，響應時(shí)間的延長(cháng)?；氐揭郧暗膖hread dump，如果通過(guò)工具我們發(fā)現，線(xiàn)程阻塞比較頻繁，并且持續時(shí)間很久，不妨多次收集這種轉儲文件，可以有效的幫助我們分析問(wèn)題。

　　我們剛才看到的轉儲文件就是XXX測試中捕獲到的，通過(guò)這些地方，我們發(fā)現了一些性能方面的問(wèn)題。除了線(xiàn)程阻塞，我們分析dump文件還可以找到消耗CPU最多的地方。如果不是windows操作系統，可以通過(guò)top(top –H)或者topas命令來(lái)查看應用程序的線(xiàn)程信息及占用CPU的情況。找到排序第一位的pid值，按照我們前面解釋的，換算成16進(jìn)制，然后在thread dump日志中搜索該數值nid就能找到耗費CPU的源代碼的具體位置，可以精確到行號。

　　另外還可以分析是否有很多thread struck在了I/O，例如：

　　"New I/O server worker #1-1" prio=10 tid=0x00000000423e0800 nid=0x5bfd runnable [0x00007f7d0a2f4000]

　　java.lang.Thread.State: RUNNABLE

　　at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)

　　at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:215)

　　或者是thread struck在數據庫，例如：

　　"[ACTIVE] ExecuteThread: '99' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaae8190800 nid=0x4857 runnable [0x0000000048554000]

　　java.lang.Thread.State: RUNNABLE

　　at java.net.SocketInputStream.socketRead0(Native Method)

　　at java.net.SocketInputStream.read(SocketInputStream.java:129)

　　at oracle.net.ns.Packet.receive(Packet.java:293)

　　at oracle.net.ns.DataPacket.receive(DataPacket.java:92)

　　等地方，便于我們定位瓶頸原因。

原文轉自：http://blog.csdn.net/xuyubotest/article/details/8158241