總覽
簡介
JTRACE 是一個簡單、輕量的「貼身」追蹤系統，其用意是記錄開發人員新增的檢測設備產生的一系列追蹤事件記錄，協助開發人員對核心停止運作和自發重新啟動作業進行偵錯，並在發生核心錯誤時自動重新播放。這麼做的用意是讓開發人員能夠從核心程式碼的任何位置建立追蹤記錄，以便提供額外資訊 (除了註冊傾印和堆疊追蹤)，進而協助瞭解導致當機的事件序列。JTRACE 的實用屬性包括：
- 無鎖定的環形緩衝區資料結構：建立追蹤事件絕不會封鎖，並且絕對不會嘗試取得任何鎖定，以在早期初始化期間、任意鎖定內、硬式 IRQ 期間以及核心程式碼中的任何其他位置使用。
- 低負擔：建立追蹤事件是一項相對便宜的作業，因此較能檢測效能敏感的程式碼，並盡可能減少時間幹擾。
- 重新啟動後可選擇的持續性：平台允許，JTRACE 可能會設定為使用一些通常用於當機記錄儲存空間的永久 RAM，協助對與隨機重新啟動相關的問題進行偵錯，問題通常是觸發硬體監控計時器所致。
不適用的功能
JTRACE 並非生產追蹤系統，根據預設，系統會完全停用此功能，而且不會在實際工作環境版本中啟用。追蹤點「不是」由開發人員檢查變更內容，而保留在程式碼中。一般使用 JTRACE 需要開發人員在程式碼中加入追蹤記錄點、重現當機，然後修改現有的追蹤記錄點或新增追蹤記錄點，並持續重複努力，直到其根問題造成錯誤為止。一旦發現錯誤、瞭解並修正後，系統就會捨棄新增追蹤點的程式碼。
設定
JTRACE 的設定是透過透過 fx set 設定的建構引數控管。目前有 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 會停用，且未包含在核心版本中。如要啟用 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。
範例
如要啟用具有大型記錄和 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>
如果找不到 include 檔案，您可能需要將標頭新增至模組 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");
}
以下是標記追蹤緩衝區最終顯示時，「之前」標記的其中一個「之前」標記的追蹤記錄陳述式。
[ 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 後，只要發生核心錯誤，系統就會自動傾印追蹤記錄緩衝區的內容、註冊傾印和 Backtrace。
使用者也可以使用核心殼層手動傾印追蹤記錄緩衝區的內容。在序列主控台中，只要執行 k jtrace 來轉儲目前的追蹤記錄緩衝區，或執行 k jtrace -r 來傾印已復原的永久追蹤記錄緩衝區 (如有) 的內容。請注意，在轉儲即時追蹤緩衝區時，系統會暫時停用追蹤功能，不會再將新的追蹤記錄項目加入緩衝區。系統會將 JTRACE 巨集的叫用視為免人工管理。
範例
以下的追蹤記錄緩衝區傾印範例設定為使用小型項目，包含 4 KB 的儲存空間和 4 個每個 CPU 的最終事件記錄。已使用兩個 JTRACE 巨集檢測 Syscall 進入和結束。這個標記用於保存發出的系統呼叫字串常值名稱，而第一個一般用途引數用於記錄布林值，指出追蹤記錄標記是以 syscall 開始或是結尾。
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 設定為永久性時會使用小型記錄，以其他方式使用大型記錄。也就是說，使用者可能會覆寫這項行為，並在這兩種情況下強制執行小型或大型記錄。
小型項目
小型追蹤記錄項目會記錄下列欄位。
- 時間戳記：記錄追蹤記錄項目新增至緩衝區的時間戳記。以滴答單位記錄，但在傾印緩衝區時會翻譯成時鐘單調時間軸。
- CPU ID：建立追蹤記錄項目的 CPU 的 ID。
- 標記：指向開發人員提供的 C 字串常值指標，以協助偵錯。
a：由開發人員提供的單一 32 位元一般用途欄位，協助偵錯。
小型追蹤記錄項目目前佔用 24 個位元組的儲存空間。
大型項目
大型項目會擴充小型項目，新增下列欄位。
- 檔案：追蹤點的位置檔案名稱。
- 行：在追蹤點位置檔案中的行號。
- 函式：追蹤記錄點位置的函式名稱。
- TID：建立追蹤記錄項目的執行緒數字執行緒 ID。
[a-d]：由開發人員提供的四個 32 位元一般用途欄位 (而不是小記錄的欄位)，以協助偵錯。[e-f]：由開發人員提供的兩個 64 位元一般用途欄位，以協助偵錯。
小型追蹤記錄項目目前佔用 72 位元組的儲存空間。
每個 CPU 的最終事件記錄
除了主要追蹤記錄緩衝區外，您也可以設定 JTRACE 以個別儲存每個 CPU 記錄的最後一個事件。啟用後，系統會在主要追蹤記錄緩衝區傾印完成後，分別傾印這些記錄。
嘗試對個別 CPU 的停止運作進行偵錯時，這項功能非常實用，尤其如果會導致 HW WDT 觸發，更是如此。如果 CPU 停滯於任何大量時間，則來自其他 CPU 的追蹤事件可能會從追蹤記錄緩衝區中迅速清除事件，尤其是因為緩衝區位於永久 RAM 中，而空間較小時。針對 CPU 停滯情形單獨的最終事件記錄，可讓開發人員在 CPU 停止回應之前，得知最後所執行的追蹤記錄點。
如要啟用「每個 CPU 的最終事件記錄」，請將 jtrace_last_entry_storage
設定參數設為等於目標硬體中顯示的 CPU 數量。請注意，如果這個數字太低，CPU ID 的最終事件記錄 >= 系統一律不會記錄已設定的數字。如果數量過高，某些項目絕不會有記錄的記錄，而會浪費在追蹤緩衝區中的部分儲存空間。
永久追蹤
總覽
開發人員有時可能正遭遇自己需要對整個系統停止運作進行偵錯的位置。發生這類情況時，想取得任何深入分析可能並不容易，因為所有觀測系統狀態或導致該系統狀態的能力喪失。在這種情況下，持續追蹤或許就能派上用場。
設定用於永久追蹤時，追蹤記錄緩衝區會放在系統啟動載入程式提供給核心的特殊「永久 RAM」中。通常，這是實體 RAM 區域，因為系統啟動載入程式不會遭到系統啟動載入程式覆蓋。也就是說，可能將資訊放入管理區域中，在系統完全重設 HW 後仍繼續保有效力。
使用方法
如要啟用永久追蹤功能，請將 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 的目標，要求 32kB 緩衝區的要求可能會產生下列結果。
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 領取，進而導致這兩個 CPU 記錄的資訊毀損。
- 環形緩衝區中項目版位的預留方式使用原子學和取得/釋放記憶體順序語意。視目標架構的記憶體排序細節而定，這項動作可能會影響部分錯誤的可重現性，因為從兩個不同 CPU 執行讀取和寫入作業，這些 CPU 也屬於 JTRACE，可能突然無法在 JTRACE 的點重新排列。
- 使用永久追蹤時，寫入 JTRACE 緩衝區的記錄必須立即從快取完整清除到實體記憶體，才能在每次重新啟動時妥善繼續保留。正確設定的
persistent_ram_allocation_granularity值應可避免這些快取清理作業與其他任何作業重疊，但應注意，將項目寫入追蹤記錄緩衝區時，會導致系統以比一般情況更頻繁地強制從快取到實體 RAM 的額外資料。