spark thrift server gc

spark thrift serverが不安定でOutOfMemoryになったりしてたんでJVMオプションをいじってた。

うちの環境だとambari管理なのでjava heapを増やす場合はAdvanced spark2-envのspark_daemon_memoryを増やせばOKです。ちなみにデフォルトは1GBです。 それ以外はSPARK_DAEMON_JAVA_OPTSを設定します。下記のような感じ。ちなみにどっちもいじるとspark history serverでも有効になります。

export SPARK_DAEMON_JAVA_OPTS="$SPARK_DAEMON_JAVA_OPTS -javaagent:/usr/local/lib/jmx_prometheus_javaagent-0.11.0.jar=20015:/usr/local/etc/jmx_exporter_spark.yaml -Xloggc:/var/log/spark2/gc_%p_%t.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps"

で、GCログを見ると以下のようになってる。

2019-03-08T12:54:41.265+0900: 89936.447: [GC (Allocation Failure) [PSYoungGen: 1225762K->14514K(1689088K)] 3800753K->2593725K(6508032K), 0.0097586 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2019-03-08T12:55:25.468+0900: 89980.650: [GC (Allocation Failure) [PSYoungGen: 1228978K->11218K(1225728K)] 3808189K->2593142K(6044672K), 0.0093735 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
2019-03-08T12:55:57.112+0900: 90012.294: [GC (System.gc()) [PSYoungGen: 937862K->8066K(1673216K)] 3519786K->2591721K(6492160K), 0.0087363 secs] [Times: user=0.15 sys=0.01, real=0.01 secs]
2019-03-08T12:55:57.121+0900: 90012.303: [Full GC (System.gc()) [PSYoungGen: 8066K->0K(1673216K)] [ParOldGen: 2583655K->1464248K(4818944K)] 2591721K->1464248K(6492160K), [Metaspace: 154960K->154935K(1187840K)], 1.3926389 secs] [Times: user=32.27 sys=0.12, real=1.39 secs]
2019-03-08T12:56:37.166+0900: 90052.347: [GC (Allocation Failure) [PSYoungGen: 1220096K->3678K(1224192K)] 2684344K->1467927K(6043136K), 0.0078803 secs] [Times: user=0.11 sys=0.00, real=0.01 secs]
2019-03-08T12:57:20.567+0900: 90095.748: [GC (Allocation Failure) [PSYoungGen: 1223774K->5886K(1647104K)] 2688023K->1470135K(6466048K), 0.0088429 secs] [Times: user=0.11 sys=0.00, real=0.01 secs]
2019-03-08T13:01:22.166+0900: 90337.347: [GC (Allocation Failure) [PSYoungGen: 1230590K->3231K(1228288K)] 2694839K->1467479K(6047232K), 0.0100951 secs] [Times: user=0.13 sys=0.01, real=0.01 secs]

Full GC (System.gc())ってなんじゃらほいって思ったけど、どうもcontext-cleaner-periodic-gcスレッドでSystem.gc()呼んでる模様 https://github.com/apache/spark/blob/v2.1.1/core/src/main/scala/org/apache/spark/ContextCleaner.scala#L128

なおambari管理だとspark thrift serverが不安定になると二度的に再起動してくれるので便利

release yanagishima 19.0(support sparksql)

yanagishimaというpresto web uiを作っていて気づけばhive, elasticsearchに続いてsparksqlをサポートしたので今回はその辺をちょっと書いてみようと思います。 https://github.com/yanagishima/yanagishima

sparkではspark thrift serverなるものを起動すればHive JDBC Driverを使ってsqlをsubmitすることができます。 https://spark.apache.org/docs/latest/sql-distributed-sql-engine.html

うちの環境だとsparkをyarn上で動かしています。 この場合spark thrift serverを起動すると一つのyarn applicationが立ち上がります。 このApplication Masterのリンクをクリックするとsparkのweb uiを見ることができます。 http://sparkthriftserver:4040にアクセスしても同じ。

複数のユーザがこのyarn applicationを共有する感じになります。 containerというかexecutorの数はsparkのdynamic allocationの仕組みで動いていてdefaultだとmaxでも10個のcontainerしか動かないので、うちの環境では増やしてます。 spark.dynamicAllocation.minExecutorsを50にしているので最初は50個のcontainerが動きます。 ちなみにspark thrift serverで一つ使うので合計すると51個動きます。

またspark thrift serverはdefaultだと1GBのメモリで動いていてOutOfMemoryに遭遇したので4GBに増やしました。 https://community.hortonworks.com/content/supportkb/233822/sparkthriftserver-crashing-with-java-heap-outofmem.html

うちはHDP環境なのでAmbariでSPARK_DAEMON_MEMORYをいじって設定しました。

なお僕はyanagishimaを作って運用して4年ぐらい経ちますが、この手のビッグデータを扱うsqlフロントエンドツールではジョブをsubmitして結果を表示するだけでは不十分です。

ジョブの進捗状況が見れて、クエリを途中でキャンセル出来ることが重要です。また全ジョブの実行状況が見れることも管理上必要です。

そしてつくづく分かったのはprestoはapiというかアーキテクチャからして上記の要件を実装しやすいが、他はそれが簡単ではないということです。 prestoの場合はJDBCではなくpresto-clientを使えばジョブをsubmitしてすぐにquery idを取得できます。 そしてこのquery idを使ってapiをたたけば途中の進捗状況も取れますし、クエリのキャンセルも可能です。 ジョブの一覧を見るのも容易です。

一方、Hive JDBC Driverを使うとStatement#cancelを使えばクエリのキャンセルこそできますが、進捗状況や全ジョブ一覧を知るには一工夫必要です。 Hive on MapReduceであればyarn rest apiを使えば割といろいろできますが、自分が投げたジョブがどのジョブかを判断するのは簡単ではありません。

yanagishima hiveではshibを真似してmapreduce.job.nameをいじってyanagishima-hive-wyukawa-20190305_060438_9235eaae6f11cd0ff3de907771b28914みたいなユニークなidを採番して設定してトラッキングします。 このidは自前で採番します。prestoとはここが違います。

Hive on Tezだと同じことができないので進捗状況を知ることができません。

sparksqlの場合はどうするかというとすごく泥臭いことをしました。

sparkもapiはありますが、十分ではありません。 https://spark.apache.org/docs/latest/monitoring.html https://medium.com/@an_chee/how-to-get-spark-metrics-as-json-using-spark-rest-api-in-yarn-cluster-mode-52a88002c826

sparkのjob idがわかればnumCompletedTasks / numTasksで進捗状況がわかります。 問題はどうやって知るかです。

http//[resourcemanager]:8088/proxy/[spark application id]/api/v1/applications/[spark application id]/jobs をたたけばジョブ一覧が取れます。

以下は一つのジョブの例です。

  "jobId" : 15,
  "name" : "run at AccessController.java:0",
  "submissionTime" : "2019-02-21T02:23:54.513GMT",
  "stageIds" : [ 21 ],
  "jobGroup" : "b46b9cee-bb9d-4d10-8b44-5f7328ce5748",
  "status" : "RUNNING",
  "numTasks" : 1093,
  "numActiveTasks" : 1,
  "numCompletedTasks" : 488,
  "numSkippedTasks" : 0,
  "numFailedTasks" : 0,
  "numActiveStages" : 1,
  "numCompletedStages" : 0,
  "numSkippedStages" : 0,
  "numFailedStages" : 0

これだけだと誰がどんなクエリ投げたのかわからないですが、http://sparkthriftserver:4040/sqlserverSQL StatisticsのところにUser, JobID, GroupID, Start Time, Finish Time, Duration, Statement, State, Detail があって、ここのJobIDと上記のjobGroupを紐づければ誰がどんなクエリを投げたかわかります。やったね。 だがしかしapiが無いようなので仕方なくhtml parseしました。。。

ともあれ、そんな感じで作りました。

sparkも今後rest apiが充実するといいなあというか、そういう状況だからApache Livyが存在しているという気もする。 遠い昔まだhadoop 1の時代にrest apiがなかったのでHuahin Managerがあったように。

ベジタブルマラソン走ってきた

記録はネットタイムが1時間51分35秒。ちなみに2017年が1時間47分39秒、2016年が1時間49分33秒。2015年が1時間44分17秒、2014年が1時間42分7秒です。

練習不足なのでこんなもんですかね。走っている時はエイドのキュウリ、ミニトマト、パイナップル、オレンジ、レモン、グレープフルーツ、チョコ、梅干しを少々、走り終わった後は豚汁、熊谷駅で満州の餃子とチャーハンを食べて帰ってきました。餃子は王将の方がうまいな。

この大会は12時スタートで人数もそんなに多くなく気軽に参加できる良い大会です。
5年連続で参加してますが、毎回良い天気ですが若干風があって寒かった。。

今日が走り納めです。runtasticによると今年は1285km走ったらしい。2017年は1471km、2016年は1476km、2015年は1633kmです。

今年はあんまり走れてなかったけど、来年はもうちょっと走ろうかな。

那覇マラソン走ってきた

記録は5時間6分57秒で、ワーストなのはある程度事前に予想できたけど5時間オーバーなのは想定外。

理由は練習不足以外にも、思ったより暑く最高気温が27度を超えたらしい。元々完走率が低い大会で今回も60%ほど。地味にアップダウンもあってコース的にもタフ。

後半はしばしば歩いてしまったし、20回以上フルマラソン走ったけどこんなにきつかったのは、初マラソンで膝やった時以来だな。

びっくりしたのはエイドでゴミ箱がほぼなくて道路にすてる前提になっていることと、立ち小便が多かった事。あとランナーが多過ぎてちょっと走りづらいかな。

エイドに関しては公式のものは少なくてほぼ私設エイドに頼っているのが実態で、僕もお世話になったけど、私設エイドが無かったら完走は難しかったと思う。

私設エイドはもちろんありがたいんだけど、参加費上げてランナー減らしてもっとクオリティ上げた方が良いのではと思ってしまった。まあずっと続いてるし評価の高い大会なのでそういうもんだと思った方がいいんでしょうけど、他の大会と雰囲気違ったんでちょっとびっくりしました

 

 

横浜マラソン走ってきた

タイムは手元のGARMINで4:43:18と自己ワーストだったけど練習不足なのでしょうがない。去年は台風で中止になり今年はその分の優先出走権を使って参加した。去年参加予定で今年も参加した人は2つの完走メダルをもらえた。

 

感想はというと、まあ次回参加は無いかなというもの。理由は下記の通り。

RUNNETの評価みてもぱっとしない感じでまあそうだろうなと思った。

  1. コースではスタート、フィニッシュ直後以外横浜らしさが無い
  2. ラッキー給食を一つも食べられなかった
  3. 給水のドリンクがぬるかった
  4. ゴール後の導線が悪く混雑していた
  5. 参加費が東京マラソンより高い
  6. 事前受付が必要

なんか批判ばかりになってしまったけど、参加者数が多すぎるんじゃないかな。もっとももっと参加者が多い東京マラソンは完璧な運営してるけど、あれと比べられると辛いというのはわかる。

イタリア旅行

9月下旬にリフレッシュ休暇でイタリアに行ってきました。

ネット環境はいままではWifiルーター使ってたんですが、繋がらないことも多かったので今回はSIM買いました。
値段も安いし、ちゃんと繋がるし良いですね。

機内ではFire HD 10にNetflixでダウンロードしたテラスハウスをずっと見てました。
普段はkindle使いなのですが、こういう動画視聴デバイスを何にするか出発前に考えていて、最初はiPadにしようかと思ったんですが、値段高いのでFire HDへ。Fire HDは雑誌読む時にカラーなのが良いのと動画見るのには向いてます。

フライトは成田からデュッセルドルフ経由でミラノに入りました。帰りは逆になります。
ミラノのマルペンサ空港からミラノ中央駅へはシャトルバスを使いましたが、これは楽でいいです。
スーツケースを持ち運ばなくていいし、空港からバス乗り場も近い。

僕は マルペンサ空港からミラノ市内へのアクセスまとめ を参考にTerravision社のバスを使いました。

ミラノカードなるものを事前に購入してこれを現地で受け取ってそれを使って地下鉄でDuomoへ

View this post on Instagram

Duomo

wyukawaさん(@wyukawa)がシェアした投稿 -


ガッレリア

View this post on Instagram

ヨーロッパっぽい

wyukawaさん(@wyukawa)がシェアした投稿 -

ブレラ絵画館は僕のような美術全く興味無い人間でも結構楽しめます。

死せるキリスト


イタロでベネチアへ。
電車は日本でレイルヨーロッパで全部予約しました。イタロ良いです。座席のグレードが3つあって僕は真ん中のPrimaにしました。
参考 イタロの予約と座席、サービスについて - 乗車レビュー

ベネチアは特別な街でミラノのような都会ではないですが、駅でてすぐ下記のように川と橋が見えて良い感じです。

View this post on Instagram

ベネチアの駅出てすぐこんな感じです。

wyukawaさん(@wyukawa)がシェアした投稿 -


サン・マルコ広場へ行き鐘楼に登ってそこからの眺め

View this post on Instagram

上からの眺め

wyukawaさん(@wyukawa)がシェアした投稿 -

他は ヴェネチアの勧め - Chikirinの日記 を参考に僕はサン・ロッコドガーナに行きました。
ベネチアは道が狭くしかも橋を渡らないといけない箇所もあってGoogle Map使っていてもちょいちょい迷いましたが、広くは無いので徒歩で割となんとかなります。水上バスのヴァポレットも使いましたが、遅いので1回乗れば十分な気がします。

ベネチアのレストランはここがお勧めです。ネット予約もできます。
Hostaria Osottoosopra (ベネチア) の口コミ675件 - トリップアドバイザー

ベネチアの次はフィレンツェへ。

フィオレンティーナの試合も見てきました。


電車でピサにも行ってきた。

View this post on Instagram

傾いてるな

wyukawaさん(@wyukawa)がシェアした投稿 -


フィレンツェ観光後はミラノに戻ってサッカー観戦。サン・シーロスタジアムです。

View this post on Instagram

始まりました

wyukawaさん(@wyukawa)がシェアした投稿 -

そのあとトリノに移動してユベントス戦観戦

View this post on Instagram

試合画像

wyukawaさん(@wyukawa)がシェアした投稿 -

ローマへ移動

トレビの泉

View this post on Instagram

トレビの泉

wyukawaさん(@wyukawa)がシェアした投稿 -


スペイン広場

View this post on Instagram

スペイン広場

wyukawaさん(@wyukawa)がシェアした投稿 -


ローマのレストランはここがお勧めです。
Ristorante Nerone (ローマ) の口コミ694件 - トリップアドバイザー



ナポリへ移動して観光
地下鉄の1日券買ったのに乗り場行こうとしたらその日は閉鎖されていたので徒歩で、ヌオーヴォ城の方へ行きました。

View this post on Instagram

城からの眺め

wyukawaさん(@wyukawa)がシェアした投稿 -


ローマに戻って観光してたら、ローマのユニフォームきたお姉さんが観光地でローマダービーのチケット売ってたのでうっかり購入して試合見てきました。
お姉さんに中田英寿知ってるか?って聞いたら知らんとのこと。まあ20代っぽかったしな。

View this post on Instagram

後半キックオフ

wyukawaさん(@wyukawa)がシェアした投稿 -

そういえば旅行来る前に

読んでて中田がペルージャにきてからもう20年もたつのかあという。
ローマ時代の思い出のところの記事が良いです。もちろんあのユベントス戦のこともかかれているし、なによりもモンテッラのくだりが熱い。
プロフェッショナルとはこうなんだなという。


そんなわけで約二週間のイタリア旅行でしたが、天気がずっとよくて、昼間は暑かったです。
心配してた治安も問題なく、不満といえばホテルがしょぼいぐらいですね。狭いし朝食の種類が少ない。ここに関してはイギリスの方がはるかに上。
これでイギリス、フランス、ベルギー、ドイツ、イタリアに行ったので次はスペインに行きたいなあ。

Hadoopのworker系nodeでのkernel panic

6月ごろからHadoopのworker系nodeつまりdatanode, nodemanager, presto workerが動いているnodeでkernel panicが多発するようになって困っていてまだ解決はしていないのですが、メモっておきます。

ログ分析基盤として使っているHadoopクラスタで深夜帯にバッチを動かします。
load averageは100を超えることもあり、マシンスペックはメモリ256GB、CPUは40プロセッサ、HDDは3TBが12本ささってます。
OSはCentOS 7.2.1511です。
データ量が増えてきたこともあり、ディスクだけじゃなくコンピューティングリソースももりもり使ってます。

だいたい午前6時から8時にkernel panic起こることが多くて、ひどいときは短い時間に3台kernel panicが起きて、マシン再起動、サービス起動が間に合わずmissing blockになってjobが失敗することもありました。
負荷がピークの時に起きているわけではないのがちょっと不思議なのですが、別の負荷がそんなに高くないHadoopクラスタでは全く起きてないので負荷が原因のひとつではありそう。

この状況はさすがに辛いので、ジョブのスケジューリングを変えて負荷を平準化するとともに、インフラチームから提案のあったkernelアップグレードをやったところ回数こそ減ったもののまだ週一回程度起きます。
さらに仮にkernel panicしても、マシン再起動したらdatanode, nodemanager, presto workerが自動起動するようにsystemctlにType=oneshotで仕込みました。

ただ

Wants=network-online.target
After=network-online.target

とかやっても期待通りに動かなかったので、

After=network.target remote-fs.target nss-lookup.target ambari-agent.service

とかしてさらにsleep 45してマシン再起動時にambari apiをたたいてdatanode, nodemanagerを起動するようにしました。


kernelは3.10.0-514.2.2から3.10.0-862.9.1にあげました。

マシン再起動が必要で3台同時にやるとmissing blockになってジョブがこけるので多くても2台まで同時に作業しました。ここは完全に手動で温かみのある作業です。40台でだいたい4時間かかりました。

その後まだkernel panicが起きたのでkdumpを仕込みました。元々kdump自体はインストール済みだったので設定だけ少し変えて起動しときました。
どこを変えたかというとvmcoreはそれなりの容量になる気がしたので、OSとは別のパーティションに出力するように変更しました。

そしてkernel panicがまた起きてcrashコマンドでの解析を試みましたが、よくわからずcentosにissue登録しました。
0015216: 3.10.0-862.9.1.el7.x86_64 kernel panic and crash under hadoop environment - CentOS Bug Tracker

メッセージに

[exception RIP: find_busiest_group+869]

とあったのでfind_busiest_groupでググる
https://qiita.com/nhiroki/items/2fa7bb048118145b00cd
が見つかりずいぶん参考になりました。
負荷が高いときにスケジューラ周りのバグを踏んだんじゃないかという気がしますが、その後centos teamから返信がきて、最新のkernel 3.10-862.11.6を試してくれない?って言われます。
タイミング悪く3.10.0-862.9.1にあげた後にすぐ3.10-862.11.6が出たようです。
cpu hot plug関連でcpu core数が正しく表示されないbug 0015108: cpu core counts change unexpectedly - CentOS Bug Trackerが関係してそうでそれがkernel 3.10-862.11.6でfixされているとのことでした。

バージョン一覧がどこにあるのかよくわからんですが、例えば下記で見れるようです。
ftp://ftp.riken.jp/Linux/cern/centos/7/updates/x86_64/repoview/kernel-devel.html

3.10.0-862.9.1と3.10-862.11.6の差分は下記で見れます。
https://git.centos.org/compare/rpms!kernel.git/refs!tags!imports!c7!kernel-3.10.0-862.11.6.el7..refs!tags!imports!c7!kernel-3.10.0-862.9.1.el7

kernel upgradeのansible playbookはこんな感じで作りました。

    - name: chattr -i
      command: chattr -i /boot/grub2/grub.cfg

    - name: upgrade kernel
      yum: name=kernel state=latest

    - name: chattr +i
      command: chattr +i /boot/grub2/grub.cfg


3.10.0-862.11.6にあげても残念ながらkernel panicは起きました。ただメッセージは違いました。

 [exception RIP: __hrtimer_get_next_event+52]

その旨を報告すると、関連しそうな部分を直したものが含まれる3.10.0-862.11.6.el7.centos.plus.2を試してくれと言われます。

plus.1だったら

yum install --enablerepo=centosplus kernel-plus

とかすれば入りましたが、plus.2はkernel-plusにはないようなのでrpmで入れます。playbookはこんな感じ。

    - name: chattr -i
      command: chattr -i /boot/grub2/grub.cfg

    - name: install kernel-plus
      yum: name=http://.../kernel-plus-3.10.0-862.11.6.el7.centos.plus.2.x86_64.rpm state=present

    - name: grubby --set-default
      command: grubby --set-default=/boot/vmlinuz-3.10.0-862.11.6.el7.centos.plus.2.x86_64

    - name: chattr +i
      command: chattr +i /boot/grub2/grub.cfg

で、今は様子見中です。今までの頻度を考えると1週間何も起きなかったら解決したと思っていい気がします。