java.util.concurrent.ExecutorService＃提交需要很長時間

Question

我有一個非常奇怪的情況，我無法得到我的頭。我已經定義了一個線程池，它的用法是這樣

 ExecutorService fixedThreadPool = Executors.newFixedThreadPool(5); 
     ....some code..... 
     logger.info("Event:{}, message:[{}]", Event.MESSAGE.name(), message); 
     fixedThreadPool.submit(new Runnable() { 
     @Override 
     public void run() { 
      ...some code... 
     } 
     }); 
     logger.info("Submitted: Event:{}, message:[{}]", Event.MESSAGE.name(), message); 

現在，這裏是我的日誌消息

2017-07-25 20:44:41,020 [New I/O worker #1] XXXXXXXXX.XXXXXXXServiceImpl - Event:MESSAGE, message:[{"delegateTaskId":"_5ejQ7gtTXyfh6qnPrUeJg","sync":true,"accountId":"kmpySmUISimoRrJL6NL73w"}] 
2017-07-25 20:45:42,356 [New I/O worker #1] XXXXXXXXX.XXXXXXXServiceImpl - Submitted: Event:MESSAGE, message:[{"delegateTaskId":"_5ejQ7gtTXyfh6qnPrUeJg","sync":true,"accountId":"kmpySmUISimoRrJL6NL73w"}] 

輸出看到這兩個消息的時間戳。雖然我期待提交到線程池的隊列應該立即，這兩條消息之間需要幾分鐘的時間。我試圖消除所有的可能性，如打印GC日誌（沒有主要的GC有暫停），加載模式等。

當我看到這個時，系統沒有負載，CPU使用量很小。它運行在亞馬遜EC2 T2LARGE框，我可以看到沒有太多的CPU使用率。

我讀了java文檔和谷歌周圍，但我找不到有用的東西。這很令人費解。任何指針，不勝感激。

------ -----編輯

我加在日誌信息的時間，以確保沒有任何記錄的問題。更新後的代碼是

logger.info("Event:{}, time:{}, message:[{}]", Event.MESSAGE.name(), new Date(), message); 
fixedThreadPool.submit(new Runnable() { 
     @Override 
     public void run() { 
      ...some code... 
     } 
     }); 
logger.info("Submitted: Event:{}, time:{}, message:[{}]", Event.MESSAGE.name(), new Date(), message); 

這裏是輸出

Event:MESSAGE, time:Wed Jul 26 17:50:18 UTC 2017, message:[{"delegateTaskId":"pN7UzXfzSWajjJY33LbM1A","sync":true,"accountId":"kmpySmUISimoRrJL6NL73w"}] 
Submitted: Event:MESSAGE, time:Wed Jul 26 17:51:19 UTC 2017, message:[{"delegateTaskId":"pN7UzXfzSWajjJY33LbM1A","sync":true,"accountId":"kmpySmUISimoRrJL6NL73w"}] 

正如你可以看到，拍攝到提交任務的線程池的時間幾乎是一分鐘

Answer 1

我測試過以下代碼也在AWS EC2 t2.large實例上：

import java.time.Instant; 
import java.util.concurrent.ExecutorService; 
import java.util.concurrent.Executors; 
import java.util.concurrent.TimeUnit; 

public class RaghvendraSinghTest 
{ 
    public static void main(String[] args) 
      throws Exception 
    { 
     ExecutorService fixedThreadPool = Executors.newFixedThreadPool(5); 

     System.out.printf("[%s] Before fixedThreadPool.submit()%n", Instant.now()); 

     fixedThreadPool.submit(new Runnable() { 
      @Override 
      public void run() 
      { 
       System.out.printf("[%s] In run()%n", Instant.now()); 
      } 
     }); 

     System.out.printf("[%s] After fixedThreadPool.submit()%n", Instant.now()); 

     fixedThreadPool.shutdown(); 
     fixedThreadPool.awaitTermination(30, TimeUnit.SECONDS); 

     System.out.printf("[%s] After fixedThreadPool.shutdown()%n", Instant.now()); 
    } 
} 

運行代碼導致t他跟着輸出：

[2017-07-26T20:11:56.730Z] Before fixedThreadPool.submit() 
[2017-07-26T20:11:56.803Z] After fixedThreadPool.submit() 
[2017-07-26T20:11:56.803Z] In run() 
[2017-07-26T20:11:56.804Z] After fixedThreadPool.shutdown() 

這表明整個程序運行時間少於75ms。關於你的問題的一件事是我的名字 - 「新的I/O工作者＃1」 - 這表明我在這裏有多個ExecutorService s。

如果你運行我已經包含的代碼 - 並且只是我已經包含的代碼 - 你會看到類似於我的結果嗎？如果你這樣做（我懷疑你會這樣做），你應該包含足夠的代碼，以便我們可以複製你的問題。否則，這當然看起來是特定於您的環境的。

Answer 2

我想出了這個問題。我們已經在logback.xml以下

<appender name="SYSLOG-TLS" class="software.wings.logging.CloudBeesSyslogAppender"> 
    <layout class="ch.qos.logback.classic.PatternLayout"> 
     <pattern>%date{ISO8601} %boldGreen(${process_id}) %boldCyan(${version}) %green([%thread]) %highlight(%-5level) %cyan(%logger) - %msg %n</pattern> 
    </layout> 

    <host>XXXXXXXX</host> 
    <port>XXXXXXXX</port> 
    <programName>XXXXXXXXX</programName> 
    <key>XXXXXXXXXXX</key> 
    <threshold>TRACE</threshold> 
</appender> 

此配置所做的logger.info撥打張貼在日誌中logdna和我們的系統配置方式，日誌的發佈到logdna服務器是同步的，有時它需要高達60秒，我們的任務已經超時。

現在需要弄清楚爲什麼這些logdna日誌發佈調用是同步的。