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 が利用するのはこの情報

これをざっくり表現すると次のようになります。


Show the source

それぞれについてより詳細に説明します。

Worker node による discovery server への登録

Presto に service discovery の機能を提供しているのが io.airlift.discovery で、clientserver があります。
coordinator では EmbeddedDiscoveryModule を利用することで discovery server の機能を持つようになります。また、coordinator・worker 共に DiscoveryModule を利用することで client の機能を持ちます。

client は /v1/announcement/{node_id} に PUT リクエストを送ることで自身のことを server に登録します。登録された内容は 30 秒しか有効じゃないので、client は 一定間隔で server にリクエストを送ります。この間隔は 8 秒なんですが、その理由はソースコードの次の箇所を見ればわかります。

実際に 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 への登録に関するシーケンス図は次のとおりです。


Show the source

なお、登録されている 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 を更新します。

流れは次のとおりです。


Show the source

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 ログを確認すると良いでしょう。