0

最近、100% の CPU 時間を使い始めた Java プロセスがあります。を使用すると、これはスレッドを繰り返し作成することjdbが原因であることがわかりました。ThreadPoolExecutor

問題のエグゼキュータは次のように定義されます。

private final ScheduledExecutorService _scheduler = Executors.newScheduledThreadPool(0, new NamedThreadFactory("OrderServiceScheduler", true, null));

スケジュールされている唯一のタスクは次のとおりです。

_scheduler.scheduleAtFixedRate(new Runnable() { @Override public void run() {  s_log.info("Resetting order books"); _liveOrderBook.clear(); } }, 
                               midnightTodayInMs, 
                               TimeUnit.MILLISECONDS.convert(1, TimeUnit.DAYS), 
                               TimeUnit.MILLISECONDS);

INFOログ ステートメントが出力されることはありません (このロガーでレベル ロギングが有効になっていることは 99% 確信しています)。

私は最初trace go methodsにjdbで実行し、次のような多くの行を見ました:

Method entered: "thread=OrderServiceScheduler-thread-22237794", com.kbcfp.util.NamedThreadFactory.newThread(), line=45 bci=0
Method entered: "thread=OrderServiceScheduler-thread-22237794", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=34 bci=0
Method exited: return value = null, "thread=OrderServiceScheduler-thread-22237794", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=38 bci=15
Method exited: return value = instance of java.lang.Thread(name='OrderServiceScheduler-thread-22237795', id=6388), "thread=OrderServiceScheduler-thread-22237794", com.kbcfp.util.NamedThreadFactory.newThread(), line=52 bci=68

そこで、ブレークポイントを設定しorg.apache.log4j.helpers.ThreadLocalMap.childValue、スレッドが予期せず実行を停止するまで処理を続けました (最後のnext, threadOrderServiceScheduler-thread-151389734 スレッドの直後isn't listed in the output of):

> stop in org.apache.log4j.helpers.ThreadLocalMap.childValue
Set breakpoint org.apache.log4j.helpers.ThreadLocalMap.childValue
>
Breakpoint hit: "thread=OrderServiceScheduler-thread-151389734", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=34 bci=0

OrderServiceScheduler-thread-151389734[1] clear org.apache.log4j.helpers.ThreadLocalMap.childValue
Removed: breakpoint org.apache.log4j.helpers.ThreadLocalMap.childValue
OrderServiceScheduler-thread-151389734[1] where
  [1] org.apache.log4j.helpers.ThreadLocalMap.childValue (ThreadLocalMap.java:34)
  [2] java.lang.ThreadLocal$ThreadLocalMap.<init> (ThreadLocal.java:353)
  [3] java.lang.ThreadLocal$ThreadLocalMap.<init> (ThreadLocal.java:261)
  [4] java.lang.ThreadLocal.createInheritedMap (ThreadLocal.java:236)
  [5] java.lang.Thread.init (Thread.java:401)
  [6] java.lang.Thread.<init> (Thread.java:652)
  [7] com.kbcfp.util.NamedThreadFactory.newThread (NamedThreadFactory.java:45)
  [8] java.util.concurrent.ThreadPoolExecutor$Worker.<init> (ThreadPoolExecutor.java:598)
  [9] java.util.concurrent.ThreadPoolExecutor.addWorker (ThreadPoolExecutor.java:913)
  [10] java.util.concurrent.ThreadPoolExecutor.processWorkerExit (ThreadPoolExecutor.java:992)
  [11] java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1,128)
  [12] java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:603)
  [13] java.lang.Thread.run (Thread.java:722)
OrderServiceScheduler-thread-151389734[1] next
>
Step completed: "thread=OrderServiceScheduler-thread-151389734", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=35 bci=5

OrderServiceScheduler-thread-151389734[1] next
>
Step completed: "thread=OrderServiceScheduler-thread-151389734", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=38 bci=14

OrderServiceScheduler-thread-151389734[1] next
>
Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=45 bci=40

OrderServiceScheduler-thread-151389734[1] next
>
Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=48 bci=41

OrderServiceScheduler-thread-151389734[1] next
>
Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=49 bci=49

OrderServiceScheduler-thread-151389734[1] next
>
Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=52 bci=67

OrderServiceScheduler-thread-151389734[1] next
>

私たちのNamedThreadFactoryクラスは何もエキサイティングなことをしていません:

  44: public Thread newThread(Runnable r) {
  45:   Thread t = new Thread(_group, r,
  46:       _namePrefix + _threadNumber.getAndIncrement(),
  47:       0);
  48:   t.setDaemon(_makeDaemon);
  49:   if(_overridePriority != null) {
  50:     t.setPriority(_overridePriority);
  51:   }
  52:   return t;
  53: }

私が知る限り、実行の次の行は 914 of のはずですThreadPoolExecutorが、代わりにスレッドが死んでいます。なんで？

参考までに、これは Solaris x86 ホスト上の JDK 1.7.0_07 で実行されています。

私が行った唯一の変更は、ActiveMQ のクライアント ライブラリの追加です。slf4j-api-1.6.6.jar私の疑いでは、これは slf4j (具体的には 、および) がクラスパスに追加されたことと関係があると思われますが、slf4j-log4j12-1.6.6.jarこれを証明することはできません。

アップデート

実行されたタスクを別のクラスに変更しました。

public class TestingFoo implements Runnable 
{
  private final Logger s_log;

  public TestingFoo(final Logger log)
  {
    s_log = log;
  }

  @Override 
  public void run() 
  {  
    try
    {
      s_log.info("Resetting order books"); 
  //    _liveOrderBook.clear(); 
    }
    catch (final Throwable t)
    {
      t.printStackTrace();
    }
  }
}

jdb行にブレークポイントを設定しましたlog.infoが、ヒットしていません。また、スタック トレースが stderr (または log4j ファイル) に出力されていません。s_log.infoさらに、タスクがスケジュールされて印刷される前に別の行を追加しました。

JDK 1.7.0_21 をダウンロードして、違いがあるかどうかを確認しています。

更新 2

これは、Peter Lawrey が回答に触れたように、コア プール サイズをゼロに設定したことが原因でした。ただし、何も実行しないという効果を持つ代わりに、ThreadPoolExecutorのrunWorkerメソッドをすぐに終了させました。メソッドの要点は次のようになります。

runWorker(Worker) {
    ...
    while (task != null || (task = getTask()) != null) {
      ...
      task.run();
      ...
    }
    processWorkerExit(..);
}

コア プール サイズを設定すると、タスクがサブミットされるのをブロックせずgetTaskに戻ります。nullこれにより、ループが終了し、processWorkerExit呼び出されて、既存のスレッドを置き換える別のスレッドが作成されます。

デバッガーで見た問題は、JIT アウトされたコードによるものだと思います。スレッド ファクトリにThread.sleepステートメントを挿入して、スレッドの作成を遅くしました。これは、最適化が適用される前にデバッガをアタッチする時間があったことを意味します。

TL;DR: 私はばかです。

更新 3

将来これに遭遇する可能性のある人のために... SOには、この動作が Java 7 で変更されたことに言及する別の同様の質問があります。これまでに作成されました (バグレポート)。1つのスレッドが確実に作成されるように変更が加えられました。これにより、スレッドが繰り返し作成される効果があるようです。これは、バグ レポートのテスト ケースと非常によく似たコードで再現できます。

import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;

class ScheduledExecutorTest {
    public static void main(String[] args) throws InterruptedException {
        final ScheduledExecutorService ex = Executors.newScheduledThreadPool(0);
        ex.scheduleWithFixedDelay(new Runnable() {
            @Override
            public void run() {
                System.out.println("hello");
            }
        }, 1, 1, TimeUnit.SECONDS);

        while (true)
            Thread.sleep(1000);
    }
}
4

1 に答える 1