ISUCON 環境に New Relic APM Agent を入れてみる (Go 編)

お題となるWebサービスを、決められたレギュレーションの中で限界まで高速化を図るチューニングバトル、ISUCON に New Relic は今回もゴールドスポンサーとしてサポートをさせて頂いております。

過去にもハンズオンなどのコンテンツをご用意させて頂きましたが今回はブログで isucon 11 のローカル開発環境の Go に対して APM を入れていきたいと思います。
今回は isucon の環境を題材にさせて頂きますが Go 言語をお使いで New Relic APM の導入を検討されている方もご利用頂ける内容ですので是非ご参考にして頂ければと思います。

こちらのリポジトリにもあげております。

Go APM Agent の導入

早速ですが Go のアプリに対して New Relic APM Agent を導入していきたいと思います。

Go Agent の導入は github.com/newrelic/go-agent/v3/newrelic を使っていきますので go get します。

go get -u github.com/newrelic/go-agent/v3/newrelic

main 関数に APM Agent の初期化処理を入れます。

var app *newrelic.Application
var err error
app, err := newrelic.NewApplication(
　　newrelic.ConfigAppName(os.Getenv("NEW_RELIC_APP_NAME")),
　　newrelic.ConfigLicense(os.Getenv("NEW_RELIC_LICENSE_KEY")),
       newrelic.ConfigAppLogEnabled(false),
)
if err != nil {
       fmt.Errorf("failed to init newrelic NewApplication reason: %v", err)
} else {
       fmt.Println("newrelic init success")
}

今回は Echo というフレームワークが使用されているため Echo の integration を導入します。
nrecho というものが New Relic から用意されていますのでそちらを使用するようにします。

 go get -u github.com/newrelic/go-agent/v3/integrations/nrecho-v4

Echo でリクエストを計測するための Middleware を追加します。

ここまでの変更はこちらです。

e.Use(middleware.Logger())
e.Use(middleware.Recover())
//ここに追加
e.Use(nrecho.Middleware(app))

ここまでできたら一連のセットアップはできていますので一度必要な環境変数などを設定して起動のテストをしてみましょう。

リポジトリの /development 配下に docker-compose と Makefile が用意されていますのでそちらを使用していきます。
先程設定した NEW_RELIC_APP_NAME と NEW_RELIC_LICENSE_KEY の値を設定して頂いてから起動するのを忘れないようにしましょう。

//docker-compose-bench.yml

  backend:
    build:
      context: ..
      dockerfile: development/backend-${target}/dev.dockerfile
    environment:
      MYSQL_HOST: mysql-backend
      MYSQL_PORT: 3306
      MYSQL_DBNAME: isucondition
      MYSQL_USER: isucon
      MYSQL_PASS: isucon
      POST_ISUCONDITION_TARGET_BASE_URL: "http://isucondition-1.t.isucon.dev:3000"
      //以下を追加
      NEW_RELIC_APP_NAME: "isucon-golang-app"
      NEW_RELIC_LICENSE_KEY: "<your-license-key>"
    entrypoint: dockerize -wait tcp://mysql-backend:3306 -timeout 60s
    command: air -c /development/air.toml
    ports:
      - "3000:3000"
    volumes:
      - "../webapp/go:/webapp/go"
      - "../webapp/ec256-public.pem:/webapp/ec256-public.pem"
      - "../webapp/NoImage.jpg:/webapp/NoImage.jpg"
      # SQLs
      - "../webapp/sql/init.sh:/webapp/sql/init.sh"
      - "../webapp/sql/0_Schema.sql:/webapp/sql/0_Schema.sql"
      - "../webapp/sql/1_InitData.sql:/webapp/sql/1_InitData.sql"
    depends_on:
      - mysql-backend

docker-compose を起動してみて New Relic 側の APM の画面に追加されていた場合成功になります。
コンソールに newrelic init success と表示されていれば成功です。

ここまでで APM のセットアップができました、ここからは実際にベンチマーカーを走らせてボトルネックの特定と改善をしましょう。
ここまでの変更はこちらです。

ベンチマーカーで New Relic にデータが流れている確認

New Relic 側の画面でリクエストが流れているかを確認してください。
以下のようになっていれば成功です。

New Relic を使ってアプリケーションのボトルネックを知りたい場合は APM の Transactions を見ていきます。

左側のサイドバーに Transaction とありますので選択して頂くと以下のような画面で Transaction の一覧が表示されます。
画像を見てもらうとわかるようにランキング形式で Transaction の一覧が並んでいますがこれは Most time consuming という単位でランキングをしていますが Time consumed = Execution time x Throughput といった形でランキングされておりますのでこのアプリケーションの中で最も使われているものがランキング化されております。

次の画像を見てみると POST /api/condition/:jia_isu_uuid がかなりの割合を締めて使われていそうなことがわかります。

この POST /api/condition/:jia_isu_uuid は実際に予選問題の解答としてもキーとなる処理として挙げられていました。

実際にこの処理に対して New Relic の計測を追加したいと思います。

POST /api/condition/:jia_isu_uuid に New Relic の計測コードを仕込む

では実際に POST /api/condition/:jia_isu_uuid の処理を New Relic で計測したいと思いますが Go 言語は言語の特性上、自動でDB などへのアクセス処理などの計測ができない言語となっており開発者が自身で計測をするためにコードを追加していく必要があります。

ISUCON のような限られた時間の中でパフォーマンス向上を目指す際には全ての計測を入れていくのは時間の都合上無理があるかと思いますので今回のように最も使われているサービスやあきらかにパフォーマンスに影響のある処理に対して New Relic で計測をする実装をお勧め致します。

また実際に業務で Go 言語を使っていく際にもいきなり全ての実装を揃えていくのではなく重要なものから実装を加えて可観測性を高めていくのも方法の一つとなります。

実際に計測を加えていきたいと思います。

Database へのアクセスを計測する

POST /api/condition/:jia_isu_uuid が実装されている postIsuCondition の関数を見てみますと SELECT と Insert で2ヶ所クエリを実行している箇所がありますのでその部分の計測をしたいと思います。

まずは SELECT 分の箇所の計測を実施したいと思います。

func postIsuCondition(c echo.Context) error {
	txn := nrecho.FromContext(c)
	defer txn.End()
        // 略
　　 var count int 
	select_isu_count_query := "SELECT COUNT(*) FROM `isu` WHERE `jia_isu_uuid` = ?"
	select_isu_count := createDataStoreSegment(select_isu_count_query, "isu", "SELECT", jiaIsuUUID)
	select_isu_count.StartTime = txn.StartSegmentNow()
	err = tx.Get(&count, select_isu_count_query, jiaIsuUUID)
	select_isu_count.End()
       // 略
}

func createDataStoreSegment(query, collection, operation string, params ...interface{}) newrelic.DatastoreSegment {
	mySQLConnectionData = NewMySQLConnectionEnv()

	queryParams := make(map[string]interface{})
	var i = 0
	for _, param := range params {
		switch x := param.(type) {
		case []interface{}:
			for _, p := range x {
				queryParams["?_"+strconv.Itoa(i)] = p
				i++
			}
		case interface{}:
			queryParams["?_"+strconv.Itoa(i)] = x
			i++
		default:
			//ignore
		}
	}

	return newrelic.DatastoreSegment{
		Product:            newrelic.DatastoreMySQL,
		Collection:         collection,
		Operation:          operation,
		ParameterizedQuery: query,
		QueryParameters:    queryParams,
		Host:               mySQLConnectionData.Host,
		PortPathOrID:       mySQLConnectionData.Port,
		DatabaseName:       mySQLConnectionData.DBName,
	}
}

Go で Database などのアクセスを計測するためには newrelic.DatastoreSegment を利用して New Relic へクエリを認識させる必要があります。

createDatastoreSegment という関数を実装して Segment を認識させるように実装します。
実際に上記のような実装を追加してからベンチマーカーを走らせてみて New Relic へ期待通りに SQL が記録されているか確認してみましょう。

ここまでのコミットはこちらに残っています。

もう一つの INSERT の箇所も実装していきます。

基本的には先ほどと同じような形で実装していきます。

for _, cond := range req {
　　//略
	insert_isu_condition_query := "INSERT INTO `isu_condition`" +
		"	(`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)" +
		"	VALUES (?, ?, ?, ?, ?)"
	insert_isu_condition := createDataStoreSegment(insert_isu_condition_query, "isu_condition", "INSERT", jiaIsuUUID, timestamp, cond.IsSitting, cond.Condition, cond.Message)
	insert_isu_condition.StartTime = txn.StartSegmentNow()
	_, err = tx.Exec(
		insert_isu_condition_query,
		jiaIsuUUID, timestamp, cond.IsSitting, cond.Condition, cond.Message)
	insert_isu_condition.End()
　　//略
}

ここまで問題なければ MySQL isu_condition INSERT というクエリが追加されているかと思います
ここまでの実装はこちらです。