Gopherの原著作者はRenée Frenchさんです
はじめに
こんにちは。次世代システム研究室のT.Tです。最近新しくWebアプリケーションを構築する機会があり、規模的には小さめなものになる見込みだったので、基盤として最近気になっていたGolangを採用しようと画策してみました。調査前の知識としては、簡単にWebアプリケーションを構築できて高速に動作するという、よくある触れ込み程度のものでしたが、調査を進めてみると標準ライブラリとかは豊富でHTTPサーバーも標準の機能で用意されていたりとなかなか良さそうな感じです。
機能的には問題なさそうなので、もう少し開発段階や運用段階を視野に入れて調査を進めてみました。開発メンバーは全員Golang初心者なのでフルスタックのフレームワークを使って、ある程度足並みを揃えて開発を進められるようにしたかったのですが、標準ではフレームワークのようなものがなく、標準ライブラリや外部ライブラリを自由に組み合わせて使うような感じだったので、結局RailsライクなBeegoをフレームワークとして使うことにしました。また、HTTPサーバーも自前で用意されてはいますが、適切にログを取得したり、デーモンとして起動するにはnginxやsupervisorと組み合わせて使うのがやりやすそうなので、この辺のミドルウェアを使う構成にすることにしました。
ざっくり構成を考えた時点で今までのPHPの環境とあまり変わり映えがなく、それならLaravelとPHP7でやるのもありかなと思い、採用の決め手になりそうな実行時のパフォーマンスをGolang、PHP 5.6、PHP 7.0で実際に比較してみました。
計測環境
MacBook ProにVirtualBoxで仮想環境を構築して、Golang、PHP 5.6、PHP 7.0、MySQL、JMeterごとにVMを一台起動して、JMterのサーバーから計測対象のプログラムを実行するURLに向けてリクエストを投げて、そのスループットを計測しました。計測環境の詳細は以下のようなものです。
MacBook Pro CPU:2.7GHz Intel Core i5 メモリ:16GB 1867MHz DDR3 VM OS:CentOS 6.7 CPU:1コア メモリ:2048MB Golang環境 Golang 1.6 supervisor 3.3.0 nginx 1.0.15 PHP 5.6環境 PHP 5.6.22 php-fpm 5.6.22 nginx 1.0.15 PHP 7.0環境 PHP 7.0.7 php-fpm 7.0.7 nginx 1.0.15 Laravel 5.2.39 nginx.conf worker_processes 1; php-fpm.d/www.conf pm.max_children = 50 pm.start_servers = 5 pm.min_spare_servers = 5 pm.max_spare_servers = 35 php.d/10-opcache.ini opcache.enable=1 opcache.memory_consumption=96 opcache.interned_strings_buffer=16 opcache.max_accelerated_files=4096 opcache.validate_timestamps=1 opcache.revalidate_freq=300 opcache.max_file_size=0 php.d/40-apcu.ini apc.enabled=1 MySQL 5.7.13 max_allowed_packet=67108864 JMeter 3.0
計測対象のプログラム
計測対象のプログラムは、ユーザーの情報をuserテーブル(id[pk], name)にプライマリキーで検索を掛けて取得した名前をjsonで返すもので、実装は以下のようになっています。Golang
main.go
package main
import (
"github.com/astaxie/beego"
"github.com/astaxie/beego/orm"
)
func init() {
orm.RegisterDriver("mysql", orm.DRMySQL)
orm.RegisterDataBase("default", "mysql", "xxx:yyy@tcp(192.168.33.22:3306)/zzz?charset=utf8")
orm.SetMaxIdleConns("default", 100)
orm.SetMaxOpenConns("default", 100)
}
func main() {
beego.Run()
}
controllers/default.gopackage controllers
import (
"github.com/astaxie/beego"
"github.com/astaxie/beego/orm"
"models"
"math/rand"
)
type MainController struct {
beego.Controller
}
type UserInfo struct {
Name string `json:"name"`
}
func (this *MainController) Get() {
o := orm.NewOrm()
o.Using("default")
user := models.Users{Uid:(rand.Intn(99999) + 1)}
o.Read(&user)
var userInfo UserInfo
userInfo = UserInfo{Name:user.Username}
this.Data["json"] = &userInfo
this.ServeJSON()
}
PHPControllers/Controller.php
<?php
namespace App\Http\Controllers;
use App\Models\User;
class Controller extends BaseController
{
public function userinfo()
{
$i = mt_rand(1, 100000);
$user = User::find($i);
return response()->json(['name' => $user->username]);
}
}
JMeterの設定
JMeterは、スレッドグループを一つ作成して、スレッド数は10、Ramp-Up期間は1秒、ループ回数は100にして、その中でHTTPリクエストを一回投げるようにしています。この計測を10回実行して、そのスループットと平均応答時間の平均、全体の中での最小応答時間と最大応答時間を比較しました。Golangの計測結果
それではまず、Golangの計測結果をご覧ください。
Golang環境で一回計測した結果
| スループット(req/s) | 平均応答時間(ms) | 最小応答時間(ms) | 最大応答時間(ms) |
| 42.7 | 225 | 39 | 639 |
全体の計測結果
PHP環境を含めた結果は次のようになりました。
スループットの比較
| 環境 | スループット(req/s) | 平均応答時間(ms) | 最小応答時間(ms) | 最大応答時間(ms) |
| Golang | 42.7 | 225 | 39 | 639 |
| PHP 5.6 | 76.7 | 113 | 14 | 3544 |
| PHP 7 | 108.5 | 73 | 9 | 2437 |
Golangが遅い理由
遅い原因をいくつか考えて改善できないか試してみました。詳細は省きますが、以下の点については問題なさそうでした。- goroutineはリクエスト単位で起動している
- コネクションプールは有効になっている
- BeegoのORM特有の処理は主原因ではない(標準ライブラリのsql関数と大差なし)
- DB側のCPU使用率は100%になっているが、CPU使用率とメモリ使用量はPHP環境と同程度の負荷になっている
(pprof) top 20 -cum
920ms of 1590ms total (57.86%)
Showing top 20 nodes out of 207 (cum >= 260ms)
flat flat% sum% cum cum%
0 0% 0% 1000ms 62.89% runtime.goexit
10ms 0.63% 0.63% 800ms 50.31% net/http.(*conn).serve
0 0% 0.63% 610ms 38.36% github.com/astaxie/beego.(*ControllerRegister).ServeHTTP
0 0% 0.63% 610ms 38.36% net/http.serverHandler.ServeHTTP
0 0% 0.63% 530ms 33.33% app/controllers.(*MainController).Get
0 0% 0.63% 510ms 32.08% github.com/astaxie/beego/orm.(*dbBase).Read
0 0% 0.63% 510ms 32.08% github.com/astaxie/beego/orm.(*orm).Read
320ms 20.13% 20.75% 420ms 26.42% syscall.Syscall
0 0% 20.75% 350ms 22.01% database/sql.(*DB).Query
0 0% 20.75% 350ms 22.01% database/sql.(*DB).QueryRow
0 0% 20.75% 350ms 22.01% database/sql.(*DB).query
0 0% 20.75% 350ms 22.01% database/sql.(*DB).queryConn
330ms 20.75% 41.51% 330ms 20.75% runtime.futex
0 0% 41.51% 280ms 17.61% runtime.systemstack
0 0% 41.51% 280ms 17.61% syscall.Write
0 0% 41.51% 280ms 17.61% syscall.write
0 0% 41.51% 260ms 16.35% net.(*conn).Write
0 0% 41.51% 260ms 16.35% net.(*netFD).Write
260ms 16.35% 57.86% 260ms 16.35% runtime._ExternalCode
0 0% 57.86% 260ms 16.35% runtime._System
これだけではどこが原因か分からないので、peek、tree、list等で詳細に調べていくとsqlのクエリを発行するときに呼ばれる以下の部分が遅いのが原因らしいことが分かりました。github.com/go-sql-driver/mysql/packets.go 397: writeCommandPacketStr 838: writeExecutePacket go/src/net/fd_unix.go 318: Writeこれでも今ひとつ状況が分からないので、DB側でgeneral_logを有効にしてどのようにクエリが来ているかを確認してみました。
実行開始直後と後半部分では以下のようなログになっていました。
実行開始直後のログ
2016-06-27T09:21:36.546200Z 4 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:36.546688Z 4 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 93459 2016-06-27T09:21:36.551404Z 5 Connect zzz@192.168.33.21 on zzz using TCP/IP 2016-06-27T09:21:36.552559Z 6 Connect zzz@192.168.33.21 on zzz using TCP/IP 2016-06-27T09:21:36.552570Z 5 Query SELECT @@max_allowed_packet 2016-06-27T09:21:36.553547Z 5 Query SET NAMES utf8 2016-06-27T09:21:36.555471Z 5 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:36.555501Z 6 Query SELECT @@max_allowed_packet 2016-06-27T09:21:36.556481Z 5 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 11201 2016-06-27T09:21:36.556712Z 6 Query SET NAMES utf8 2016-06-27T09:21:36.557819Z 6 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:36.558576Z 6 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 56068 ... 2016-06-27T09:21:36.663214Z 6 Close stmt 2016-06-27T09:21:36.678301Z 4 Close stmt 2016-06-27T09:21:36.684282Z 5 Close stmt 2016-06-27T09:21:36.709373Z 6 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:36.710447Z 6 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 42539 2016-06-27T09:21:36.753589Z 5 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:36.753686Z 5 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 21759 2016-06-27T09:21:36.762082Z 4 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:36.762259Z 4 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 9763後半のログ
2016-06-27T09:21:54.648277Z 4 Close stmt 2016-06-27T09:21:54.648553Z 4 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.653484Z 4 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 59148 2016-06-27T09:21:54.669546Z 9 Close stmt 2016-06-27T09:21:54.669808Z 9 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.674126Z 6 Close stmt 2016-06-27T09:21:54.674444Z 6 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.674580Z 9 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 12327 2016-06-27T09:21:54.679057Z 6 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 71366 2016-06-27T09:21:54.679211Z 10 Close stmt 2016-06-27T09:21:54.679454Z 10 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.682508Z 10 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 14219 2016-06-27T09:21:54.719285Z 12 Close stmt 2016-06-27T09:21:54.719892Z 12 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.720184Z 12 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 3847 2016-06-27T09:21:54.752585Z 8 Close stmt 2016-06-27T09:21:54.752818Z 8 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.756653Z 8 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 17333 2016-06-27T09:21:54.773227Z 13 Close stmt 2016-06-27T09:21:54.773490Z 13 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.776512Z 13 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 79768 2016-06-27T09:21:54.805596Z 11 Close stmt 2016-06-27T09:21:54.808238Z 11 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.808340Z 11 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 74059 2016-06-27T09:21:54.822258Z 5 Close stmt 2016-06-27T09:21:54.822695Z 5 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.825512Z 5 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 2186 2016-06-27T09:21:54.849498Z 7 Close stmt 2016-06-27T09:21:54.849719Z 7 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.854120Z 7 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 74343 2016-06-27T09:21:54.896666Z 9 Close stmt 2016-06-27T09:21:54.896929Z 9 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.897024Z 6 Close stmt 2016-06-27T09:21:54.898668Z 9 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 43000 2016-06-27T09:21:54.903154Z 6 Prepare SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ? 2016-06-27T09:21:54.904607Z 6 Execute SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 68603 2016-06-27T09:21:54.914514Z 4 Close stmtスレッドIDが4のものを見ると、開始直後は140msくらいでPrepareからCloseまで実行されていますが、後半は270msくらい掛かっています。また、後半は同じスレッドでClose、Prepare、Excecuteまではすぐに実行されていますが、その流れが他のスレッドでしばらく続いてようやくCloseが呼ばれる傾向が高くなっていて、シングルスレッドで処理しているかのように振る舞っています。
さらに実行時に遅かった部分を中心にsrc/database/sqlの辺りのソースコードも読んでみました。割とクリティカルセクションが多いようで、一斉にリクエストが来るとパフォーマンスが落ちてしまいそうな印象は受けました。また、最小応答時間でもPHP環境に負けてしまっているので、環境的な要因もありそうな気もしています。*sql.DB is slow when shared by goroutines?でのやり取りで同じような現象が発生しているのも気になりますが、今回は環境を変えて検証するのも時間的に難しいためひとまず検証はここまでになります。
まとめ
結論としては、パフォーマンスを改善できるには至りませんでした。Webのフロント部分でも使おうと思っていたのですが、DBアクセスでパフォーマンスが出ないとあまり導入メリットはないので、実用化するには引き続き調査と検証が必要という感じです。Venta Commerce: PHP7, GOLANG vs PHP, DOCUMENTATION HOMEのベンチマークとかを見てGolangのパフォーマンスに期待していたのですが、今回の計測ではあまり良い成果が出ず残念でした。
今回調査を進める上で言語思想的なところでも面白みは感じられたので、本番導入も視野に入れて引き続き動向を追っていきたいと思います。
参考リンク
- Venta Commerce: PHP7, GOLANG vs PHP, DOCUMENTATION HOME
- *sql.DB is slow when shared by goroutines?
- Go pprof 入門編 (CPU Profile とコマンドラインツール)
皆さんのご応募をお待ちしています。