Golang vs PHP7(追記あり)

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.go

package 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()
}

PHP
Controllers/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環境と比較してみます。

全体の計測結果

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が一番パフォーマンスが良いかと予想していましたが、全く逆の結果になってしまいました。

Golangが遅い理由

遅い原因をいくつか考えて改善できないか試してみました。詳細は省きますが、以下の点については問題なさそうでした。

goroutineはリクエスト単位で起動している
コネクションプールは有効になっている
BeegoのORM特有の処理は主原因ではない(標準ライブラリのsql関数と大差なし)
DB側のCPU使用率は100%になっているが、CPU使用率とメモリ使用量はPHP環境と同程度の負荷になっている

ここまで確認して、プロファイラを使った方が良さそうに思えたので、いったんプロファイラで状況を確認するために、標準で提供されていて手軽に使えそうなpprofを使ってみました。topで確認すると次のような結果がでました。

(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	[email protected] on zzz using TCP/IP
2016-06-27T09:21:36.552559Z    6 Connect	[email protected] 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のパフォーマンスに期待していたのですが、今回の計測ではあまり良い成果が出ず残念でした。

今回調査を進める上で言語思想的なところでも面白みは感じられたので、本番導入も視野に入れて引き続き動向を追っていきたいと思います。

—以下追記—

interpolateParams有効時の比較

methaneさんからご紹介いただいた記事を参考に、GolangのMySQLドライバのinterpolateParamsオプションを有効にして追加で計測してみました。実行時のMySQLのgeneral_logは以下のようになり、prepare文は発行されなくなっています。

interpolateParams=falseのログ

2016-11-10T04:43:11.000050Z   11 Prepare	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ?
2016-11-10T04:43:11.000226Z   14 Close stmt
2016-11-10T04:43:11.001804Z   11 Execute	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 29418
2016-11-10T04:43:11.009794Z   16 Close stmt
2016-11-10T04:43:11.042876Z   15 Close stmt
2016-11-10T04:43:11.044736Z   12 Prepare	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ?
2016-11-10T04:43:11.044964Z   12 Execute	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 15307
2016-11-10T04:43:11.063940Z   19 Prepare	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ?
2016-11-10T04:43:11.064747Z   20 Close stmt
2016-11-10T04:43:11.064831Z   19 Execute	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 82308
2016-11-10T04:43:11.102078Z   18 Prepare	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ?
2016-11-10T04:43:11.102245Z   11 Close stmt
2016-11-10T04:43:11.102389Z   18 Execute	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 13972
2016-11-10T04:43:11.115736Z   12 Close stmt
2016-11-10T04:43:11.129541Z   19 Close stmt
2016-11-10T04:43:11.149373Z   18 Close stmt
2016-11-10T04:43:11.151216Z   13 Prepare	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = ?
2016-11-10T04:43:11.151549Z   13 Execute	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 72423
2016-11-10T04:43:11.187031Z   13 Close stmt

interpolateParams=trueのログ

2016-11-10T06:46:42.540420Z   25 Query	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 58399
2016-11-10T06:46:42.713174Z   29 Query	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 89385
2016-11-10T06:46:42.786018Z   24 Query	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 67158
2016-11-10T06:46:42.813429Z   26 Query	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 72117
2016-11-10T06:46:42.889940Z   21 Query	SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 21741

スループットは以下のようになりました。interpolateParamsが無効の場合よりスループットは向上しましたが、PHP環境程までは改善されないようです。

interpolateParams有効時のスループットの比較

遅い箇所の再検証

pprofを使ってどこに時間が掛かっているかを検証してみました。topの結果は以下のようになり、アプリケーションのコード上はormのReadが遅いようです。

(pprof) top -cum
10ms of 760ms total ( 1.32%)
Showing top 10 nodes out of 147 (cum >= 180ms)
      flat  flat%   sum%        cum   cum%
         0     0%     0%      460ms 60.53%  runtime.goexit
      10ms  1.32%  1.32%      370ms 48.68%  net/http.(*conn).serve
         0     0%  1.32%      250ms 32.89%  github.com/astaxie/beego.(*ControllerRegister).ServeHTTP
         0     0%  1.32%      250ms 32.89%  app/controllers.(*MainController).Get
         0     0%  1.32%      250ms 32.89%  net/http.serverHandler.ServeHTTP
         0     0%  1.32%      200ms 26.32%  github.com/astaxie/beego/orm.(*dbBase).Read
         0     0%  1.32%      200ms 26.32%  github.com/astaxie/beego/orm.(*orm).Read
         0     0%  1.32%      180ms 23.68%  database/sql.(*DB).Query
         0     0%  1.32%      180ms 23.68%  database/sql.(*DB).QueryRow
         0     0%  1.32%      180ms 23.68%  database/sql.(*DB).query

そこで、一度controllers/default.goの以下の箇所をコメントアウトして再度JMeterの計測を実行してみるとスループットは20倍程度になりました。遅いのはこのメソッドの中のようです。

    o.Read(&user)

さらにbeego/orm.(*dbBase).Readの遅い箇所をpprofで追いかけてみると以下の箇所が遅いようです。

github.com/go-sql-driver/mysql/packets.go
397: writeCommandPacketStr
482: readResultSetHeaderPacket

(pprof) list Read
ROUTINE ======================== github.com/go-sql-driver/mysql.(*mysqlConn).Query in /home/vagrant/go/src/github.com/go-sql-driver/mysql/connection.go
         0      180ms (flat, cum) 23.68% of Total
         .          .    318:		}
         .          .    319:		query = prepared
         .          .    320:		args = nil
         .          .    321:	}
         .          .    322:	// Send command
         .       50ms    323:	err := mc.writeCommandPacketStr(comQuery, query)
         .          .    324:	if err == nil {
         .          .    325:		// Read Result
         .          .    326:		var resLen int
         .       90ms    327:		resLen, err = mc.readResultSetHeaderPacket()
         .          .    328:		if err == nil {
         .       10ms    329:			rows := new(textRows)
         .          .    330:			rows.mc = mc
         .          .    331:
         .          .    332:			if resLen == 0 {
         .          .    333:				// no columns, no more data
         .          .    334:				return emptyRows{}, nil
         .          .    335:			}
         .          .    336:			// Columns
         .       30ms    337:			rows.columns, err = mc.readColumns(resLen)
         .          .    338:			return rows, err
         .          .    339:		}
         .          .    340:	}
         .          .    341:	return nil, err
         .          .    342:}

さらにその先まで追っていくと最終的にはアセンブラでレジスタの値を比較している箇所が遅いようですが、何故この箇所が遅いのかがよく分かりません。

(pprof) list Syscall
ROUTINE ======================== syscall.Syscall in /usr/local/go/src/syscall/asm_linux_amd64.s
     120ms      170ms (flat, cum) 22.37% of Total
         .          .     13:// Trap # in AX, args in DI SI DX R10 R8 R9, return in AX DX
         .          .     14:// Note that this differs from "standard" ABI convention, which
         .          .     15:// would pass 4th arg in CX, not R10.
         .          .     16:
         .          .     17:TEXT	·Syscall(SB),NOSPLIT,$0-56
         .       40ms     18:	CALL	runtime·entersyscall(SB)
         .          .     19:	MOVQ	a1+8(FP), DI
         .          .     20:	MOVQ	a2+16(FP), SI
         .          .     21:	MOVQ	a3+24(FP), DX
         .          .     22:	MOVQ	$0, R10
         .          .     23:	MOVQ	$0, R8
         .          .     24:	MOVQ	$0, R9
         .          .     25:	MOVQ	trap+0(FP), AX	// syscall entry
         .          .     26:	SYSCALL
     120ms      120ms     27:	CMPQ	AX, $0xfffffffffffff001
         .          .     28:	JLS	ok
         .          .     29:	MOVQ	$-1, r1+32(FP)
         .          .     30:	MOVQ	$0, r2+40(FP)
         .          .     31:	NEGQ	AX
         .          .     32:	MOVQ	AX, err+48(FP)
         .          .     33:	CALL	runtime·exitsyscall(SB)
         .          .     34:	RET
         .          .     35:ok:
         .          .     36:	MOVQ	AX, r1+32(FP)
         .          .     37:	MOVQ	DX, r2+40(FP)
         .          .     38:	MOVQ	$0, err+48(FP)
         .       10ms     39:	CALL	runtime·exitsyscall(SB)
         .          .     40:	RET
         .          .     41:
         .          .     42:// func Syscall6(trap, a1, a2, a3, a4, a5, a6 uintptr) (r1, r2, err uintptr)
         .          .     43:TEXT ·Syscall6(SB),NOSPLIT,$0-80
         .          .     44:	CALL	runtime·entersyscall(SB)

ConoHa環境での再計測

実行環境に問題があるかもしれないので、環境を変えて計測してみます。部署内ではGMOアプリクラウドやConoHaを検証用に無料で使えるためどちらかを利用することが多いですが、今回は小規模の検証なので手軽に使えるConoHaを使います。

計測環境

ConoHaのインスタンスはスペックと主だった設定は以下です。

VPS
 Golang、PHP 5.6、PHP 7
  OS:CentOS 6.7
  CPU:4コア
  メモリ:4GB

 JMeter
  OS:CentOS 6.7
  CPU:2コア
  メモリ:1GB

sysctl.conf
 net.core.somaxconn=2048
 net.ipv4.tcp_max_syn_backlog=2048
 net.ipv4.ip_local_port_range=1024 65535
 net.ipv4.tcp_tw_recycle = 1 // JMeterサーバーのみ有効

ulimit -a
 core file size          (blocks, -c) 0
 data seg size           (kbytes, -d) unlimited
 scheduling priority             (-e) 0
 file size               (blocks, -f) unlimited
 pending signals                 (-i) 15223
 max locked memory       (kbytes, -l) 64
 max memory size         (kbytes, -m) unlimited
 open files                      (-n) 65535
 pipe size            (512 bytes, -p) 8
 POSIX message queues     (bytes, -q) 819200
 real-time priority              (-r) 0
 stack size              (kbytes, -s) 10240
 cpu time               (seconds, -t) unlimited
 max user processes              (-u) 15223
 virtual memory          (kbytes, -v) unlimited
 file locks                      (-x) unlimited

ミドルウェアのバージョンと主だった設定等は以下のようにしました。いくつかの条件で負荷を掛けた状態でVPSのリソース状況を確認して、今回の計測内容に概ね最適と思われる値に設定してあります。PDOのオプションはPHPで発行されるSQLのクエリ数を減らすために設定しています。PDO::ATTR_PERSISTENTを有効にする際に伴うエラーハンドラの設定はしていません。

()内は以前計測した時のバージョンまたは設定値です。Golang以外はバージョンを揃えるのに時間が掛かりそうだったので、用意しやすいもので代用しています。

Golang環境
 Golang 1.6
  MySQLドライバ
   interpolateParams=true
 Beego 1.7.1
  conf/app.conf
   runmode=prod
 supervisor 3.3.1 (<= 3.3.0)
 nginx 1.10.2     (<= 1.0.15)

PHP 5.6環境
 PHP 5.6.27       (<= 5.6.22)
 php-fpm 5.6.27   (<= 5.6.22)
 nginx 1.10.2     (<= 1.0.15)

PHP 7.0環境
 PHP 7.0.7        (<= 7.0.12)
 php-fpm 7.0.7    (<= 7.0.12)
 nginx 1.10.2     (<= 1.0.15)

Laravel 5.3.22    (<= 5.2.39)
 xdebugを無効にして以下を実行
 composer install
 php artisan config:cache
 php artisan route:cache

 config/app.php
   'env' => 'production'
   'debug' => false
   'log_level' => 'error'

 config/database.php
   'mysql' => [
     'options'   => [
       PDO::ATTR_PERSISTENT => true,
       PDO::ATTR_EMULATE_PREPARES => true,
     ],
   ]

 app/Http/Kernel.php
   protected $middlewareGroups = [
     'web' => [
       \App\Http\Middleware\EncryptCookies::class,
       \Illuminate\Cookie\Middleware\AddQueuedCookiesToResponse::class,
//     \Illuminate\Session\Middleware\StartSession::class,
//     \Illuminate\View\Middleware\ShareErrorsFromSession::class,
//     \App\Http\Middleware\VerifyCsrfToken::class,
       \Illuminate\Routing\Middleware\SubstituteBindings::class,
     ],

nginx.conf
 worker_processes  4;     (<= 1)
 worker_rlimit_nofile 4096;
 worker_connections 1024;
 keepalive_timeout 65;

php-fpm.d/www.conf
 pm.max_children = 400      (<= 50)
 pm.start_servers = 200     (<= 5)
 pm.min_spare_servers = 200 (<= 5)
 pm.max_spare_servers = 400 (<= 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.16      (<= 5.7.13)
 max_connections=2000
 max_allowed_packet=64MB
 general_log='OFF'

JMeter 3.0

Golangを実行した時のMySQLのgeneral_log

2016-11-10T07:07:21.586918Z      248 Query    SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 14957
2016-11-10T07:07:21.588405Z      249 Query    SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 35991
2016-11-10T07:07:21.589945Z      250 Query    SELECT `uid`, `username` FROM `auth_users` WHERE `uid` = 44839

PHPを実行した時のMySQLのgeneral_log

2016-11-10T07:09:55.397345Z      258 Query    use `test`
2016-11-10T07:09:55.397611Z      258 Query    set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'
2016-11-10T07:09:55.397882Z      258 Query    select * from `auth_users` where `auth_users`.`uid` = 92691 limit 1
2016-11-10T07:09:55.402926Z      439 Query    use `test`
2016-11-10T07:09:55.403205Z      439 Query    set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'
2016-11-10T07:09:55.403470Z      439 Query    select * from `auth_users` where `auth_users`.`uid` = 83157 limit 1
2016-11-10T07:09:55.439246Z      434 Query    use `test`
2016-11-10T07:09:55.439551Z      434 Query    set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'
2016-11-10T07:09:55.439792Z      434 Query    select * from `auth_users` where `auth_users`.`uid` = 58285 limit 1

計測結果

この設定で以前と同様の条件(スレッド数=10、Ramp-Up期間=1秒、ループ回数=100)で実行した結果は次のようになりました。

ConoHa環境でのスループット

環境	スループット(req/s)	平均応答時間(ms)	最小応答時間(ms)	最大応答時間(ms)
Golang	909.6	1	1	115
Golang interpolateParams =true	919.3	1	1	121
PHP 5.6	337.3	20	7	131
PHP 7	570.8	9	4	119

GolangでinterpolateParamsを有効にしたときのスループットがPHP 5.6の約3.3倍と最も高くなり、PHP 7はPHP 5.6の約1.7倍のスループットが出ています。VirtualBox環境で計測したときのGolangの問題は発生しませんでした。

追加の計測

Golang環境もPHP環境もリソース的には余裕があるので、何かしらのエラーが発生するかスループットが著しく低下するまで負荷を上げて計測してみました。JMeterのスレッド数とループ回数いろいろ変えて計測してみましたが、その中の限界付近の計測結果だけ載せておきます。

PHP 7環境の計測結果

負荷	スループット(req/s)	最大応答時間(ms)	エラー数	PHPサーバーの最大CPU使用率(%)	MySQLサーバーの最大CPU使用率(%)
400スレッド 200ループ	952.7	2,231	0	100	7
500スレッド 200ループ	939.8	63,002	1	100	9
600スレッド 200ループ	790.7	63,004	5	100	9
700スレッド 200ループ	892.8	63,004	21	100	10

400スレッド辺りでスループットは最大になり、500スレッドで定常的に負荷を掛け始めた辺りからエラーが発生するようになりました。発生したエラーはいずれもJMeter側のリクエストタイムアウトです。PHP 7環境ではphp-fpmのプロセス数がボトルネックになり、最大スループットは950req/sくらいという結論になりました。

余談ですが、JMeter側でセッションキーを送るようにしていなかったため、(ファイル)セッションを無効化する前はリクエストごとにセッションが生成されて10分の1くらいのスループットしか出なくなってしまいました。Golang側ではセッションを生成していなかったため、セッションを生成しないようにして計測しました。

Golang環境の計測結果

負荷	スループット(req/s)	最大応答時間(ms)	エラー数	Golangサーバーの最大CPU使用率(%)	MySQLサーバーの最大CPU使用率(%)
500スレッド 200ループ	5,050.2	1,276	0	53	20
1,000スレッド 200ループ	4,624.6	3,615	0	63	30

Golang環境で計測した結果、5,000req/sくらい出るところまで確認できましたが、まだCPUには大分余裕があります。他のリソースも問題なさそうだったので、負荷発生サーバーの状況を確認してみると500スレッドの時点で既にCPU使用率が100%に達していました。Golang+Nginxからのレスポンスが早すぎて負荷が掛けきれていないようです。

PHP 7環境の計測時は700スレッドでも負荷発生サーバーのCPUには余裕があり負荷発生側には問題なかったようです。

負荷発生改善後のGolang環境の計測結果

2コアの小さなConoHaでは4コアの普通のConoHaの壁を壊すことができませんでした。そこでその壁をぶち壊すべく24コアの超大型ConoHaを投入してみました。

負荷発生改善後のGolang環境の計測結果

負荷	スループット(req/s)	最大応答時間(ms)	エラー数	Golangサーバーの最大CPU使用率(%)	MySQLサーバーの最大CPU使用率(%)
500スレッド 200ループ	15,976.5	1,063	0	96	58
1,000スレッド 200ループ	16,066.7	4,361	0	98	55
1,500スレッド 200ループ	16,788.9	10,292	0	99	56
2,000スレッド 200ループ	16,767.9	9,220	0	99	63

計測中の負荷発生サーバーのCPU使用率は10%以下に収まり、GolangサーバーのCPUは100%近くまで使われて十分な負荷が掛かっているようです。結果としては最大スループットは16,800req/sくらいという結論になりました。

ここの結果には載せていないですが、スレッド数やループ数を上げてエラーが返るか試してみると、その中でたまに1件くらいタイムアウトを起こすことはありました。また、10,000スレッドまで上げてみると逆にスループットが低下するような現象も起きましたが、Golangが原因ではなさそうでした。結局、壁は壊せず終いとなりました。

Golangに直接負荷を掛けた計測結果

最後にNginxを通さずに直接Golangに負荷を掛けた場合を計測しました。

Golangに直接負荷を掛けた計測結果

負荷	スループット(req/s)	最大応答時間(ms)	エラー数	Golangサーバーの最大CPU使用率(%)	MySQLサーバーの最大CPU使用率(%)
500スレッド 200ループ	22,638.1	1,026	0	61	80
1,000スレッド 200ループ	24,479.4	3,987	0	63	83
1,500スレッド 200ループ	20,639.8	10,021	0	69	85
2,000スレッド 200ループ	22,393.7	14,015	0	69	93

スループットが上がり、MySQLサーバーの負荷の方が高くなりました。MySQLサーバー側に微妙に余力がありそうなのでスレッド数やループ数を上げてみたり、MySQL側のパラメータもいくつか変えてみましたが試した範囲では計測結果に特に大きな変化はありませんでした。負荷を掛けきれないのは少し気になりますが、結果としては最大スループットは24,500req/sくらいという結論になりました。

追記分のまとめ

methaneさんを初め貴重なご意見をいただきありがとうございました。結局、最初に計測した際のGolang環境で遅くなる原因の究明までは至らず歯切れの悪い結果となってしまいました。

一方、ConoHa環境で再計測することでPHP 7とGolangのパフォーマンスについては興味深い結果が得られたと思います。今回計測したプログラムは実際に稼働させるサービスからすると大分乖離があり、使ったパラメータ等もそのまま本番環境に適用することはない部分もありますが、それぞれのポテンシャルについては意味のある知見が得られたのではないかと思います。

最後にお願いになり恐縮ですが、Golangのパフォーマンスについては元の記事と異なる結論となりましたので、元の記事をご覧の方がお近くにいらしたら共有いただけると幸いです。

参考リンク

次世代システム研究室では、アプリケーション開発や設計を行うアーキテクトを募集しています。アプリケーション開発者の方、次世代システム研究室にご興味を持って頂ける方がいらっしゃいましたら、ぜひ募集職種一覧からご応募をお願いします。

皆さんのご応募をお待ちしています。

Golang vs PHP7(追記あり)

はじめに

計測環境

計測対象のプログラム

JMeterの設定

Golangの計測結果

全体の計測結果

Golangが遅い理由

まとめ

—以下追記—

interpolateParams有効時の比較

遅い箇所の再検証

ConoHa環境での再計測

計測環境

計測結果

追加の計測

PHP 7環境の計測結果

Golang環境の計測結果

負荷発生改善後のGolang環境の計測結果

Golangに直接負荷を掛けた計測結果

追記分のまとめ

参考リンク

関連記事

平和チャレンジ