追查出異步執(zhí)行的代碼中出現(xiàn)的錯(cuò)誤往往是一件非常困難的事,因?yàn)闂W粉?(stack trace) 局限于發(fā)生崩潰的線程,這就意味著你無(wú)法獲得全部的上下文信息。與此同時(shí),編寫異步代碼卻得益于 libdispatch,運(yùn)行隊(duì)列 (operation queues) 和 XPC 提供的 API 變得越發(fā)的簡(jiǎn)單。
活動(dòng)追蹤是一項(xiàng) iOS 8 和 OS X 10.10 新引入的技術(shù),它正是為了幫助我們更好地解決上面提到的這個(gè)問(wèn)題。今年的 WWDC 有一個(gè)有關(guān)這個(gè)主題非常棒的 session,不過(guò)我們認(rèn)為在這里為它另外寫一篇簡(jiǎn)介也是一個(gè)好主意,畢竟知道它的人還不多。
活動(dòng)追蹤技術(shù)最基本的思想是,用一個(gè)活動(dòng)匯集響應(yīng)某個(gè)用戶交互行為或其他事件的全部工作,無(wú)論這些工作是同步的執(zhí)行的還是被分配到其他隊(duì)列和進(jìn)程中去的。舉個(gè)例子來(lái)說(shuō),如果用戶在你的應(yīng)用中觸發(fā)了一個(gè)刷新然后崩潰了,即使這個(gè)崩潰是發(fā)生在其他的隊(duì)列中或者有其他的代碼路徑也能運(yùn)行到崩潰的代碼,但你總能知道就是“刷新”這個(gè)特定的用戶行為造成了接下來(lái)發(fā)生的崩潰。
活動(dòng)追蹤由三部分組成:活動(dòng),面包屑 (譯者注:參考面包屑導(dǎo)航) 和追蹤信息。我們會(huì)在接下來(lái)詳細(xì)探討這三部分,在這里先給出要點(diǎn):活動(dòng)可以在跨隊(duì)列跨進(jìn)程的情況下幫助你追蹤出導(dǎo)致崩潰發(fā)生的事件。面包屑可以幫你跨越多個(gè)活動(dòng)畫出導(dǎo)致崩潰發(fā)生的事件軌跡。最后,追蹤信息可以幫助你為當(dāng)前活動(dòng)添加更詳細(xì)的信息。出現(xiàn)任何問(wèn)題,這三種信息都會(huì)出現(xiàn)在最終的崩潰報(bào)告中。
在我們進(jìn)入細(xì)節(jié)講解之前,讓我簡(jiǎn)單的提一下使用活動(dòng)追蹤過(guò)程中可能的坑:如果活動(dòng)追蹤信息沒(méi)有顯示出來(lái),檢查 system.log 中是否有 diagnosticd 這個(gè)守護(hù)進(jìn)程 (譯者注:參考守護(hù)進(jìn)程) 給出的類似 "Signature Validation Failed" 的信息,你可以會(huì)遇到代碼簽名的問(wèn)題。此外,注意在 iOS 上活動(dòng)追蹤只能在真機(jī)上工作,在模擬器上不行。
活動(dòng)是這項(xiàng)新技術(shù)的核心部分。一個(gè)活動(dòng)匯集了響應(yīng)一個(gè)事件所需的全部代碼運(yùn)行過(guò)程,而無(wú)論代碼是運(yùn)行在哪個(gè)隊(duì)列哪個(gè)進(jìn)程中的。這樣在代碼運(yùn)行過(guò)程中出現(xiàn)任何問(wèn)題,都可以輕易地追蹤回造成崩潰的源頭的事件。
活動(dòng)追蹤集成在 AppKit 和 UIKit 中,所以每當(dāng)一個(gè)用戶界面事件通過(guò) target-action 機(jī)制傳遞,一個(gè)活動(dòng)會(huì)自動(dòng)開(kāi)啟。對(duì)于不會(huì)向響應(yīng)鏈發(fā)送事件的用戶交互,例如點(diǎn)擊 table view cell,你就需要自己手動(dòng)初始化一個(gè)活動(dòng)。
啟動(dòng)一個(gè)活動(dòng)非常簡(jiǎn)單:
#import <os/activity.h>
os_activity_initiate("activity name", OS_ACTIVITY_FLAG_DEFAULT, ^{
// do some work...
});
這個(gè) API 會(huì)同步地執(zhí)行 block,在 block 中運(yùn)行的任何代碼,即使是那些你分配到其他隊(duì)列上去運(yùn)行的工作或者進(jìn)行了 XPC 調(diào)用,都會(huì)被歸為這個(gè)活動(dòng)中。第一個(gè)參數(shù)是活動(dòng)的標(biāo)記,必須賦予一個(gè)字符串常量 (活動(dòng)追蹤 API 中其他字符串參數(shù)也都必須是常量)。
第二個(gè)參數(shù),OS_ACTIVITY_FLAG_DEFAULT,是你要新建一個(gè)全新活動(dòng)的標(biāo)識(shí)。如果你想在一個(gè)已經(jīng)存在的活動(dòng)中創(chuàng)建一個(gè)新的活動(dòng),那么必須使用 OS_ACTIVITY_FLAG_DETACHED。舉例來(lái)說(shuō),當(dāng)響應(yīng)一個(gè)用戶交互控件發(fā)送的行為信息時(shí),AppKit 已經(jīng)為你開(kāi)啟一個(gè)活動(dòng)。如果你想在這個(gè)用戶交互響應(yīng)沒(méi)有完成的時(shí)候開(kāi)啟一個(gè)活動(dòng),你就需要一個(gè)分離的活動(dòng)。
There are other variants of this API that work in the same away — a function-based one (os_activity_initiate_f), and one that consists of a pair of macros:
這個(gè) API 有幾個(gè)同樣功能的變體,一個(gè)基于函數(shù) (os_activity_initiate_f),一個(gè)由幾個(gè)宏命令組成:
os_activity_t activity = os_activity_start("label", OS_ACTIVITY_FLAG_DEFAULT);
// do some work...
os_activity_end(activity);
注意你必須設(shè)置至少一個(gè)追蹤信息,否則活動(dòng)就不會(huì)出現(xiàn)在崩潰報(bào)告或者其他任何形式的查看方式中。在后面會(huì)有更多有關(guān)追蹤信息的細(xì)節(jié)。
面包屑所起到的作用就像它的名字所暗示的那樣:當(dāng)代碼出現(xiàn)崩潰,你的代碼會(huì)留下一個(gè)可以說(shuō)明上下文信息的跨活動(dòng)事件標(biāo)記軌跡。添加面包屑非常的簡(jiǎn)單:
os_activity_set_breadcrumb("event description");
事件被存儲(chǔ)在一個(gè)環(huán)形的緩沖區(qū)內(nèi),這個(gè)緩沖區(qū)只記錄最近運(yùn)行的50個(gè)事件。所以這個(gè) API 只應(yīng)該用來(lái)標(biāo)記宏觀的事件,比如像特定的用戶交互行為。
注意調(diào)用這個(gè) API 只能在一個(gè)活動(dòng)過(guò)程當(dāng)中時(shí)有效:將當(dāng)前這個(gè)活動(dòng)標(biāo)記為一個(gè)面包屑。這也意味著每一個(gè)活動(dòng)你只能標(biāo)記一次,接下來(lái)的調(diào)用會(huì)被系統(tǒng)忽略。
追蹤信息用來(lái)為活動(dòng)添加附加的說(shuō)明信息,就跟你使用 log 信息的目的一樣。你可以用來(lái)向崩潰報(bào)告添加一些重要的說(shuō)明信息,這樣就可以使你更容易理解造成問(wèn)題出現(xiàn)的根源。在一個(gè)活動(dòng)中,一個(gè)簡(jiǎn)單的追蹤信息可以這樣添加:
#import <os/trace.h>
os_trace("my message");
除此之外,追蹤信息可以起到更大的作用。os_trace 的第一個(gè)參數(shù)是一個(gè)格式化字符串,和你在 printf 或 NSLog 中的用法一樣。不過(guò) os_trace 有一些限制:格式化字符串最長(zhǎng)只能包含 100 個(gè)字符和最多 7 個(gè)標(biāo)量值的占位符。這就意味著你不能輸出字符串,如果你嘗試輸出字符串,字符串會(huì)被一個(gè)占位符所替換。
下面是兩個(gè)在 os_trace 中使用格式化字符串的例子:
os_trace("Received %d creates, %d updates, %d deletes", created, updated, deleted);
os_trace("Processed %d records in %g seconds", count, time);
我在嘗試使用這個(gè) API 時(shí)偶然發(fā)現(xiàn)了一個(gè)坑,那就是如果沒(méi)有從發(fā)生崩潰的線程中發(fā)送出來(lái)追蹤信息,那么所有的追蹤信息都不會(huì)出現(xiàn)在崩潰報(bào)告中。
在 os_trace 的基礎(chǔ)上有好幾個(gè)功能相似的 API。首先是 os_trace_debug,可以用來(lái)只在調(diào)試模式下輸出追蹤信息。在生產(chǎn)環(huán)境中這會(huì)很有幫助,可以減少環(huán)形緩沖區(qū)存儲(chǔ)的無(wú)用追蹤信息,這樣你就可以得到最有價(jià)值的那些信息。要開(kāi)啟調(diào)試模式,需要設(shè)置環(huán)境變量 OS_ACTIVITY_MODE 為 debug。
除此之外,還有兩個(gè)功能相近的宏命令可以輸出追蹤信息:os_trace_error 和 os_trace_fault。前者可以用來(lái)表明出現(xiàn)了未預(yù)料到的錯(cuò)誤,后者用來(lái)表明出現(xiàn)了致命的錯(cuò)誤,比如說(shuō)馬上就要崩潰了。
前面我們提到了,標(biāo)準(zhǔn)的 os_trace API 只接受一個(gè)限制長(zhǎng)度和標(biāo)量類型的格式化字符串。這樣的設(shè)計(jì)是基于對(duì)隱私性,安全性和運(yùn)行效率的考慮。但是,當(dāng)你在調(diào)試一個(gè)問(wèn)題的時(shí)候,總有一些情況下會(huì)想要得到更多的數(shù)據(jù)。這個(gè)時(shí)候帶有負(fù)載 (payload) 的追蹤信息就派上了用場(chǎng)了。
帶有負(fù)載的追蹤信息對(duì)應(yīng)的 API 是 os_trace_with_payload,初看可能會(huì)有些奇怪:它類似于 os_trace,這個(gè) API 接收一個(gè)格式化字符串,一個(gè)可變數(shù)量的參數(shù)值,和一個(gè)帶有 xpc_object_t 類型參數(shù)的 block。這個(gè) block 在生產(chǎn)環(huán)境中不會(huì)被調(diào)用,也就不會(huì)產(chǎn)生額外開(kāi)銷。不同的是,在調(diào)試的過(guò)程中你可以在 block 唯一的字典參數(shù)中存儲(chǔ)任何你想要的數(shù)據(jù)。
os_trace_with_payload("logged in: %d", guid, ^(xpc_object_t xdict) {
xpc_dictionary_set_string(xdict, "name", username);
});
這個(gè) block 的參數(shù)類型之所以是 XPC 對(duì)象,是因?yàn)樵诨顒?dòng)追蹤技術(shù)的底層使用了 diagnosticd 守護(hù)進(jìn)程收集數(shù)據(jù)。通過(guò) API xpc_dictionary_set_* 設(shè)置這個(gè)字典對(duì)象的值就是在與這個(gè)進(jìn)程進(jìn)行通信。你可以通過(guò)命令行工具 ostraceutil 來(lái)查看負(fù)載的數(shù)據(jù),關(guān)于這個(gè)工具我們接下來(lái)會(huì)深入探討。
我們之前討論的所有與 os_trace 相似的宏命令都可以進(jìn)行負(fù)載。與上面使用的 os_trace_with_payload 很像,我們還有 os_trace_debug_with_payload,os_trace_error_with_payload,和 os_trace_fault_with_payload。
除了崩潰報(bào)告之外你還有兩種辦法可以查看活動(dòng)追蹤的輸出。首先,活動(dòng)追蹤集成在調(diào)試器中。在 LLDB 的控制臺(tái)中輸入 thread info,你可以得到當(dāng)前線程中當(dāng)前進(jìn)行的活動(dòng)和追蹤的信息。
(lldb) thread info
thread #1: tid = 0x19514a, 0x000000010000125b ActivityTracing2`__24-[ViewController crash:]_block_invoke_4(.block_descriptor=<unavailable>) + 27 at ViewController.m:26, queue = 'com.apple.main-thread', activity = 'crash button pressed', 1 messages, stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
Activity 'crash button pressed', 0x8e700000005
Current Breadcrumb: button pressed
1 trace messages:
message1
另一種選擇是使用命令行工具 ostraceutil,在終端中運(yùn)行
sudo ostraceutil -diagnostic -process <pid> -quiet
(將 <pid> 替換為進(jìn)程 id) 會(huì)輸出如下信息 (有縮減)
Process:
==================
PID: 16992
Image_uuid: FE5A6C31-8710-330A-9203-CA56366876E6
Image_path: [...]
Application Breadcrumbs:
==================
Timestamp: 59740.861604, Breadcrumb ID = 6768, Name = 'Opened theme picker', Activity ID: 0x000008e700000001
Timestamp: 59742.202451, Breadcrumb ID = 6788, Name = 'button pressed', Activity ID: 0x000008e700000005
Activity:
==================
Activity ID: 0x000008e700000005
Activity Name: crash button pressed
Image Path: [...]
Image UUID: FE5A6C31-8710-330A-9203-CA56366876E6
Offset: 0x1031
Timestamp: 59742.202350
Reason: none detected
Messages:
==================
Timestamp: 59742.202508
FAULT
Activity ID: 0x000008e700000005
Trace ID: 0x0000c10000001ac0
Thread: 0x1951a8
Image UUID: FE5A6C31-8710-330A-9203-CA56366876E6
Image Path: [...]
Offset: 0x118d
Message: 'payload message'
----------------------
Timestamp: 59742.202508
RELEASE
Trace ID: 0x0000010000001aad
Offset: 0x114c
Message: 'message2'
----------------------
Timestamp: 59742.202350
RELEASE
Trace ID: 0x0000010000001aa4
Thread: 0x19514a
Offset: 0x10b2
Message: 'message1'
真正的輸出會(huì)比 LLDB 控制臺(tái)的輸出多很多,因?yàn)檫€包括了面包屑軌跡和所有線程的追蹤信息。
除了使用 ostraceutil 的 -diagnostic 參數(shù)之外,我們還可以使用 -watch 參數(shù)動(dòng)態(tài)地查看追蹤信息和面包屑的輸出。在這種模式下,還會(huì)輸出追蹤信息的負(fù)載數(shù)據(jù)。
[...]
----------------------
Timestamp: 60059.327207
FAULT
Trace ID: 0x0000c10000001ac0
Offset: 0x118d
Message: 'payload message'
Payload: '<dictionary: 0x7fd2b8700540> { count = 1, contents =
"test-key" => <string: 0x7fd2b87000c0> { length = 10, contents = "test-value" }
}'
----------------------
[...]
在寫下這篇文章的時(shí)候,Swift 還不能直接調(diào)用活動(dòng)追蹤 API。
如果你想在一個(gè) Swift 項(xiàng)目中使用活動(dòng)追蹤,就必須創(chuàng)建一個(gè) Objective-C 的封裝,使得 Swift 可以通過(guò)橋接頭文件 (bridging header) 來(lái)調(diào)用那些 API。注意活動(dòng)追蹤那些宏命令要求字符串是常量,也就是說(shuō)你不能直接用封裝函數(shù)的參數(shù)做活動(dòng)追蹤 API 的參數(shù)。為了說(shuō)明這一點(diǎn),下面這樣的調(diào)用是不起作用的:
void sendTraceMessage(const char *msg) {
os_trace(msg); // this doesn't work!
}
一種可能的解決方法是定義特定的輔助函數(shù)像這樣:
void traceLogin(int guid) {
os_trace("Login: %d", guid);
}
活動(dòng)追蹤作為一個(gè)新的調(diào)試工具非常受歡迎,它使得我們更容易診斷異步代碼中出現(xiàn)的錯(cuò)誤。我們都應(yīng)該將標(biāo)記活動(dòng)面包屑和追蹤信息作為編碼的新習(xí)慣。
對(duì)于那些已經(jīng)在正式生產(chǎn)環(huán)境中使用 Swift 的人來(lái)說(shuō),目前最大的遺憾是 Swift 不能夠直接調(diào)用。希望 Swift 的集成只是一個(gè)不會(huì)很久遠(yuǎn)的時(shí)間問(wèn)題。