Lettuce の スレッドイシュー で頑張った話

まとめ

  • 以下の issue リンクを見てください。
    github.com

  • 同じく IDEデバッグモードで Thread 別の停止を使えば Threading issue を再現しやすい

  • Lettuce で Request queue size exceeded を継続的にみかけたら多分これだよ、新しいバージョンにするか再起動で対応

以下本文

去年から数ヶ月に一回サーバ群中のいち台が OOM を発生することがあった、OOM なら迷わず heap dump なので、dump してみたら redis connection の command buffer に command が超溜め込んでいる事が見つかった。 f:id:kojilin:20180216164712p:plain

初めの対応は開発者の言う通り、先に command quene のサイズを制限して OOM 回避ぐらいしてみた。しかしその後またまた OOM、コードを見てみると queue のサイズチェックにミスって assert があったので、assert を取る PR 作ったら何故か作者が command buffer の作り直しがw、一応この修正で OOM はもう発生しない。

後は開発者が command 貯まる理由は connection が途切れた場合、再度接続するまで貯まるのを聞いて調べてみたら、ConnectionWatchdog が再接続をしているのが見つかった。ここで変なのが ConnectionWatchdog の接続 timer タスクが既に過ぎてるのに(expired)、何故か connection 関連のフィールドが null のままだった。 f:id:kojilin:20180216172121p:plain

f:id:kojilin:20180216172214p:plain

実際 lettuce は netty を使っていたので、新しいスレッドを作らない限り、同じチャンネルのメソッドコールは全て netty スレッドで問題はないと思って調べたら、再度接続のところが netty の Timer だった。

色々スレッドの順番を脳内想像して、多分問題は Timer の使い方だなと思ってきた。コードを見てみると、this.reconnectScheduleTimeout使って再接続の重複を防止している、ただ reconnectScheduleTimeoutアサインはタスクを作った後なので、GC の pause とかでもしかしたらアサインする前に既に Timer#newTimeout のブロックが先に実行される可能性があるかなと。実際元のコードの想定では Timer#newTimeoutthis.reconnectScheduleTimeoutアサイン → Timer task が timeout して実行後 this.reconnectScheduleTimeoutnull にすると思いますが。前述の通り、もし先に 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);

ただこういうケースは稀すぎて、実際自分の環境でも数十〜百台で2,3ヶ月で一台が発生するので、テスト環境でロードを追加して回してもなかなか再現できない(ログを追加して、想定シナリオになってるかどうかを試してみたかった)。最後はやっぱり IDEデバッグモードで HashedWheelTimer#newTimeoutreturn の一歩手前に 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 分享了一下自己所屬的專案的非同步化的經驗,終於在日本的研討會講過了,希望明年也有梗可以講。

docs.google.com

開發上除了專案和公司armeria 貢獻幾個 PR 外,也在幾個開放源碼專案幫忙找找 bug 跟發發 issue。今年大概花了一堆時間在看 RxJava,Lettuce,Caffeine 的原始碼。

2018,希望明年在工作上可以做得更稱職。

Remove all ads

キャッシュライブラリのスレッドイシューで頑張った話

まとめ

  • 以下の issue リンクを見てください。
    github.com

  • IDEデバッグモードで Thread 別の停止を使えば Threading issue を再現しやすい

  • Caffeine 使用者は早く2.6.1-snapshot にした方がいいかも

以下本文

最近あるサーバが古いデータを返してるという現像があり、最近自分がその付近のコードをいじってたので、自分の変更の原因かを調べながら、ローカル再現とか頑張って、全部で一週間ぐらいかかって、最後は多分キャッシュライブラリの問題じゃない?まで行き着いた記録です。

自分が使ってたのは Caffeine という高パフォーマンスなキャッシュライブラリです。使い方は簡単で、以下のような感じでデータをキャッシュ後にもし2分半後にアクセスが来た場合、キャッシュデータを戻しながら、非同期アクセスを始める;又は5分後にアクセスが来た場合、キャッシュデータは失効されてるので、新しく非同期アクセスを初めて、クライアントはそのリクエストの CompletableFuture を利用する形です。

Caffeine.newBuilder()
    .refreshAfterWrite(300 / 2, TimeUnit.SECONDS)
    .expireAfterWrite(300, TimeUnit.SECONDS)
    .maximumSize(cacheSize)
    .buildAsync((key, ignored) -> getFromRemote(key))

初めはもしかしたら getFromRemote に問題あるんじゃない?と疑って調べたが、実際他のサーバの同キーのデータは正常だし、再起動したら治ってるので、すぐメモリキャッシュの問題かな?につきました。

古いデータがキャッシュ内にあるので、何か手がかりが必要ならヒープダンプ見るしか無いかな、と面倒くさいと思いながら問題データの参照を見ながら発見したのがキャッシュエントリーの writeTime が他の正常データの writeTime とすごく離れてるのを気づきました。正常データの writeTime33948135258891076 とその上下なのに、以下のように -9189666743569861076 な数値があった。

f:id:kojilin:20171223115107p:plain

ソースコードを追ってみて、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);
    }
  }
}

データを非同期取ってる時に失効されないように時間を未来に設定していた。なので問題データと正常データを計算してみて、2日ぐらい前の時間で Long.MAX_VALUE を足してた数値が出て、もう既に2日以上キャッシュされていたのがわかった。-9189666743569861076 - Long.MAX_VALUE = 33705293284914733、なので (33948247-33705293)/60/60/24 = 2.xぐらい。

ただコードのコメントで言ってる通り、完了のコールバックで元に戻すと書いてるが、何かの問題で戻ってないかも?

その後デバッグモードで調べたら、コールバックは LocalAsyncLoadingCache#getにありました。

コード自体見てみると AddTask#runLocalAsyncLoadingCache#get のコールバックは並行で実行されるんじゃない?といろいろ調べたらちゃんと BoundedLocalCache#replace で synchronized を使っていました。

なので並行のシナリオ的に2つ:

  1. AddTask#runsynchronized に入った後、writeTime を未来にして、その後 BoundedLocalCache#replace で現在の nanoTime にする。ここでの hasExpire12の判断も合理(実はここが問題)に見える、now - node.getWriteTime() >= expiresAfterWriteNanos() は 現在を未来(現在 + Long.MAX_VALUE)で引くとネガティブな数値になる。

  2. 先に 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 の外にあった。

https://github.com/ben-manes/caffeine/blob/bb6198a0c3aa276c76be4f98406f4965398f81d5/caffeine/src/main/java/com/github/benmanes/caffeine/cache/BoundedLocalCache.java#L1873

こうなるともし AddTasksynchronized に入った後、先に BoundedLocalCache#replace 内が now(ここで0とする) を取得した後、AddTask 内が now(ここで10とする) を取って Long.MAX_VALUE を足して writeTime を 10 + Long.MAX_VALUE にする。その後 BoundedLocalCache#replacesynchronized に入ったら、 0 - (10 + Long.MAX_VALUE) になるので、とてもでかい値になり、 hasExpiretrue になって、元のコールバックリセットに失敗するシナリオになってしまう。

ただ全て想像上なので、どう再現するか悩んだ後、IDEデバッグを使えばいいじゃんと思いだした。デバッグで Thread 毎停止(Suspend Thread)と、Evaluation and log はスレッドイシューに大変使える!

f:id:kojilin:20171223131337p:plain

なので上の AddTask#runBoundedLocalCache#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 f:id:kojilin:20170706222647j:plain

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。

轉高度人才簽證

今年開始一直有聽說日本政府將縮短高度人才申請永住的限制年數,所以趁著分數夠時想說快快申請。高度人才簽證是分數制,七十分以上才可以申請且優惠也比其他工作簽證再多一些。然後今年開始將會把申請時七十分以上變成三年,八十分以上變成一年就可以申請永住。雖然不知道自己會待上多久,但有著選擇總比到時想到時在申請好吧,就趁著這個月把資料收齊後跑去申請了。

申請時需要如下資料,因為我是軟體工程師,所以是填高度専門職1号(ロ。先從網頁上看一下點數表需要的資料,只是我下載時剛好改訂,所以到現場後又叫我再填一份新的點數表,還好我申請的當下改訂前後並沒有太大差異的樣子。我大概帶了以下資料跟證件:

  • 護照
  • 在留卡
  • 英文畢業證書
  • 所有前職在職證明
  • 日文檢定結果
  • 大頭照
  • 現職在職證明
  • 労働条件通知書(上面有薪資)
  • 高度専門職1号(ロ 的變更申請文件(公司已經幫一些人申請過,所以告知人事後,他們直接填好給我)

交給櫃台人員後,現場等確認完資料沒問題,再等兩到四週後就會收到結果。記得盡量避開中午時段,中午雖然窗口還會運作,但一部分的人去吃飯所以叫號速度會變得非常慢。外加現場申請,延長的人也不少,我總共在現場待了兩個多快三小時。

補充事項:

  • 本來寫相關工作經驗十年以上,但因為有些前職在職證明已經申請不到了,所以被告知不一定可以拿到那麼多分數。記得盡量申請一下前職工作證明,另外還提醒我說最好上面有職位。(有人知道他們認定嚴不嚴嗎?
  • 非英文日文的證書要記得翻譯過,窗口跟我說本人署名翻也可以(真的嗎?

更換駕照

滿週年後就是要換駕照了,尤其在九州出去玩時開車還是比較方便一點。之前就稍微查過網路上台灣人分享的換駕照經驗,自己也簡單記錄一下換駕照準備的東西。

  • 護照跟有涵蓋考到駕照那年的護照。
  • 住民票,去區役所申請就好,跟承辦人員說要申請駕照用。
  • 台灣駕照。
  • 駕照譯本。(之前的搞丟了,又忘記回台灣時再申請,所以在台北駐大阪經濟文化辦事處福岡分處又申請了一份)
  • 在留卡。
  • 半年內照片兩張,現場有機器可以攝影。

我申請時時間規定是下午一點到一點半,申請時稍微填一下個人資料跟簡單的問答,例如有沒有生病,有沒有違規紀錄..等等。交出文件後等到三點驗視力,再等到三點半拍照領證件,大概到四點才離開,花的時間比想像中多了一點。另外自己的護照可以證明在台灣拿到駕照後有待超過三個月,所以免除新手貼紙,旁邊的外國人就因為護照無法證明有在自己國家待夠時間,被要求一開始得貼新手貼紙上路。

跟之前網上查到的分享有個不一樣的地方是沒被特別問當時考駕照時考了什麼,或是在哪個駕訓班。還好一切順利下次出遊可以再租車了!

Remove all ads