2017-11-17

hiveserver2とFull GC

Hive Ambari

昔からhiveserver2はあんまり安定してない気がしますが、最近ちょっと不調でたまに下記のようなエラーが出て接続できないときがありました。

hiveserver2 log

2017-11-10 01:18:38,430 ERROR [CuratorFramework-0]: curator.ConnectionState (ConnectionState.java:checkTimeouts(201)) - Connection timed out for connection string (...) and timeout (15000) / elapsed (27689)
org.apache.curator.CuratorConnectionLossException: KeeperErrorCode = ConnectionLoss
        at org.apache.curator.ConnectionState.checkTimeouts(ConnectionState.java:198)
        at org.apache.curator.ConnectionState.getZooKeeper(ConnectionState.java:88)
        at org.apache.curator.CuratorZookeeperClient.getZooKeeper(CuratorZookeeperClient.java:115)
        at org.apache.curator.framework.imps.CuratorFrameworkImpl.performBackgroundOperation(CuratorFrameworkImpl.java:793)
        at org.apache.curator.framework.imps.CuratorFrameworkImpl.backgroundOperationsLoop(CuratorFrameworkImpl.java:779)
        at org.apache.curator.framework.imps.CuratorFrameworkImpl.access$400(CuratorFrameworkImpl.java:58)
        at org.apache.curator.framework.imps.CuratorFrameworkImpl$4.call(CuratorFrameworkImpl.java:265)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)
2017-11-10 01:20:20,112 INFO  [HiveServer2-Handler-Pool: Thread-7717854]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(316)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V1
2017-11-10 01:20:15,609 INFO  [main-SendThread(...)]: zookeeper.ClientCnxn (ClientCnxn.java:logStartConnect(1019)) - Opening socket connection to server ... Will not attempt to authenticate using SASL (unknown error)
2017-11-10 01:19:57,850 INFO  [org.apache.hadoop.hive.common.JvmPauseMonitor$Monitor@1b8aaeab]: common.JvmPauseMonitor (JvmPauseMonitor.java:run(193)) - Detected pause in JVM or host machine (eg GC): pause of approximately 4750ms
GC pool 'PS MarkSweep' had collection(s): count=3 time=16270ms
2017-11-10 01:19:47,440 WARN  [ResponseProcessor for block BP-1300916934-10.133.205.214-1498027028735:blk_1430709533_370841656]: hdfs.DFSClient (DFSOutputStream.java:run(952)) - DFSOutputStream ResponseProcessor exception  for block BP-1300916934-10.133.205.214-1498027028735:blk_1430709533_370841656
java.io.EOFException: Premature EOF: no length prefix available
        at org.apache.hadoop.hdfs.protocolPB.PBHelper.vintPrefixed(PBHelper.java:2464)
        at org.apache.hadoop.hdfs.protocol.datatransfer.PipelineAck.readFields(PipelineAck.java:244)
        at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSOutputStream.java:843)

https://community.hortonworks.com/questions/51735/hiveserver-2-zookeeper-discovery-connection-timeou.html
と同じっぽいんですが、GCに時間がかかりZookeeperとのsessionがtimeoutしたのかなと。

確かにこの時間帯にmap数が1万を超えるでかいジョブがあって、なんでそんなmap数なのかというとfluent-plugin-webhdfsで書き込むときにappend noにしていてそのせいでファイル数が多いからですね。

append trueにするとArrayIndexOutOfBoundsExceptionがでることがあってnoにしてます。
http://community.cloudera.com/t5/Storage-Random-Access-HDFS/Cannot-get-a-file-on-HDFS-becouse-of-quot-java-lang/td-p/53169
https://issues.apache.org/jira/browse/HDFS-11797

困ったなあと思ってて、設定いじるのもいいけど、それより1回のバッチでどかんとやるよりこまめにバッチ回して1回で処理するファイル数を減らす方がいいだろうということでそうしました。
その結果Full GCも起きなくなってSTWもなくなりめでたしめでたし。

HDP 2.6だとデフォルトではgcログが取られないので、下記を追加して取るようにしました。

      if [ "$SERVICE" = "hiveserver2" ]; then
        export HADOOP_OPTS="$HADOOP_OPTS -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/var/log/hive/gc-${SERVICE}.log-`date +'%Y%m%d%H%M'`"
      fi

https://community.hortonworks.com/content/supportkb/49404/how-to-setup-gc-log-for-hiveserver2.html

バッチ変える前は下記のようにFull GCが発生してました。2回起きてますね。

2017-11-16T00:52:22.671+0900: 47249.284: [GC (Allocation Failure) [PSYoungGen: 6918137K->72176K(6012928K)] 7981039K->2023320K(8730624K), 0.5683705 secs] [Times: user=3.29 sys=12.50, real=0.57 secs]
2017-11-16T00:52:32.438+0900: 47259.050: [GC (Allocation Failure) [PSYoungGen: 6012912K->524788K(6465536K)] 7964056K->2807209K(9183232K), 0.1574991 secs] [Times: user=3.64 sys=0.65, real=0.15 secs]
2017-11-16T00:52:32.595+0900: 47259.208: [Full GC (Ergonomics) [PSYoungGen: 524788K->0K(6465536K)] [ParOldGen: 2282420K->2185571K(5553664K)] 2807209K->2185571K(12019200K), [Metaspace: 102986K->101087K(1150976K)], 4.4533082 secs] [Times: user=112.93 sys=0.78, real=4.46 secs]
2017-11-16T00:52:47.234+0900: 47273.847: [GC (Allocation Failure) [PSYoungGen: 5940736K->524790K(5734400K)] 8126307K->2964402K(11288064K), 0.1517864 secs] [Times: user=3.36 sys=0.82, real=0.15 secs]
2017-11-16T00:52:55.600+0900: 47282.213: [GC (Allocation Failure) [PSYoungGen: 5734390K->890342K(6099968K)] 8174002K->3661994K(11653632K), 0.2500997 secs] [Times: user=3.94 sys=3.00, real=0.25 secs]
2017-11-16T00:53:03.919+0900: 47290.532: [GC (Allocation Failure) [PSYoungGen: 6099942K->890364K(4796416K)] 8871594K->4367760K(10350080K), 0.3153721 secs] [Times: user=6.27 sys=2.49, real=0.31 secs]
2017-11-16T00:53:10.345+0900: 47296.958: [GC (Allocation Failure) [PSYoungGen: 4796412K->1405980K(5312512K)] 8273808K->4883376K(10866176K), 0.1721397 secs] [Times: user=4.61 sys=0.15, real=0.18 secs]
2017-11-16T00:53:16.567+0900: 47303.180: [GC (Allocation Failure) [PSYoungGen: 5312028K->1677820K(4380672K)] 8789424K->5401912K(9934336K), 0.2496912 secs] [Times: user=6.51 sys=0.42, real=0.25 secs]
2017-11-16T00:53:21.011+0900: 47307.623: [GC (Allocation Failure) [PSYoungGen: 4380668K->2038332K(4741632K)] 8104760K->5762424K(10295296K), 0.2283467 secs] [Times: user=6.27 sys=0.06, real=0.23 secs]
2017-11-16T00:57:50.867+0900: 47577.479: [GC (Allocation Failure) [PSYoungGen: 4741180K->2134990K(4578816K)] 8465272K->5907156K(10132480K), 0.9619241 secs] [Times: user=4.24 sys=22.59, real=0.96 secs]
2017-11-16T00:59:40.294+0900: 47686.906: [GC (Allocation Failure) [PSYoungGen: 4465102K->1578231K(4660224K)] 8237268K->5951856K(10213888K), 0.7729100 secs] [Times: user=6.00 sys=15.55, real=0.78 secs]
2017-11-16T00:59:47.430+0900: 47694.043: [GC (Allocation Failure) [PSYoungGen: 3908343K->651882K(4660224K)] 8281968K->6069434K(10213888K), 0.3658849 secs] [Times: user=7.25 sys=2.90, real=0.36 secs]
2017-11-16T00:59:47.796+0900: 47694.409: [Full GC (Ergonomics) [PSYoungGen: 651882K->441154K(4660224K)] [ParOldGen: 5417552K->5553660K(9667584K)] 6069434K->5994814K(14327808K), [Metaspace: 101091K->100992K(1150976K)], 11.4661588 secs] [Times: user=297.51 sys=2.60, real=11.47 secs]
2017-11-16T01:00:04.212+0900: 47710.825: [GC (Allocation Failure) [PSYoungGen: 2771266K->109925K(4660224K)] 8324926K->6103217K(14327808K), 0.2945256 secs] [Times: user=7.64 sys=0.53, real=0.30 secs]
2017-11-16T01:00:09.922+0900: 47716.534: [GC (Allocation Failure) [PSYoungGen: 2440037K->205643K(4660224K)] 8433329K->6206800K(14327808K), 0.1023913 secs] [Times: user=2.02 sys=0.72, real=0.10 secs]

GCViewerだとこんな感じ。日付も出してくれると嬉しい。。

Ambari Metricsだとこんな感じ。上がヒープ使用量で下がGCによる停止時間です。

Heap Usageの黄色のグラフがMemHeapUsedなんですけど、これってallocateじゃないかなあ。
あと粒度が5分おきでかつ停止時間の数値が累計なのでちょっとわかりにくい。

2017-10-31

転職して5年経った

仕事

転職します - wyukawa’s blog
入社しました - wyukawa’s blog

早いもので転職して5年経ちました。ほんと、あっという間でしたね。

5年前にSIerから転職してきました。

最近は優秀な若者が新卒でそこそこ高い給料で入社して、でもなかなか上がらないから転職カードを切って給料を上げるという流れっぽいですが、僕はそういうのとは無縁でした。

僕の場合は、前職でもらっていた金額とほぼ同じです。でも最初はボーナスが1回無いのでその年の年収は前より下がってます。
また前職で有給使い切ってボーナスもらって辞めりゃいいものをなぜかそうしなかったんですよね。。

やってる仕事自体はこの5年でそう大きくは変わってなくてHadoop周りを触っているデータエンジニアです。

入社してみんな優秀だなあと思いましたが、不思議とこのレベルについていけないとか自分にやれることは無いんじゃないかみたいなことは全く思いませんでした。

結局のところ完璧なエンジニア、組織というものは存在しなくて、何かしら改善すべき点というものはあるもんです。新しい視点から見るとそういうのが見える。

最初の1年で割と大きめのデータ扱って、かついろんなプロダクトもあって、割と大変でした。ランニング始めたのもこのころだし、歯が知覚過敏になったのもこのころ。
もしかしたら音楽性が若干合わなくてストレスを感じているのかなあと思って2014年5月に異動しました。

僕にとって幸運だったのは、ちょうど新たに分析チームを作ろうとしている時でそこに最初からjoinできたことです。

新しくHadoop クラスタを構築して新たな分析基盤を構築するチャンスに恵まれました。そのクラスタを触るのは当時は僕一人しかいなかったので、一人で0から始めることができました。

いわゆる0から1にする仕事だったのですが、やったことは簡単に言うと異動前の環境のコピペです。とは言っても修正したほうがいいと判断したものは直しましたし、依存しているソフトウェアは最新のものを使い、モニタリングやデプロイに内製ツールを使っていたのをやめてOSSを採用しました。異動前の良い部分は残し、辛かった部分は改善したというわけです。異動前の経験が無ければ今ほど良いシステムを作れなかったのは間違いありません。

本当の意味で0から1にしたと言えるのはprestogresを採用してBIツールから繋げるようにしてレポート開発を容易にしたことと、yanagishimaを開発したことですね。2014年後半から2015年始めにかけてのころです。yanagishimaはその後も改善を続け、今年になってUIを別のエンジニアにまるっと任せたことにより飛躍的な進化を遂げました。

2015年最初のほうで同僚の優秀なエンジニアが退職したことにより、その人が持っていたHadoop, Fluentdクラスタも見る必要があって大変になったなあと思ったのですが、その後しばらしくしてその辺のスキルセットをまるっと持った優秀なインフラエンジニアが入社したことによりその不安は解消しました。

その人から運用のやり方の多くを学んだ気がします。特にFluentd周りはそう。

運用するにあたってモニタリング周りが重要なのでその辺も興味をもって調べるようになった結果Prometheus, Grafanaの存在を知り2016年から使い始めてその勢いでPromcon2016で発表しました。初の海外英語プレゼンでした。勢い大事。

最初は数人しかいなかった今の組織も気づいたら、すごい大きくなって、今までとは違った課題も出るようになってそれに順次取り組んでいる今日この頃です。

2017-10-04

yanagishima v8をリリースしました。

yanagishima

https://github.com/wyukawa/yanagishima

yanagishima v7をリリースしました。 - wyukawa’s blogから1週間ぐらいしか経ってませんが、v8をリリースしました。

今回の目玉はクエリ履歴とブックマークをサーバーサイドで保存できるようにしたことです。
今まではlocal storageを使っていたんですが、ブラウザが変わると引き継がれないのは不便だということで対応しました。
ただyanagishima側ではユーザ管理機能は持っていないため認証用のreverse proxyサーバーが別途必要です。
そのためdefaultでは変わらずlocal storageを使います。

それ以外にはパーティション表示を階層的にしたり、jsonデータをpretty printできるようにしたりといった機能追加があります。
設定ファイルもデフォルト値を設定できるものは設定してユーザがあまり設定ファイルをいじる必要がないようにしました。

2017-10-01

データ民主化の負の側面

技術

データの活用が当然のことのようになってエンジニア以外でもSQL書いてデータ抽出するのが一般的になってきました。さらにデータサイエンティストの登場により高度な分析もされるようになってきて、顕在化してきたのがHadoop クラスタの無法地帯化とエンジニアの疲弊なんじゃないかと最近思っております。なおHadoopに限らずElasticsearchでも言えたりします。

これって要はユーザと管理者のバランスの問題で、Hadoopエンジニアを採用するのが難しいというのが背景にあります。

SQL書ける人はそれなりにいるけど、インフラ側の人材不足ですね。この状態でデータの民主化が進むとどうなるかというと、

クエリの数が増える -> なかにも重いクエリも結構ある -> 管理者がそれをチェックするのに疲れて放置するようになる -> クラスタの負荷が増えて障害も出るようになる -> クエリ実行にも時間かかるようになるため、まとめてクエリを投入する人がでてくる -> クエリの数が増える -> ...

というような流れになっていきます。ユーザも多くなっている状況なのでクラスタのアップグレードのようなメンテナンス作業も難しいでしょう。そうして管理者が去り古いインフラを使い続けるユーザだけが残りましたとさ、、、という暗い未来が想像できてしまいます。

まあそうなったらもう外注なり外部のクラウドサービス使った方が良いでしょう。

データの民主化が成立するのって、ユースケースとして重いクエリを投げる必要がないというのと、クエリ投げる人が少数でモラルがある、例えばクエリを投げっぱなしで帰らないとか、自分が投げたクエリをチェックしていて時間かかってそうなら一旦killしてクエリに問題ないか見直すとか、そういう前提が必要なのかなと思っています。

セキュリティ周りとかその辺の基盤がちゃんと整う前になし崩し的にデータの民主化が進むと、クラスタの荒廃化は進みがちです。まあそれでもちゃんとデータサイエンティストの成果が出てそれがエンジニアの給料に反映されるなら問題無いという説もあります。

ただともかくデータにアクセスさせろという人が増えてくると、RDBSからHiveにデータ持ってくる仕事ばかりが増えてきて、そんな仕事モチベーション湧かないよねという。。。なのでエンジニアがツール用意してそれを使って好きにやってもらうというのが現実的なのかもしれませんが、Spark使いたいとかR使いたいとかいろいろ出てくるとそれ全部対応するのは難しいでしょう。

エンジニアを疲弊させるもうひとつの例が、データサイエンティストが書いたクエリ、コードはそのままじゃプロダクションに入れられないから、エンジニアが引き取ってってやつ。や、長い複雑なクエリ渡された人の気持ちを考えると。。。原則としてシンプルなコードじゃない限り人のコードを読むのは気が進まないものです。

このようにエンジニアを疲弊させるものが増えているので、どうしたもんかなと考えています。そういう背景があるので、データくれっていう人に対して感じ悪く塩対応するエンジニアとか、糞クエリを容赦なくkillするhive/presto警察とか、クエリ実行中だろうがメンテナンスして強引にアップグレードするとか、そういった強引さが時として必要なのではないかと思ったりしております。まあデータサイエンティストの人も気を使ってるとは思いますが。

GoogleとかFacebookとかだと充実したインフラがありそうだからそういう問題はないのかもね。

2017-09-25

yanagishima v7をリリースしました。

yanagishima

yanagishimaは割とカジュアルにメジャーバージョンを上げていて、作っている方も正直ちゃんとchange logを管理してないのはよくないのですが、最近7.0をリリースしました。

3.0のリリースブログがyanagishima v3をリリースしました。 - wyukawa’s blogなんで4,5,6はどうしたんだというツッコミは置いときます。

7.0はhive対応がメインです。3.0からの変更という意味ではいっぱいあるんだけど忘れた。。。デスクトップ通知、テーブル補完、テーブルバリデーション、ブックマークにタイトル追加、クエリをfluentd経由でロギング、見せたくないスキーマを非表示、、、あたりかな。

うちの環境だとhiveでバッチを書いてアドホッククエリはprestoというすみわけで、prestoでデータチェックできればほとんどのケースで困らないんですが、hiveを使いたいケースもたまにあります。

例えばバッチでhive viewを使っているケースです。prestoからhive view見れないですからね。
まあそれ以外にもたまにhiveを使いたいケースがあるだろうということと、僕がStrata Data Conference in Singapore 2017で喋る予定なのでそこでyanagishimaがpresto, hive両方対応している方が多少なりともインパクトあるだろうということで実装しました。最近流行りのカンファレンス駆動に近いものがあります。ただyanagishimaが日本人以外には発音しにくいということに最近気づきました。。。まあ長い名前というのもありますが、ただ長いおかげでSEOに強いという側面もあったりします。

閑話休題

yanagishimaがhive対応するにあたってどうやったかというと普通にjdbc使いました。

prestoではJDBC使ってないです。その理由は、yanagishimaでなぜJDBCを使ってないのか - wyukawa’s blog

hiveはprestoと違ってjobをsubmitしたあとに戻り値でapplication idを取れないので、そこは工夫が必要なところなのですが、そこは先人の知恵を借りてGitHub - tagomoris/shib: WebUI for query engines: Hive and Prestoの方式を採用しています。

どうやっているかといういとyanagishima側で独自のid(例：20170809_164758_ac5624e46a802ea3acdcff3fdfa100d1)を生成してそれをset mapreduce.job.name=...を使ってjob名にセットします。例えば、yanagishima-hive-20170809_164758_ac5624e46a802ea3acdcff3fdfa100d1

Yarnのジョブ一覧はresource manager APIの/ws/v1/cluster/appsをたたけば取れるのであとはこの一覧からjob名をgrepしてapplication idを取得するという流れです。application idさえ取れればkillできます。

https://hadoop.apache.org/docs/stable/hadoop-yarn/hadoop-yarn-site/ResourceManagerRest.html#Cluster_Applications_API

注釈：startedTimeBeginをつけないと最新のjobを取ってきてくれない環境もありました。

こういう流れなのでset mapreduce.job.name=...が使える環境、つまりHive on MRでかつセキュリティ的な制約が無い環境じゃないと完全には動かないと思います。
まあHive on Tezでも動きそうな気がするけど、少なくとも自分がクエリ投げた画面でkillはできない。一覧から探してkillはできると思うけど。

またhadoopのresource managerのapplication idごとの画面にはX-Frame-Options SAMEORIGINが付いてるのでiframeで表示できないためprestoと違って新規ウィンドウで表示するようにしています。

hive対応したこともあり設定できる項目が増えて、設定ファイルの書き方が難しくなっている状況です。

7.0を出した後も細かい改善は随時入れています。社内でアンケート取ってフィードバックもらって、すぐ対応できそうなものからやっているという感じです。その辺が一通り終わったら8.0出すと思います。

本当はドキュメントやデモサイトも整備したほうがいいんですが、そこまで手が回ってない状況です。