java.util.concurrent.ExecutorService#submit 需要很长时间

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());
    }
}

运行代码会产生以下输出：

[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()

这表明程序的整个运行时间不到 75 毫秒。关于您的问题，让我印象深刻的一件事是您的线程名称 - “New I/O worker #1” - 这向我表明这里有多个ExecutorServices 在起作用。

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

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 日志发布调用是同步的。