Presto における Service Discovery の動作原理
Presto を運用していると “No worker nodes available” というエラーに遭遇することがあります。これは coordinator が planning をする際に active な worker nodes が存在しないと起きるエラーなんですが、worker nodes に問題ではなく service discovery が上手く機能していなくて起きることがあります。
worker nodes が異常なのか service discovery が上手く機能していないのかを切り分けるには、Presto がどのように service discovery を実現しているかを理解している必要がありますが、よくわかってなかったので調べてみました。
環境は Amazon Elastic MapReduce (EMR) ではじめる Presto 入門と同じく、Presto 0.215 を対象とします。記事中ところどころに出てくるログは、Presto 入門で言及しているのと同様の方法で起動した EMR クラスタのものです。
Presto の Service Discovery に関連する 4 つの操作
coordinator は discovery node manager の更新する worker nodes のリストを利用するんですが、このリストの更新には次のように大きく 4 つの操作が関係しています。
- 各 worker node が 8 秒間隔で discovery server に自身を登録
- service selector が discovery server に登録されている node 情報のキャッシュを 10 秒間隔で更新
- failure detector が 0.5 秒間隔で worker nodes に対するヘルスチェックを実施
- discovery node manager が worker nodes のリストを更新
- coordinator が利用するのはこの情報
これをざっくり表現すると次のようになります。
それぞれについてより詳細に説明します。
Worker node による discovery server への登録
Presto に service discovery の機能を提供しているのが io.airlift.discovery で、client と server があります。
coordinator では EmbeddedDiscoveryModule を利用することで discovery server の機能を持つようになります。また、coordinator・worker 共に DiscoveryModule を利用することで client の機能を持ちます。
client は /v1/announcement/{node_id} に PUT リクエストを送ることで自身のことを server に登録します。登録された内容は 30 秒しか有効じゃないので、client は 一定間隔で server にリクエストを送ります。この間隔は 8 秒なんですが、その理由はソースコードの次の箇所を見ればわかります。
- Announcer.java#L152-L162
- HttpDiscoveryAnnouncementClient.java#L140-L150
- 特に手を入れない限り server のレスポンスヘッダには Cache-Control の max-age が含まれないので
DEFAULT_DELAY
が使われる
- 特に手を入れない限り server のレスポンスヘッダには Cache-Control の max-age が含まれないので
実際に discovery server のログを見てみると、自身 (172.31.12.132) からのリクエストも含めて、8 秒間隔でリクエストが届いているのがわかります。
[hadoop@ip-172-31-12-132 ~]$ grep /v1/announcement/ /var/log/presto/http-request.log | tail -6
2019-12-30T20:11:58.554Z 172.31.11.228 PUT /v1/announcement/i-03b318a81b0e7e111 null i-03b318a81b0e7e111 202 653 0 0 4a9527959d254d12892a7ddb075d07af0000002c3fHTTP/1.1 0 0 -1 null
2019-12-30T20:12:02.427Z 172.31.6.91 PUT /v1/announcement/i-0a310199806b303fd null i-0a310199806b303fd 202 643 0 0 4a9527959d254d12892a7ddb075d07af0000002c44HTTP/1.1 0 0 -1 null
2019-12-30T20:12:03.673Z 172.31.12.132 PUT /v1/announcement/i-0a4878ec8276e705a null i-0a4878ec8276e705a 202 968 0 1 4a9527959d254d12892a7ddb075d07af0000002c46HTTP/1.1 0 0 -1 null
2019-12-30T20:12:06.555Z 172.31.11.228 PUT /v1/announcement/i-03b318a81b0e7e111 null i-03b318a81b0e7e111 202 653 0 1 4a9527959d254d12892a7ddb075d07af0000002c49HTTP/1.1 0 0 -1 null
2019-12-30T20:12:10.429Z 172.31.6.91 PUT /v1/announcement/i-0a310199806b303fd null i-0a310199806b303fd 202 643 0 0 4a9527959d254d12892a7ddb075d07af0000002c4bHTTP/1.1 0 0 -1 null
2019-12-30T20:12:11.674Z 172.31.12.132 PUT /v1/announcement/i-0a4878ec8276e705a null i-0a4878ec8276e705a 202 968 0 1 4a9527959d254d12892a7ddb075d07af0000002c4dHTTP/1.1 0 0 -1 null
discovery server への登録に関するシーケンス図は次のとおりです。
なお、登録されている node の情報は GET /v1/service/presto/general で取得できます。
[hadoop@ip-172-31-12-132 ~]$ curl localhost:8889/v1/service/presto/general?pretty
{
"environment" : "production",
"services" : [ {
"id" : "6b8c8bdc-810e-4e08-b9c4-6213563fc475",
"nodeId" : "i-0a310199806b303fd",
"type" : "presto",
"pool" : "general",
"location" : "/i-0a310199806b303fd",
"properties" : {
"node_version" : "0.215",
"coordinator" : "false",
"http" : "http://172.31.6.91:8889",
"http-external" : "http://172.31.6.91:8889",
"connectorIds" : "hive,system"
}
}, {
"id" : "29da201e-d555-435a-8647-d13660483e01",
"nodeId" : "i-03b318a81b0e7e111",
"type" : "presto",
"pool" : "general",
"location" : "/i-03b318a81b0e7e111",
"properties" : {
"node_version" : "0.215",
"coordinator" : "false",
"http" : "http://172.31.11.228:8889",
"http-external" : "http://172.31.11.228:8889",
"connectorIds" : "hive,system"
}
}, {
"id" : "ada55185-24c2-4d56-9283-9b976e3ec837",
"nodeId" : "i-0a4878ec8276e705a",
"type" : "presto",
"pool" : "general",
"location" : "/i-0a4878ec8276e705a",
"properties" : {
"node_version" : "0.215",
"coordinator" : "true",
"http" : "http://172.31.12.132:8889",
"http-external" : "http://172.31.12.132:8889",
"connectorIds" : ""
}
} ]
}
Service selector による node 情報キャッシュの更新
DiscoveryModule では discovery server に登録されている service の情報を取得するのに CachingServiceSelector を使用します。
厳密には MergingServiceSelector なんですが、MergingServiceSelector が CachingServiceSelector を所有しており、discovery server に問い合わせを行うのは CachingServiceSelector です。
CachingServiceSelector は 10 秒間隔で discovery server にリクエストを送り、node の一覧を更新します。
実際に discovery server のログを見てみると、10 秒間隔でリクエストが届いているのがわかります。DiscoveryModule の機能であるため、coordinator・worker 問わず discovery server から node の一覧を取得します。
[hadoop@ip-172-31-12-132 ~]$ grep /v1/service/presto /var/log/presto/http-request.log | tail -6
2019-12-30T20:13:03.923Z 172.31.11.228 GET /v1/service/presto/general null i-03b318a81b0e7e111 200 0 962 1 4a9527959d254d12892a7ddb075d07af0000002c8d HTTP/1.1 0 0 0 null
2019-12-30T20:13:11.591Z 172.31.6.91 GET /v1/service/presto/general null i-0a310199806b303fd 200 0 962 1 4a9527959d254d12892a7ddb075d07af0000002c93 HTTP/1.1 0 0 0 null
2019-12-30T20:13:11.807Z 172.31.12.132 GET /v1/service/presto/general null i-0a4878ec8276e705a 200 0 962 0 4a9527959d254d12892a7ddb075d07af0000002c95 HTTP/1.1 0 0 0 null
2019-12-30T20:13:13.925Z 172.31.11.228 GET /v1/service/presto/general null i-03b318a81b0e7e111 200 0 962 1 4a9527959d254d12892a7ddb075d07af0000002c99 HTTP/1.1 0 0 0 null
2019-12-30T20:13:21.611Z 172.31.6.91 GET /v1/service/presto/general null i-0a310199806b303fd 200 0 962 1 4a9527959d254d12892a7ddb075d07af0000002c9e HTTP/1.1 0 0 0 null
2019-12-30T20:13:21.808Z 172.31.12.132 GET /v1/service/presto/general null i-0a4878ec8276e705a 200 0 962 1 4a9527959d254d12892a7ddb075d07af0000002c9f HTTP/1.1 0 0 0 null
Failure detector によるヘルスチェックの実施
failure detector としては HeartbeatFailureDetector が使われます。
HeartbeatFailureDetector は一定間隔で worker nodes に HEAD リクエストを送ることでヘルスチェックを行います。
デフォルトの設定だと、ヘルスチェックの間隔は 500 ms で、1 分間の失敗の割合が 0.1 を超えると異常とみなされます。
Discovery node manager による worker nodes のリストの更新
coordinator が利用する node のリストを管理しているのは DiscoveryNodeManager です。DiscoveryNodeManager は 5 秒間隔で pollWorkers を実行することで node のリストと各 node の state を更新します。
流れは次のとおりです。
node の state は /v1/info/state にリクエストすることで取得しています。
各 worker のログを見ると、5 秒間隔で coordinator (172.31.12.132) からリクエストが来ていることがわかります。
[hadoop@ip-172-31-6-91 ~]$ grep /v1/info/state /var/log/presto/http-request.log | tail -3
2019-12-30T20:51:48.469Z 172.31.12.132 GET /v1/info/state null null 200 0 9 0 f2b3905f1ba842e4957ad46855b567f700000048b5 HTTP/1.1 0 0 0null
2019-12-30T20:51:53.47Z 172.31.12.132 GET /v1/info/state null null 200 0 9 0 f2b3905f1ba842e4957ad46855b567f700000048c2 HTTP/1.1 0 0 0 null
2019-12-30T20:51:58.47Z 172.31.12.132 GET /v1/info/state null null 200 0 9 1 f2b3905f1ba842e4957ad46855b567f700000048d0 HTTP/1.1 0 0 0 null
なお、state は ACTIVE, SHUTTING_DOWN, INACTIVE(presto-server のバージョンが coordinator と違う)の 3 種類しかないようです。
No worker nodes available が起きたら確認すること
DiscoveryNodeManager は、前まで登録されていた node がいなくなると、“Previously active node is missing” というログを server.log に吐きます。
Presto における service discovery の動作原理について理解していれば、これが起きる場合次のどちらかが起きているということはわかるはずです。
- discovery server が当該 worker node からの PUT リクエストを 30 秒以上受け取っていない
- それによって
GET /v1/service/presto/general
の結果に含まれなくなった
- それによって
- 当該 worker node が直近 1 分間のヘルスチェックに失敗する確率が 1 割を超えている
よって、前者であれば coordinator の http-request.log を見て、当該 worker node から /v1/announcement/{node_id}
に対してリクエストがあるか確認すればよいでしょう。当該 worker node からだけリクエストのログがない場合、当該 worker node の不具合である可能性が濃厚です。後者であれば当該 worker node の http-request.log を見て、HEAD /
に対してリクエストがあるか確認すればよいでしょう。
/v1/announcement/{node_id}
に対してリクエストがない場合、当該 worker node の server.log を確認し、不穏なエラーが出ていないか確認しましょう。例えば、discovery server からの応答がない場合は次のようなエラーログが記録されます。
2019-12-30T21:04:12.449Z ERROR Discovery-4 io.airlift.discovery.client.CachingServiceSelector Cannot connect to discovery server for refresh (presto/general): Lookup of presto failed for http://ip-172-31-12-132.ap-northeast-1.compute.internal:8889/v1/service/presto/general
2019-12-30T21:04:12.852Z ERROR Discovery-0 io.airlift.discovery.client.CachingServiceSelector Cannot connect to discovery server for refresh (collector/general): Lookup of collector failed for http://ip-172-31-12-132.ap-northeast-1.compute.internal:8889/v1/service/collector/general
2019-12-30T21:04:15.523Z ERROR Announcer-3 io.airlift.discovery.client.Announcer Cannot connect to discovery server for announce: Announcement failed for http://ip-172-31-12-132.ap-northeast-1.compute.internal:8889
2019-12-30T21:04:15.524Z ERROR Announcer-3 io.airlift.discovery.client.Announcer Service announcement failed after 1.00m. Next request will happen within 8000.00ms
このようなログが全 worker nodes で出ている場合、coordinator で Stop The World が起きているかもしれません。coordinator の GC ログを確認すると良いでしょう。