bufferings

30秒後の後を見て得たもの

gae | 23:38 |

30秒後

App Engine には

• 30秒以内にレスポンスを返さないといけない

というルールがある。

30秒たって、まだ実行中の場合は DeadlineExceededException が発生して処理が終了するようになっている。

疑問

そこでふと疑問が。

処理中に何か問題があって例外が発生した場合はトランザクションをロールバックしたい。

なのでフィルターをかけて finally でロールバック処理を行うことにする。

さて。30秒制限で DeadlineExceededException が発生した場合。

• このフィルターの処理は実行されるのだろうか？
• それとも30秒過ぎているから無視されるんだろうか？

結果

上記の疑問をついったーにポストしたところ。

数人の方々が確認してくださった。感謝。

結果は

• finally で書いたロールバック処理は実行される
• 最初は DeadlineExceededException が発生して、数秒後に HardDeadlineExceededError が発生する

ということだった。

なるほど。ロールバックは実行されるのか。それはよかった。

自分の目で見る

自分の目でも確認しておこう。

ということでテストを作った。・・・こんなのあまり実行しないほうがいいんだろうけど。

public class Limit30msTest {
  private static final Logger logger =
    Logger.getLogger(Limit30msTest.class.getSimpleName());

  @Test
  public void 例外後にfinallyで100ミリ秒待つのを100個ネスト() throws Exception {
    limit30ms(100, 100);
  }

  private void limit30ms(int nestCount, long wait) throws Exception {
    try {
      if (--nestCount <= 0) {
        Thread.sleep(40000);
      } else {
        limit30ms(nestCount, wait);
      }
    } catch (Exception e) {
      logger.info("[catch]" + e.toString());
      throw e;
    } finally {
      logger.info("[finally]");
      Thread.sleep(wait);
    }
  }
}

このテストを実行した結果のログは

I 11-29 04:57AM 12.106 bufferings.lab.limit30.Limit30msTest limit30ms: [catch]com.google.apphosting.api.DeadlineExceededException: 
This request started at 2009/11/29 12:56:43.277 UTC and was still executing at 2009/11/29 12:57:12.100 UTC.
I 11-29 04:57AM 12.112 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]
I 11-29 04:57AM 12.214 bufferings.lab.limit30.Limit30msTest limit30ms: [catch]com.google.apphosting.api.DeadlineExceededException: (略)
I 11-29 04:57AM 12.215 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]
I 11-29 04:57AM 12.317 bufferings.lab.limit30.Limit30msTest limit30ms: [catch]com.google.apphosting.api.DeadlineExceededException: (略)
I 11-29 04:57AM 12.318 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]
I 11-29 04:57AM 12.421 bufferings.lab.limit30.Limit30msTest limit30ms: [catch]com.google.apphosting.api.DeadlineExceededException: (略)
I 11-29 04:57AM 12.422 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]
I 11-29 04:57AM 12.495 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]

･･･(略：100ms ごとに全部で 100 個分)･･･

I 11-29 04:57AM 22.246 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]
I 11-29 04:57AM 22.349 bufferings.lab.limit30.Limit30msTest limit30ms: [finally]
W 11-29 04:57AM 22.467 Error for /ktrwjr/ktrwjr/ktrwjr.s3gwt com.google.apphosting.runtime.HardDeadlineExceededError: 
This request started at 2009/11/29 12:56:43.277 UTC and was still executing at 2009/11/29 12:57:12.492 UTC.
C 11-29 04:57AM 22.479 Uncaught exception from servlet com.google.apphosting.runtime.HardDeadlineExceededError: 
This request started at 2009/11/29 12:56:43.277 UTC and was still executing at 2009/11/29 12:57:12.492 UTC.

最初の4個分までは DeadlineExceededException で、その後 HardDeadlineExceededError になっている。

てことは300ms〜400msで Error になるってことか。

finally 自体は最後まで全部 100ms sleep してる。

finally の中で実行できることには制限があるだろうけど。

30秒後の後を見て得たもの

結局。

finally で何が実行できるのかを確かめてないし。

トランザクションがロールバックできるかどうかさえ確かめてない。

つまり。この実験で僕が新しく得たものは特にない。

でも僕が手に入れたかったものは手に入れた。それは。

自己満足感。

すっきりした。

おまけ

ログを見ていて

• com.google.apphosting.utils.servlet.TransactionCleanupFilter

というフィルターが本番サーバーでもかかっていることを発見。ふーん。

すごく悲しかったこと

クラス名などに「30ms」とつけているが。・・・「30s」だろ。ばかめ。