JNDI查找時間巨大差異

在Weblogic 10.3上運行的傳統J2EE Web應用程序的響應時間方面存在巨大差異。該系統由兩個Weblogic服務器實例（前端和後端）組成，它們在同一臺物理服務器上運行，另一臺主機上運行Oracle數據庫。每次登錄系統需要四秒鐘以上時，外部測量工具纔會提醒我們。最近這些警告經常發生。查看由處理登錄請求的servlet編寫的日誌顯示，時間花費在從前端到後端的EJB調用上。所述測量的時間的JNDI查找時間巨大差異

實施例：

time ms 
8:40:43 25 
8:42:14 26 
8:44:04 26 
8:44:25 26 
8:44:47 26 
8:46:06 26 
8:46:41 7744 
8:47:00 27 
8:47:37 27 
8:49:00 26 
8:49:37 26 
8:50:03 8213 
8:50:57 27 
8:51:04 26 
8:51:06 25 
8:57:26 2545 
8:58:13 26 
9:00:06 5195

可以看出，大部分的請求（70％，從較大的樣品中取出）完全在及時的，但它們的顯著部分需要很長的時間完成。

期間所測量的時間執行的步驟如下：

會話bean的

JNDI查找提供認證接口（前端）
調用會話bean（frontend->後端的認證方法）
預留連接池中的JDBC連接（後端）
撥打查詢到的用戶數據庫（表的大小非常適中，表應正確索引）（後端）
讀取結果集，創建POJO用戶對象（後端）
返還POJO用戶對象（backend->前端）

在服務器機器上的負載是非常小的（99％空閒）和用戶數量非常適中。在兩臺服務器上，Weblogic報告的可用內存量在60％到90％之間。垃圾回收被記錄。主要收藏品在他們確實發生時很少見，並且在2-3秒內完成。此外，主要的GC發生似乎不會在長時間響應時間的同一時間發生。在繁忙和非繁忙時段都會出現較長的響應時間。 JDBC連接池最大大小目前設置爲80，這比並發用戶數量多。

更新：

得到重新啓動系統多用一些性能記錄添加權限。日誌清楚地表明，JNDI查找是其中時間都花在部分：

03:01:23.977 PERFORMANCE: looking up foo.bar.Bar from JNDI took 6 ms 
03:14:47.179 PERFORMANCE: looking up foo.bar.Bar from JNDI took 2332 ms 
03:15:55.040 PERFORMANCE: looking up foo.bar.Bar from JNDI took 1585 ms 
03:29:25.548 PERFORMANCE: looking up foo.bar.Bar from JNDI took 7 ms 
03:31:09.010 PERFORMANCE: looking up foo.bar.Bar from JNDI took 6 ms 
03:44:25.587 PERFORMANCE: looking up foo.bar.Bar from JNDI took 6 ms 
03:46:00.289 PERFORMANCE: looking up foo.bar.Bar from JNDI took 7 ms 
03:59:28.028 PERFORMANCE: looking up foo.bar.Bar from JNDI took 2052 ms

縱觀前端和後端的GC日誌表明緩慢的JNDI查找發生時GC沒有這樣做。

的背景下得到了下面的方法是創建一個會話時：

Hashtable ht = new Hashtable(); 
ht.put(Context.PROVIDER_URL, url); 
ht.put(Context.INITIAL_CONTEXT_FACTORY, "weblogic.jndi.WLInitialContextFactory"); 
jndiContext = new InitialContext(ht);

其中url是T3 URL指向後端服務器的DNS名稱和端口。這應該沒問題吧？

要想到的第一件事就是緩存從JNDI獲得的引用，至少這是10年前的首選方式......但不應該Weblogic的InitialContext實現已經做了這種緩存，或者它不是真的在每次通話時從後端服務器獲取參考？

什麼可能導致頻繁緩慢的JNDI查找？有沒有解決方法（例如緩存引用幫助）？

來源

2011-08-30 MarkoU

您是否曾嘗試在上述步驟之間放置日誌消息，以確定哪些消耗大部分額外時間？ –

沒有。這是JNDI查找。請參閱上面編輯的問題。 – MarkoU

還有一件事：它可能是有用的消除簡單的明顯的東西，所以：你檢查了該機器上的硬盤？它可能與錯誤的硬件一樣簡單！ –

作爲第一步，我會嘗試通過記錄每個人執行的時間量來確定執行這些步驟的哪一部分導致問題。通過這種方式，您可以消除無關緊要的問題，並將注意力集中在正確的區域，當您弄清楚這些問題時，任何人都可以再次發帖，以便人們提供具體的建議。

來源

2011-08-30 09:31:33

那麼，什麼會導致這種相當不穩定的行爲？

我們說的任何事情都可能是猜測。這裏有一些關於調查問題的建議：

嘗試使用分析器查看時間花費在哪裏。
嘗試使用網絡工具（如WireShark）來查看是否存在異常網絡流量。
在關鍵點添加一些記錄/追蹤以查看時間正在進行的時間。
尋找Thread.sleep(...)來電。（Ooops ...這是一個猜測。）

來源

2011-08-30 09:33:29

+1：探查器最有可能在時間消耗的地方拾取。我會嘗試創建一個加載測試以重現問題的負載測試。如果你能找到一個具體的行動是否會引發這個問題，那麼它可以提供信息。 –

感謝您的建議！問題是生產服務器上發生此問題，到目前爲止，我們還無法在測試服務器上重現此問題。我們將在下一個補丁中添加更多日誌記錄，並可能在測試環境中使用負載生成器和分析器來深入瞭解問題。 – MarkoU

即使在生產服務器上，您也可以執行上述大部分操作。是的，它在調查期間可能會對績效產生一定影響，但效果不會比您已經患上的問題更糟糕。（只要確保您可以快速「退出」任何臨時調查變更。） –

正如StephenC所說，其中的一些猜測沒有足夠的日誌記錄。您已經清楚地列出了交易中的每個元素，但我假設您沒有可以打開的logger.debug，其中有時間戳。

一些問題來看待：

多少豆子在池中的每個前端和後端豆類 - 它應該是的weblogic-ejb-jar.xml

的max-beans-in-free-pool元素，如果你有更多的請求到後端EJB比bean可用，那麼將會有一個等待堆積。

同樣在JDBC前端，您可以使用Weblogic控制檯來監視獲取連接的任何爭用 - 您是否在JDBC監視選項卡中執行高計數和等待？這應該是下一個要檢查的事情。

來源

2011-08-30 12:27:22 JoseK

謝謝，我查了'max-beans-in-free-pool'。它是100，所以它不應該是一個問題。請參閱我編輯的問題，並提供更多信息。畢竟有一個調試開關... – MarkoU

對，任何與GC模式的鏈接，然後用反射，我想知道是否許多類加載在年輕的空間和服務器GC與響應時間峯值一致。檢查控制檯 – JoseK

檢查GC日誌，並且在緩慢的JNDI查找期間似乎沒有任何GC活動。重新啓動確實有些幫助：偶爾的長時間查找仍然存在，但它們不再那麼長，也不再頻繁。 – MarkoU

JNDI查找時間巨大差異

回答

相關問題