剖析

Profile 模組提供工具,協助開發人員提升其程式碼的效能。使用時,它會對執行的程式碼進行測量,並產生輸出,協助您了解在個別行 (line) 上花費多少時間。最常見的用法是找出「瓶頸」,作為最佳化的目標。

Profile 實作一種稱為「抽樣」或 統計剖析器 的技術。它的運作方式是在任何任務執行期間定期擷取回溯。每個回溯會擷取目前執行的函式和行號,以及導致此行的完整函式呼叫鏈,因此是執行狀態的「快照」。

如果執行時間大部分花在執行特定程式碼列,這列程式碼會頻繁出現在所有回溯追蹤中。換句話說,特定程式碼列的「成本」–或實際上,包含此程式碼列在內的函式呼叫順序的成本–與其在所有回溯追蹤中出現的頻率成正比。

抽樣分析器不會提供完整的逐行涵蓋率,因為回溯追蹤會間隔發生(在 Unix 系統上預設為 1 毫秒,在 Windows 上為 10 毫秒,雖然實際排程會受到作業系統負載影響)。此外,正如以下進一步說明,由於樣本是在所有執行點的稀疏子集中收集,因此抽樣分析器收集的資料會受到統計雜訊影響。

儘管有這些限制,抽樣分析器仍有顯著的優點

  • 您不必對程式碼進行任何修改即可進行計時測量。
  • 它可以分析 Julia 的核心程式碼,甚至(選擇性地)分析 C 和 Fortran 函式庫。
  • 透過「不頻繁」執行,效能開銷非常小;在分析期間,您的程式碼幾乎可以以原生速度執行。

基於這些原因,建議您在考慮任何替代方案之前,先嘗試使用內建的抽樣分析器。

基本用法

讓我們使用一個簡單的測試案例

julia> function myfunc()
           A = rand(200, 200, 400)
           maximum(A)
       end

建議先執行您打算分析的程式碼至少一次(除非您想分析 Julia 的 JIT 編譯器)

julia> myfunc() # run once to force compilation

現在我們準備分析此函式

julia> using Profile

julia> @profile myfunc()

有幾個圖形瀏覽器可以查看分析結果。其中一個視覺化「系列」基於 FlameGraphs.jl,每個系列成員提供不同的使用者介面

一種完全獨立的剖析視覺化方法是 PProf.jl,它使用外部的 pprof 工具。

不過,在這裡,我們將使用標準函式庫附帶的文字顯示

julia> Profile.print()
80 ./event.jl:73; (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
 80 ./REPL.jl:97; macro expansion
  80 ./REPL.jl:66; eval_user_input(::Any, ::Base.REPL.REPLBackend)
   80 ./boot.jl:235; eval(::Module, ::Any)
    80 ./<missing>:?; anonymous
     80 ./profile.jl:23; macro expansion
      52 ./REPL[1]:2; myfunc()
       38 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type{B...
        38 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr{F...
       14 ./random.jl:278; rand
        14 ./random.jl:277; rand
         14 ./random.jl:366; rand
          14 ./random.jl:369; rand
      28 ./REPL[1]:3; myfunc()
       28 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinear,...
        3  ./reduce.jl:426; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...
        25 ./reduce.jl:428; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...

此顯示的每一行代表程式碼中的特定點(行號)。縮排用於表示函式呼叫的巢狀順序,縮排較多的行在呼叫順序中較深。在每一行中,第一個「欄位」是回溯(樣本)的數量,取自此行或此行執行的任何函式。第二個欄位是檔案名稱和行號,第三個欄位是函式名稱。請注意,隨著 Julia 程式碼的變更,特定的行號可能會變更;如果您想繼續進行,最好自己執行此範例。

在此範例中,我們可以看到呼叫的頂層函式位於檔案 event.jl 中。這是當您啟動 Julia 時執行 REPL 的函式。如果您檢查 REPL.jl 的第 97 行,您會看到這是呼叫函式 eval_user_input() 的地方。這是評估您在 REPL 中輸入內容的函式,由於我們以互動方式工作,因此當我們輸入 @profile myfunc() 時,便會呼叫這些函式。下一行反映了 @profile 巨集中執行的動作。

第一行顯示在 event.jl 的第 73 行採取了 80 個回溯,但這並不表示這行本身「昂貴」:第三行揭示了這 80 個回溯實際上都是觸發於其對 eval_user_input 的呼叫中,以此類推。若要找出實際耗時的作業,我們需要更深入地查看呼叫鏈。

此輸出的第一個「重要」行是這一行

52 ./REPL[1]:2; myfunc()

REPL 指的是我們在 REPL 中定義了 myfunc,而不是將其放入檔案中;如果我們使用檔案,這將顯示檔案名稱。[1] 顯示函式 myfunc 是在此 REPL 會話中評估的第一個表達式。myfunc() 的第 2 行包含對 rand 的呼叫,而且有 52 個(共 80 個)回溯發生在此行。在該行下方,您可以在 dSFMT.jl 中看到對 dsfmt_fill_array_close_open! 的呼叫。

再往下一點,您會看到

28 ./REPL[1]:3; myfunc()

myfunc 的第 3 行包含對 maximum 的呼叫,而且有 28 個(共 80 個)回溯在此採取。在該行下方,您可以在 base/reduce.jl 中看到對此類輸入資料執行 maximum 函式中耗時作業的特定位置。

總體而言,我們可以暫時得出結論,產生隨機數的成本大約是尋找最大元素的兩倍。我們可以透過收集更多樣本,來增加對此結果的信心

julia> @profile (for i = 1:100; myfunc(); end)

julia> Profile.print()
[....]
 3821 ./REPL[1]:2; myfunc()
  3511 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type...
   3511 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr...
  310  ./random.jl:278; rand
   [....]
 2893 ./REPL[1]:3; myfunc()
  2893 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinea...
   [....]

一般來說,如果您在某一行收集了 N 個樣本,您可以預期不確定性約為 sqrt(N)(排除其他雜訊來源,例如電腦執行其他任務的忙碌程度)。此規則的主要例外是垃圾收集,它執行頻率低,但往往相當昂貴。(由於 Julia 的垃圾收集器是用 C 編寫的,因此可以使用下面描述的 C=true 輸出模式或使用 ProfileView.jl 來偵測此類事件。)

這說明了預設的「樹狀」傾印;另一種選擇是「平面」傾印,它會累積計數,而與它們的巢狀無關

julia> Profile.print(format=:flat)
 Count File          Line Function
  6714 ./<missing>     -1 anonymous
  6714 ./REPL.jl       66 eval_user_input(::Any, ::Base.REPL.REPLBackend)
  6714 ./REPL.jl       97 macro expansion
  3821 ./REPL[1]        2 myfunc()
  2893 ./REPL[1]        3 myfunc()
  6714 ./REPL[7]        1 macro expansion
  6714 ./boot.jl      235 eval(::Module, ::Any)
  3511 ./dSFMT.jl      84 dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_s...
  6714 ./event.jl      73 (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
  6714 ./profile.jl    23 macro expansion
  3511 ./random.jl    431 rand!(::MersenneTwister, ::Array{Float64,3}, ::In...
   310 ./random.jl    277 rand
   310 ./random.jl    278 rand
   310 ./random.jl    366 rand
   310 ./random.jl    369 rand
  2893 ./reduce.jl    270 _mapreduce(::Base.#identity, ::Base.#scalarmax, :...
     5 ./reduce.jl    420 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
   253 ./reduce.jl    426 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
  2592 ./reduce.jl    428 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
    43 ./reduce.jl    429 mapreduce_impl(::Base.#identity, ::Base.#scalarma...

如果您的程式碼有遞迴,一個潛在會令人困惑的點是「子」函式中的一行可以累積比總回溯更多的計數。考量下列函式定義

dumbsum(n::Integer) = n == 1 ? 1 : 1 + dumbsum(n-1)
dumbsum3() = dumbsum(3)

如果您要對 dumbsum3 進行剖析,而回溯是在它執行 dumbsum(1) 時進行的,那麼回溯會看起來像這樣

dumbsum3
    dumbsum(3)
        dumbsum(2)
            dumbsum(1)

因此,這個子函式會得到 3 個計數,即使父函式只得到一個。這個「樹狀」表示會讓這點更清楚,也因此(還有其他原因)這可能是檢視結果最實用的方式。

累積和清除

來自 @profile 的結果會累積在一個緩衝區中;如果您在 @profile 下執行多段程式碼,那麼 Profile.print() 會顯示您合併的結果。這可能非常有用,但有時您會想要重新開始;您可以使用 Profile.clear() 來執行此動作。

控制剖析結果顯示的選項

Profile.print 有比我們到目前為止描述的更多選項。我們來看一下完整的宣告

function print(io::IO = stdout, data = fetch(); kwargs...)

我們先來討論兩個位置引數,稍後再討論關鍵字引數

  • io – 讓您可以將結果儲存到緩衝區,例如檔案,但預設是列印到 stdout(主控台)。

  • data – 包含您想要分析的資料;預設情況下,這是從 Profile.fetch() 取得的,它會從預先配置的緩衝區中提取回溯。例如,如果您想要剖析剖析器,您可以說

    data = copy(Profile.fetch())
    Profile.clear()
    @profile Profile.print(stdout, data) # Prints the previous results
    Profile.print()                      # Prints results from Profile.print()

關鍵字引數可以是下列項目的任意組合

  • 格式 – 如上所述,決定是否以(預設,:tree)或不帶(:flat)表示樹狀結構的縮排來列印回溯。
  • C – 如果為 true,則顯示來自 C 和 Fortran 程式碼的回溯(通常會排除)。嘗試使用 Profile.print(C = true) 執行簡介範例。這在決定造成瓶頸的是 Julia 程式碼還是 C 程式碼時非常有幫助;設定 C = true 也能改善巢狀結構的可解讀性,但會讓剖析轉儲更長。
  • 合併 – 有些程式碼行包含多個運算;例如,s += A[i] 同時包含陣列參考(A[i])和加總運算。這些對應於產生機器碼中的不同行,因此在回溯時可能會擷取到此行中兩個或以上的不同位址。合併 = true 會將它們合併在一起,這可能是您通常想要的,但您可以使用 合併 = false 為每個唯一的指令指標產生個別輸出。
  • 最大深度 – 在 :tree 格式中限制深度高於 最大深度 的框架。
  • 排序依據 – 控制 :flat 格式中的順序。:filefuncline(預設)依據原始碼行排序,而 :count 則依據收集到的樣本數排序。
  • 雜訊底限 – 限制低於樣本經驗法則雜訊底限的框架(僅適用於格式 :tree)。建議嘗試的值為 2.0(預設為 0)。此參數會隱藏 n <= 雜訊底限 * √N 的樣本,其中 n 是此行上的樣本數,而 N 是被呼叫者的樣本數。
  • 最小計數 – 限制出現次數少於 最小計數 的框架。

檔案/函式名稱有時會被截斷(使用 ...),而縮排會在開頭以 +n 截斷,其中 n 是如果還有空間,會插入的額外空格數目。如果您想要深度巢狀程式碼的完整剖析,通常一個好主意是使用 IOContext 中的寬廣 displaysize 儲存到檔案中

open("/tmp/prof.txt", "w") do s
    Profile.print(IOContext(s, :displaysize => (24, 500)))
end

組態

@profile 只會累積回溯,而分析會在您呼叫 Profile.print() 時發生。對於長時間運算,儲存回溯的預先配置緩衝區可能會被填滿。如果發生這種情況,回溯會停止,但運算會繼續。因此,您可能會遺漏一些重要的剖析資料(發生這種情況時,您會收到警告)。

您可以這樣取得並組態相關參數

Profile.init() # returns the current settings
Profile.init(n = 10^7, delay = 0.01)

n 是您可以儲存的指令指標總數,預設值為 10^6。如果您的典型回溯是 20 個指令指標,那麼您可以收集 50000 個回溯,這表示統計不確定性小於 1%。這對於大多數應用程式來說可能已經夠好。

因此,您更有可能需要修改以秒為單位的 delay,它設定 Julia 在快照之間執行所要求運算的時間量。執行時間很長的作業可能不需要頻繁的回溯。預設設定為 delay = 0.001。當然,您可以減少或增加延遲;但是,一旦延遲與執行回溯所需的時間相近(在作者的筆電上約為 30 微秒),剖析的負擔就會增加。

記憶體配置分析

改善效能最常見的技術之一是減少記憶體配置。Julia 提供了幾個工具來衡量這一點

@time

總配置量可以用 @time@allocated@allocations 來衡量,而觸發配置的特定程式碼行通常可以從剖析中推論出來,透過這些程式碼行產生的垃圾收集成本。但是,有時直接衡量每一行程式碼配置的記憶體量會更有效率。

GC 記錄

@time 記錄了在評估表達式的過程中關於記憶體使用量和垃圾回收的高階統計資料,記錄每個垃圾回收事件可能會很有用,以便直觀地了解垃圾回收器執行頻率、每次執行的時間長度,以及每次回收的垃圾數量。這可以使用 GC.enable_logging(true) 來啟用,這會導致 Julia 在每次發生垃圾回收時記錄到 stderr。

配置檔案分析器

Julia 1.8

此功能至少需要 Julia 1.8。

配置檔案分析器會在執行時記錄堆疊追蹤、類型和每個配置檔案的大小。它可以使用 Profile.Allocs.@profile 來呼叫。

關於配置檔案的這些資訊會以陣列形式傳回,其中包含 Alloc 物件,並包裝在 AllocResults 物件中。目前最佳的視覺化方式是使用 PProf.jlProfileCanvas.jl 套件,它們可以視覺化產生最多配置檔案的呼叫堆疊。

配置檔案分析器確實有顯著的負擔,因此可以傳遞 sample_rate 參數來透過略過一些配置檔案來加速它。傳遞 sample_rate=1.0 會讓它記錄所有內容(速度較慢);sample_rate=0.1 會只記錄 10% 的配置檔案(速度較快),依此類推。

注意

配置檔案分析器的目前實作並未擷取所有配置檔案的類型。分析器無法擷取其類型的配置檔案會表示為類型 Profile.Allocs.UnknownType

您可以在此處進一步了解遺失的類型以及改進計畫:問題 #43688

逐行配置追蹤

測量配置的另一種方法是使用 --track-allocation=<設定> 命令列選項啟動 Julia,您可以選擇 none(預設值,不測量配置)、user(測量 Julia 核心程式碼以外的所有地方的記憶體配置)或 all(測量 Julia 程式碼每一行的記憶體配置)。配置會針對已編譯程式碼的每一行進行測量。當您退出 Julia 時,累積結果會寫入文字檔,檔名後方會加上 .mem,並與原始檔儲存在同一個目錄中。每一行都會列出配置的總位元組數。Coverage 套件包含一些基本分析工具,例如依配置的位元組數順序排列各行。

在解讀結果時,有幾個重要的細節。在 user 設定下,任何直接從 REPL 呼叫的函式的第一行會顯示配置,這是因為 REPL 程式碼本身發生的事件所致。更重要的是,JIT 編譯也會增加配置計數,因為 Julia 的許多編譯器都是用 Julia 編寫的(而且編譯通常需要記憶體配置)。建議的程序是強制編譯,執行您想要分析的所有命令,然後呼叫 Profile.clear_malloc_data() 重設所有配置計數器。最後,執行所需的命令並退出 Julia 以觸發 .mem 檔的產生。

注意

--track-allocation 會變更程式碼產生以記錄配置,因此配置可能與沒有選項時的情況不同。我們建議改用 配置分析器

外部剖析

目前 Julia 支援使用 Intel VTuneOProfileperf 作為外部剖析工具。

根據你選擇的工具,在 Make.user 中將 USE_INTEL_JITEVENTSUSE_OPROFILE_JITEVENTSUSE_PERF_JITEVENTS 編譯設定為 1。支援多個旗標。

在執行 Julia 之前,將環境變數 ENABLE_JITPROFILING 設定為 1。

現在你可以使用多種方法來運用這些工具!例如,使用 OProfile,你可以嘗試簡單的記錄

>ENABLE_JITPROFILING=1 sudo operf -Vdebug ./julia test/fastmath.jl
>opreport -l `which ./julia`

或者類似地使用 perf

$ ENABLE_JITPROFILING=1 perf record -o /tmp/perf.data --call-graph dwarf -k 1 ./julia /test/fastmath.jl
$ perf inject --jit --input /tmp/perf.data --output /tmp/perf-jit.data
$ perf report --call-graph -G -i /tmp/perf-jit.data

你可以測量程式中更多有趣的內容,若要取得完整的清單,請閱讀 Linux perf 範例頁面

請記住,perf 會為每個執行儲存一個 perf.data 檔案,即使對於小型程式,檔案大小也可能相當大。此外,perf LLVM 模組會暫時將偵錯物件儲存在 ~/.debug/jit 中,請記得定期清除該資料夾。