java.util.concurrent.ExecutorService＃提交需要很长时间

问题描述：

我有一个非常奇怪的情况，我无法得到我的头。我已经定义了一个线程池，它的用法是这样java.util.concurrent.ExecutorService＃提交需要很长时间

 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"}]

正如你可以看到，拍摄到提交任务的线程池的时间几乎是一分钟

时间戳由记录器创建，它看起来像在线程本身中运行。可能会有一些同步或IO延迟。你可以在邮件中添加时间戳吗？ – Serge

从上面的描述不清楚问题的确切原因，你可以使用一个分析器，并检查是否有任何线索。 –

上面显示的第一条记录的消息与线程的'run'调用中的日志消息之间的时间增量是多少？ – Adonis

答

我测试过以下代码也在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。

如果你运行我已经包含的代码 - 并且只是我已经包含的代码 - 你会看到类似于我的结果吗？如果你这样做（我怀疑你会这样做），你应该包含足够的代码，以便我们可以复制你的问题。否则，这当然看起来是特定于您的环境的。

答

我想出了这个问题。我们已经在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日志发布调用是同步的。

java.util.concurrent.ExecutorService＃提交需要很长时间

相关推荐