Armeria の Zipkin tracing の改善を手伝ったよ
今年の6月くらいに Zipkin のメインコントリビューターの @adrian から一緒になんか改善しないかと声がかかったので、8月に福岡に来て、自分と東京にいる元同僚 anuraaga の3人で二日半ぐらいかけて、Armeria のこの PR Reworks tracing to use RequestContext natively をモブプログラミングっぽい感じで進行して作りました。Release Brave 5.2 · openzipkin/brave · GitHub にも詳しく書いてもらっています。
もともとは会社主催の 【東京】LINE Developer Meetup #35 - Zipkin - - connpass でAdrian Coleが来て一緒に Zipkin 関連の話題と Shop の事例で Armeria と Zipkin 連携で大変だったことを話してたので、リアクティブや非同期の環境で Zipkin のどこが使いやすくないか、どうしたら良くなるかについて話して、その後にせっかくだから又日本来て一緒にやらないかと声をかけられました。当日の資料はLINE スタンプショップにおける Zipkin 利用事例です。簡略に言うと、Zipkin はデフォルトでは ThreadLocal を利用して現在のトレーシングコンテキストを埋めていますので、非同期ではない場合、サーブレットフィルターや Spring MVC のインターセプターに埋め込めば、簡単に使えます。ただ Armeria はもともと非同期のライブラリなので、Zipkin を別で RequestContext の Attribute や ThreadLocal を利用して open/close していたら何回もコーナーケースでバグに当たって、Armeria 上での Zipkin 関連の修正が何回もされてます。そもそも Armeria には RequestContext の概念があるので、その上に乗っかった方がやりやすいのでは？という方向になり、最終的には RequestContext にずっと保存して、RequestContext のライフサイクルの最後に close すればいいようにした。
実際自分はこの内容で追いつくまでかなり時間がかかって、他の二名はハイスピードで議論しながら仕上げていました（いろいろ勉強になりました；；。中で面白かったのが、今回の変更で Armeria では絶対に RequestContextCurrentTraceContext を使わないと動かなくなるようになるので、起動時に検査をするにはどうしたらいいかを話してると、PingPongExtraと言うクラスで、ダミーコンテキストを突っ込んで実際に RequestContextCurrentTraceContext を使っているかどうかを検査するとか。もう一つは RequestContext が無い場合、警告を一回しか出したくないから、Lazy class loading で対応したとか。
終わった後に、CurrentTraceContext の元々の継承方式をデコレータにしたとか進んで、色々勉強になった３日だった。こうやって社外の人と一緒に会社が使っているオープンソースプロジェクトの改善をして、自分達がもっと使いやすくなるので、これからも続けてやっていきたいですね。最近は東京でもやっているみたいで zipkin/zipkin-lens at master · openzipkin/zipkin · GitHub ができてます。
申請永住紀錄
拖了很久還是記錄一下，去年這篇 轉高度人才簽證 - kojilin’s diary 後過了一年，今年六月時終於花點時間去申請永住後，四個月後的十月拿到手了。 當時申請高階人才的文件大多數都可以透過調用之前的資料來補齊，所以只要在備齊最近的繳稅資料，理由書，高階人才的點數表證明分數有保持跟在職證明就差不多了。 其中最麻煩的應該就是理由書了，Google 一下別人怎麼寫理由書，發現自己實在寫不出這麼多理由的內容，最後就寫個大概還會想在日本工作久一點，小孩也打算在這繼續讀書之類的內容。
拿到永住後比較方便應該就是換工作較方便，據說貸款可能容易些，更新期間變長之類（每三，五年跑一次都覺得很麻煩，光這次申請在櫃檯就讓我等了一上午）。想想自己也還沒要貸款，但是先申請好，如果未來要貸款或換工作時才不會急急忙忙的去申請。
Lettuce の スレッドイシュー で頑張った話
まとめ
以下の issue リンクを見てください。
github.com- Lettuce で
Request queue size exceededを継続的にみかけたら多分これだよ、新しいバージョンにするか再起動で対応
以下本文
去年から数ヶ月に一回サーバ群中のいち台が OOM を発生することがあった、OOM なら迷わず heap dump なので、dump してみたら redis connection の command buffer に command が超溜め込んでいる事が見つかった。
初めの対応は開発者の言う通り、先に command quene のサイズを制限して OOM 回避ぐらいしてみた。しかしその後またまた OOM、コードを見てみると queue のサイズチェックにミスって assert があったので、assert を取る PR 作ったら何故か作者が command buffer の作り直しがw、一応この修正で OOM はもう発生しない。
後は開発者が command 貯まる理由は connection が途切れた場合、再度接続するまで貯まるのを聞いて調べてみたら、ConnectionWatchdog が再接続をしているのが見つかった。ここで変なのが ConnectionWatchdog の接続 timer タスクが既に過ぎてるのに(expired)、何故か connection 関連のフィールドが null のままだった。
実際 lettuce は netty を使っていたので、新しいスレッドを作らない限り、同じチャンネルのメソッドコールは全て netty スレッドで問題はないと思って調べたら、再度接続のところが netty の Timer だった。
色々スレッドの順番を脳内想像して、多分問題は Timer の使い方だなと思ってきた。コードを見てみると、this.reconnectScheduleTimeout を使って再接続の重複を防止している、ただ reconnectScheduleTimeout のアサインはタスクを作った後なので、GC の pause とかでもしかしたらアサインする前に既に Timer#newTimeout のブロックが先に実行される可能性があるかなと。実際元のコードの想定では Timer#newTimeout → this.reconnectScheduleTimeout のアサイン → Timer task が timeout して実行後 this.reconnectScheduleTimeout を null にすると思いますが。前述の通り、もし先に timer task が先に実行されると、this.reconnectScheduleTimeout は永遠に null にならないので、次回の再接続で止まってしまう。
this.reconnectScheduleTimeout = timer.newTimeout(it -> {
if (!isEventLoopGroupActive()) {
logger.debug("isEventLoopGroupActive() == false");
return;
}
reconnectWorkers.submit(() -> {
ConnectionWatchdog.this.run(it);
return null;
});
}, timeout, TimeUnit.MILLISECONDS);
ただこういうケースは稀すぎて、実際自分の環境でも数十〜百台で２，３ヶ月で一台が発生するので、テスト環境でロードを追加して回してもなかなか再現できない（ログを追加して、想定シナリオになってるかどうかを試してみたかった）。最後はやっぱり IDE のデバッグモードで HashedWheelTimer#newTimeout の return の一歩手前に thread suspend を使って再現して、可能性がゼロではないのを知って、PR を作って送った。
- コードを書く時間が減ってきたので、こういうアウテージ対応でチームに貢献できて良かった
- プロジェクトによって開発者の美感とか設計思想にそって PR 作るの難しいなといつも思う
2017 回顧
2017 年要結束了，簡單回顧一下今年。
五月申請了高階人才，因為有八十分，順利的話明年五月可以申請永居看看。
上半年拿到了公司內的 dev award（每個公司或大部門各一到兩人）。因為還蠻愛除錯的，今年來在專案中處理了幾件麻煩的 bug（leak 或是 race condition 為主），所以因此被成員推舉成福岡的 award 吧！？
十月第一次去 JavaOne，總算是在 Java 開發生涯中朝聖了一次。
十一月是到福岡滿二年，在 LINE Fukuoka 的工作除了開發外，也開始幫忙管理團隊了。其實蠻擔心自己是不是適合當 Team Leader，所以一直看書和看看其他主管級朋友平常的心得分享，想辦法避免當個不稱職的管理職。尤其自己很容易有類似書上說的 micro management 的心態，只能時時刻刻提醒自己多信任成員，而且就算跟想像中不是完全相同，只要方向對了就應該多放手一點。最後往好處想，只要能時時反省的話，至少不會走到最糟的狀況吧。關於 manager 該怎樣跟做什麼，個人推薦 The Manager's Path 這本書。 shop.oreilly.com
還有就是開始習慣做 1on1，工作十年第一次做週期性的 1on1 就是聽的一方還蠻特別的。以前在 cubie/gamelet 時大概都是好幾個月或半年一次，資策會時代也沒有很週期做的印象。
另外也在 JJUG CCC 2017 Fall 分享了一下自己所屬的專案的非同步化的經驗，終於在日本的研討會講過了，希望明年也有梗可以講。
開發上除了專案和公司的 armeria 貢獻幾個 PR 外，也在幾個開放源碼專案幫忙找找 bug 跟發發 issue。今年大概花了一堆時間在看 RxJava，Lettuce，Caffeine 的原始碼。
2018，希望明年在工作上可以做得更稱職。
キャッシュライブラリのスレッドイシューで頑張った話
まとめ
以下の issue リンクを見てください。
github.com- Caffeine 使用者は早く2.6.1-snapshot にした方がいいかも
以下本文
最近あるサーバが古いデータを返してるという現像があり、最近自分がその付近のコードをいじってたので、自分の変更の原因かを調べながら、ローカル再現とか頑張って、全部で一週間ぐらいかかって、最後は多分キャッシュライブラリの問題じゃない？まで行き着いた記録です。
自分が使ってたのは Caffeine という高パフォーマンスなキャッシュライブラリです。使い方は簡単で、以下のような感じでデータをキャッシュ後にもし２分半後にアクセスが来た場合、キャッシュデータを戻しながら、非同期アクセスを始める；又は５分後にアクセスが来た場合、キャッシュデータは失効されてるので、新しく非同期アクセスを初めて、クライアントはそのリクエストの CompletableFuture を利用する形です。
Caffeine.newBuilder()
.refreshAfterWrite(300 / 2, TimeUnit.SECONDS)
.expireAfterWrite(300, TimeUnit.SECONDS)
.maximumSize(cacheSize)
.buildAsync((key, ignored) -> getFromRemote(key))
初めはもしかしたら getFromRemote に問題あるんじゃない？と疑って調べたが、実際他のサーバの同キーのデータは正常だし、再起動したら治ってるので、すぐメモリキャッシュの問題かな？につきました。
古いデータがキャッシュ内にあるので、何か手がかりが必要ならヒープダンプ見るしか無いかな、と面倒くさいと思いながら問題データの参照を見ながら発見したのがキャッシュエントリーの writeTime が他の正常データの writeTime とすごく離れてるのを気づきました。正常データの writeTime は 33948135258891076 とその上下なのに、以下のように -9189666743569861076 な数値があった。
ソースコードを追ってみて、setWriteTime を呼んでいるところを探してみたら、以下のコードがありました。
// Ensure that in-flight async computation cannot expire (reset on a completion callback)
if (isComputingAsync(node)) {
synchronized (node) {
if (!Async.isReady((CompletableFuture<?>) node.getValue())) {
long expirationTime = expirationTicker().read() + Long.MAX_VALUE;
setVariableTime(node, expirationTime);
setAccessTime(node, expirationTime);
setWriteTime(node, expirationTime);
}
}
}
データを非同期取ってる時に失効されないように時間を未来に設定していた。なので問題データと正常データを計算してみて、２日ぐらい前の時間で Long.MAX_VALUE を足してた数値が出て、もう既に２日以上キャッシュされていたのがわかった。-9189666743569861076 - Long.MAX_VALUE = 33705293284914733、なので (33948247-33705293)/60/60/24 = 2.xぐらい。
ただコードのコメントで言ってる通り、完了のコールバックで元に戻すと書いてるが、何かの問題で戻ってないかも？
その後デバッグモードで調べたら、コールバックは LocalAsyncLoadingCache#getにありました。
コード自体見てみると AddTask#run と LocalAsyncLoadingCache#get のコールバックは並行で実行されるんじゃない？といろいろ調べたらちゃんと BoundedLocalCache#replace で synchronized を使っていました。
なので並行のシナリオ的に２つ：
AddTask#runのsynchronizedに入った後、writeTimeを未来にして、その後BoundedLocalCache#replaceで現在の nanoTime にする。ここでのhasExpire1 と 2の判断も合理（実はここが問題）に見える、now - node.getWriteTime() >= expiresAfterWriteNanos()は 現在を未来(現在 +Long.MAX_VALUE)で引くとネガティブな数値になる。先に
BoundedLocalCache#replace内の後処理を完了した場合、既にwhenCompleteに入ってるのが分かるため、if (!Async.isReady((CompletableFuture<?>) node.getValue()))はfalseになるので、未来時間を書き込まない。
なので問題がなさそうなので、次はそろそろ自分の見落としか、JVM のバグかなと。丁度最近同僚と System#nanoTime はマルチスレッド/コアで安全かの話題があり、昔 Windows でコア違いで nanoTime がまさかの end - start がマイナスの値になるとかを見た記憶が。
java - Is System.nanoTime() completely useless? - Stack Overflow
ただこれは超昔な情報だし、Linux 上でも聞いた事ないが、もうなんでもいいから試そうと思ってヤケクソでサンプル書いたが、色々試しても再現できない。もうだめだと思って、この機にもう一回時間付近のコードを調べたら、現在時間の now を取るコードが BoundedLocalCache#replace では synchronized の外にあった。
こうなるともし AddTask の synchronized に入った後、先に BoundedLocalCache#replace 内が now(ここで０とする) を取得した後、AddTask 内が now(ここで１０とする) を取って Long.MAX_VALUE を足して writeTime を 10 + Long.MAX_VALUE にする。その後 BoundedLocalCache#replace が synchronized に入ったら、 0 - (10 + Long.MAX_VALUE) になるので、とてもでかい値になり、 hasExpire が true になって、元のコールバックリセットに失敗するシナリオになってしまう。
ただ全て想像上なので、どう再現するか悩んだ後、IDE のデバッグを使えばいいじゃんと思いだした。デバッグで Thread 毎停止(Suspend Thread)と、Evaluation and log はスレッドイシューに大変使える！
なので上の AddTask#run と BoundedLocalCache#replace でブレークポイントを設定して、交互に実行しながら再現できたので、開発者に教えて修正してもらった。キャッシュでデータが失効できないのはかなりやばいので、使っている方は早く snapshot でも良いからアップデートしたほうが良いかも。
參加 YAPC::Fukuoka 2017
雖然沒在寫 Perl ，但剛好公司協辦而且不少福岡跟東京的同事參加，就當作湊熱鬧心情參加 YAPC::Fukuoka 2017 HAKATA。當天參加的幾個技術 session 其實都跟語言本身沒啥關係，就算看不太懂 Perl 也能大概了解在講什麼，例如某家公司仿 snowflake 刻了 id 產生器，怎樣算是好的 log 訊息，Perl6 對應的問題，CPAN client 加速之類。
其中兩個跟技術比較沒關的，但覺得蠻有趣的 session。第一個是找來福岡各家深耕或有名(有些台灣人可能知道的 Nulab )的 IT 公司的技術負責人或代表的座談會。有趣在於，東京福岡軟體業個人感覺就像台灣的台北高雄，大多數人還是會被吸到東京去。就算有些人想離開東京到這，也會擔心就算現在到了一家公司後做了三四年離開，會不會又得搬回東京，可能有這種疑慮就還是待在東京了。另一個有趣的點是，福岡的工程師好像不太換公司，感覺流動率非常低。所以對公司來說找人非常不容易，像我們公司現在大約一半是外籍人士，其他家公司也多少有一點外國人，畢竟真的很難找到日本人工程師。但以上狀況應該會越來越好轉吧，因為最近有越來越多的公司開始在福岡設點，例如 pixiv，yahoo(剛好看到 fb 上有福岡徵才廣告)。所以我如果被怎樣應該不用擔心得搬離福岡了(?。最後還有聽眾問東京福岡都有設點的公司，兩個地點的工程師間薪水基準有沒有不同，大家都說沒有，薪水兩邊都是一樣算法。
第二個是找了 Nulab 駐紐約的工程師來分享紐約設點找人的辛酸史，講者真的講得很心酸，例如1. 英文不夠好就過去。2.小孩而且年齡不小才換國家，真的對家庭來說很辛苦。3.福岡可能以前軟體公司不多，一般人一待就是待很久，但是紐約這種地方你可能得預期對方待個一到三年不到就跳槽。唯一覺得他突然語氣有點開心是講到超市啤酒種類很多或是公司有放生啤機之類（是有多愛啤酒），聽著聽著我都想上去拍拍講者了。
我們也有在徵熟 Perl 的工程師，有興趣的歡迎留言給我 koji (@kojilin) | Twitter。
最後覺得有趣的禮物是 perl 米…微妙XD
Armeria Retrofit 可以使用 @Url 了
最近送了一個 PR 給 Armeria ，終於讓 Armeria 上的 Retrofit 可以使用 @Url 了。之前不行主要是因為 Armeria 的 HttpClient 本身就已經綁在某個 authority 上，所以無法在之後存取不同 authority。現在改成依照 authority 是否相同再產生一個新的 HttpClient 處理。
interface MyService {
@GET("/userInfo/{id}")
CompletableFuture<UserInfo> getUserInfo(@Path("id") String id);
CompletableFuture<ResponseBody> getContent(@Url String url);
}
Retrofit retrofit = new ArmeriaRetrofitBuilder()
.baseUrl("http://localhost:8080/")
.addConverterFactory(JacksonConverterFactory.create())
.addCallAdapterFactory(Java8CallAdapterFactory.create())
.build();
MyService service = retrofit.create(MyService.class);
service.getContent("http://example.com");
但是 Retrofit 還真不錯，把 Call.Factory 換掉就可以想辦法換掉 http engine。
