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

總覽

簡介

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'

如要將這個儲存空間擴充至 64KB,並改用小型記錄,引數 應為:

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

為了啟用具有大量記錄的持續追蹤 (覆寫預設值) 以及儲存 4 個每個 CPU 的最終事件記錄 (同時覆寫預設值),要求 4 KB 最值得用的儲存空間,請在 fx set 行新增以下程式碼。

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

請注意,persistent前後必須加上 ""

新增追蹤點

需求條件

如要將追蹤點新增至檔案,使用者必須按照 在追蹤記錄點的每個檔案中新增下列 #include 陳述式 。

#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 巨集即可新增追蹤點。每個追蹤記錄點 必須指定字串常值「tag」,指定多個一般用途 做為已設定的追蹤記錄項目記錄支援的引數。標記 必須為字串文字,才能在每次重新啟動時都維持有效。 永久追蹤

一般用途引數不需要指定,且會預設為 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");
}

接下來加上標記的 Trace 陳述式看起來會像這樣 追蹤緩衝區最終顯示的時機

[   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 第一個 32 位元引數的值 (i)
00000006 第二個 32 位元引數的值 (foo)
00000001 第三個 32 位元引數的值 (bar)
00000000 第 4 個 32 位元引數 (0) 的值
ffffffff0024c720 第一個 64 位元引數的值 (ptr1)
ffffff9519077e60 第二個 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 的最終事件記錄)。 Syscall 進入和退出是使用兩個 JTRACE 巨集檢測。代碼之前為 用於保留所進行 sys 呼叫 的字串常值名稱,而 一般用途引數的用途是記錄布林值,指出追蹤記錄是否 標示系統呼叫的開始或結尾。

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 的當機情形進行偵錯 尤其是觸發並觸發硬體 WDT 的情況下,更是如此。 如果 CPU 長時間卡住,很可能是進行追蹤記錄 其他 CPU 的事件將迅速清除 追蹤緩衝區,尤其是由於緩衝區位於 永久性 RAM停滯 CPU 允許的個別最終事件記錄 開發人員能提前得知 CPU 停滯在哪個追蹤點 停止回應。

如要啟用個別 CPU 的最後事件記錄,請設定 jtrace_last_entry_storage configuration 參數等於 CPU 數量 執行動作請注意,如果這個數字太低,表示最終事件 值 >= 的 CPU 記錄則一律不會記錄。如果號碼是 部分項目永遠都不會有記錄 系統會浪費追蹤記錄緩衝區所保留的儲存空間。

持續追蹤

總覽

有時候,開發人員可能會想到 必須對整個系統當機進行偵錯發生這種情況時 難以深入分析 或是導致系統遺失的原因這種情況 不妨多多利用追蹤記錄。

設定用於持續追蹤時,追蹤緩衝區會 放置在特殊的「永久 RAM」中。 通常這是實體 RAM 區域 系統開機時,可能會發生 ,確保在該區域完全重設 有些人會將 Cloud Storage 視為檔案系統 但實際上不是

用量

如要啟用永久追蹤,請將 jtrace_enabled 設為值 "persistent」。當機後,重新啟動系統 (透過 HW WDT 或 目標)。系統重新啟動後,如果復原的追蹤記錄緩衝區 成功復原,可使用 k jtrace -r 序列殼層請注意,永久 RAM 通常只是 DRAM 的一個部分 停在系統啟動載入程式鏈結旁,短期內可能會出現損毀 早期的系統啟動載入程式必須重新啟用動態 RAM 重新整理功能。 追蹤系統會盡力從復原後的資料中轉儲 緩衝區,如有需要,可改回該區域的十六進位傾印 應在解讀此傾印結果時 (如果有的話) 可能會損毀。

目前並非所有目標都支援可記憶體直接記憶體的永久 RAM 區域和地區後,這個區域通常非常小目前僅適用於 ARM64 目標支援這些區域,因此目前並未提供永久追蹤功能 適用於 x64 系統已設定的 jtrace_target_buffer_size 值。 使用者只是要購買儲存空間,因此 足以支援要求如果沒有, 追蹤系統會聲明儲存空間盡可能多的儲存空間 預訂量啟動完成後, 從序列主控台執行 k jtrace -i,藉此建構 JTRACE 子系統。適用對象 舉例來說,永久 RAM 為 8 kB 的目標上,針對 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 資訊
  • 環形緩衝區的保留項目運算單元會使用 atomics 和 取得/釋放記憶體順序語意。視記憶體順序而定 目標架構的詳細資料,這「可能」可能會影響 例如讀取和寫入作業 屬於 JTRACEing 的 CPU 可能突然無法重新排序 橫跨 JTRACE 的各領域
  • 使用永久追蹤記錄時,必須寫入 JTRACE 緩衝區的記錄 從快取清除到實體記憶體 才能確保裝置在突然重新啟動時仍可正常運作。設定妥當 persistent_ram_allocation_granularity 的值應防止這些快取 與其他項目重疊的清潔作業,但應該 注意,將項目寫入追蹤記錄緩衝區會導致 額外從快取寫入實體 RAM 的資料量更多 比平時更常