ISUCON10予選問題にNew Relic Go APM Agentを入れてみる

ISUCON11 New Relic 支援プログラムにあわせて、ISUCON10 予選問題(以下、予選問題)をテーマにNew Relic Go APM Agentをインストールし計測するための手順について解説したいと思います。ISUCON運営による、ISUCON10予選問題の解説と講評もあわせてご一読ください。また、Infrastructure Agentの導入についての記事も公開しています。

この記事では、Go言語での予選問題の参考実装にNew Relic Agentを適用し、より詳細に計装するためのコードを記述する手順を説明します。

New RelicのAPM Agentはほとんどの言語で数行のコードを追加するだけで計装でき、トランザクションあるいは分散トレーシングの計測を開始することができます。しかし、Go言語では自動でトランザクションの計測ができず手動でのコード追加が必要です。Go言語以外の言語をISUCONで使う方は、この記事で説明している手順の多くは不要です。各言語向けのAPM Agentのドキュメントをご参照ください。

また、Go言語で必要な計装の詳細についてはドキュメントや、New Relic Go Agent向けMaster Classのハンズオン資料をご一読ください。

Go Agentパッケージを追加してセットアップする

まず、New Relicライセンスキーをメモしておきます。ライセンスキーはデフォルトで作成されていますが、このデフォルトのキーを変更するためにはテクニカルサポートへの問い合わせが必要です。デフォルトとは別に作成し好きなタイミングで削除することもできますので、こちらの記事もご参照ください。

ライセンスキーが準備できたら、github.com/newrelic/go-agent パッケージを例えば次のようにアプリケーションに追加します。

go get github.com/newrelic/go-agent

そして、main関数の先頭に次の処理を追加します。

app, err := newrelic.NewApplication(

newrelic.ConfigAppName("ISUUMO"),

newrelic.ConfigFromEnvironment(),

newrelic.ConfigDistributedTracerEnabled(true),

newrelic.ConfigDebugLogger(os.Stdout),

)

そして、Dockerfileに次の行を追加します。

これは、設定のうちアプリケーション名と分散トレーシングの有効化をソースコードで、ライセンスキーをDockerfileに記述した環境変数経由で設定しています。混在させる必要はないので、どちらかに揃えることも可能です。設定できるすべての項目と対応する環境変数名はドキュメントを参照ください。

もし、Go Agentを利用するのが初めてなのであれば、ここで一度アプリケーションを起動してみましょう。New Relic Oneのホーム画面(Explorer)に指定したアプリケーション名でアプリケーションが表示されているはずです。リンクをクリックするとAPMに移動できますが、まだほとんどデータは表示されないはずです。

また、標準出力にたくさんログがでますが、api-server_1から次のようなメッセージが出ているはずです。

Reporting to: https://rpm.newrelic.com/accounts/<アカウントID>/applications/<アプリケーションID>

このログはAgentが正常に起動していると判断してよいメッセージです。このURLを開くとAPMの画面に移動します。

もし、表示されていない場合はログのメッセージを確認してみてください。ライセンスキーが指定されていない・誤っている、New Relicへの通信がファイヤーウォールなどで遮断されている、などが考えられます。

トランザクションを計測するためにecho向けのintegrationをセットアップする

いよいよ、意味ある計測するための計装コードを追加していきます。まずはトランザクションを検出しましょう。New Relic APMにおけるトランザクションは計測するための処理の単位で、Webアプリの場合、HTTPリクエストに対応する処理の全体となります。予選問題の例では /api/chair/low_pricedというAPIに対応する処理 getLowPricedChair  が1つのトランザクションとなります。

1つ1つの処理に個別にトランザクションとして認識させる計装コードを入れることもできますが、煩雑になるため、よく使われているいくつかのHTTPミドルウェアのライブラリに対しては簡潔に適用できるintegrationが提供されています。予選問題の場合、labstack/echo v3が使われていますが、これに対応したnrecho integrationが提供されているため、これを利用します。integrationの利用方法はそれぞれのリンク先のgodocに記載されています。nrechoの場合、次のようにルーティング処理の前にミドルウェアとして追加します。

これでトランザクションとして検出できるようになります。試しに予選問題のベンチマークを動かすと先程開いたAPMの画面にデータが表示され始めます。（なお、下の図はデータベースの計測を設定済みであるため多少異なります）特に、Transactionsのところにエンドポイントごとの処理時間の統計が表示されていることを確認してください。

カスタム属性を追加する

トランザクションの分析をすすめる際に、個別のトランザクションに任意の名前と値の組み合わせで属性をトランザクショントレースおよび分散トレースのスパンに追加できます。例えば/api/chair/searchの searchChairs でパラメーターによって処理時間が異なるのではないかと予想したのであれば、そのパラメーターの値を属性として記録し、分析に活用することができます。

Go Agentでは、AddAttribute関数を使ってカスタム属性を追加します。AddAttribute関数はnewrelic.Transactionをレシーバーとしているため、属性を追加したい関数内(例でいえばsearchChairs)でTransactionを取得する必要があります。

New Relic Go Agentでは、Transactionを始めとする現在実行している関数が計測されているオブジェクトにアクセスするAPIを提供していますが、原則としてcontext.Contextオブジェクトが必要です。echoでは、context.Contextではなくecho.Contextが利用されているため、nrechoに用意されているnrecho.FromContext関数を使ってTransactionを取得します。したがって次のような計装コードを記述します。

Transactinを取得するのは、このあとのデータベースの計測でも利用するため、機械的にすべてのメソッドの先頭に挿入するようにして、不要なものは削除するようにしてもよいかもしれません。

データベースへのクエリを計測するために計装コードを追加する

次に、ISUCONで最も改善する場所といっても過言ではないデータベースのクエリを計測します。次の図のように分散トレースで表示した際に、トレースの中でデータベースへのクエリが占める割合とそのSQLクエリが表示できるようにします。

トランザクションと同様にミドルウェアごとにintegrationが提供されているのですが、MySQL向けのintegration nrmysqlが標準で用意している手順では実現できない機能があります。それはSQLクエリの表示です。標準の手順では chair select のようにテーブル名と操作名しか表示されません。

データベース操作を記録する仕組みは、1つのトランザクション内の詳細な経過時間を記録するセグメントの仕組みを利用しています。nrmysqlは内部で自動的にDataStoreSegementを作成するのですが、手動で作成することで対応します。DataStoreSegmentを作成するcreateDataStoreSegment関数とその利用例は以下のようになります。

この計装コードをDBクエリしているすべての箇所に適用します。ある程度機械的なコードになるのと、予選問題ではクエリする箇所が20前後であるためそこまで時間はかかりませんでした。これを完了させると上の図のように分析できるようになります。

Logs in Contextを利用するためにログフォーマッターを追加する

予選問題ではログ出力自体は実装されています。このログをファイル出力し、そのファイルをInfrastructure同梱のfluentbitやfluentdでNew Relic Logsに送信すると、ひとまずアプリケーションログの分析は可能になります。

さらにLogs in Contextという機能を利用すると、APMのエラーページや先ほどの分散トレースの画面から関連するログをすぐに表示することができます。詳しくはこちらの記事を参照ください。

https://blog.newrelic.co.jp/uncategorized/new-relic-logs-in-context/

さて、Logs in Contextは技術的には、ログ出力する際にAPM Agentからの情報を取得し所定のフォーマットにして出力することで実現しています。このため、New Relicではそのような処理を行うフォーマッターをログライブラリごとに提供していますが、Goではlogrusのみ提供しています。予選問題はechoのログ機能を利用しているので、logrusを利用し、echoのロガーとしてlogrusを指定できるplutov/echo-logrusを利用することにします。実際のコードは次のようになります。

このようにしてLogs in Contextを有効にすると、例えば先程の分散トレースの右上にsee logsというリンクが表示され、クリックすると次のように関連するログが表示されるようになります。

ここまで計装コードをセットアップするとかなり分析できるようになっているはずですので、問題発見・改善策の適用・効果の確認、といったフローが回しやすくなるはずです。ぜひ、ISUCON11 New Relic 支援プログラムをご利用いただき、このブログの内容含めて気になることがあればISUCON向けのサポートプログラムをご利用ください。