ベジタブルマラソン走ってきた
記録はネットタイムが1時間47分39秒、ちなみに去年が1時間49分33秒。2年前が1時間44分17秒、3年前が1時間42分7秒です。
去年よりは早かったのでまあよしとします。衰えは隠せないですが、走っている時はエイドのキュウリ、ミニトマト、パイナップル、オレンジを少々、走り終わった後は豚汁、熊谷駅ではうどん、を食べて帰ってきました。去年と同じだな。
この大会は12時スタートで人数もそんなに多くなく気軽に参加できる良い大会です。
4年連続で参加してますが、毎回良い天気です。今年は若干風が強かったかも。
今日が走り納めです。今年はフルを6回、ハーフを2回、30kmを1回走りました。
来年はちょっとフルを減らそうかなと思ってます。
2017年振り返り
今日が仕事納めでした。
今年も相変わらずデータエンジニアリング業をしていて、大きなところではHadoopクラスタのアップグレード作業を2回やりました。
クラスタが2つあるから2回。とりわけ3年使ってたクラスタをHDP 2.1から2.5.3にしたのは大きいところで現在も運用中です。
最近datanodeがGC頻発して調子悪かったのですが、heap増やして今は大丈夫そうです。
Presto, Elasticsearch, Kibana, Azkabanといったところも随時アップグレードしています。やはり新しいものはいいですね。
今年はyanagishimaが大きく進化したとしでもあります。進化した理由はUIの専門家にjoinしてもらったからです。
飲み会の席で頼んだらOKしてもらいました。飲み会重要。
社内でもyanagishimaユーザはかなり増えてDAU 100人ぐらいいってます。
Hadoopクラスタの運用事例やyanagishimaをstrataで発表してきて、結構質問も出て嬉しかったですが、
僕の英語力がイマイチで質疑応答がうまくできず。。来年も引き続き英語勉強しないとダメですが、ちょっと伸び悩んでいます。
現在はレアジョブをやりつつNHK実践ビジネス英語を聞いたりしてます。
ランニングは引き続きやってて、だいたい週二回走ってますが、こちらもフルマラソンのタイムは低迷中で、シーズンに1回サブ4出せるかどうかという状況です。
英語とランニングは来年なんとかあしたいなあ。
仕事の方はバッチ系はこなれてきたのでリアルタイム系に重点を移そうかなという気持ちです。
KafkaとFlinkは僕はそんなにやってないんですが、身近にあるしそろそろやっていこうかなという気持ちです。
バージョンがちょっと古いのでこちらもアップグレードしていきたい気持ちです。
障害を恐れずアップグレードしていく気持ちが大事
Strata Data Conference in Singaporeで発表してきた
abstractやスライドは下記からたどれます。
https://conferences.oreilly.com/strata/strata-sg/public/schedule/detail/62948
2014年5月に異動してから新規に構築したHadoopクラスタの3年にわたる歴史を紹介しております。
Hadoopに初めて触ったのが6年前にSIerにいたときで、孫請けで某所に客先常駐で入ったときまで遡ります。
それから転職して異動して、自分が構築したHadoopクラスタや開発したOSSプロダクトについて海外で英語で発表できるようになったのは感慨深いものがあります。6年は長すぎじゃね？という話もありますが。
英語に関しては正直まだ厳しくて、プレゼンのヒアリングはほぼ出来てなくてスライドとかろうじて聞き取れた単語から想像するだけです。
発表に関しては事前準備ができるのでまだいいですが、質疑応答はちょっと難しくてよく聞き取れないこともありました。英語発表は今回で3回目ですが、今回の持ち時間は今までで最長の40分でした。事前リハーサルでは30分で発表が終わったので、残りは質疑応答に回そうと思っててだいたいその通りになりました。
今回のカンファレンスは機械学習やSparkやクラウドといったネタが多くて、僕のようにオンプレミス環境でHadoop使ってデータエンジニアリング業やってる話はレアだったのですが、思ったより多くの方に参加していただいてありがたいかぎりです。質問も結構でました。
GrabのエンジニアがPresto使ってて、彼らとは情報交換したり、オフィスに遊びにいかせてもらいました。ありがたい限りです。ひとりで行くのも寂しかったんで、ついでに他の人（日本人）も誘ったんですが、僕より英語できるし間が持つので誘ってよかったw ありがとうございました。
Hadoopでトラフィックが多いと言われたのでtcpdump使って調べてみた
8:20から9時ぐらいまで断続的にoutboundトラフィックが増えてなんでだろって思ったのでtcpdumpしてみた。
やり方は下記参照
定期的にtcpdumpをある期間だけ実行したいという時 - その手の平は尻もつかめるさ
Hadoopのdatanodeマシンを一つ使って以下のようにcronに仕込んでみた。
20 8 * * * /usr/sbin/tcpdump -w /data1/\%Y\%m\%d\%H\%M\%S.pcap -W1 -G300 > /data1/tcpdump.log
どれだけキャプチャするかは迷った。あんまり短いとわからないだろうし、かといって長すぎるとdiskを圧迫するから。
平常時に試しに1分でやったら378MBだったけど、トラフィックがはねているときだと予想がつかなかったのでとりあえず5分にして出力先は比較的容量があるdatanodeのHDFSがあるパーティションにした。
最悪でもdatanodeが1台ぽしゃるだけだからまあ大丈夫だろうと予想しました。
5分でやったところ結果は44GBでした。注意点としては、僕の環境、CentOS7ではrootじゃないと実行できなかったですね。
あと結果を分割するのにtcpsliceがうまく動かなかったのでtcpdumpで下記のように1GB単位で分割しました。
tcpdump -r 20171127082001.pcap -w /data1/work/aaa -C 1000
これも最初パーミッションで怒られたので/data1/workを777にしました。
あとは/data1/work/aaa1, /data1/work/aaa2みたいにファイルが分割されるのでこれをwiresharkにくわせました。
wiresharkの統計 -> HTTP -> 要求をみると/webhdfs/v1/apps/hive/warehouse/hoge.db/piyo/yyyymmdd=20140101/...みたいなリクエストがあってどうもパーティション指定せずに全期間scanしちゃってるっぽいのでこれが原因かなと。うちの環境だとhiveのexternalでwebhdfs使ってるんですよね。
そんな感じです。
hiveserver2とFull GC
昔から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'`"
fihttps://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分おきでかつ停止時間の数値が累計なのでちょっとわかりにくい。
転職して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で発表しました。初の海外英語プレゼンでした。勢い大事。
最初は数人しかいなかった今の組織も気づいたら、すごい大きくなって、今までとは違った課題も出るようになってそれに順次取り組んでいる今日この頃です。
