1. 程式人生 > >使用日誌記錄來衡量效能(WWDC 2018 session 405)

使用日誌記錄來衡量效能(WWDC 2018 session 405)

引言

效能是實現卓越的使用者體驗的關鍵之一。當應用或者遊戲表現的執行迅速,反應靈敏時,使用者會更喜歡。但是軟體是很複雜的,當你的應用檢視做某事時,例如只是點了一個按鈕,但程式也有可能做了很多的事情,這就意味著你可以在一些看似不太可能的地方找到一些優化點。但這樣做,挖掘效能的優化點,有時就需要深入理解你的程式正在做些什麼。它需要您知道程式碼什麼時候執行的,以及特定的操作需要多長時間。所以這就體驗出來了有一個好的測試工具是多麼的重要。

我們知道開發更好的工具,並讓開發者使用這些工具,是我們幫助您成為更高效的開發人員的方法之一。所以今天我們要談談其中的一個工具——Signposts(路標)。

介紹Signposts及歷史

SignpostsOSLog家族的新成員,我們正準備讓它支援iOS和macOs。您可以在swift和C中使用它們,但最酷的是我們讓他們和Instruments整合在了一起。這就意味著Instruments可以獲取Signposts所產生的資料,並且讓深入你理解你的程式正在做什麼。

首先要介紹一點歷史,幾年前我們介紹了OSLog。這是我們現代化的呈現日誌記錄的工具。這是我們從系統中獲取除錯資訊的方法。它是在我們“效率”、“隱私”的目標下完成的。具體瞭解,請檢視WWDC 2016 Unified Logging and Activity Tracing

這裡你可以看到一個OSLog的例子,建立一個簡單的日誌控制代碼,並且像它傳送了一個Hello world。

let logHandle = OSLog(subsystem: "com.example.widget", category: "Setup")
os_log(.info, log: logHandle, "Hello, %{public}s!", world)

Signposts擴充套件了OSLogAPI,但它們是為效能用例而做的。這意味著它們正在傳達與效能相關的資訊,並且它們與我們的開發工具整合在一起,您可以使用Signposts對程式碼進行標註,然後啟動Instruments檢視類似的內容。因此,Instruments向您展示了您的程式正在做的事情的視覺化時間軸,以及Signposts

展示在上面。然後底部有個表,統計彙總和分析Signposts資料,資料分成一塊一塊的,可以讓您看到程式到底做了些什麼。
image

這個session,我將談談如何在您的程式碼中使用Signposts,以及展示一下他們的作用。然後展示Instruments中Signposts的視覺化介面,讓您瞭解Instruments和Signpost是如何協同工作的。那讓我們開始吧。

使用Signposts

讓我們從一個非常基礎的例子開始。想象一下這是你的應用。
image
你要研究的就是一個介面特定部分重新整理所需要的時間。你知道你需要載入一些圖片並在螢幕上展示。所以,在這個簡單、抽象的檢視中,可能你需要做的就是獲取圖片資源。
image
所有操作完成後,介面會重新整理。Signposts允許我們在一系列工作的開始和結尾進行標記,然後將這兩個時間點關聯起來,同時這兩個日誌事件也會互相關聯。這就需要呼叫Siginposts的兩個函式。os_signpost(.begin, ...)os_signpost(.end, ...)。圖中b箭頭代表開始,e箭頭代表結束。然後我們將這兩個時間點互相關聯,讓您瞭解這一段經過的時間。
image
在程式碼中,有一個簡單的演算法實現,對於我們介面中的每個元素,我們將獲取該資源,這正是我們想要去測量的。

for element in panel.elements {
    fetchAsset(for: element)
}

因此,為了將Signposts程式碼加入到基本的程式碼中,我們需要匯入OS模組,然後由於SiginpostsOSLog的一部分,所以我們需要建立一個日誌控制代碼。這個日誌控制代碼需要兩個引數一個是子系統,一個是類別。

子系統在整個專案中可能都是相同的,它看起來很像您的app的包名。它代表了元件或者軟體,或者是您正在使用的框架。

類別用於關聯,將相關的操作或者Signposts繫結在一起。之後我們會講到這麼做的好處。

當我們擁有了日誌控制代碼,我們只需要呼叫Siginposts.begin.end兩個函式即可。引數中,我們將日誌控制代碼傳遞過去,然後再傳遞一個Signpost的名字。名字是一個字串,用來標識我們感興趣的操作的時間間隔。

import os.signpost

let refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")

for element in panel.elements {
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
    fetchAsset(for: element)
    os_signpost(.end, log: refreshLog, name: "Fetch Asset")
}

image
所以返回之前的時間軸,它就變成了這個樣子。在每次開始、結束獲取資源時,我們都添加了一個路標。因為在開始和結束的路標的標識一樣,所以我們可以將他們兩者匹配在一起。但是,如果我們還想要測試整個操作的全部時間,整個重新整理過程是怎樣的,該如何去做呢?我們在程式碼中,只需要再新增一對新路標即可(新的名字)。

import os.signpost

let refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")

os_signpost(.begin, log: refreshLog, name: "Refresh Panel")
for element in panel.elements {
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
    fetchAsset(for: element)
    os_signpost(.end, log: refreshLog, name: "Fetch Asset")
}
os_signpost(.end, log: refreshLog, name: "Refresh Panel")

這時,我們的時間軸又發生了變化。
image

測量非同步任務的時間

上面是一個很簡單的例子。如果你的應用順序執行第一步、第二步、第三步等等,那麼這樣測量是非常有效的。但是我們會經常用到一些非同步的工作,他們可能同時發生,他們之間也可能會有重疊或者交叉。
image
在這種情況下,我們需要向系統提供一些額外的資訊,以便系統可以將這些路標彼此區分開來。到現在為止,我們在呼叫方法的時候只用到了名字,通過名字將相同路標的繫結在一起。名字已經確定了時間間隔,但是沒有給我們一種區分重疊時間間隔的方法,所以在這裡引入了Signpost IDs。路標ID將告訴系統哪些是相同型別的操作,但每個操作彼此不同。在路標開始和結尾傳遞相同的id,則系統知道這兩個是關聯的。你可以通過日誌控制代碼來得到一個路標ID。

let spid = OSSignpostID(log: refreshLog)
os_signpost(.begin, log: refreshLog, name: "Fetch Asset", signpostID: spid)
//  some code or even async...
os_signpost(.end, log: refreshLog, name: "Fetch Asset", signpostID: spid)

同樣你也可以通過一個物件來得到日誌控制代碼。如果你有一些物件代表您正在嘗試的工作,只要您使用該物件例項就會生成相同的路標ID。這就意味著您不用去存放路標ID,只需要通過物件去管理ID就好了。

let spid = OSSignpostID(log: refreshLog, object: element)

在視覺上,您可以將路標ID視為允許我們向每一個路標呼叫傳遞一些額外的上下文,這可以將特定操作的開始和結束標記互相關聯。
image
這很重要,因為這些操作不僅僅可以重疊,而且通常他們需要的時間也不同。
image
我們現在把示例中的fetchAsset從同步呼叫改為非同步呼叫。並且由於是非同步的,這些時間間隔可能會相互重疊,所以我們還要在建立路標時加上路標ID。

let refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")

let spidForRefresh = OSSignpostID(log: refreshLog)
os_signpost(.begin, log: refreshLog, name: "Refresh Panel", signpostID: spidForRefresh)

for element in panel.elements {
    //通過物件去建立路標ID
    let spid = OSSignpostID(log: refreshLog, object: element)
    //通過ID去記錄一個路標
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset", signpostID:spid)    
    fetchAssetAsync(for: element) {
        //每一個完成之後的回撥
        os_signpost(.end, log: refreshLog, name: "Fetch Asset", signpostID: spid)
    } 
}
//  全部完成完成的回撥
notifyWhenDone {
    os_signpost(.end, log: refreshLog, name: "Refresh Panel", signpostID: spidForRefresh)
}

這樣就完成了,您可以將Signposts視為一種分類或等級制度。所有的操作都通過日誌控制代碼相關聯,這意味著日誌分類。然後對我們感興趣的每個操作,我們給它一個路標名字,如果可能有重疊,我們在給他們路標ID,告訴系統雖然名字相同了,但是我希望通過ID區分。

這個介面設計的特別靈活,所以你可以控制起始點和結束點的所有引數,日誌控制代碼,路標名字及ID。只要傳遞的引數是一致的,起始點與結束點就可以對應上,即便他們寫在了不同的方法或者檔案中。我們之所以這樣做是因為希望您能夠將它應用到實際開發中。

在Signposts中新增元資料

您可能希望在路標中傳達一些額外的資訊,額外的效能相關的資訊。很巧,我們有一個方法來為路標新增元資料。下面是一個基本的路標。

os_signpost(.begin, log: log, name: "Compute Physics")

我們可以新增一個額外的字串(OSLog格式化的)引數。這允許您向開始點與結束點新增一些上下文。我們可以通過%d來傳遞整數。當然也可以傳遞其他的格式化型別的引數。

os_signpost(.begin, log: log, name: "Compute Physics", "%d %d %d %d",x1, y1, x2, y2)

os_signpost(.begin, log: log, name: "Compute Physics","%{public}s %.1f %.1f %.2f %.1f %.1f", description, x1, y1, m, x2, y2)

至於字串的長度,不用擔心,您可以自由、隨意的使用。該字串也會全部渲染到Instruments的介面中,或者仍然可以在程式中訪問附加的資料。

新增獨立事件

除了元資料之外,您可能還希望及時新增單獨的時間點。這就表示,除了開始的路標以及結尾的路標外,你可能還有一個路標,該路標沒有連線到特定的時間間隔,而是一些固定的時刻。為此,我們提供了一個帶有事件型別的路標。
image
用法與設定開始、結束的路標類似,只不過它標識一個單一的時間點。

os_signpost(.event, log: log, name: "Fetch Asset", "Fetched first chunk, size %u", size)
os_signpost(.event, log: log, name: "Swipe", "For action 0x%x", actionCode)

您可以在間隔的上下文中使用該方法,或者一些您想追蹤的與使用者互動無關等時間間隔無關的內容。如果您真的在調查一個性能上的問題,您可能會大量使用它。
image

有條件啟動Signposts

如果你啟用了一些路標,那麼他們通常預設是開啟的,但我想談談有條件的開啟和關閉它們。首先我要強調一下,路標是輕量級的。這說明我們已經做了很多優化。我們通過編譯器優化來完成這些工作,這些優化在編譯時就做了,而不是在執行時完成的。我們還推遲了很多工作,以便他們在Instruments後端完成。這意味著路標應該佔用很少的系統資源。我們之所有這樣做是因為我們希望儘量減少對您程式碼的影響。我們也做到了這一點,因為我們確保即使您的時間跨度非常小,也可以發出許多路標來獲取一些細粒度的測量結果。

但您可能希望能夠關閉路標。要做到一這點,我們將利用OSLog的功能,即禁用的日誌控制代碼。禁用的日誌控制代碼也是一個簡單的控制代碼。它的作用是針對該控制代碼進行的每個OSLog和os_signpost呼叫都會幾乎會變為無操作。事實上,如果你在C中採用這個,我們甚至會對你進行檢查,然後我們甚至不會評估其餘的引數。所以你可以在執行時更改這個控制代碼

舉個例子,讓我們回到第一個示例的程式碼上。我以一個環境變數作為條件,來初始化。如果包含該變數,那麼使用普通的os日誌建構函式;如果不包含,那麼將使用禁用的日誌控制代碼。

let refreshLog: OSLog
if ProcessInfo.processInfo.environment.keys.contains("SIGNPOSTS_FOR_REFRESH") {
    refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")
} else {
    refreshLog = .disabled
}
os_signpost(.begin, log: refreshLog, name: "Refresh Panel")
for element in panel.elements {
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
    fetchAsset(for: element)
    os_signpost(.end, log: refreshLog, name: "Fetch Asset")
}
os_signpost(.end, log: refreshLog, name: "Refresh Panel")

環境變數是您在除錯程式時可以在Xcode scheme中設定的內容。現在我說你不必在呼叫中進行更改,但這種方式相當昂貴並且只適用於除錯時。因此如果您有一些基於Instruments的特定的功能,你可以檢查特定的日誌控制代碼,檢視它是否打開了siginposts enabled屬性。然後試用該屬性來控制新增該附加操作。

if refreshLog.signpostsEnabled {
    let information = copyDescription() os_signpost(..., information)
}

C語言中的Signposts

上面我們所有示例都是swift的,但是C語言中也提供了路標。到目前為止,上述功能都是可用的:長控制代碼、使用不用的路標、以及管理路標識別符號。
image
那些對C語言中使用路標感興趣的人,推薦你們閱讀標頭檔案中的文件。文件中包含了所有資訊,都是從C語言開發人員的角度考慮的。

Instruments 10

現在介紹完如何在程式碼中應用路標,接下來很開心為大家介紹路標和Instruments是如何在一起工作的。向大家展示Instruments 10中三個重要的新功能,來幫助您使用路標資料。

  • 路標工具

    該工具允許您記錄、檢視和分析應用程式中所有的路標活動。

  • 興趣點

    談談什麼是興趣點,以及何時您要設定一個興趣點

  • 自定義工具

    介紹新的自定義工具,以及如何將它與路標一起使用,以獲得更精緻的路標展示。

路標

接下來就看下例子吧。示例的app名叫開拓者,主要是展示一些風景。
image
當我們滾動時,最初展示一個白色的背景,當圖片下載完之後,會填充到白色背景區域。這是一種常見的設計,儘管這樣設計可以提升一些使用者體驗,但很難分析它的效能,因為在這個過程中進行了很多非同步的活動。如果使用者快速滾動,那麼有可能出現某個單元格還沒有下載完畢之前,就已經要被重用了,那麼就必須取消下載。如果不取消的話,可能會有幾個並行下載,而展示出來的圖也不一定是我們想要的(圖和標題不對應)。接下來看看如何通過路標來分析這個應用吧。
首先,在每個單元格中,有一個startImageDownload方法。當我們需要下載圖片時會呼叫它,並傳遞要下載圖片的名字。方法內部,有一個圖片下載類,我們通過圖片名字和設定自己為委託來初始化該類。在這種情況下,由於downloader物件代表正在進行的併發活動,因為下載是非同步的,所以可以通過downloader來建立一個路標ID。接著在下載開始之前,呼叫os_signpost(.begin,...方法,設定日誌控制代碼、名稱、ID、以及一些元資料。然後開始下載圖片,並且將downloader設定為當前單元格正在執行的下載器。
image
圖片下載完畢的回撥中將圖片展示到螢幕上,然後呼叫os_siginpost(.end, ...方法,設定日誌控制代碼、名稱、ID、以及一些元資料。您會注意到,我們用xcode:size-in-bytes註釋了這個引數。它的作用是告訴Xcode和Instruments這個引數應該被視為展示和分析位元組大小。這種被稱作為工程型別。可以Instruments開發人員幫助文件中找到他們的詳細介紹。最後,我們下載完畢了,將下載器設定為空。
image
當然下載除了成功以外,還有失敗的情況,在單元格準備重用時,進行相關的路標設定。
image
設定完之後,就可以來進行分析了。開啟Instruments後,可以選擇一個空白的文件。
image
然後從右側新增中選擇os_signpost工具,並推動到軌跡中。
image
接下來就可以在app中操作了,一陣操作猛如虎之後,我們回到Instruments來看一下。
image
通過選擇某一段時間,可以檢視這段時間內的情況。我們可以看到左側的路標名稱Background Image,以及右側的一些使用元資料來註釋的時間段。
image
現在再縮小然後看看其他未知的追蹤,我們注意到我們最多隻有五個並行下載圖片的任務,這是一件好事,證明我們取消了。
image
檢視底部間隔的摘要,我們看到是按照類別、路標的名字、開始的訊息和結束的訊息來區分的。我們來看一共觸發了93次的圖片下載請求。其中location1觸發了12次,7次取消,5次下載成功,下載成功時間共計3.04秒,3.31MB。並且可以檢視每次請求時間的最小值、最大值和平均值。如果對某類資料感興趣,可以點選進入檢視詳細內容。
image
如果要檢視元資料相關的內容,可以進行篩選,然後檢視資料。
image
image
這是一種很好的方式來檢視您通過元資料傳達的值的統計分析。

興趣點

接下里,我們看看興趣點。回到應用,我們我們在主頁點選一個單元格,就會進入詳情頁面。
image
如果現在我們每次都能追蹤這些詳情頁面出現的時間就太好了,因為這樣我們就可以知道使用者正在做什麼,並且我們知道使用者在app中的哪個頁面。當然可以通過路標完成這件事,但是你需要在Instruments中把它拖到軌跡中,並且記錄所有的活動。這樣有點淡化了導航事件的重要性。所以我們提供了興趣點。

點在我們在詳情頁面的程式碼中檢視viewDidAppear方法,我們通過os_signpost(.event, ...來建立一個路標事件。這個事件要傳送到我們建立的稱之為興趣點的日誌控制代碼中。類別設定為興趣點,這正是Instruments尋找的一個特殊類別。
image
我們回到再次開啟Instruments選擇時間分析,會發現自動有了興趣點這一項。
image
然後開始錄製,從首頁進入詳情頁,選擇不同的單元格反覆執行,然後返回Instruments,就可以看到這些興趣點了。
image
因此您可以在看到使用者在哪個頁面,並且將其與其他效能資料相關聯。

自定義Instruments