Linux上のSwiftサーバをCPUプロファイリングする
背景
SwiftアプリケーションのプロファイリングにはInstrumentsが非常に便利です。
しかしInstrumentsはmacOS用のアプリケーションであり、Linux上のSwiftサーバに対してプロファイリングを行うことができません。
そこで今回はgperftoolsを用いてLinux上のSwiftプロセスをプロファイリングする方法を紹介します。
gperftools(Google Performance Tools)はC(C++)言語によるツールキットで、その機能にCPUプロファイリングが含まれています。
Go言語では、有名なプロファイラとしてnet/http/pprofが存在します。こちらは当然Go言語でしか使用できませんが、そのビジュアライゼーションツールであるpprofは、レガシーフォーマット対応としてgperftoolsに対応しています。
そのため今回はプロファイルをgperftoolsで行い、可視化をpporfで行う、という仕組みでSwiftをCPUプロファイリングしていきます。
gperftoolsによるプロファイリング
gperftoolsのインストール
- apt
apt install libgoogle-perftools-dev - brew
brew install gperftools
Swiftプログラムへのインストール
gperftoolsはシンプルなC(C++)ライブラリであるため、Swiftからも利用できます。
Swiftから使用するためのラッパーライブラリとしてgperftoolsSwiftを作成しました。
gperftoolsSwiftは非常に薄いラッパーであるため、使い方はgperftoolsと同じになります。
.package(url: "https://github.com/sidepelican/gperftoolsSwift.git", from: "0.1.0"),
import gperftoolsSwift
let file = NSTemporaryDirectory() + "a.profile"
Profiler.start(fname: file) // 計測の開始。結果保存先のパスを指定する
// ...なにか処理
Profiler.stop() // 計測終了
Profiler.stop()を呼び出すとstart時の引数に指定したパスに結果ファイルが生成されます。
pprofによる可視化
pprofのインストール
Go言語の実行環境を用意した上で、go installを用います。
$ go install github.com/google/pprof@latest
pprofによる可視化
pprofコマンドにはプロファイル結果ファイルの他に、関数ポインタをシンボル化するための実行バイナリが必要となります。
pprofコマンドに出力結果フォーマットと、実行バイナリへのパスと、プロファイル結果を与えて実行します。
$ pprof -top .build/release/Run a.profile
結果の表示方法には様々なオプションがあります。個人的にはテキスト形式では-tree、またはブラウザによるGUI形式-http=":"が便利でした。その他のオプションは公式ドキュメントを確認してください。
サンプルアプリによる動作確認
コマンドの紹介をしただけでは味気ないので、サンプルアプリを使って実際に計測してみます。
Vaporを用いて2つのエンドポイントを作成し、大量のリクエストを投げてどちらのエンドポイントが重いか調べます。
サンプルアプリはこちらです。
エンドポイント実装
import Foundation
import Vapor
private let message = "eAhkbq0exzR3vSuqdKplrRv8P8IDI0LhB87MONLhemkJcutgrzY7iKc8EWt6sHcRRLmrdjUVrvB0Q8zgDk0sSkGdbdSYva7AngwYSUplT5coKfBqF80Ptq2JQ47wuA7nNXgdYdJNEwtSkqxTKjfG8yPeF8Df5cYxvXMRUwW2g2PZhRt8Qw9baFNF9bsLcWZ37iIGxyQVW8ljsT3NnKNPH6N6bmfBgrWzSkmwOnKofClx2tmjycggKBgtqkykGpNtbGlbXt9ynhnTyXQeCEX77tqWKSwqwZ1UZdrRmiwY7iw5Ipg5Oe9SRPuTx1UeZiNKqxAEWWXOPmleQf8LVpOldrhazt2GNHrWeEK7QBDIDT7Hjel31an3iebuxREKi1IKqTJQQ6G0e33ijhbNU3xfMTYNNZdCKJjwtanqTKHXEpHToIcsWvc1cTCAvakVbFm1BzTLxKrUoeLR6X1BIr738vIDRM12K7nw"
.data(using: .utf8)!
struct MyController: RouteCollection {
func boot(routes: RoutesBuilder) throws {
routes.get("sha512", use: handleSha512)
routes.get("tarai", use: handleTarai)
}
func handleSha512(req: Request) -> some ResponseEncodable {
hashTask(hf: SHA512.self)
}
func hashTask<H: HashFunction>(hf: H.Type) -> String {
var current = Data()
for _ in 0..<1000 {
var h = hf.init()
h.update(data: message)
h.update(data: current)
current = Data(h.finalize())
}
return current.hexEncodedString()
}
func handleTarai(req: Request) -> some ResponseEncodable {
tarai(x: 12, y: 6, z: 0)
}
func tarai(x: Int, y: Int, z: Int) -> Int {
if x <= y {
return y
}
return tarai(
x: tarai(x: x - 1, y: y, z: z),
y: tarai(x: y - 1, y: z, z: x),
z: tarai(x: z - 1, y: x, z: y)
)
}
}
適当なデータ列をSHA512で1000回ハッシュ計算を行う関数と、竹内関数を用意しました。
プロファイル命令用実装
サーバはコンテナ化されたのちにマネージドなLinuxインスタンス上で実行されることを想定します。
そのようなインスタンスに対しプロファイル命令を送ったり結果ファイルを手で拾ってくるのは面倒であるため、これらもHTTP経由で行えるようにしました。
また、実行バイナリ取得用のエンドポイントも追加しています。
let profilePath = NSTemporaryDirectory() + "a.profile"
app.get("profile") { (req) -> EventLoopFuture<Response> in
let waitSecond = min((try? req.query.get(TimeInterval.self, at: "s")) ?? 30, 120)
Profiler.start(fname: profilePath)
let promise = req.eventLoop.makePromise(of: Response.self)
DispatchQueue.global().asyncAfter(deadline: .now() + waitSecond) {
Profiler.stop()
let res = req.fileio.streamFile(at: profilePath)
promise.completeWith(.success(res))
}
return promise.futureResult
}
app.get("binary") { (req) -> Response in
return req.fileio.streamFile(at: ProcessInfo.processInfo.arguments[0])
}
雑ですがGETリクエストを投げるとプロファイルを開始して、指定時間待ったあとプロファイルを終了し、結果ファイルをそのリクエストに対して返すという形式にしてします。
サーバ実行
適当にDockerfileを書いてコンテナ上でサーバを実行します。
$ docker build -t sample:local .
$ docker run -p 8080:8080 sample:local
ベンチマークリクエストの実行とプロファイル
ベンチマークツールを用いて大量のリクエストを投げます。今回はwrkを使用しました。
luaスクリプトによる設定で2つのパスにランダムにリクエストを投げます。
local paths = {
"/tarai",
"/sha512",
}
math.randomseed(os.time())
randomPath = function()
local path = math.random(1,table.getn(paths))
return paths[path]
end
request = function()
path = randomPath()
return wrk.format(nil, path)
end
ベンチマークを実行します。
$ wrk -c 1000 -d 30s -s access.lua --latency http://localhost:8080
ベンチマーク実行で負荷がかかっている時に、プロファイル起動&結果取得のエンドポイントを叩きます。
$ wget localhost:8080/profile
ついでにバイナリも拾います。
$ wget localhost:8080/binary
可視化
必要なデータが揃ったので可視化を行ってみましょう。pprofコマンドを実行します。
$ pprof -tree binary profile
Local symbolization failed for libswiftCore.so: stat /usr/lib/swift/linux/libswiftCore.so: no such file or directory
Local symbolization failed for libpthread-2.31.so: stat /usr/lib/x86_64-linux-gnu/libpthread-2.31.so: no such file or directory
Local symbolization failed for libc-2.31.so: stat /usr/lib/x86_64-linux-gnu/libc-2.31.so: no such file or directory
Local symbolization failed for libFoundation.so: stat /usr/lib/swift/linux/libFoundation.so: no such file or directory
Local symbolization failed for ld-2.31.so: stat /usr/lib/x86_64-linux-gnu/ld-2.31.so: no such file or directory
Local symbolization failed for libdispatch.so: stat /usr/lib/swift/linux/libdispatch.so: no such file or directory
Local symbolization failed for libswiftDispatch.so: stat /usr/lib/swift/linux/libswiftDispatch.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
File: binary
Type: cpu
Showing nodes accounting for 229.10s, 99.08% of 231.23s total
Dropped 216 nodes (cum <= 1.16s)
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
208.69s 100% | $s3Run12MyControllerV4boot6routesy5Vapor13RoutesBuilder_p_tKFAC11handleTarai3reqQrAF7RequestC_tFQOy_Qo_AKcACcfu1_AlKcfu2_TA
208.69s 90.25% 90.25% 208.69s 90.25% | $s3Run12MyControllerV5tarai1x1y1zS2i_S2itF
----------------------------------------------------------+-------------
7.70s 80.04% | CCryptoBoringSSL_SHA512_Update
1.91s 19.85% | sha512_final_impl
9.62s 4.16% 94.41% 9.62s 4.16% | sha512_block_data_order_avx
----------------------------------------------------------+-------------
2.46s 31.58% | $s3Run12MyControllerV8hashTask2hfSSxm_t6Crypto12HashFunctionRzlFAF6SHA512V_Tg5Tf4dd_n
1.28s 16.43% | $s6Crypto12SHA512DigestV15withUnsafeBytesyxxSWKXEKlF
1.22s 15.66% | $s6Crypto6SHA512V8finalizeAA0B6DigestVyF
0.88s 11.30% | [libFoundation.so]
0.72s 9.24% | $s6Crypto12HashFunctionPAAE6update4datayqd___t10Foundation12DataProtocolRd__lFy7Regions_7ElementQYd__XEfU_AA6SHA512V_AF0G0VTg5
0.42s 5.39% | $s6Crypto13DigestContextC8finalizeSays5UInt8VGyF
5.28s 2.28% 96.70% 7.79s 3.37% | [libswiftCore.so]
1.23s 15.79% | $s6Crypto12SHA512DigestV15withUnsafeBytesyxxSWKXEKlFxSWKXEfU_TA
1.05s 13.48% | [libc-2.31.so]
0.37s 4.75% | [libFoundation.so]
...
先頭にLocal symbolization failedというエラーメッセージがたくさん表示されています。実行バイナリが依存しているライブラリを見つけられないとのことですが、コンテナ環境からは1個の実行バイナリしか取り出していないのでそれはそうですね。これにうまく対応する方法は思いついていません。
システム関数のシンボル化ができず不便ですが、自前Swiftコードとstatic linkしているパッケージのシンボルは見えているようですので、一旦目をつむります。
さて結果をみると、最も負荷が高かった関数はs3Run12MyControllerV5tarai1x1y1zS2i_S2itFでした。シンボル名はマングル化されています。なんとなくわかる気もしますが、デマングルするとより明確になります。
$ swift demangle s3Run12MyControllerV5tarai1x1y1zS2i_S2itF
$s3Run12MyControllerV5tarai1x1y1zS2i_S2itF ---> Run.MyController.tarai(x: Swift.Int, y: Swift.Int, z: Swift.Int) -> Swift.Int
ということで自作の大量ハッシュ関数より竹内関数のほうが圧倒的に負荷がかかっていたということがよくわかります。20倍くらい差がありそうですね。
またWebインターフェースを使えばよりリッチなビューを利用できます。
$ pprof -http=":" binary profile
-
Graph。シンボル名が長すぎて見づらくなっています。
-
Flame Graph。こちらも長くてわかりづらいですが、大まかな様子はわかります。
おわりに
Goで用いられている方法と同じような形でプロファイルを行うことができました。
システムライブラリのシンボルが見えなかったり、長くて分かりづらいといった難点は今後の課題です。
Goのnet/http/pprofでは実行バイナリがなくてもプロファイル結果だけで関数名などが表示されていたような気がするんですが、net/http/pprofとgperftoolsのフォーマットの違いなんでしょうかね？
CPUプロファイルが必要となるタイミングはめったにないと思いますが、いざ必要なときに使えない状態では困ります。
Swift on Serverはまだユーザ数が少ないのでこの手のノウハウが欠落しがちです。
いざというときに最低限使える状態になっていたいと思っての今回の調査でした。
Discussion