第二十五章:性能分析與優(yōu)化

2018-08-12 22:20 更新

Haskell 是一門高級編程語言,一門真正的高級編程語言。 我們可以一直使用抽象概念、幺半群、函子、以及多態(tài)進行編程,而不必與任何特定的硬件模型打交道。Haskell 在語言規(guī)范方面下了很大的功夫,力求語言可以不受制于某個特定的求值模型。這幾層抽象使得我們可以把 Haskell 作為計算本身的記號,讓編程人員關心他們問題的關鍵點,而不用操心低層次的實現細節(jié),使得人們可以心無旁騖地進行編程。

但是,本書介紹的是真實世界中的編程行為,而真實世界中的代碼都運行在資源有限的硬件之上,并且程序也會有時間和空間上的限制。因此,我們需要掌握好表達程序數據的方法,準確地理解使用惰性求值和嚴格求值策略帶來的后果,并學會如何分析和控制程序在執(zhí)行時的時間和空間。

在這一章,我們將看到 Haskell 編程中可能遇到的典型空間和時間問題,并且如何有條理地分析、理解并解決它們。為此我們將研究使用一系列的技術:時間和空間使用分析,運行時統計,以及對嚴格求值和惰性求值。我們也會看下編譯器優(yōu)化對性能的影響,以及高級優(yōu)化技術在純函數式編程語言中的應用。那么,讓我們用一個挑戰(zhàn)開始吧:調查一個簡單程序中不必要內存的使用問題。

Haskell程序性能分析?

請看下面這個列表處理程序,它用于計算某個大型列表的平均值。這里展示的只是程序的其中一部分代碼(并且具體的實現算法我們并不關心),這是我們經常會在真實的 Haskell 程序中看到的典型的簡單列表操作代碼,這些代碼大量地使用標準庫函數,并且包含了一些因為疏忽大意而導致的性能問題。這里也展示了幾種因疏忽而易出現的性能問題。

-- file: ch25/A.hs
import System.Environment
import Text.Printf

main = do
    [d] <- map read `fmap` getArgs
    printf "%f\n" (mean [1..d])

mean :: [Double] -> Double
mean xs = sum xs / fromIntegral (length xs)

這個程序非常簡單:我們引用了訪問系統環(huán)境的函數(即 getArgs ),和 Haskell 版的 printf 函數來格式化輸出。接著這個程序從命令行讀入一個數字來構建一個由浮點數組成的列表。我們用這個列表的和除以列表的長度得到平均值,然后以字符串的形式打印出來。我們來將此代碼編譯成機器代碼(打開優(yōu)化開關)然后用 time 執(zhí)行它看看情況吧:

$ ghc --make -rtsopts -O2 A.hs
[1 of 1] Compiling Main             ( A.hs, A.o )
Linking A ...
$ time ./A 1e5
50000.5
./A 1e5  0.05s user 0.01s system 102% cpu 0.059 total
$ time ./A 1e6
500000.5
./A 1e6  0.26s user 0.04s system 99% cpu 0.298 total
$ time ./A 1e7
5000000.5
./A 1e7  63.80s user 0.62s system 99% cpu 1:04.53 total

程序在處理少量輸入時運行得非常好,但是當輸入的列表元素數量達到一千萬個時,程序的運行速度就會變得相當緩慢。從這點我們就能感覺到應該有什么地方做得不對,但我們并不清楚它的資源使用情況。 我們需要研究下。

記錄運行時統計數據?

為了能收集這些情報,GHC支持傳入 +RTS-RTS 這些特殊選項。這些選項是傳給 Haskell 運行時本身的,Haskell程序為會感知到它們的存在。

特別地,我們可以用 -s 選項來讓運行時系統收集內存和垃圾收集性能參數(并可以用 -N來控制系統線程的數量,或調整棧和堆的大?。N覀儗⒂眠\行時選項來打開性能分析的幾種不同變量。Haskell 運行時所能接受的所有選項列表可以參見GHC用戶手冊。

那么讓我們用 +RTS -sstderr 來運行程序收集我們所需要的結果吧。

$ ./A 1e7 +RTS -sstderr
5000000.5
1,689,133,824 bytes allocated in the heap
697,882,192 bytes copied during GC (scavenged)
465,051,008 bytes copied during GC (not scavenged)
382,705,664 bytes maximum residency (10 sample(s))

       3222 collections in generation 0 (  0.91s)
         10 collections in generation 1 ( 18.69s)

        742 Mb total memory in use

  INIT  time    0.00s  (  0.00s elapsed)
  MUT   time    0.63s  (  0.71s elapsed)
  GC    time   19.60s  ( 20.73s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time   20.23s  ( 21.44s elapsed)

  %GC time      96.9%  (96.7% elapsed)

  Alloc rate    2,681,318,018 bytes per MUT second

  Productivity   3.1% of total user, 2.9% of total elapsed

當使用 -sstderr 時,程序的性能數字會輸出到標準錯誤流里,告訴我們很多關于程序在具體做什么的信息。具體地說,它告訴我們GC用了多少時間以及最大活動內存使用情況。原來程序計算一千萬個元素的平均值在堆上使用了多達742M的你內存,并且 96.9% 的時間是花費到垃圾收集上的!總共只有 3.1% 的時間是程序用來干正事的。

那么為什么我們的程序運行情況這么差?我們如何來提高它呢?畢竟,Haskell是一個惰性語言:它不應該只用恒定的內存空間來處理列表嗎?

時間消耗分析?

慶幸的是,GHC提供了幾個工具可以分析程序的時間和空間使用情況。尤其是,我們可以在編寫程序時打開性能調試選項,這樣程序在執(zhí)行時會得到每個函數所使用的資源使用的信息。性能調試過程分為三步:以性能調試方式編譯程序;用性能調試模式執(zhí)行程序;最后是分析收集到的結果數據。

編譯程序時,我們可以打開 -prof 選項來記錄基本時間和空間性能信息。我們也需要給感興趣的函數標記為 “cost centres” 以便讓性能分析程序知曉。一個 cost centre 即是一個信息收集點。GHC會生成代碼來計算這些地方的資源消耗。我們可以用 SCC 語法使得任何語句成為 cost centre。

-- file: ch25/SCC.hs
mean :: [Double] -> Double
mean xs = {-# SCC "mean" #-} sum xs / fromIntegral (length xs)

另外我們也可以用 -auto-all 選項來讓編譯器將所有頂級函數設為 cost centre。手動添加 cost centre 的能力作為自動 cost centre 性能調試的輔助,使得我們可以在發(fā)現某個熱點(hot spot)有問題時,針對性地分析一個函數的資源消耗。

另外需要注意的一個難點是:在 Haskell 這類惰性、純函數式編程語言里,沒有參數的值只會被計算一次(比如之前的程序展示過的巨大的列表),而計算的結果會被之后的所有其他計算所共享。這些值不是程序調用的其中一部分,因此它們不會每次都被計算。當然我們仍然需要評估它們的唯一一次計算的資源占用情況。這些只會計算一次的值被成為 CAF (Constant Applicative Forms),它們的確切數量可以通過 -caf-all 選項來得到。

那么以分析性能的方式來編譯我們的程序吧(用 -fforce-recomp 選項來強制重新編譯所有部分):

$ ghc -O2 --make A.hs -prof -auto-all -caf-all -fforce-recomp
[1 of 1] Compiling Main             ( A.hs, A.o )
Linking A ...

現在我們可以執(zhí)行這個標記了性能分析點的程序了 (標記了性能分析的程序會變慢,所以我們用一個較小的輸入來執(zhí)行):

$ time ./A  1e6 +RTS -p
Stack space overflow: current size 8388608 bytes.
Use `+RTS -Ksize' to increase it.
./A 1e6 +RTS -p  1.11s user 0.15s system 95% cpu 1.319 total

程序竟然把??臻g耗完了!這就是使用 profiling 時需要注意的主要影響:給程序加Cost Centre會使它的優(yōu)化發(fā)生變化,甚至改變它的運行時行為,因為每一個表達式都被附加了額外代碼來檢測它們的執(zhí)行情況。對于我們這樣情況,修正起來很簡單 —— 只需要用GHC運行時標記 -K 來增加??臻g上限即可(并附帶指示大小的后綴):

$ time ./A 1e6 +RTS -p -K100M
500000.5
./A 1e6 +RTS -p -K100M  4.27s user 0.20s system 99% cpu 4.489 total

運行時會將性能信息生成到一個名字為 A.prof (以程序本身名字命名) 的文件中。其中含有以下信息:

$ cat A.prof

Time and Allocation Profiling Report  (Final)

       A +RTS -p -K100M -RTS 1e6

    total time  =        0.28 secs   (14 ticks @ 20 ms)
    total alloc = 224,041,656 bytes  (excludes profiling overheads)

COST CENTRE  MODULE               %time %alloc

CAF:sum      Main                  78.6   25.0
CAF          GHC.Float             21.4   75.0

                                            individual    inherited
COST CENTRE MODULE         no.    entries  %time %alloc   %time %alloc

MAIN        MAIN            1           0   0.0    0.0   100.0  100.0
 main       Main          166           2   0.0    0.0     0.0    0.0
  mean      Main          168           1   0.0    0.0     0.0    0.0
 CAF:sum    Main          160           1  78.6   25.0    78.6   25.0
 CAF:lvl    Main          158           1   0.0    0.0     0.0    0.0
  main      Main          167           0   0.0    0.0     0.0    0.0
 CAF        Numeric       136           1   0.0    0.0     0.0    0.0
 CAF        Text.Read.Lex 135           9   0.0    0.0     0.0    0.0
 CAF        GHC.Read      130           1   0.0    0.0     0.0    0.0
 CAF        GHC.Float     129           1  21.4   75.0    21.4   75.0
 CAF        GHC.Handle    110           4   0.0    0.0     0.0    0.0

這些信息呈現給一些我們關于程序的運行時行為的情況。里面包含了程序的名字以及執(zhí)行程序時用到的選項和參數?!簍otal time』是運行時系統視角所見的程序運行的確切總時長?!篢otal allocation』是程序在運行過程中分配的內存總字節(jié)數(不是程序運行時內存使用的峰值;那個峰值大概是700MB)

報告中的第二小節(jié)是各個函數所消耗的時間和空間部分。第三小節(jié)是Cost Centre報告:其結構為調用關系樹(比如我們可以看到 mean 是被 main 調用的)?!癷ndividual”和”inherited”列提供了每個Cost Centre其本身、其整體、以及其子節(jié)點所消耗的資源。最下面那些 CAF 是執(zhí)行一些常量的一次性消耗(例如大列表中浮點數以及列表本身)。

我們能從這些信息得出什么結論呢?我們可以看出兩個 CAF 占用了大多數時間。分別是計算總和相關和浮點數相關。這基本解釋了所有程序運行的消耗。加上之前我們觀察到的關于GC的壓力,我們就可以推測出列表節(jié)點和浮點數值可能是問題之源。

簡單的性能熱點檢測,特別是對于我們難以知道時間花費點的大型程序,這個時間分析會突出一些特定的問題模塊或高層函數。這往往足夠顯示出問題所在了。就像我們的程序,一旦我們窄化了問題所在,我們就可以用更加成熟的分析工具來拿到更多的信息。

空間性能調試?

GHC除了可以進行基本的時間和空間分析外,還能為程序整個執(zhí)行期間的堆內存使用情況生成圖表。這能完美檢測內存泄露問題。內存泄露是指不再需要的內存沒有被釋放。這會對GC造成壓力,就像在我們的例子程序中見到的那樣。

構建內存占用情況的性能調試和構建一般時間占用調試的步驟是一樣,都需要用到 -prof -auto-all -caf-all 選項。 但當執(zhí)行程序時,我們會讓運行時系統收集關于堆使用的最多細節(jié)。堆使用信息能夠以幾種方式分解:cost-centre,模塊(module),構建器,數據類型。不同分解可以展現不同信息。對 A.hs 進行內存調試所得的原始信息會被記錄到一個名為 A.hp 的文件里面,之后只要使用 hp2ps 處理這個文件,就可以得到一個基于 PostScript 的內存占用歷史可視圖像。

程序的一般內存占用情況可以通過使用 -hc 選項來獲?。?/p>

$ time ./A 1e6 +RTS -hc -p -K100M
500000.5
./A 1e6 +RTS -hc -p -K100M  4.15s user 0.27s system 99% cpu 4.432 total

一個內存使用的性能調試的log文件 A.hp 被會創(chuàng)建,其內容為以下形式:

JOB "A 1e6 +RTS -hc -p -K100M"
SAMPLE_UNIT "seconds"
VALUE_UNIT "bytes"
BEGIN_SAMPLE 0.00
END_SAMPLE 0.00
BEGIN_SAMPLE 0.24
(167)main/CAF:lvl   48
(136)Numeric.CAF    112
(166)main   8384
(110)GHC.Handle.CAF 8480
(160)CAF:sum    10562000
(129)GHC.Float.CAF  10562080
END_SAMPLE 0.24

這些樣本是以程序的正常執(zhí)行步長取得的。我們可以用 -iN 選項來增加取樣頻率,這里的 N 是內存取樣之間相隔的秒數(如 0.01 秒)。很明顯,取樣越多,得到的結果越精確,但程序會執(zhí)行得更慢。我們可以用 hp2ps 將調試結果生成一張圖表:

$ hp2ps -e8in -c A.hp

這就是生成的圖表 A.ps

[IMG#TODO]

我們能從圖片中看出什么?第一點,程序執(zhí)行分兩個階段:在計算總和的同時, 前一階段不斷分配大量的內存,后一半清理釋放這些內存。內存初始化分配的同時, sum 也開始干活,并消耗大量的內存。如果用 -hy 調試選項來按類型分解的話,我們會得到一個稍有不同的圖像:

$ time ./A 1e6 +RTS -hy -p -K100M
500000.5
./A 1e6 +RTS -i0.001 -hy -p -K100M  34.96s user 0.22s system 99% cpu 35.237 total
$ hp2ps -e8in -c A.hp

以下是生成的圖像:

[IMG#TODO]

這里最有趣的是有很大部分的內存被list類型([])和Double類型所占用;我們看到未知類型(圖中用 * 標記)也占用了一些內存。最后,讓我們用 -hd 選項來按構建器分解一下結果:

$ time ./A 1e6 +RTS -hd -p -K100M
$ time ./A 1e6 +RTS -i0.001 -hd -p -K100M
500000.5
./A 1e6 +RTS -i0.001 -hd -p -K100M  27.85s user 0.31s system 99% cpu 28.222 total

下面就是我們最后一張展示了程序執(zhí)行的所有情況的圖像:

[IMG#TODO]

程序在分配雙精度浮點數列表上面花了不少功夫。列表在 Haskell 語言中的惰性的,所以含有上百萬個元素的列表都是在程序執(zhí)行過程中一點點地構建出來的。但這些元素在被遍歷的同時并沒有被逐步釋放,所以導致內存占用變得越來越大。最終,在程序執(zhí)行稍稍超過一半時,終于將列表總和計算出來,并開始計算其長度。如果看下關于 mean 的程序片斷的話,我們就會知道內存沒被釋放的確切原因:

-- file: ch25/Fragment.hs
mean :: [Double] -> Double
mean xs = sum xs / fromIntegral (length xs)

首先我們計算列表的總和,這會使得所有列表元素被分配到內存。但我們現在還不能釋放列表元素,因為 length 還需要整個列表。一旦 sum 結束, length 會馬上開始訪問列表,同時 GC 會跟進,逐步釋放列表元素,直到 length 結束。這兩個計算階段展示了兩種明顯不同的分配與釋放,并指出我們需要改進的確切思路:只對列表遍歷一次,遍歷過程中同時計算總和與平均值。

-- file: ch25/B.hs
mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    (n, s)     = foldl k (0, 0) xs
    k (n, s) x = (n+1, s+x)
$ ghc -O2 --make B.hs -fforce-recomp
$ time ./B 1e6
Stack space overflow: current size 8388608 bytes.
Use `+RTS -Ksize' to increase it.
./B 1e6  0.44s user 0.10s system 96% cpu 0.565 total
$ ghc -O2 --make B.hs -prof -auto-all -caf-all -fforce-recomp
[1 of 1] Compiling Main             ( B.hs, B.o )
Linking B ...
$ time ./B 1e6 +RTS -i0.001 -hc -p -K100M
500000.5
./B 1e6 +RTS -i0.001 -hc -p -K100M  38.70s user 0.27s system 99% cpu 39.241 total
-- file: ch25/C.hs
mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    (n, s)     = foldl' k (0, 0) xs
    k (n, s) x = (n+1, s+x)
$ ghc -O2 --make C.hs
[1 of 1] Compiling Main             ( C.hs, C.o )
Linking C ...
$ time ./C 1e6
Stack space overflow: current size 8388608 bytes.
Use `+RTS -Ksize' to increase it.
./C 1e6  0.44s user 0.13s system 94% cpu 0.601 total
-- file: ch25/Foldl.hs
foldl' :: (a -> b -> a) -> a -> [b] -> a
foldl' f z xs = lgo z xs
    where lgo z []     = z
          lgo z (x:xs) = let z' = f z x in z' `seq` lgo z' xs
-- file: ch25/D.hs
mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    (n, s)     = foldl' k (0, 0) xs
    k (n, s) x = n `seq` s `seq` (n+1, s+x)
$ ghc -O2 D.hs --make
[1 of 1] Compiling Main             ( D.hs, D.o )
Linking D ...
$ time ./D 1e6 +RTS -sstderr
./D 1e6 +RTS -sstderr
500000.5
256,060,848 bytes allocated in the heap
     43,928 bytes copied during GC (scavenged)
     23,456 bytes copied during GC (not scavenged)
     45,056 bytes maximum residency (1 sample(s))

        489 collections in generation 0 (  0.00s)
          1 collections in generation 1 (  0.00s)

          1 Mb total memory in use

  INIT  time    0.00s  (  0.00s elapsed)
  MUT   time    0.12s  (  0.13s elapsed)
  GC    time    0.00s  (  0.00s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time    0.13s  (  0.13s elapsed)

  %GC time       2.6%  (2.6% elapsed)

  Alloc rate    2,076,309,329 bytes per MUT second

  Productivity  97.4% of total user, 94.8% of total elapsed

./D 1e6 +RTS -sstderr  0.13s user 0.00s system 95% cpu 0.133 total
-- file: ch25/E.hs
import System.Environment
import Text.Printf
import Control.Parallel.Strategies

main = do
    [d] <- map read `fmap` getArgs
    printf "%f\n" (mean [1..d])

foldl'rnf :: NFData a => (a -> b -> a) -> a -> [b] -> a
foldl'rnf f z xs = lgo z xs
    where
        lgo z []     = z
        lgo z (x:xs) = lgo z' xs
            where
                z' = f z x `using` rnf

mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    (n, s)     = foldl'rnf k (0, 0) xs
    k (n, s) x = (n+1, s+x) :: (Int, Double)
-- file: ch25/F.hs
{-# LANGUAGE BangPatterns #-}
-- file: ch25/F.hs
mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    (n, s)       = foldl' k (0, 0) xs
    k (!n, !s) x = (n+1, s+x)
$ ghc -O2 F.hs --make
$ time ./F 1e6 +RTS -sstderr
./F 1e6 +RTS -sstderr
500000.5
256,060,848 bytes allocated in the heap
     43,928 bytes copied during GC (scavenged)
     23,456 bytes copied during GC (not scavenged)
     45,056 bytes maximum residency (1 sample(s))

        489 collections in generation 0 (  0.00s)
          1 collections in generation 1 (  0.00s)

          1 Mb total memory in use

  INIT  time    0.00s  (  0.00s elapsed)
  MUT   time    0.14s  (  0.15s elapsed)
  GC    time    0.00s  (  0.00s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time    0.14s  (  0.15s elapsed)

  %GC time       0.0%  (2.3% elapsed)

  Alloc rate    1,786,599,833 bytes per MUT second

  Productivity 100.0% of total user, 94.6% of total elapsed

./F 1e6 +RTS -sstderr  0.14s user 0.01s system 96% cpu 0.155 total
-- file: ch25/G.hs
data Pair a b = Pair !a !b
-- file: ch25/G.hs
mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    Pair n s       = foldl' k (Pair 0 0) xs
    k (Pair n s) x = Pair (n+1) (s+x)
$ ghc -O2 -ddump-simpl G.hs
lgo :: Integer -> [Double] -> Double# -> (# Integer, Double #)

lgo = \ n xs s ->
    case xs of
      []       -> (# n, D# s #);
      (:) x ys ->
        case plusInteger n 1 of
            n' -> case x of
                D# y -> lgo n' ys (+## s y)
-- file: ch25/H.hs
data Pair = Pair !Int !Double

mean :: [Double] -> Double
mean xs = s / fromIntegral n
  where
    Pair n s       = foldl' k (Pair 0 0) xs
    k (Pair n s) x = Pair (n+1) (s+x)
lgo :: Int# -> Double# -> [Double] -> (# Int#, Double# #)
lgo = \ n s xs ->
    case xs of
      []       -> (# n, s #)
      (:) x ys ->
        case x of
            D# y -> lgo (+# n 1) (+## s y) ys
$ time ./H 1e7 +RTS -sstderr
./H 1e7 +RTS -sstderr
5000000.5
1,689,133,824 bytes allocated in the heap
    284,432 bytes copied during GC (scavenged)
         32 bytes copied during GC (not scavenged)
     45,056 bytes maximum residency (1 sample(s))

       3222 collections in generation 0 (  0.01s)
          1 collections in generation 1 (  0.00s)

          1 Mb total memory in use

  INIT  time    0.00s  (  0.00s elapsed)
  MUT   time    0.63s  (  0.63s elapsed)
  GC    time    0.01s  (  0.02s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time    0.64s  (  0.64s elapsed)

  %GC time       1.0%  (2.4% elapsed)

  Alloc rate    2,667,227,478 bytes per MUT second

  Productivity  98.4% of total user, 98.2% of total elapsed

./H 1e7 +RTS -sstderr  0.64s user 0.00s system 99% cpu 0.644 total
-- file: ch25/I.hs
import System.Environment
import Text.Printf
import Data.Array.Vector

main = do
    [d] <- map read `fmap` getArgs
    printf "%f\n" (mean (enumFromToFracU 1 d))

data Pair = Pair !Int !Double

mean :: UArr Double -> Double
mean xs = s / fromIntegral n
  where
    Pair n s       = foldlU k (Pair 0 0) xs
    k (Pair n s) x = Pair (n+1) (s+x)
fold :: Int# -> Double# -> Double# -> (# Int#, Double# #)
fold = \ n s t ->
    case >## t limit of {
      False -> fold (+# n 1) (+## s t) (+## t 1.0)
      True  -> (# n, s #)
$ time ./I 1e7
5000000.5
./I 1e7  0.06s user 0.00s system 72% cpu 0.083 total
$ ghc -fforce-recomp --make -O2 -funbox-strict-fields -fvia-C -optc-O2 I.hs
[1 of 1] Compiling Main             ( I.hs, I.o )
Linking I ...
$ time ./I 1e7
5000000.5
./I 1e7  0.04s user 0.00s system 98% cpu 0.047 total
go:
  ucomisd     5(%rbx), %xmm6
  ja  .L31
  addsd       %xmm6, %xmm5
  addq        $1, %rsi
  addsd       .LC0(%rip), %xmm6
  jmp go
以上內容是否對您有幫助:
在線筆記
App下載
App下載

掃描二維碼

下載編程獅App

公眾號
微信公眾號

編程獅公眾號