golang--效能測試和分析
前言
測試分為：壓力測試、負載測試、效能測試，功能測試等等，其中在開發過程中開發人員經常要寫一些test case unit 自己的模組進行功能測試測和效能。在分析出模組的效能瓶頸後開發人員就需要針對性的調優，但需要提醒的是調優工程一般要放在最後在進行，過早地優化會浪費開發時間，而且有時在需求或者功能變動後就會變成無用功，這是顯而易見的。
隨著移動網際網路的興起，各種遠端服務的效能遇到巨大的挑戰，雖然硬體資源日益豐富，但成本的增加和使用者體驗的嚴苛，效能調優在軟體開發中佔的權重也越來越高，尤其是一些經常被呼叫的模組，如核心演算法的部分，即使把每次執行的cpu執行的時間降低1%，把記憶體消耗降低1%，在面對海量的使用者請求時對效能也會帶來提升。
Go語言作為一個“新興語言”，它自身為我們提供了一套用於效能測試和分析的工具和介面，作者這裡結合一個具體例項來講解一下簡單的調優過程。
常用的測試命令
啟動指定的測試函式
go test -run=xxx $packetpath編譯一個測試binary檔案
go test -c -o $binaryname啟動一個bench測試
go test -bench=xxx -run=None在 -bench 的選項上設定一個None代表著不執行功能測試函式即Test開頭的函式，-bench後面接的是一個匹配項，任何符合該匹配項的Bench測試函式都會被觸發執行。
go test -bench=xxx -run=None -benchmem新增 -benchmem 會顯示出測試過程中分配mem的數量。
啟動profile分析
在go 自帶的工具中支援三種profile收集： cpu、block、memory，cpuprofile 是用來記錄各個事件或函式對cpu的消耗情況的資料；blockprofile是為了記錄攜程阻塞的操作，可以用來分析每個阻塞操作佔用的時間；memprofile是用於堆效能剖析，記錄攜程內部堆分配的具體情況。
go test -bench=xxx -run=None -cpuprofile=cpu.out go test -bench=xxx -run=None -blockprofile=block.out go test -bench=xxx -run=None -memprofile=mem.out無論是cpu分析、阻塞分析、堆分析，主要目的都是為了消耗更少的計算資源、記憶體資源來取得更高的效率，但有時候時間和空間並不能兼得，用空間換時間是很常用的一種做法，需要根據具體情況進行權衡。
列舉包內的檔案
# 列舉一個包中的.go 檔案 go list -f={{.GoFiles}} # 列舉一個包中的_test.go檔案 go list -f={{.TestGoFiles}} # 列舉一個包中的外部測試檔案 go list -f={{.XTestGoFiles}}外部測試檔案：在一些特殊情況下，外部測試包需要對待測試包有特殊的訪問許可權，例如為了避免迴圈引用，一個白盒測試必須存在一個單獨的包中，在這種情況下我們使用了一種小技巧：在包內測試未見中新增一些函式宣告，將包內部的功能暴露給外部測試，這種做法為為包測試留了一個“後門”。如果一個原始檔的存在的唯一目的就在於此，並且自己不包含任何測試，它們一般稱作export_test.go
測試覆蓋率
在測試的時候有一種最簡單的統計方法--語句覆蓋率，部分語句在一次測試過程中至少執行了一次，則稱之為覆蓋，否則為非覆蓋。# 執行測試並生成coverprofile 檔案 go test -run=TransferProofGenerator -cover -coverprofile=c.out # 檢視覆蓋率，通過go tool 工具 go tool cover -html=c.out // 會在瀏覽器中開啟一個測試報告如果在生成profile的命令中加入了 -covermode=count 的標記，則可以標記出執行效率較高和較低的模組。
效能剖析流程
這裡作者會結合一個示例來說明一下效能剖析的具體操作流程。效能調優首要的任務就是找出消耗時間最多的函式。
收集程式的profile
一般收集有兩種方法，一種是通過工具命令來收集，上面已經提到了；另一種是通過呼叫相關模組來收集，這裡面以cpuprofile為例：
import( "runtime/pprof" "testing" "os" ) func BenchmarkXXX(b *testing.B){ fd, _ := os.OpenFile("cpu.log", os.O_CREATE| os.O_RDWR, os.ModeSetuid) if err := pprof.StartCPUProfile(fd); err != nil{ b.Fatalf("TestTransferProofValidator %s", err.Error()) } defer func() { pprof.StopCPUProfile() fd.Close() }() }這樣在執行後自動就會生成cpuprofile檔案，這裡是將函式放在裡Bench測試函式中，也可以將它放在正常函式中比如main函式。有的時候需要實時的監聽web服務的執行狀態，這個時候就可以通過引入net/http/pprof來收集profile：
package main import ( "net/http" "github.com/utxo/webserver/router" _ "net/http/pprof" ) func main() { handler:= http.FileServer(http.Dir("./template")); http.Handle("/", handler) http.HandleFunc("/transfer", router.Transfer); http.ListenAndServe("0.0.0.0:8082", nil); }此時會預設開啟proof收集服務，go tool作為客戶端來訪問該router來收集profile:
go tool pprof http://localhost:8082/debug/pprof/profile在收集結束後會進入cmd命令介面（預設進行 30s 的 CPU Profiling收集），通過命令列來檢視、處理收集到的資料。
檢視profile資料
go tool pprof -text -nodecount=10 cpu.log-nodecount 函式會為我們列出cpu時間消耗前十的函式。也可以進入cmd模式，進行更詳細的剖析：
go tool pprof list cpu.log
詳細示例
作者這裡展示的是一個零知識證明的生成和校驗的演算法的效能分析過程，按照上節所說我們先收集profile，使用的方法是呼叫pprof模組的方法：
func BenchmarkTransferProofValidator(b *testing.B) { once.Do(testInit) fd, _ := os.OpenFile("cpu_validator.log", os.O_CREATE| os.O_RDWR, os.ModeSetuid) inputs, T := generateInputs(100, big.NewInt(1000000)) proof, output, B, err := TransferProofGenerator(inputs, T, pairsA, pairsB, zkpKeyPairsA, zkpKeyPairsB, zkpRange) if err != nil{ b.Fatalf("TestTransferProofValidator: %s", err.Error()) } if err := pprof.StartCPUProfile(fd); err != nil{ b.Fatalf("TestTransferProofValidator %s", err.Error()) } defer func() { pprof.StopCPUProfile() fd.Close() }() for i := 0; i < b.N; i++ { err = TransferProofValidator(inputs, output, B, pairsA, pairsB, zkpKeyPairsA, zkpKeyPairsB, proof) if err != nil{ b.Fatalf("TestTransferProofValidator: %s", err.Error()) } } }執行如下命令：
go test -c -bench=BenchmarkTransferProofValidator -run=None顯示結果如下：
TransferProofValidator運行了三次，gomaxprocs = 4，這些都是go tool自動分配，暫時不用深究。 可以看到我們的函式執行十分的緩慢，執行一次需要 0.4s 左右，它將作為一個高頻呼叫的模組遠遠達不到使用的需求。D:\gopath\src\github.com\utxo\balance>go test -run=None -bench=Va goos: windows goarch: amd64 pkg: github.com/utxo/balance BenchmarkTransferProofValidator-4 3 397296900 ns/op PASS ok github.com/utxo/balance 3.237s
接下來我們要找到耗時最多的那個部分：
go tool pprof list cpu_validator.log顯示結果如下：
D:\gopath\src\github.com\utxo\balance> go tool pprof list cpu_validator.log list: open list: The system cannot find the file specified. Fetched 1 source profiles out of 2 Main binary filename not available. Type: cpu Time: Dec 20, 2018 at 11:15pm (CST) Duration: 625.81ms, Total samples = 420ms (67.11%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 420ms, 100% of 420ms total Showing top 10 nodes out of 25 flat flat% sum% cum cum% 240ms 57.14% 57.14% 240ms 57.14% math/big.addMulVVW 110ms 26.19% 83.33% 380ms 90.48% math/big.nat.montgomery 30ms 7.14% 90.48% 30ms 7.14% runtime.memmove 10ms 2.38% 92.86% 10ms 2.38% math/big.(*Int).QuoRem 10ms 2.38% 95.24% 10ms 2.38% math/big.nat.add 10ms 2.38% 97.62% 10ms 2.38% runtime.lock 10ms 2.38% 100% 20ms 4.76% runtime.newstack 0 0% 100% 400ms 95.24% github.com/utxo/balance.BenchmarkTransferProofValidator 0 0% 100% 400ms 95.24% github.com/utxo/balance.TransferProofValidator 0 0% 100% 400ms 95.24% github.com/utxo/crypto/base.Exp每一行表示一個函式的資訊。前兩列表示函式在 CPU 上執行的時間以及百分比；第三列是當前所有函式累加使用 CPU 的比例；第四列和第五列代表這個函式以及子函式執行所佔用的時間和比例（也被稱為累加值 cumulative），應該大於等於前兩列的值；最後一列就是函式的名字。如果應用程式有效能問題，上面這些資訊應該能告訴我們時間都花費在哪些函式的執行上了。
以上面顯示的結果為例，根據cum來觀察大部分的時間都花費在了Exp的執行過程中（base.Exp 函式在其他模組內被呼叫），我們可以通過list命令來仔細分析一下Exp函式中在那部分比較耗時：
Total: 420ms ROUTINE ======================== github.com/utxo/crypto/base.Exp in D:\gopath\src\github.com\utxo\crypto\base\base.go 0 400ms (flat, cum) 95.24% of Total . . 91: return E . . 92: } . . 93: . . 94: if x.Sign() < 1{ . . 95: x = (&big.Int{}).Neg(x) . 30ms 96: E = (&big.Int{}).Exp(g, x, n) . . 97: if 1 != Gcd(E, n).Int64(){ . . 98: log.Printf("h_r is not prime with n") . . 99: return nil . . 100: } . . 101: . 20ms 102: E = (&big.Int{}).ModInverse(E, n) . . 103: E = (&big.Int{}).Mod(E, n) . . 104: . . 105: }else { . 350ms 106: E = (&big.Int{}).Exp(g, x, n) . . 107: } . . 108: . . 109: return E . . 110:} . . 111:如上所示，base.Exp 總計佔用了 95.24% 的cpu時間， 而整個函式內最耗時的就是 big.Exp() 函式。這就給作者製造了個難題，因為在本模組中涉及到大量的指數運算，而且輸入資料都較大（平均 512bit）。
因為本模組的功能相對比較簡單，所以比較容易的定位到了問題的所在，接下來我們要想辦法進行調優。
因為本模組目前是純粹的演算法模組，可以考慮進行併發改造，來發揮go協程的特點，尤其是在呼叫base.Exp的部分中。但作者將嘗試併發改造後發現改造的結果並不理想，因為使用channel進行同步導致阻塞，‘抵消’了多協程帶來的效能提升。另外一個思路就是儘量避免big.Exp指數運算，即將指數型運算轉換為其他時間複雜度較低的運算，多協程是利用go本身的特性和cpu的多核運算。而這一種方法則純粹是從數學角度上進行優化，並不具有普適性。改造後再進行測試顯示結果如下：
D:\gopath\src\github.com\utxo\balance>go test -run=None -bench=Va goos: windows goarch: amd64 pkg: github.com/utxo/balance BenchmarkTransferProofValidator-4 200 5096903 ns/op PASS ok github.com/utxo/balance 3.753s雖然在零知識證明校驗過程中多協程並未帶來顯著的效果提升，但在零知識證明生成的過程中起到了很大的作用。
優化結果
