とあるWebサービスでの出来事。
synchronizedを使って、マルチスレッドを一本道に通す工夫をしていたにもかかわらず、突然、一本道にならない事象がありました。こんな事例もあるのだなということで、ご注意を。

前提

具体的なコードイメージは下記を参照してください。

問題となったコードでは、レコードをユニークにするためキーとして日時(ミリ秒精度)を生成します。
synchronizedで括った内側で、日時を生成し、その後でsleepも1ミリ秒入れることで、ユニークになるようにしていました。

JUnitのテストコードの方は、複数のスレッドでこのメソッドを実行し、同一の結果が一つでもあったらNGとしました。

テストもパスして、無事本番して、しばらく安定稼働していました。

事象

ある日突然、同一の日時でキー生成され、キーダブりの障害が発生しました。

原因

わかってしまえば単純で、本番のアプリケーションサーバ構成が、ある日から複数サーバ構成に変わったからです。
当初は、一台のサーバ構成であったため、synchronizedで一本道になっていましたが、複数サーバとなったので、Javaインスタンスが分かれてしまい、この障害となりました。

対処

この時は、Oracleデータベースサーバの所で一本道になったので、SEQUENCEオブジェクトで連番を生成してユニークキーとしました。
※時刻が絡む設計は、やはり、きな臭いです。

教訓

この件についての、根本対策は難しいですが、設計時、実装時に本番稼働環境をどこまで想像できているかがポイントだと思います。
マルチスレッドを一本道の直列化を狙って、synchronizedを入れたとしても、
Javaインスタンスが分かれてしまえば、synchronizedでは防げないのケースがあるので注意のこと。

恒久対策案

本番環境と同じ構成のテスト環境でテストを行う。

とはいえ、本番と同じ構成がとれるほどリッチなアプリケーション開発がどれだけあるのか・・・だし、
どれだけ状況が想像できるかがポイントであるが・・・。

レビューで障害リスクを軽減

レビュー時のキーワード

並列して処理することはある？
例えば、
①Aさん、Bさんと複数人が並列することはある？
②本番マシンが複数台あり、それが並列して処理することはある？
③オンライン処理とバッチ処理が並列して処理することはある？

問題のコード

  /** 
   * JUnitにパスしたコード
   * @param csv 商品ID文字列をカンマ区切りした文字列。
   * @return 日時(ミリ秒精度)をキーを商品IDにつけた文字列。
   */
  public String register(@QueryParam("csv") String csv) {
    String uniqeKey = "KEY";
    synchronized (lock_) {
      uniqeKey += df_.format(Calendar.getInstance().getTime()).toString();
      try {
        // キー重複が発生するため、1ミリ秒のsleepを入れている。
        Thread.sleep(1);
      } catch (InterruptedException e) {
        e.printStackTrace();
      }
    }

    StringBuffer buf = new StringBuffer();
    String[] values = csv.split(",");
    for (String value : values) {
      buf.append(uniqeKey);      buf.append(",");      buf.append(value);      buf.append("\n");
    }

    return buf.toString();
  }

  /** 
   * 一番最初のコード。今回紹介する障害とは関係ないので、このメソッドはなくてもよいのですが、マルチスレッドのJUnitでマルチスレッドのテストの挙動をしめすために、あえて書いています。
   * @param csv 商品ID文字列をカンマ区切りした文字列。
   * @return 日時(ミリ秒精度)をキーを商品IDにつけた文字列。
   */
  public String registerBUG2(String csv) {
    String uniqeKey = "BUG2";
    synchronized (lock_) {
      // 複数スレッドで実行されても、synchronizedで括って一本道にすることで、
      // 同一時刻になるのことを防ぐ・・・つもりであったが、
      // synchronizedの後の処理が短い時間で処理されてしまうので、
      // やはり、同一時刻が取得されてしまい、キー重複のバグが発生する。
      uniqeKey += df_.format(Calendar.getInstance().getTime()).toString();
    }

    StringBuffer buf = new StringBuffer();
    String[] values = csv.split(",");
    for (String value : values) {
      buf.append(uniqeKey);      buf.append(",");      buf.append(value);      buf.append("\n");
    }

    return buf.toString();
  }

マルチスレッド時のJUnitテストコード

  @Test
  public void testOK() throws InterruptedException, ExecutionException {
    final HelloResource target = new HelloResource();
    this.testSub(4, new Callable<String>() {
      @Override
      public String call() {
        return target.register("a,b,c");
      }
    });
  }

  @Test
  public void testBUG2() throws InterruptedException, ExecutionException {
    final HelloResource target = new HelloResource();
    this.testSub(4, new Callable<String>() {
      @Override
      public String call() {
        return target.registerBUG2("a,b,c");
      }
    });
  }

  private void testSub(final int threadCount, Callable<String> task) throws InterruptedException, ExecutionException {
    // スレッド数分タスクを複製。
    List<Callable<String>> tasks = Collections.nCopies(threadCount, task);

    // スレッド数分タスクを実行。
    ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
    List<Future<String>> futures = executorService.invokeAll(tasks);

    // タスク実行結果リストの宣言と定義。
    List<String> actualList = new ArrayList<String>(futures.size());

    // タスクの実行結果をテスト。
    for (Future<String> future : futures) {
      String msg = future.get();

      System.out.println(msg);
      // 取り出したタスク実行結果が、既にタスク実行結果リストに含まれていないこと(falseであること)。
      assertFalse(actualList.contains(msg));

      actualList.add(msg);
    }

  }