R·ex / Zeng


音遊狗、安全狗、攻城獅、業餘設計師、段子手、苦學日語的少年。

追根究底:不開啟 DevTools 時,console.log 會不會記憶體洩漏?

太長不看:會。並且雖然 Chromium 有試圖做限制,但因為方法不合適所以並沒能解決問題。

JavaScript 的記憶體洩漏原因有很多,例如 DOM、計時器、閉包、意外的全域性變數,以及本文的主題:console.log。關於 console.log 會不會造成記憶體洩漏,掘金上面有大佬發過兩篇文章:

這兩篇文章的結論是:在開啟 DevTools 時一定有洩漏(文中的程式碼很顯然可以證明),但如果沒開啟 DevTools,似乎就不會有問題了(文中 performance 的資料也可以證明)。

但我結合自己之前的經驗,產生了一個疑惑:如果不會造成記憶體洩漏,說明物件被 GC 掉了,那我為什麼在開啟 DevTools 後還能看到開啟之前 log 的物件呢?這些物件肯定被存到了一個地方,肯定還佔據著記憶體。於是本著追根究底的精神,我決定透過實驗、猜想、追蹤程式碼求證等方式來得到答案。

可以復現的記憶體洩漏

其實在文章的評論區有人就指出:只要每次 log 的是不同的物件,不管是否開啟 DevTools 都會記憶體溢位。我這裡以一個長度為 1 M 的 number 陣列為例,簡單修改一下文中的程式碼:

const MB = 1024 * 1024;
function log() {
  const memory = performance.memory.totalJSHeapSize;
  const usagedMemory = Math.floor(memory / MB);
  box.insertAdjacentHTML('beforeend', `<span>${usagedMemory} </span>`);
  const obj = {
    usagedMemory,
    str: Array(1 * MB).fill(0).map(() => Math.random()),
  };
  console.log(obj.str);
  setTimeout(() => log(), 50);
}
log();

本來我是打算用作業系統的任務管理器來檢視記憶體佔用的,但為了避免其它程序以及作業系統的記憶體壓縮、虛擬記憶體的影響,我最終打開了 Chrome 自己的任務管理器。

可以看出,頁面上輸出的 usagedMemory 始終是 9,但 Chrome 的任務管理器裡面這個 Tab 的記憶體佔用卻一直在往上漲,直到用到 3.4~3.6 GB 時頁面崩潰。之後我關掉任務管理器重試,頁面依舊會崩潰,所以一定是因為“超過了記憶體限制”,而不是“任務管理器的觀測會造成記憶體洩漏”。

test.html 耗費了 3.4 GB 記憶體

即使不開 DevTools 頁面也會崩潰

光是憑藉這個例子就足以證明,即使不開啟 DevTools 也會造成記憶體洩漏。並且可以發現 console.log 列印的資料並不在 performance.memory.totalJSHeapSize 的管轄範圍內。那它們去了哪裡呢?我把目光看向了 Chromium 的原始碼。

靜態程式碼追蹤

作為一個對速度要求極高的程式,Chromium 的大部分內容(包括 v8)是用 C++ 寫的。追蹤程式碼首先要能看到程式碼,雖然我可以將倉庫 clone 下來本地追蹤,但其專案過大,clone 需要一些時間,且會對我的 IDE 造成不小的壓力。一個更好的方法是透過官方提供的 Chromium Code Search 頁面來搜尋程式碼、跟蹤跳轉。

一開始,我試圖在 The Chromium Projects 頁面尋找專案結構相關的文件,目的是直接找到 console API 所在的目錄,但無果,因此只能直接搜尋程式碼。考慮到 console.log 可能會被轉化為看似完全不相干的 C++ 函式呼叫,且這個函式呼叫過於通用,可能會搜到很多文件註釋相關的東西,於是我轉而去搜索 console info,因為按照經驗它一定會跟 console.log 的實現在同一個模組下,並且它並不經常出現。

運氣不錯,第一個結果看起來就很接近目標了:

第一個結果就可能是我想要的

檔案是 v8/src/inspector/v8-console.h,按照 C++ 的專案規範,.h 檔案一般只有 declaration 而不是 implementation(網站裡叫 definition),因此先點進去,然後依次單擊程式碼中的 Log 符號、彈出視窗中唯一一條 Definition 結果,右邊新的彈窗就是我們要找的函數了,如下圖所示。

追程式碼的過程

這只是第一步,順著這個思路,可以追蹤到 reportCall,然後是 V8ConsoleMessageStorage::addMessage 方法,在函式的結尾將引數 message 追加到了一個 vector(C++ STL 提供的可變長度的陣列)的末尾(傳送門):

m_messages.push_back(std::move(message));

至於 m_messages,則是 V8ConsoleMessageStorage 這個 class 的一個成員變數,而這個 class 的例項是跟著 v8 isolates 走的,並且只有用到的時候才建立,例如呼叫 console.log 時。關於什麼是 v8 isolates,Cloudflare 有一段 很好的解釋

V8 引擎將 isolate 作為輕量級的上下文,為你的程式碼提供變數訪問和安全的執行環境。你甚至可以將 isolate 視為你的函式執行的沙盒。

原來是存在了 v8 相關的例項裡面,那 performance API 拿不到似乎也情有可原了。

Chromium 中失效的限制

值的留意的是,剛剛追蹤到的程式碼在 push_back 之前其實有一個小判斷:

DCHECK(m_messages.size() <= maxConsoleMessageCount);
if (m_messages.size() == maxConsoleMessageCount) {
  m_estimatedSize -= m_messages.front()->estimatedSize();
  m_messages.pop_front();
}
while (m_estimatedSize + message->estimatedSize() > maxConsoleMessageV8Size &&
      !m_messages.empty()) {
  m_estimatedSize -= m_messages.front()->estimatedSize();
  m_messages.pop_front();
}

可以看出,Chromium 對 m_messages 可以存放的總預估體積(estimateSize,可能不準確)做了限制,如果超出了這個限制,最早放入 m_messages 中的訊息將被刪除。這個限制的定義是 maxConsoleMessageV8Size = 10 * 1024 * 1024,也就是……10 MB??

這個值我覺得過於小了,我們的測試程式碼每 50 ms 會產生至少 1 MB 記憶體,即使預估再不準確,應該也很快就會超過這個限制才對。難道是限制失效了?但透過靜態分析程式碼我已經沒有太多頭緒了,說不定動態除錯可以幫我瞭解更多的細節。

動態除錯

四年前我有個機會自己編譯並簡單(透過輸出日誌的方式)除錯了 Chromium 專案(文章傳送門),憑藉著那次經歷,我決定再試一次。

編譯 Chromium(再次)

由於年代久遠,我又一次打開了 The Chromium Projects 的指南。不同的是這次我沒有在 Ubuntu 虛擬機器上搞,而是直接用了 Mac 系統,因此需要檢視 Mac 對應的文件:Checking out and building Chromium for Mac。關鍵的幾步是:

# 1. 安裝完整版的 Xcode,注意不能是命令列版的。如果此命令可以正常輸出則表示安裝完成:
ls `xcode-select -p`/Platforms/MacOSX.platform/Developer/SDKs

# 2. 安裝官方工具集 `depot_tools`,並將其新增到環境變數中:
git clone https://chromium.googlesource.com/chromium/tools/depot_tools.git
export PATH="$PATH:/path/to/depot_tools"

# 3. 透過工具 clone 程式碼,只 clone 最新的提交,忽略歷史提交:
# !! 倉庫很大,需要有穩定的梯子。
# !! 如果你對 Git 不感興趣,也可以在 clone 完畢後刪掉 .git 目錄,
# !! 否則如果你的 shell 會自動展示 Git 資訊,那每條命令執行都會很慢。
fetch --no-history chromium

# 4. 透過工具生成一個編譯用的配置檔案:
gn gen out/Default

# 5. 透過工具編譯:
# !! 耗時很長,在我的 M1 Mac 上面花了接近 7 小時。
# !! 不過由於這類專案都會有編譯快取,因此簡單修改程式碼後的重編譯還不到 1 分鐘。
autoninja -C out/Default chrome

# 6. 執行 Chromium
out/Default/Chromium.app/Contents/MacOS/Chromium

只要能看到下面這個介面,就說明編譯沒問題,你已經有一個自己的 Chromium 啦!

自己編譯並執行的 Chromium

簡單的除錯方法

在之前的經歷中,我透過 LOG 宏來列印自定義的資料,透過 base::debug::StackTrace().Print() 列印堆疊以確認呼叫鏈路。但這次似乎不太一樣了——LOG 的說明文件沒有了,並且我直接呼叫會報編譯錯誤;列印堆疊也是直接報編譯錯誤,說找不到 StackTrace 方法。

憑藉一點點 C++ 的知識,我發現在 v8 這個 namespace 裡,這兩個東西都是被重定義了——

  • LOGv8/src/logging/log.h 裡面被重定義,需要提供 v8 isolate,但 V8ConsoleMessageStoragecontextGroup 級別的 class,沒法提供具體某一個 context 的 isolate。因此我只好先用 std::cout 臨時代替一下。
  • debugv8 這個 namespace 下也被重新實現了一次,需要用 v8::base::debug::StackTrace().Print() 來代替。

執行並檢視結果

首先我在 V8ConsoleMessageStorage::addMessage 裡面列印一下堆疊,確認了之前程式碼追蹤的結果,確實是經過這條呼叫鏈路進來的。

==== C stack trace ===============================
[18709:259:0227/174421.484558:INFO:CONSOLE(6)] "[object Object]", source: file:///Users/rexzeng/Desktop/test.html (6)
    0  libv8_libbase.dylib 0x0000000114a0e8b4 v8::base::debug::StackTrace::StackTrace() + 24
    1  libv8.dylib         0x00000002dd939f40 v8_inspector::V8ConsoleMessageStorage::addMessage(std::Cr::unique_ptr<v8_inspector::V8ConsoleMessage, std::Cr::default_delete<v8_inspector::V8ConsoleMessage>>) + 912
    2  libv8.dylib         0x00000002dd93ff28 v8_inspector::(anonymous namespace)::ConsoleHelper::reportCall(v8_inspector::ConsoleAPIType, std::Cr::vector<v8::Local<v8::Value>, std::Cr::allocator<v8::Local<v8::Value>>> const&) + 204
    3  libv8.dylib         0x00000002dd93cf54 v8_inspector::(anonymous namespace)::ConsoleHelper::reportCall(v8_inspector::ConsoleAPIType) + 564
    4  libv8.dylib         0x00000002dd93d484 v8_inspector::V8Console::Log(v8::debug::ConsoleCallArguments const&, v8::debug::ConsoleContext const&) + 332
    5  libv8.dylib         0x00000002dc46a960 v8::internal::(anonymous namespace)::ConsoleCall(v8::internal::Isolate*, v8::internal::BuiltinArguments const&, void (v8::debug::ConsoleDelegate::*)(v8::debug::ConsoleCallArguments const&, v8::debug::ConsoleContext const&)) + 808
    6  libv8.dylib         0x00000002dc465e90 v8::internal::Builtin_Impl_ConsoleLog(v8::internal::BuiltinArguments, v8::internal::Isolate*) + 84
    7  libv8.dylib         0x00000002dc465aa8 v8::internal::Builtin_ConsoleLog(int, unsigned long*, v8::internal::Isolate*) + 208
    8  ???                 0x0000000377b4f8a8 0x0 + 14893250728
    9  ???                 0x00000003778b339c 0x0 + 14890513308
    10 ???                 0x00000003778ad55c 0x0 + 14890489180
    11 ???                 0x00000003778ad1e8 0x0 + 14890488296
    12 libv8.dylib         0x00000002dc731f54 v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 5292

那麼為什麼程式碼中的限制不生效呢?我在限制附近加了一段 log 來分析原因:

+ std::cout << "[rex] V8ConsoleMessageStorage::addMessage called." << std::endl;
+ std::cout << "[rex] Current, new, limit = " << m_estimatedSize << ", "
+           << message->estimatedSize() << ", " << maxConsoleMessageV8Size
+           << std::endl;

  while (m_estimatedSize + message->estimatedSize() > maxConsoleMessageV8Size &&
        !m_messages.empty()) {
+   std::cout << "[rex] Estimate size exceeded, removing oldest message."
+             << std::endl;
    m_estimatedSize -= m_messages.front()->estimatedSize();
    m_messages.pop_front();
  }

  m_messages.push_back(std::move(message));
  m_estimatedSize += m_messages.back()->estimatedSize();

結果發現,這個迴圈根本就沒進去,因為 message->estimatedSize() 的大小始終是 50!想要超過 maxConsoleMessageV8Size 這個 10485760 的限制實在是過於困難了。

[rex] V8ConsoleMessageStorage::addMessage called.
[rex] Current, new, limit = 0, 50, 10485760
[23733:259:0227/175711.516016:INFO:CONSOLE(23)] "[object Object]", source: file:///Users/rexzeng/Desktop/test.html (23) [rex] V8ConsoleMessageStorage::addMessage called.
[rex] Current, new, limit = 50, 50, 10485760
[23733:259:0227/175713.549701:INFO:CONSOLE(23)] "[object Object]", source: file:///Users/rexzeng/Desktop/test.html (23) [rex] V8ConsoleMessageStorage::addMessage called.
[rex] Current, new, limit = 100, 50, 10485760
[23733:259:0227/175715.563253:INFO:CONSOLE(23)] "[object Object]", source: file:///Users/rexzeng/Desktop/test.html (23) [rex] V8ConsoleMessageStorage::addMessage called.
[rex] Current, new, limit = 150, 50, 10485760
[23733:259:0227/175717.693054:INFO:CONSOLE(23)] "[object Object]", source: file:///Users/rexzeng/Desktop/test.html (23) [rex] V8ConsoleMessageStorage::addMessage called.
[rex] Current, new, limit = 200, 50, 10485760

明明我 log 的物件裡面有一個很長的字串,為什麼預估大小隻有 50 呢?看來 estimatedSize 可能有點問題。點進去一看,發現它取的是例項內部的 m_message 的長度:

int estimatedSize() const {
  return m_v8Size + static_cast<int>(m_message.length() * sizeof(UChar));
}

不合適的取值來源

從程式碼中可以發現,在 V8ConsoleMessage 類中,m_message 只是一個 String16 型別(定義在 v8/src/inspector/string-16.h,其實就是 UTF-16 的一個 C++ 實現),實際的值(型別是 v8::Value)其實存在一個 private 屬性中:

using Arguments = std::vector<std::unique_ptr<v8::Global<v8::Value>>>;

經過簡單檢視,m_message 其實就是 log 裡面出現的 "[object Object]",自然長度固定。那麼如果我 log 的不是物件,而是隻有一個長字串呢?我簡單改了一下程式碼(為了避免被刷屏,我特地改小了訊息體,只有 10 的長度):

  const obj = {
    usagedMemory,
-   str: Array(1 * MB).fill(0).map(() => Math.random()),
+   str: Array(10).fill(0).map(() => Math.random()),
  };
- console.log(obj);
+ console.log(obj.str);

果然,預估大小變了,每條訊息大概在 400 左右:

[rex] V8ConsoleMessageStorage::addMessage called: 0.006429781392031542,0.7025972903865423,0.10886522086870132,0.7463988173118989,0.1726929587177901,0.4041939919687627,0.6177604000139703,0.5011661616460559,0.12152624198222584,0.42717062777130876
[rex] Current, new, limit = 0, 404, 10485760
[29381:259:0227/181116.796558:INFO:CONSOLE(23)] "0.006429781392031542,0.7025972903865423,0.10886522086870132,0.7463988173118989,0.1726929587177901,0.4041939919687627,0.6177604000139703,0.5011661616460559,0.12152624198222584,0.42717062777130876", source: file:/// Users/rexzeng/Desktop/test.html (23)
[rex] V8ConsoleMessageStorage::addMessage called: 0.4775464572140946,0.22521271497851258,0.3548952458618082,0.07826429207660479,0.7868981992965354,0.9738662411476406,0.4493962839312635,0.17173905749902962,0.41509559133406393,0.6175669281153542
[rex] Current, new, limit = 404, 402, 10485760
[29381:259:0227/181116.854073:INFO:CONSOLE(23)] "0.4775464572140946,0.22521271497851258,0.3548952458618082,0.07826429207660479,0.7868981992965354,0.9738662411476406,0.4493962839312635,0.17173905749902962,0.41509559133406393,0.6175669281153542", source: file:/// Users/rexzeng/Desktop/test.html (23)
[rex] V8ConsoleMessageStorage::addMessage called: 0.016472809214265194,0.8297652370608959,0.5951015092506107,0.014495767431445872,0.04746432220371455,0.7227116481240548,0.9557890005161374,0.6282763394913704,0.3914123998466803,0.29088587247350106
[rex] Current, new, limit = 806, 406, 10485760

值得注意的是,雖然 m_message 欄位看起來像是對 log 的值做 toString() 之後的結果,但實際上並不是。透過追蹤程式碼可以看到 V8ConsoleMessage::createForConsoleAPI 函式(傳送門)和 V8ValueStringBuilder::append 函式(傳送門)的實現,最終定位到了 這裡

if (value->IsObject() && !value->IsDate() && !value->IsFunction() &&
    !value->IsNativeError() && !value->IsRegExp()) {
  v8::Local<v8::Object> object = value.As<v8::Object>();
  v8::Local<v8::String> stringValue;
  if (object->ObjectProtoToString(m_context).ToLocal(&stringValue))
    return append(stringValue);
}

也就是類似於 JavaScript 裡面的 Object.prototype.toString.call 的效果。可以使用下面這段 JavaScript 程式碼來驗證——雖然在 JavaScript 裡面強轉 string 的結果是 "Rex Zeng is the greatest alive",但 std::cout 的結果依舊是 "[object Object]"

console.log({
  toString: () => {
    return 'Rex Zeng is the greatest alive';
  },
});

自此可以得出結論:Chromium 對 console.log 總大小限制失效的原因,是因為其在判斷時沒有使用合適的方式,導致預估大小與實際大小嚴重不符。

那麼——該不該用 console.log?

本文只是在討論“不開啟 DevTools 時 console.log 是否還會造成記憶體洩漏”,至於在生產環境使用 console.log 的合理性不在討論範圍中。事實上對於大多數頁面,log 打多打少並沒有太大影響,而對於可能需要常開的頁面(如 Telegram Web、企業監控大屏),記憶體佔用的不斷飆升最終會導致頁面崩潰,這就必須要注意了。

如果因為一些原因,希望避免在生產環境使用 console.log,可以用 ESLint 幫助開發養成習慣,也可以透過編譯器外掛直接在 NODE_ENV === 'production' 時去除相關的程式碼。

Disqus 載入中……如未能載入,請將 disqus.com 和 disquscdn.com 加入白名單。

這是我們共同度過的

第 3853 天