使用 JTRACE 對核心停止運作進行偵錯

總覽

說明

JTRACE 是簡單、輕量且「以防萬一」的追蹤系統，旨在協助開發人員偵錯核心當機和自動重新啟動問題，方法是記錄開發人員新增的檢測功能所產生的一系列追蹤事件記錄，並在核心發生異常時自動播放這些記錄。這項功能的用意是讓開發人員能夠在核心程式碼的幾乎任何位置建立追蹤記錄，提供額外資訊 (而非僅限於註冊傾印和堆疊追蹤)，協助瞭解導致當機的事件順序。JTRACE 的實用屬性包括：

  • 無鎖環狀緩衝區資料結構：建立追蹤事件時，不會造成封鎖，也不會嘗試取得任何鎖定，因此可在早期初始化、任意鎖定內部、硬體中斷時間，以及核心程式碼中幾乎任何位置使用。
  • 低負擔：建立追蹤記錄事件是相對低成本的作業，因此可在時間中斷最少的情況下，對效能敏感的程式碼進行檢測。
  • 可選的跨重啟持續性：在平台允許的情況下，JTRACE 可設定為使用部分持續性 RAM，通常用於儲存當機記錄，以協助偵錯涉及自動重新啟動的問題，這類問題通常是因為觸發硬體監控器計時器而發生。

不適用情形

JTRACE 並非正式環境追蹤系統。根據預設，這項功能會完全停用，且絕不會在正式版版本中啟用。追蹤點不是開發人員在提交變更時，應在程式碼中保留的項目。開發人員通常會在使用 JTRACE 時，在程式碼中新增追蹤點，重現當機情形，然後修改現有的追蹤點或新增新的追蹤點，並重複執行，直到找出錯誤的根本原因為止。找到、瞭解並修正錯誤後，系統就會捨棄新增追蹤點的程式碼。

設定

使用透過 fx set 設定的建構引數，即可控制 JTRACE 設定。目前可指定 4 個選項。如下所示：

名稱 類型 附註
jtrace_enabled 三態 將其設為 true 或 "persistent" 時，就會啟用 JTRACE。預設為停用。
jtrace_target_buffer_size uint32_t 控制追蹤緩衝區預留的 RAM 量。
jtrace_last_entry_storage uint32_t 控管系統為每個 CPU 的最終事件記錄保留的 RAM 量。
jtrace_use_large_entries 布林值 控管是否要使用大型或小型追蹤記錄。
jtrace_use_mono_timestamps 布林值 控制是否要使用單調或啟動時間軸為追蹤記錄加入時間戳記。

根據預設，JTRACE 會停用，且不會納入核心版本。如要啟用 JTRACE，使用者可以將 jtrace_enabled 建構引數設為 true 或 "persistent" 的值，以便啟用 JTRACE 並設定持續追蹤。

如果選擇持續追蹤，jtrace_target_buffer_size 必須是核心設定的 persistent_ram_allocation_granularity 值的倍數 (預設為 128 位元組)。

如果使用者未明確指定，系統會根據您是否選取「持續追蹤」，選擇每個其他設定參數的預設值。

名稱 非持久性預設 永久預設
jtrace_target_buffer_size 32768 4096
jtrace_last_entry_storage 0 0
jtrace_use_large_entries true false
jtrace_use_mono_timestamps false false

設定完畢後，只要重新建構並將新核心部署至目標，即可開始使用 JTRACE。

範例

如要啟用具有大型記錄和 32 KB 儲存空間的非永久追蹤功能，請將以下內容新增至 fx set 行。

--args 'jtrace_enabled=true'

如要將儲存空間擴充至 64 KB，並改用小型記錄，則引數如下：

--args 'jtrace_enabled=true jtrace_target_buffer_size=65536 jtrace_use_large_entries=false'

如要啟用含大型記錄的持續追蹤功能 (覆寫預設值)，以及每個 CPU 的 4 個最後事件記錄的儲存空間 (同樣覆寫預設值)，請要求 4 KB 的儲存空間，並將以下內容新增至 fx set 行。

--args 'jtrace_enabled="persistent" jtrace_last_entry_storage=4 jtrace_use_large_entries=true'

請注意，persistent 周圍必須有 ""。

新增追蹤點

需求條件

如要在檔案中新增追蹤點，使用者必須在要新增追蹤點的每個檔案中加入以下 #include 陳述式，以便加入 jtrace 標頭。

#include <lib/jtrace/jtrace.h>

如果找不到包含檔案，可能需要在模組 BUILD.gn 檔案的 deps 部分新增標頭。

deps = [ "//zircon/kernel/lib/jtrace:headers" ] # If deps has not been declared yet.
deps += [ "//zircon/kernel/lib/jtrace:headers" ] # If deps has already been declared.

JTRACE 巨集。

您現在可以透過叫用 JTRACE 巨集來新增追蹤點。每個追蹤點都必須指定字串文字「標記」，並可以指定任意數量的通用引數，數量取決於設定的追蹤項目記錄支援的數量。在設定持續追蹤功能時，標記必須是字串文字，才能在重新啟動時保持有效。

您不需要指定一般用途的引數，如果省略，則預設值為 0。此外，指定通用用途引數時，不應需要轉換。如果引數欄位足以儲存值，就會儲存。小型追蹤記錄項目有一個 32 位元引數的空間，而大型追蹤記錄項目則有四個 32 位元引數的空間，後面接著兩個 64 位元引數。

以下是使用追蹤功能的範例，適用於設定為大型項目的情況。

#include <lib/jtrace/jtrace.h>

struct MyStruct {
  void *ptr1, *ptr2;
  uint32_t foo, bar;
};

void MyFunction(const MyStruct* args, uint32_t num_args) {
  JTRACE("(num_args, args)", num_args, 0, 0, 0, args);

  for (uint32_t i = 0; i < num_args; ++i) {
    const auto& a = args[i];
    JTRACE("Before (i, foo, bar, 0, ptr1, ptr2)", i, a.foo, a.bar, 0, a.ptr1, a.ptr2);
    zx_status_t status = DoAThingWithMyStruct(a);
    JTRACE("After (status)", status);
  }

  JTRACE("Finished");
}

以下是「Before」標記的追蹤陳述式，當追蹤緩衝區最終顯示時，會是這個樣子。

[   7.718998976][cpu 2 tid     3702] : 00000002 00000006 00000001 00000000 ffffffff0024c720 ffffff9519077e60 : (       0.308 uSec) : jtrace_example.cc:MyFunction:12 (Before (i, foo, bar, 0, ptr1, ptr2))

按照欄位細分後，我們有：

欄位 說明
[ 7.718998976] 追蹤記錄項目的單調時鐘時間戳記
[cpu 2 tid 3702] 在記錄追蹤記錄項目時，處於活動狀態的 CPU 和執行緒 ID
00000002 第 1 個 32 位元引數 (i) 的值
00000006 第 2 個 32 位元引數 (foo) 的值
00000001 第 3 個 32 位元引數 (bar) 的值
00000000 第 4 個 32 位元引數的值 (0)
ffffffff0024c720 第 1 個 64 位元引數 (ptr1) 的值
ffffff9519077e60 第 2 個 64 位元引數 (ptr2) 的值
( 0.308 uSec) 上次顯示追蹤記錄項目後經過的時間
jtrace_example.cc:MyFunction:12 追蹤項目的檔案名稱、函式名稱和行號
(Before (i, foo, bar, 0, ptr1, ptr2)) 使用者的字串文字標記

顯示追蹤緩衝區的內容

啟用 JTRACE 後，每當發生核心恐慌時，系統都會自動轉儲追蹤緩衝區的內容，以及註冊轉儲和回溯追蹤。

使用者也可以使用核心殼，手動轉儲追蹤緩衝區的內容。只要在序列主控台中執行 k jtrace，即可轉儲目前的追蹤緩衝區，或執行 k jtrace -r 轉儲已復原的持續追蹤緩衝區內容 (如有)。請注意，在即時追蹤緩衝區傾印期間，追蹤功能會暫時停用，且不會有新的追蹤項目加入緩衝區。系統會將 JTRACE 巨集的叫用視為無操作。

範例

以下是追蹤緩衝區的傾印範例，該緩衝區已設定為使用小型項目，且有 4 kB 的儲存空間和 4 個 Per-CPU 最後事件記錄。使用兩個 JTRACE 巨集對系統呼叫的進入和退出進行檢測。標記用於保存所發出系統呼叫的字串文字名稱，而第一個通用引數則用於記錄布林值，指出追蹤記錄是否標示系統呼叫的開始或結束。

JTRACE: Recovered 166/166 entries
[  17.431102506][cpu 0] : 00000001 : (    0.000 uSec) : (futex_wait)
[  17.431107979][cpu 0] : 00000000 : (    5.473 uSec) : (nanosleep)
[  17.431109757][cpu 0] : 00000001 : (    1.778 uSec) : (nanosleep)
[  17.431118119][cpu 0] : 00000000 : (    8.362 uSec) : (futex_wake)
[  17.431131543][cpu 0] : 00000001 : (   13.424 uSec) : (futex_wake)
[  17.431134424][cpu 0] : 00000000 : (    2.881 uSec) : (futex_wake)
<snip>
[  17.437545001][cpu 3] : 00000001 : (    1.443 uSec) : (object_wait_async)
[  17.437547341][cpu 3] : 00000000 : (    2.340 uSec) : (port_wait)
[  17.437548263][cpu 3] : 00000001 : (    0.922 uSec) : (port_wait)
[  17.437666664][cpu 3] : 00000000 : (  118.401 uSec) : (channel_read_etc)
[  17.437668850][cpu 3] : 00000001 : (    2.186 uSec) : (channel_read_etc)
[  17.437678993][cpu 3] : 00000000 : (   10.143 uSec) : (debug_send_command)

JTRACE: Last recorded per-CPU events.
[  17.437001443][cpu 0] : 00000000 : (    0.000 uSec) : (futex_wait)
[  17.436016989][cpu 1] : 00000000 : (    0.000 uSec) : (channel_call_etc_noretry)
[  17.437066990][cpu 2] : 00000000 : (    0.000 uSec) : (futex_wait)
[  17.437678993][cpu 3] : 00000000 : (    0.000 uSec) : (debug_send_command)

JTRACE: Last log timestamp [  17.437678993]

以下是相同的範例，但這次已設定大型記錄。

JTRACE: Recovered 47/47 entries
[  24.270872973][cpu 2 tid     1301] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_post:84 (channel_read_etc)
[  24.270875158][cpu 2 tid     1301] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       2.185 uSec) : syscalls.cc:do_syscall_pre:59 (object_wait_async)
[  24.270879083][cpu 2 tid     1301] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       3.925 uSec) : syscalls.cc:do_syscall_post:84 (object_wait_async)
[  24.270886634][cpu 2 tid     1301] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       7.551 uSec) : syscalls.cc:do_syscall_pre:59 (port_wait)
[  24.273031016][cpu 1 tid     1295] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (    2144.382 uSec) : syscalls.cc:do_syscall_pre:59 (channel_write_etc)
[  24.273057126][cpu 1 tid     1295] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (      26.110 uSec) : syscalls.cc:do_syscall_post:84 (channel_write_etc)
<snip>
[  24.273871139][cpu 1 tid     2735] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       5.089 uSec) : syscalls.cc:do_syscall_post:84 (object_wait_async)
[  24.273875048][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       3.909 uSec) : syscalls.cc:do_syscall_pre:59 (port_wait)
[  24.273876820][cpu 1 tid     2735] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       1.772 uSec) : syscalls.cc:do_syscall_post:84 (port_wait)
[  24.274000887][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (     124.067 uSec) : syscalls.cc:do_syscall_pre:59 (channel_read_etc)
[  24.274003866][cpu 1 tid     2735] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       2.979 uSec) : syscalls.cc:do_syscall_post:84 (channel_read_etc)
[  24.274019066][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (      15.200 uSec) : syscalls.cc:do_syscall_pre:59 (debug_send_command)

JTRACE: Last recorded per-CPU events.
[  24.269107951][cpu 0 tid     2475] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (debug_read)
[  24.274019066][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (debug_send_command)
[  24.273785974][cpu 2 tid     1902] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (port_wait)
[  24.154375056][cpu 3 tid    28770] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (futex_wait)

JTRACE: Last log timestamp [  24.274019066]

追蹤記錄項目

您可以在編譯時將追蹤記錄項目設為「大型」或「小型」記錄 (請參閱「設定」)。追蹤緩衝區中的所有記錄都會採用相同的設定大小。您無法將小型記錄與大型記錄混合。大型項目是小型項目的超集。換句話說，大型項目包含小型記錄所含的所有欄位，以及一些額外的記錄。

由於系統可用的 DRAM 記憶體 (通常) 有限，因此當 JTRACE 設為永久性時，通常會使用小型記錄，否則則會使用大型記錄。不過，使用者可以覆寫這項行為，並在任何情況下強制使用小型或大型記錄。

小型項目

小型追蹤記錄會記錄下列欄位。

  • 時間戳記：記錄追蹤項目何時新增至緩衝區的時間戳記。以 ticks 單位記錄，但在傾印緩衝區時會轉譯為 clock monotonic 時間軸。
  • CPU ID：建立追蹤記錄項目的 CPU ID。
  • 標記：開發人員提供的 C 字串運算式常值指標，可協助偵錯。
  • a：開發人員提供的單一 32 位元通用欄位，可協助偵錯。

小型追蹤記錄項目目前每個會佔用 24 個位元組的儲存空間。

大型項目

大型項目會擴充小型項目，新增下列欄位。

  • File：追蹤點位置的檔案名稱。
  • 行：追蹤點位置的檔案中行號。
  • 函式：追蹤點位置的函式名稱。
  • TID：建立追蹤記錄項目的執行緒的數字執行緒 ID。
  • [a-d]：開發人員提供的四個 32 位元通用欄位 (而非小型記錄欄位)，可協助進行偵錯。
  • [e-f]：開發人員提供的兩個 64 位元通用欄位，可協助進行偵錯。

目前小型追蹤記錄項目每個都會佔用 72 個位元組的儲存空間。

每個 CPU 的最後事件記錄

除了主要追蹤緩衝區外，JTRACE 還可設定為分別儲存各個 CPU 記錄的最後事件。啟用後，系統會在主追蹤緩衝區 dump 完成後，分別轉儲這些記錄。

嘗試偵錯個別 CPU 的當機問題時，這項功能就非常實用，尤其是當這些問題導致 HW WDT 觸發時。如果 CPU 卡住的時間過長，其他 CPU 的追蹤記錄事件很可能會快速將卡住的 CPU 事件從追蹤記錄緩衝區中清除，特別是如果緩衝區位於持續性 RAM 中，且緩衝區較小時。卡住的 CPU 會提供個別的最後事件記錄，讓開發人員瞭解卡住的 CPU 在停止回應前執行的最後追蹤點。

如要啟用每個 CPU 的最後事件記錄，請將 jtrace_last_entry_storage configuration 參數設為等於目標硬體中 CPU 的數量。請注意，如果這個數字太低，則 CPU ID 大於等於設定數字的最後事件記錄將永遠不會記錄。如果數量太高，部分項目將永遠不會記錄任何記錄，而追蹤記錄緩衝區中保留的部分儲存空間也會浪費。

持久追蹤

總覽

有時，開發人員可能會遇到需要對整個系統掛起情形進行偵錯的情況。發生這些情況時，由於無法觀察系統狀態或導致系統異常的因素，因此很難獲得任何洞察資料。在這種情況下，持續追蹤功能可能會有所幫助。

當設定持續追蹤功能時，追蹤緩衝區會放置在引導程式提供給核心的特殊「持續性 RAM」中。通常，這是實體 RAM 的區域，可確保在系統啟動時不會受到引導程式影響，也就是說，您可以將資訊儲存在這個區域中，讓系統在完整的硬體重設程序中保留下來。

用量

如要啟用持續追蹤功能，請將 jtrace_enabled 設為 "persistent 值。發生當機後，請重新啟動系統 (透過 HW WDT 或目標中的手動重設行)。系統重新啟動後，如果已成功復原追蹤快取，您可以從序列殼層執行 k jtrace -r 來轉儲追蹤快取。請注意，持久性 RAM 通常只是由啟動載入程式鏈保留的 DRAM 部分，在早期啟動載入程式重新啟用動態 RAM 重新整理功能的期間，可能會發生損毀。追蹤系統會盡力從已復原的緩衝區中傾印所有可用的資料，並視需要改為區塊的十六進位資料。不過，如果重新啟動可能導致資料毀損，則應謹慎解讀此傾印結果。

目前並非所有目標都支援直接記憶體對應的永久 RAM 區域，而且即使支援，這個區域通常都非常小。目前只有 ARM64 目標支援這些區域，因此 x64 系統目前無法使用持續追蹤功能。使用者設定的 jtrace_target_buffer_size 值只是儲存空間要求，無法保證有足夠的儲存空間來支援要求。如果沒有，追蹤系統會盡可能要求儲存空間，並使用可預留的空間。啟動後，使用者可以透過從序列主控台執行 k jtrace -i，查看 JTRACE 子系統的目前設定。舉例來說，在具有 8 KB 永久性 RAM 的目標上，要求 32 KB 緩衝區可能會導致以下情況。

JTRACE configuration
--------------------
Requested Buffer Size  : 32768
Allocated Buffer Size  : 6144
Allocated Buffer Loc   : 0xffff00023fff8000
Per-CPU last entry cnt : 0
Large entries          : no
Persistent             : yes

要求 32 KB，但只有 8 KB 可用，其中 2 KB 已預留給前端的當機記錄，因此只剩 6 KB 可用於追蹤緩衝區。

注意事項

使用者應注意，JTRACE 系統本身具有某些副作用和限制。

  • 追蹤記錄不必須以單調遞增的時間戳記順序存在。由於環形緩衝區儲存空間屬於無鎖定性質，因此系統會先保留記錄時段，然後記錄時間戳記。快取錯失和 IRQ 等效果可能會導致兩個相鄰的追蹤記錄項目實際上有錯誤的時間戳記。
  • 從技術層面來說，兩個 CPU 同時寫入記錄，導致追蹤記錄損毀的情況是有可能發生 (但極不可能發生)。為達到這一點，CPU 需要保留一個插槽並開始寫入，然後遇到長時間延遲 (可能是由搶先權所造成)。在這個延遲期間，如果記錄的項目足以包覆追蹤緩衝區，第二個 CPU 就可能會在環狀緩衝區中宣告與第一個相同的空格，導致記錄到兩個 CPU 的資訊而導致記錄遭到破壞。
  • 在環形緩衝區中預留項目插槽時，會使用原子操作和取得/釋放記憶體順序意義。視目標架構的記憶體排序詳細資料而定，這項功能可能會影響某些錯誤的可重現性，因為來自兩個同時進行 JTRACE 的 CPU 的讀取和寫入作業，可能會突然無法在 JTRACE 點上重新排序。
  • 使用持續追蹤功能時，寫入 JTRACE 緩衝區的記錄必須立即從快取中清除，並傳送至實體記憶體，才能在系統自動重新啟動時正確保留。正確設定的 persistent_ram_allocation_granularity 值應可避免這些快取清除作業與其他作業重疊，但請注意，將項目寫入追蹤緩衝區的動作會導致系統比平常更頻繁地將少量額外資料從快取強制寫入實體 RAM。