最近一個朋友公司的OA系統總是出故障,具體表現在某個特定用戶在登錄后,無法查看自己的任務。等過了一會后,就報503錯誤。讓我幫忙看看。
首先服務器是JBOSS,數據庫是SQL Server 2005 64位企業版。
根據以上提供的信息,首先找到JBOSS日志,當某個用戶登錄后點查看待辦任務,JBOSS日志就會顯示:
ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackLocalException in method: public abstract xxxx xxx(), causedBy:
org.jboss.util.NestedSQLException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ))
at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:106)
at com.adobe.pof.ConnectionWrapper.getConnection(ConnectionWrapper.java:25)
at com.adobe.pof.ConnectionWrapper.getMetaData(ConnectionWrapper.java:101)
at com.adobe.pof.POFBean.getAdapter(POFBean.java:120)
at com.adobe.pof.omapi.POFObjectManagerRemoteBean.getObjectManagerImpl(POFObjectManagerRemoteBean.java:108)
at com.adobe.pof.omapi.POFObjectManagerRemoteBean.getEnvironment(POFObjectManagerRemoteBean.java:489)
at sun.reflect.GeneratedMethodAccessor144.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:592)
at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:683)
根據報錯日志,很明顯問題是出在連接超時。當超時超過30秒后,數據庫Session斷開。然后服務器報503錯誤。而只有這個特定用戶存在這個問題,測試了幾個其它用戶均不存在這個問題,因此可以知道錯誤應該沒出在應用程序那一端。
由於只有這個特定用戶存在這個問題,因此也基本排除數據庫無法連接,T-SQL代碼存在一些問題等原因。
因此,超時我首先想到是阻塞,阻塞我首先想到可能是鎖引起的。我先運行了這個代碼來看哪個session下鎖跑得最多。
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
SELECT COUNT(*),request_session_id FROM
(
SELECT DB_NAME(resource_database_id) AS DatabaseName
, request_session_id
, resource_type
, CASE
WHEN resource_type = 'OBJECT'
THEN OBJECT_NAME(resource_associated_entity_id)
WHEN resource_type IN ('KEY', 'PAGE', 'RID')
THEN (SELECT OBJECT_NAME(OBJECT_ID)
FROM sys.partitions p
WHERE p.hobt_id = l.resource_associated_entity_id)
END AS resource_type_name
, request_status
, request_mode
FROM sys.dm_tran_locks l
) AS a
GROUP BY a.request_session_id
發現session id為150的連接上跑了4000+個鎖。再通過sys.dm_tran_locks 來具體的看,發現這些鎖都是key級的S鎖,以及對應Page和表上的IS鎖。當30秒過后超時,所有這些鎖都會被自動釋放。
我產生兩個疑問:
1.為什么僅僅是這個用戶一查看數據庫就會產生這么多的鎖,而其它用戶不會產生這么多鎖呢?
2.為什么4000+個鎖沒有升級呢?
帶着這個疑問,我使用Profiler對這個Session ID查看待辦工作時的操作進行了抓取。發現對應的T-SQL語句僅僅是一個普通的Select語句。為了看清返回的行數,我使用未提交讀看到這個用戶尚待辦的工作有1900條(用戶是一個地區的經理,所有地區產生的任務無論他是否參與都要轉給他一個),而其它不產生阻塞的用戶待辦工作不超過50條。
4000+個鎖沒有升級我想是因為表上存在了意向鎖。
因此我懷疑表上的多個索引之間在選擇多條語句時可能產生互相阻塞。因此對相關的表上索引進行查看,發現在用於關聯用戶和任務的assignment表中存在兩個索引的最左列完全一樣,估計這里就是產生問題的根源。
因此kill掉Session 150之后,Drop了那個鍵少的索引。問題解決!