邮件服务优化方案(2018年3月23日)

Skip to end of metadata

 

Go to start of metadata

 

 

 

一、问题

1、report耗时

从目前来看,一次report的耗时从1个半小时到2个小时不等,时间略长。每次report的邮件数从3万-6万不等,得出这个数据的过程可以参考附件。

2、内存

不仅仅是邮件服务,JVM老年代内存逐渐上涨直至报警,需要重启来解决的问题在各个系统中几乎全部存在,只不过邮件服务的迭代周期较长(重启的次数很低),所以报警问题较为突出。

二、分析

1、report

工作的线程模型可以用下图来表示:

阶段一

阶段一在定时任务线程中执行,这一步所做的工作是从数据库中一次性查出最近3天内需要进行report的所有邮件(总数在3万-6万不等),并提交到pull线程池中。

阶段二

直接上源码,MailReportPullJobs.doPull:

for (MailReports mailReports : reportList) {
    executor.execute(() -> {
        MailReportRequest mailReportRequest = new MailReportRequest();
        String messageId = mailReports.getMessageId();
        mailReportRequest.setMessageId(messageId);
        //为了兼容老数据,需要去mails表里查询toMail字段
        String recipient = "";
        if(StringUtils.isBlank(mailReports.getToMail())){
            Mails mail = mailService.getMails(mailReports.getMailId());
            recipient = mail != null ? mail.getToMail() : "";
        }else{
            recipient = mailReports.getToMail();
        }
        mailReportRequest.setRecipient(recipient);
        if(StringUtils.isNotBlank(messageId) && StringUtils.isNotBlank(recipient)) {
            mailStrategy.doPullReport(mailReportRequest, mailReports.getId());
        }
    });
}

由于在当前的数据中可以直接获得toMail,所以这里不会进行一次数据库查询,即:全部是简单的、步骤有限的内存操作,所以可以进一步得出推论:这个pull线程池没有存在的必要

下面是此线程池的定义:

private static final ThreadPoolExecutor executor =
        new ThreadPoolExecutor(Runtime.getRuntime().availableProcessors(), Runtime.getRuntime().availableProcessors() * 10, 0L, TimeUnit.MILLISECONDS,
        new LinkedBlockingQueue<>(), ThreadUtils.newThreadFactoryByName("pullExecutor"));

由于队列大小上限是int最大值,考虑到目前需要report的邮件数远小于此值,所以此时线程池maximumPoolSize参数实际上失去了意义,即线程数永远不会达到此值

Q: Why?

A: 参考ThreadPoolExecutor的execute方法源码:

public void execute(Runnable command) {
    int c = ctl.get();
    if (workerCountOf(c) < corePoolSize) {
        if (addWorker(command, true))
            return;
        c = ctl.get();
    }
    if (isRunning(c) && workQueue.offer(command)) {
        int recheck = ctl.get();
        if (! isRunning(recheck) && remove(command))
            reject(command);
        else if (workerCountOf(recheck) == 0)
            addWorker(nullfalse);
    }
    else if (!addWorker(command, false))
        reject(command);
}

概括来说,一个任务被提交的步骤是:

  1. 如果当前线程数未达到corePoolSize,提升线程数,并将任务直接交给新创建的线程池执行。
  2. 如果已达到corePoolSize,那么尝试提交到任务队列,如果提交成功,返回。
  3. 如果线程数尚未达到maximumPoolSize,那么提升线程数。
  4. 此时仍未成功,那么触发reject。

我们可以在线上机器执行report时用jstack打印线程堆栈的方式来正式这一点。2018年3月22日15点的report由机器l-mail2.ter.prod.aws.dm完成,查看其堆栈:

得证。

阶段三

此阶段是report操作的核心所在,归纳为两步:

可以明显的看出,这是一个IO密集型操作。从目前日志来看,阶段三的耗时约1秒。

下面是其线程池的定义:

private static final int QUEUE_SIZE = 50000;
private static final ThreadPoolExecutor reportExecutor =
        new ThreadPoolExecutor(Runtime.getRuntime().availableProcessors(), Runtime.getRuntime().availableProcessors() * 2, 10L, TimeUnit.MILLISECONDS,
                new LinkedBlockingQueue<>(QUEUE_SIZE), ThreadUtils.newThreadFactoryByName("reportExecutor"));

这是一个有界队列(准确来说,int最大值也是有界…),仍以2018年3月22日l-mail2.ter.prod.aws.dm这次report为例,共有6万多report请求,所以我们可以推断,实际的工作线程数为8(核心数4):

同样得证。

但是,如果需要report的邮件数不足5万,那么实际工作的线程数便只有四个,以30607封为例,那么:

30607 / 4(线程数) / 1(秒) / 60 / 60 = 2.12小时

通过日志便可以印证此结论。进一步延伸,当邮件数超过5万(以51000为例),此时的耗时为:

51000 / 8 / 1 / 3600 = 1.77小时

反而比更少的邮件数时耗时低。

2、内存

这里重点关注老年代中的不可达对象,即垃圾。

 

可见,这里有大约300MB的由report线程池导致的垃圾,原因很容易想到:

每次report时都会有大量的MailReportRequest对象等待被处理。

3、昂贵的连接

我们服务请求mail gun使用的是HTTPS连接,众所周知,TCP连接的建立需要三次握手,断开需要四次挥手,是一个较重的操作。而HTTPS连接又加重了这一情形。但是:

我们的服务并未使用连接池(HTTP 1.1版本默认开始keep-alive,即连接复用),这就意味这每个时段的report需要执行5万次(约)TCP连接建立与HTTPS握手

无需测试,只需脑补即可想象这有多痛苦。

下面用debug的方法证明上述论断。使用MailGunMailVendor的getReports方法作为切入点,源码:

@Override
public List<MailReportResponse> getReports(MailReportEvent mailReportEvent) {
    WebResource webResource = client.resource(MAIL_EVENT_API);
 
    String responseBody = webResource.queryParams(queryParams).get(String.class);
 
    return mailReportResponses;
}

一路跟下去,核心点位于URLConnectionClientHandler的_invoke方法,如下图:

openConnection即JDK中URL类的方法,这就直接证明了我们上面的结论。所以,对昂贵的HTTPS连接进行复用是势在必行的。

4、并发更新

如果一封邮件mail gun有了状态变化,那么系统将拉取到的最新的状态更新到数据库中,按照原有的线程模型,有三个潜在的问题:

  1. 拉取report和更新状态为串行操作,无法充分利用多线程并发处理的优势。
  2. 单次更新按照主键进行,性能并不是问题,但是总体来看,会产生大量的小事物的提交。
  3. 每次与MySQL的交互均需要通过网络I/O完成。

所以,本次优化将其改为异步化、批量化。

三、优化

1、report线程池

提升report线程池的corePoolSize(比如改为40)即可,注意改pull线程池是没有作用的。

2、线程模型调整

消耗

每次report都会创建3万-6万的MailReportRequest对象、3万-6万的Runnable实现类对象(提交到线程池用)、3-6万的LinkedBlockingQueue的Node对象。我们来看看三种对象分别有多大。

MailReportRequest

com.vipkid.mail.MailReportRequest.limit @12 (int, 4b)
com.vipkid.mail.MailReportRequest.startTime @16 (java.lang.String, 4b)
com.vipkid.mail.MailReportRequest.endTime @20 (java.lang.String, 4b)
com.vipkid.mail.MailReportRequest.recipient @24 (java.lang.String, 4b)
com.vipkid.mail.MailReportRequest.from @28 (java.lang.String, 4b)
com.vipkid.mail.MailReportRequest.messageId @32 (java.lang.String, 4b)
size = 40

共40字节。

Runnable

size = 16

LinkedBlockingQueue$Node

外部无法访问其内部类Node,目测为4 + 4 + 8 = 16字节。

总结

简单计算一下,每天需要执行24 / 3 = 8次report,随机分配至3台机器,即每台机器每天执行约3次,故有:

40000(假设每次report邮件数) * 72B(每次邮件report消耗老年代大小) * 3(每台机器每天report次数) * 36(重启后到报警所需的天数) / 1024(KB) / 1024(MB) = 296.6MB

感觉和实际差不多。

新的线程模型

概括

总的来说,可以从下面两方面入手:

  1. 干掉pull线程池。此优化的意义不在于能够提升多少性能(或者说降低多少内存消耗),而是简化代码结构、线程模型。原因是将MailReportRequest提交到线程池其实是一个非常高效的操作,预计这里创建的Runnable对象可以在 Minor GC中就得到回收。
  2. 引入disruptor

示意图

图中report、更新DB的线程数只是一个示意。Disruptor是一个lock-free实现的高性能环形队列,当然这里引入disruptor的主要原因并不是其无锁特性(因为目前的处理速度锁应该还不是瓶颈),而是其事件对象预分配且固定

这就意味着上面提到的MailReportRequest、Runnable和Node不断堆积的问题便得到解决了。

3、连接池

我们服务使用的是1.9版本的jersey客户端,结合Apache HttpClient可以实现连接池的效果,这里参考:

Connection pooling using jersey client

Jersey Client 1.x Example

Q: Jersey如何处理连接关闭?

A: 既然有了”池”的概念,那么就不得不提资源的close/回收方法,我们下面来看看引入了连接池后jersey是在何时何地进行连接回收的。仍以下面请求代码为例:

String responseBody = webResource.queryParams(queryParams).get(String.class);

这里返回的是String类型,这很重要。跳过复杂的调用关系,核心位于org.apache.commons.httpclient.AutoCloseInputStream的close方法:

public void close() {
    if (!selfClosed) {
        selfClosed = true;
        notifyWatcher();
    }
}
notifyWatcher方法:
private void notifyWatcher() throws IOException {
    if (streamOpen) {
        super.close();
        streamOpen = false;
 
        if (watcher != null) {
            watcher.responseConsumed();
        }
    }
}

连接的回收最终就是在这里完成的。watcher在HttpMethodBase的readResponseBody方法中设置,部分源码:

private InputStream readResponseBody(HttpConnection conn){
    InputStream result = null;
    // if there is a result - ALWAYS wrap it in an observer which will
    // close the underlying stream as soon as it is consumed, and notify
    // the watcher that the stream has been consumed.
    if (result != null) {
        result = new AutoCloseInputStream(
            result,
            new ResponseConsumedWatcher() {
                public void responseConsumed() {
                    responseBodyConsumed();
                }
            }
        );
    }
    return result;
}

responseBodyConsumed方法最终会触发连接的回收。回收触发的时机便是当读取响应完成(遇到EOF)或显式调用close方法时

其中连接池参数设置参考了此篇文章,作者结合了在京东的实战经验,2333:

使用httpclient必须知道的参数设置及代码写法、存在的风险

本次新增的三个核心配置如下:

jersey.report.maxPoolSizePerHost=500
jersey.report.maxPoolSize=500
# milliseconds
jersey.connect.poolTimeout=500
jersey.send.maxPoolSize=200
jersey.send.maxPoolSizePerHost=200

这里maxPoolSizePerHost和maxPoolSize的取值相等,因为目前jersey只对mail gun一个host进行请求。除此之外,这里对发送和report连接池进行了隔离,防止大量的并发report对发送产生影响。

Q: Apache http client是如何检查连接是否有效的?

A: HttpConnection的closeIfStale方法:

public boolean closeIfStale() throws IOException {
    if (isOpen && isStale()) {
        LOG.debug("Connection is stale, closing...");
        close();
        return true;
    }
    return false;
}

核心逻辑位于isStale:

protected boolean isStale() throws IOException {
    boolean isStale = true;
    if (isOpen) {
        // the connection is open, but now we have to see if we can read it
        // assume the connection is not stale.
        isStale = false;
        try {
            if (inputStream.available() <= 0) {
                try {
                    socket.setSoTimeout(1);
                    inputStream.mark(1);
                    int byteRead = inputStream.read();
                    if (byteRead == -1) {
                        // again - if the socket is reporting all data read,
                        // probably stale
                        isStale = true;
                    else {
                        inputStream.reset();
                    }
                finally {
                    socket.setSoTimeout(this.params.getSoTimeout());
                }
            }
        catch (InterruptedIOException e) {
            if (!ExceptionUtil.isSocketTimeoutException(e)) {
                throw e;
            }
            // aha - the connection is NOT stale - continue on!
        catch (IOException e) {
            // oops - the connection is stale, the read or soTimeout failed.
            LOG.debug(
                "An error occurred while reading from the socket, is appears to be stale",
                e
            );
            isStale = true;
        }
    }
 
    return isStale;
}

总结为:

  1. 判断(inputStream.available() <= 0)的目的是支持BufferedInputStream,如果此时连接已经断开但是buffer中尚有未处理的数据,仍然认为是有效的。
  2. 核心的检查逻辑是首先设置一个较短的超时时间,然后执行读操作,如果返回-1,那么说明已断开,如果抛出超时异常(SocketTimeoutException),那么我们依然认为是有效的
  3. 如果抛出其它异常(非SocketTimeoutException),那么认为已断开。

其实这样的判断逻辑依然有问题,即如果网络断开,那么此方法依然会认为是有效的。真正可以准确判断TCP连接断开的方式是write,而不是read,但是精确的判断需要一个较长的耗时(甚至可以达到15分钟)。所以,此种判断方式其实是在准确性和性能之间做了一个折中与取舍。

Q: 服务器是否开启了keep-alive支持?

A: 首先,mail gun服务使用的是HTTP 1.1协议,而此协议默认是开启了keep-alive,我们直接使用curl工具打印一下请求report的响应头,命令:

curl -i -s --user 'api:key-5f57bf6ed1fe62dfed144e551c60b07f' -G \
      https://api.mailgun.net/v3/vipkid.net/events \
      --data-urlencode begin='Fri, 3 May 2013 09:00:00 -0000' \
      --data-urlencode ascending=yes \
      --data-urlencode limit=25 \
      --data-urlencode pretty=yes \
      --data-urlencode recipient=zhangpeilei@vipkid.com.cn \
      --data-urlencode message-id=20180410103836.1.A1CC5A23FBE20FF4@vipkid.net

响应头如下所示:

HTTP/1.1 200 OK
Access-Control-Allow-Headers: Content-Type, x-requested-with
Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS
Access-Control-Allow-Origin: *
Access-Control-Max-Age: 600
Content-Type: application/json
Date: Wed, 11 Apr 2018 03:32:21 GMT
Content-Length: 5107
Server: nginx
Connection: keep-alive

注意最后两行,说明mail gun的服务器是nginx且支持keep-alive,但是这里还是有一个隐藏的问题,即:mail gun的nginx设置的超时时间是多少?

此参数由配置keepalive_timeout决定,默认为75秒,设置为0即关闭keep-alive,所以我们的连接池中的连接可以复用多久取决于mail gun的配置。

如果在nginx中配置为:

http {
    keepalive_timeout  0;
}

那么响应头其实是这样的:

对比一下大于零时:

即可进一步得出结论:我们虽然不知道mail gun服务器设置的keep-alive超时时间是多少,但是可以肯定必定大于零

另外,nginx除了对连接有时间上的限制外,还在一个连接处理的请求数维度上进行了限制,来自官方文档:

下面从WireShark的角度确认连接池确实已生效,测试的方法为对两封邮件进行report,注意应该先将连接池的最大连接数设置为1,否则看不到效果,如下:

非常和谐的结果,一次握手,两次交互。

与之对比,使用相同的数据、原来的代码进行测试,如下:

明显的两次握手,两次交互,证明我们的连接池是确实生效的。

Q: HTTP的keep-alive和TCP的keep alive什么区别?

A: Google, Baidu…

4、异步更新

如上面线程模型图,初步设置的批量更新的批次大小为100。这里有个问题,100条是否过大会导致执行失败?

首先MySQL似乎并没有对这个批量的条数有明确的限制,摘自官方文档:

所以唯一的限制应该是喜闻乐见的max_allowed_packet参数,即每次与MySQL服务器交互最大的包大小。可以在nods平台执行以下语句查看其取值:

show VARIABLES like '%max_allowed_packet%';

线上的执行结果如下图:

即128MB。这是MySQL服务器的设置,在jdbc驱动层面上同样可以对此参数进行设置,以下是官方文档:

由于在jdbc层面上我们没有对此参数进行设置,所以最终的上限就是64MB。

一个典型的update语句如下:

UPDATE mail_reports SET status = 1, content = '[{"recipient":"hasekiue@hotmail.com","event":"delivered","timestamp":"1.522422415268628E9","result":1},{"recipient":"hasekiue@hotmail.com","event":"accepted","timestamp":"1.522422414412456E9","result":0}]' WHERE id = 98842348;

长度为273B,所以100条的长度为:273B * 100 / 1024 = 27KB,可以得出最终结论:

100条update语句的大小远小于单次交互字节数上限,不必担心

5、参数调整

-Xms4608M -Xmx4608M -XX:MaxDirectMemorySize=200M -XX:NewRatio=2

思路:

  1. 降低整个堆的大小,内存报警很大程度是由于配置不合理导致,堆内存 + Metaspace等空间 + 其它程序占用内存早已超过物理内存。
  2. 限制堆外内存(NIO用)大小,默认情况下为堆内存减去一个Survivor,虽然在目前的业务场景下堆外内存不会大量使用,但仍然是一个隐患。
  3. 在降低堆的总大小的前提下保持新生代大小不变:4608M / 3 == 6144M / 4.

同时按照如下公式:

4608MB * 70%(CMS回收阈值) + 0.5GB(Metaspace) + 0.5GB(CompressedClassSpaceSize) + 1GB(机器上的其它进程(比如:日志收集进程)) + 0.2GB(Direct buffer) = 5.35GB

而:

5.35GB / 7GB = 76%

未达到报警阈值的80%,所以这样也不会导致内存报警。

Q: NIO用的direct buffer默认上限是多大?

A: 堆内存上限(Xmx)减去一个survivor,非常恐怖。

四、不可描述

  1. 邮件服务从启动到开始报警,没有一次Full GC,也就是说,直到报警,堆的占用率也未达到CMS垃圾回收的阈值 从上图可以看出,堆的最大占用率为59.6%,而我们设置的CMS垃圾回收阈值是70%.
  2. 目前线上Minor GC的频率约为3分钟一次。
  3. 内存暴涨和report之间的关系: 以mail2的GC日志server-gc.log.201804120649为例,内存增长曲线图: 明显有几个暴涨的时间点,这里的时间点是一个相对值(相对于启动时间),结合系统在2018年4月12号早晨6点49启动,所以可以大体推断出绝对值。通过日志查看下mail2机器report执行情况: 后两次report与启动时间的相对值分别为8和14,大体和前两个暴涨的时间点吻合,所以这似乎可以说明report对老年代的增长起到了很大的作用。

五、参考

  1. Shallow heap & Retained heap
  2. LMAX Disruptor
  3. 高性能队列——Disruptor
  4. 新生代和老年代怎样的比例比较合适
  5. JVM源码分析之Metaspace解密
  6. MySQL 加锁处理分析
  7. connector-j-reference-configuration-properties
  8. packet-too-large
  9. [HotSpot VM] JVM调优的”标准参数”的各种陷阱
  10. keepalive_timeout
  11. TCP keepalive 和 http keep-alive

六、附件

server-gc.log.201804120649

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s