如何在Node.js/V8中調試/分析極長的GC暫停

Question

我想分析一個相對複雜的Node.js服務器應用程序中的內存/ GC問題。即使在非常適中的負荷下，它在明顯的時段也變得沒有反應，而且這些停頓隨着時間的推移而變長。與--trace-gc參數運行表明，極長的垃圾收集的時間是有可能的原因：

[4805]  537 ms: Mark-sweep 17.6 (46.4) -> 10.3 (47.4) MB, 20 ms [allocation failure] [GC in old space requested]. 
[4805]  1338 ms: Mark-sweep 31.3 (58.4) -> 19.2 (57.2) MB, 40 ms [allocation failure] [promotion limit reached]. 
[4805]  2662 ms: Mark-sweep 58.0 (79.2) -> 43.9 (85.2) MB, 109 ms [Runtime::PerformGC] [promotion limit reached]. 
[4805]  4014 ms: Mark-sweep 90.1 (111.5) -> 70.6 (113.9) MB, 114 ms [allocation failure] [promotion limit reached]. 
[4805]  7283 ms: Mark-sweep 129.7 (153.9) -> 112.0 (158.9) MB, 511 ms [allocation failure] [promotion limit reached]. 
[4805] 10979 ms: Mark-sweep 184.6 (210.9) -> 160.3 (212.9) MB, 422 ms [Runtime::PerformGC] [promotion limit reached]. 
[4805] 1146869 ms: Mark-sweep 243.8 (271.4) -> 191.6 (267.9) MB, 1856 ms [allocation failure] [promotion limit reached]. 
[4805] 1731440 ms: Mark-sweep 282.1 (307.4) -> 197.5 (298.9) MB, 1/11230 ms [allocation failure] [promotion limit reached]. 
[4805] 2024385 ms: Mark-sweep 291.0 (320.8) -> 197.3 (306.9) MB, 9076 ms [Runtime::PerformGC] [promotion limit reached]. 
[4805] 2623396 ms: Mark-sweep 290.9 (317.1) -> 196.9 (311.9) MB, 1/15401 ms [allocation failure] [promotion limit reached]. 
[4805] 3223769 ms: Mark-sweep 291.4 (323.6) -> 187.8 (318.9) MB, 1/13385 ms [allocation failure] [promotion limit reached]. 
[4805] 4225777 ms: Mark-sweep 280.1 (324.2) -> 190.6 (315.9) MB, 1/13266 ms [allocation failure] [promotion limit reached]. 
[4805] 4705442 ms: Mark-sweep 286.2 (321.4) -> 195.2 (314.9) MB, 1/17256 ms [Runtime::PerformGC] [promotion limit reached]. 
[4805] 5225595 ms: Mark-sweep 288.3 (324.0) -> 201.7 (316.9) MB, 1/22266 ms [Runtime::PerformGC] [promotion limit reached]. 
[4805] 6127372 ms: Mark-sweep 296.5 (324.6) -> 200.5 (316.9) MB, 1/28325 ms [allocation failure] [promotion limit reached]. 
[4805] 6523938 ms: Mark-sweep 297.8 (328.9) -> 198.8 (323.9) MB, 1/27213 ms [allocation failure] [promotion limit reached]. 
[4805] 7355394 ms: Mark-sweep 292.1 (330.7) -> 223.9 (322.9) MB, 60202 ms [allocation failure] [promotion limit reached]. 

全（--trace-gc-verbose）輸出，可以發現here。

這些日誌是用下列參數運行的服務器的結果：

--expose-gc --trace-gc --trace-gc-verbose --trace-gc-ignore-scavenger --max-old-space-size=1000 

它運行的時間越長，時間越長暫停得到（通常幾分鐘），直到最終一對夫婦後徹底鎖定了幾小時。可用內存永遠不會用完，RSS甚至不會接近1000mb舊的空間限制，所以它似乎不是泄漏。在我看來，代碼中可能存在一些非常不尋常的東西，使GC在可接受的時間框架內完成工作非常「困難」。

我的問題是：如何進一步分析這個問題，並縮小可能的原因？任何推薦的工具來幫助解決像這樣的問題？我基本上是在尋找一種比天真地關閉代碼部分更高效的方法，這非常麻煩和費時。另外，我非常感謝鏈接到解釋GC調試輸出中使用的術語/消息（例如「達到促銷限制」）的任何文檔，以及那裏列出的數字。我對V8 GC的工作原理有了非常基本的瞭解（this幫了很大忙），但大部分輸出仍然超出了我的想象。

萬一它很重要：它在Ubuntu 14.04服務器上的Node.js v0.10.33上運行。

編輯： 前一段時間，我們轉移到io.js，這裏根本不再發生（大概是由於更近期的V8版本）這個問題。但我從來沒有在Node v0.10上找到這個問題的原因，更不用說修復了。

Answer 1

您是否能夠在單個節點上重現問題？我想，如果我是在情況下，我可能會做以下的混合：

• 寫裝載機，讓我複製一個本地實例
• 如果沒有，就把一個實例中督促，將收到的流量子集，並修改它以執行以下操作
• 將node-heapdump添加到您的源代碼中，每隔一段時間調用一次並以N分鐘間隔將結果導出到json文件。
• 潛在地，如果您在本地運行，您可能也可以利用memwatch。
• 等待慢啓動GC。
• 當您知道緩慢的GC開始發生時，您可以獲取大量堆轉儲。
• 裝載它們到Chrome和使用分析它們的three snap shot technique（我想你可以把這個在我們的例子N個快照技術）

基本上，你會加載堆並開始希望通過他們嘗試和了解什麼類型的東西堆疊起來，什麼東西堆疊起來，結果你就會理解GC爲什麼要這麼長時間。

可用內存永遠不會用完，RSS甚至不會接近1000mb舊的空間限制，所以它似乎不是泄漏。在我看來，代碼中可能存在一些非常不尋常的東西，使GC在可接受的時間框架內完成工作非常「困難」。

在這裏您可能正在尋找長的和圓形的保留樹。但是在一天結束的時候，即使是這樣，您也應該能夠確定該樹的根源是什麼，它的內容是什麼，並嘗試減少移除。

我也同意@dandavis和可疑的關閉。

Answer 2

這個答案可能不是特定的，但我建議您查看沃爾瑪hapi.js框架的一部分good package。它在擴展日誌記錄之後做了很好的工作，超出了--trace-gc。這是一個過程監控監聽一個或多個以下事件：

• ops - 系統和工藝性能 - CPU，內存，磁盤和其他指標。
• response - 有關傳入請求和響應的信息。這映射到hapi服務器發出的「響應」或「尾部」事件。
• log - 日誌信息未綁定到特定請求，如系統錯誤，後臺處理，配置錯誤等。映射到從hapi服務器發出的「日誌」事件。
• error - 請求具有狀態代碼爲500的響應。這映射到「請求錯誤」hapi事件。
• request - 請求記錄信息。這映射到通過request.log()發出的hapi「請求」事件。

你將不得不拉動Hapi庫供此工作，但它可能暫時值得用於調試目的。總的來說，我強烈建議Hapi擴展Node.js應用程序，沃爾瑪的這些人在過去一年中一直在做着令人驚歎的事情。