线上服务堆外内存OOM问题

Posted on Edited on In

问题描述

最近我们生产上的消息推送服务不断的爆出内存增长过大导致操作系统kill该进程，并且随着业务量的增长出现的频次越来越高，由去年12月底的半个月出现一次，到现在的一天出现一次。

该服务的业务逻辑就是消息推送，业务方推送消息，服务方通过rocketmq做削峰处理（之前使用kafka来左右消息队列没出现过问题），其中主要通道是个推和apns（使用pushy框架）通道，业务方的全局推送大概在5000w用户左右，每全局推送一次，内存就会增长几百mb，直到jvm进程内存达到5g之后，系统就会出现服务请求没响应或者被守护进程重启等问题。

刚开始的快速解决方案也只能重启，虽然重启能解决问题，但是也没找到根本原因！

问题排查

由于我们jvm堆内的初始内存和最大内存都是配置成2g ,但是进程的内存达到5g，那就是说堆外占了3g

-Xms2048m -Xmx2048m

运维平台监控

下面是运维监控平台的cpu、内存、线程资源数据，内存在一直在增长，没有回收释放。

oom内存和cpu

出问题的时候监控应用fullgc情况

fullgc情况

监控jvm虚拟机的线程增长情况

线程增长情况

NMT监控

接下来我们就一直想知道这个增长的内存到底是啥，我们参考Spring Boot引起的“堆外内存泄漏”排查及经验总结文章来监控堆外内存,然后看了官方文档How to Monitor VM Internal Memory。

jvm参数增加 “-XX:NativeMemoryTracking=detail”

然后在jvm启动成功后，执行命令”jcmd pid VM.native_memory baseline”设置基准。

使用命令jcmd pid VM.native_memory summary.diff查看到的内存分布如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
Native Memory Tracking:
Total: reserved=6292013KB +1539438KB, committed=5135497KB +1547890KB
-                 Java Heap (reserved=2097152KB, committed=2097152KB)
                            (mmap: reserved=2097152KB, committed=2097152KB)
-                     Class (reserved=1195883KB +2229KB, committed=164035KB +2229KB)
                            (classes #24637)
                            (malloc=14187KB +181KB #58583 -3174)
                            (mmap: reserved=1181696KB +2048KB, committed=149848KB +2048KB)
-                    Thread (reserved=330857KB +16399KB, committed=330857KB +16399KB)
                            (thread #625 +32)
                            (stack: reserved=328076KB +16512KB, committed=328076KB +16512KB)
                            (malloc=2049KB +105KB #3129 +160)
                            (arena=732KB -218 #1246 +64)
-                      Code (reserved=269720KB -4533KB, committed=145052KB +3919KB)
                            (malloc=20120KB -4533KB #22197 -10586)
                            (mmap: reserved=249600KB, committed=124932KB +8452KB)
-                        GC (reserved=85877KB -1KB, committed=85877KB -1KB)
                            (malloc=9253KB -1KB #856 -42)
                            (mmap: reserved=76624KB, committed=76624KB)
-                  Compiler (reserved=1753KB -159KB, committed=1753KB -159KB)
                            (malloc=1623KB -159KB #2892 -1291)
                            (arena=131KB #6)
-                  Internal (reserved=2267668KB +1520485KB, committed=2267668KB +1520485KB)
                            (malloc=2267636KB +1520485KB #39668 +996)
                            (mmap: reserved=32KB, committed=32KB)
-                    Symbol (reserved=30690KB +10KB, committed=30690KB +10KB)
                            (malloc=26686KB +10KB #273270 +61)
                            (arena=4004KB #1)
-    Native Memory Tracking (reserved=7216KB +16KB, committed=7216KB +16KB)
                            (malloc=766KB +190KB #10648 +2568)
                            (tracking overhead=6450KB -173KB)
-               Arena Chunk (reserved=5196KB +4991KB, committed=5196KB +4991KB)
                            (malloc=5196KB +4991KB)

发现增长的区域居然是Internal区域，刚开始感到一脸疑惑，后来在网上看到堆外内存申请也是属于Internal区域，才觉得应该是什么中间件使用了堆外内存导致的内存泄漏。

pmap查看内存分配情况

通过linux工具查看进程的内存映射

pmap -x 11305|sort -k 3 -n -r 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
---------------- ------- ------- ------- 
0000000080000000       0       0       0 rw---   [ anon ]
0000000101100000       0       0       0 -----   [ anon ]
0000000101100000 1031168       0       0 -----   [ anon ]
000055f7262ed000       0       0       0 r-x-- java
000055f7264ed000       0       0       0 r---- java
000055f7264ee000       0       0       0 rw--- java
000055f728243000       0       0       0 rw---   [ anon ]
00007f6970000000       0       0       0 rw---   [ anon ]
00007f6973003000       0       0       0 -----   [ anon ]
00007f6973003000   16372       0       0 -----   [ anon ]
00007f6974000000       0       0       0 rw---   [ anon ]
00007f6977010000       0       0       0 -----   [ anon ]
00007f6977010000   16320       0       0 -----   [ anon ]
00007f6978000000       0       0       0 rw---   [ anon ]
00007f697b001000       0       0       0 -----   [ anon ]
00007f697b001000   16380       0       0 -----   [ anon ]
00007f697c000000       0       0       0 rw---   [ anon ]
00007f697e001000       0       0       0 -----   [ anon ]
00007f697e001000   32764       0       0 -----   [ anon ]
00007f6980000000       0       0       0 rw---   [ anon ]
00007f6983001000       0       0       0 -----   [ anon ]
00007f6983001000   16380       0       0 -----   [ anon ]
00007f6988000000       0       0       0 rw---   [ anon ]
00007f698b001000       0       0       0 -----   [ anon ]
00007f698b001000   16380       0       0 -----   [ anon ]
00007f698c000000       0       0       0 rw---   [ anon ]
00007f698f001000       0       0       0 -----   [ anon ]
00007f698f001000   16380       0       0 -----   [ anon ]
00007f6990000000       0       0       0 rw---   [ anon ]
00007f6993001000       0       0       0 -----   [ anon ]
00007f6993001000   16380       0       0 -----   [ anon ]
00007f6994000000       0       0       0 rw---   [ anon ]
00007f6997001000       0       0       0 -----   [ anon ]
00007f6997001000   16380       0       0 -----   [ anon ]
00007f6998000000       0       0       0 rw---   [ anon ]
00007f699b001000       0       0       0 -----   [ anon ]
00007f699b001000   16380       0       0 -----   [ anon ]
00007f699c000000       0       0       0 rw---   [ anon ]
00007f699f001000       0       0       0 -----   [ anon ]
00007f699f001000   16380       0       0 -----   [ anon ]
00007f69a0000000       0       0       0 rw---   [ anon ]
00007f69a3001000       0       0       0 -----   [ anon ]
00007f69a3001000   16380       0       0 -----   [ anon ]
00007f69a4000000       0       0       0 rw---   [ anon ]
00007f69a7001000       0       0       0 -----   [ anon ]
00007f69a7001000   16380       0       0 -----   [ anon ]
00007f69a8000000       0       0       0 rw---   [ anon ]
00007f69ab001000       0       0       0 -----   [ anon ]
00007f69ab001000   16380       0       0 -----   [ anon ]
00007f69ada9a000       0       0       0 rw---   [ anon ]
00007f69afa9c000       0       0       0 -----   [ anon ]
00007f69afa9c000      12       0       0 -----   [ anon ]
00007f69afa9f000       0       0       0 rw---   [ anon ]
00007f69afb1d000       0       0       0 -----   [ anon ]
00007f69afb1d000      12       0       0 -----   [ anon ]
00007f69afb20000       0       0       0 rw---   [ anon ]
00007f69afb9e000       0       0       0 -----   [ anon ]
00007f69afb9e000      12       0       0 -----   [ anon ]
00007f69afba1000       0       0       0 rw---   [ anon ]
00007f69afc1f000       0       0       0 -----   [ anon ]
00007f69afc1f000      12       0       0 -----   [ anon ]
00007f69afc22000       0       0       0 rw---   [ anon ]
00007f69afda2000       0       0       0 -----   [ anon ]

备注：由于篇幅问题，该地方只截取了部分。

从以上也没看出有啥特别多的内存块，所以这里也不好怀疑。

操作系统工具分析

由于操作系统监控运维不给装，我们也就放弃这方面的定位了，这边就写一下大概的思路。

1.使用strace去追踪系统调用

2.使用GDB去dump可疑内存

3.使用jstack去查看对应的线程

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
strace: Process 11305 attached with 442 threads
strace: [ Process PID=11314 runs in x32 mode. ]
strace: [ Process PID=11312 runs in x32 mode. ]
strace: [ Process PID=11314 runs in 64 bit mode. ]
strace: [ Process PID=11308 runs in x32 mode. ]
strace: [ Process PID=11312 runs in 64 bit mode. ]
strace: [ Process PID=11307 runs in x32 mode. ]
strace: [ Process PID=11307 runs in 64 bit mode. ]
strace: [ Process PID=11308 runs in 64 bit mode. ]
[pid 11453] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x8} ---
[pid 11453] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x8} ---
[pid 11453] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x8} ---
[pid 11452] mmap(NULL, 8329, PROT_READ, MAP_SHARED, 296, 0x12000) = 0x7ff8c036b000
[pid 11462] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0xc} ---
[pid 11452] mmap(NULL, 3482, PROT_READ, MAP_SHARED, 186, 0) = 0x7ff8c0672000
[pid 11452] mmap(NULL, 8742, PROT_READ, MAP_SHARED, 189, 0x14000) = 0x7ff8c0368000
[pid 11452] mmap(NULL, 19304, PROT_READ, MAP_SHARED, 192, 0x68000) = 0x7ff8c0363000
[pid 11485] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_ACCERR, si_addr=0x7ff8e901fc00} ---
[pid 11452] mmap(NULL, 25507, PROT_READ, MAP_SHARED, 302, 0x4c000) = 0x7ff8c035c000
[pid 11452] mmap(NULL, 2164, PROT_READ, MAP_SHARED, 306, 0) = 0x7ff8c035b000
[pid 11452] mmap(NULL, 99469, PROT_READ, MAP_SHARED, 307, 0x1bf000) = 0x7ff8c0342000
[pid 11452] mmap(NULL, 15813, PROT_READ, MAP_SHARED, 308, 0x35000) = 0x7ff8c033e000
[pid 11452] mmap(NULL, 27163, PROT_READ, MAP_SHARED, 309, 0x38000) = 0x7ff8c0337000
[pid 11452] mmap(NULL, 2155, PROT_READ, MAP_SHARED, 310, 0x2000) = 0x7ff8c0336000
[pid 11452] mmap(NULL, 9433, PROT_READ, MAP_SHARED, 311, 0x18000) = 0x7ff8c0333000
[pid 11452] mmap(NULL, 4679, PROT_READ, MAP_SHARED, 312, 0x15000) = 0x7ff8c0331000
[pid 11452] mmap(NULL, 8824, PROT_READ, MAP_SHARED, 314, 0x21000) = 0x7ff8c032e000
[pid 11452] mmap(NULL, 26825, PROT_READ, MAP_SHARED, 315, 0x73000) = 0x7ff8c0327000
[pid 11452] mmap(NULL, 6971, PROT_READ, MAP_SHARED, 316, 0x6000) = 0x7ff8c0023000
[pid 11452] mmap(NULL, 7756, PROT_READ, MAP_SHARED, 317, 0xe000) = 0x7ff8c0021000
[pid 11452] mmap(NULL, 16798, PROT_READ, MAP_SHARED, 318, 0x38000) = 0x7ff8c001c000
[pid 11452] mmap(NULL, 14199, PROT_READ, MAP_SHARED, 319, 0x2f000) = 0x7ff8c0018000
[pid 11452] mmap(NULL, 26136, PROT_READ, MAP_SHARED, 320, 0x3f000) = 0x7ff8c0011000
[pid 11452] mmap(NULL, 51761, PROT_READ, MAP_SHARED, 321, 0x83000) = 0x7ff8c0004000
[pid 11452] mmap(NULL, 60574, PROT_READ, MAP_SHARED, 322, 0xa9000) = 0x7ff8b8de4000
[pid 11452] mmap(NULL, 26807, PROT_READ, MAP_SHARED, 323, 0x52000) = 0x7ff8b8ddd000
[pid 11452] mmap(NULL, 7562, PROT_READ, MAP_SHARED, 324, 0xf000) = 0x7ff8c0002000
[pid 11452] mmap(NULL, 22377, PROT_READ, MAP_SHARED, 325, 0x45000) = 0x7ff8b8dd7000
[pid 11452] mmap(NULL, 13843, PROT_READ, MAP_SHARED, 326, 0x27000) = 0x7ff8b8dd3000
[pid 11452] mmap(NULL, 16049, PROT_READ, MAP_SHARED, 327, 0x3c000) = 0x7ff8b8dcf000
[pid 11452] mmap(NULL, 32840, PROT_READ, MAP_SHARED, 328, 0x73000) = 0x7ff8b8dc6000
[pid 11452] mmap(NULL, 7438, PROT_READ, MAP_SHARED, 329, 0xd000) = 0x7ff8c0000000
[pid 11452] mmap(NULL, 12333, PROT_READ, MAP_SHARED, 330, 0x1c000) = 0x7ff8b8dc2000
[pid 11452] mmap(NULL, 244913, PROT_READ, MAP_SHARED, 331, 0x24d000) = 0x7ff8b8027000
[pid 11452] mmap(NULL, 33213, PROT_READ, MAP_SHARED, 332, 0x43000) = 0x7ff8b8db9000
[pid 11452] mmap(NULL, 28353, PROT_READ, MAP_SHARED, 333, 0x41000) = 0x7ff8b837b000
[pid 11452] mmap(NULL, 9944, PROT_READ, MAP_SHARED, 334, 0x11000) = 0x7ff8b8db6000
[pid 11452] mmap(NULL, 18986, PROT_READ, MAP_SHARED, 335, 0x48000) = 0x7ff8b8376000
[pid 11452] mmap(NULL, 21674, PROT_READ, MAP_SHARED, 336, 0x3e000) = 0x7ff8b8370000
[pid 11452] mmap(NULL, 136760, PROT_READ, MAP_SHARED, 337, 0x1f1000) = 0x7ff8b8005000
[pid 11452] mmap(NULL, 5109, PROT_READ, MAP_SHARED, 338, 0x4000) = 0x7ff8b836e000
[pid 11452] mmap(NULL, 3686, PROT_READ, MAP_SHARED, 339, 0) = 0x7ff8b836d000
[pid 11452] mmap(NULL, 4542, PROT_READ, MAP_SHARED, 340, 0x5000) = 0x7ff8b836b000
[pid 11452] mmap(NULL, 1280, PROT_READ, MAP_SHARED, 341, 0x1000) = 0x7ff8b836a000
[pid 11452] mmap(NULL, 8572, PROT_READ, MAP_SHARED, 342, 0xb000) = 0x7ff8b8367000
[pid 11452] mmap(NULL, 893527, PROT_READ, MAP_SHARED, 343, 0x7c4000) = 0x7ff7485e6000
[pid 11452] mmap(NULL, 5512, PROT_READ, MAP_SHARED, 344, 0x2000) = 0x7ff8b8365000

内存堆栈分析

由于系统层面堆栈无法分析，我们只能考虑dump内存，如果是堆外内存，肯定有堆内的引用，此时也只能这样操作。

jmap -heap pid

jmap -histo:live pid | more

jmap -dump:format=b,file=/filetransfer/heap.hprof

以下是通过jprofile的分析图

大对象图

nioEventLoop引用分析

经过以上分析我们能分析出堆内存在大对象是apns推送相关，我们苹果推送用的是pushy框架，此时发现需要看关注下业务代码发送逻辑和pushy源码相关。

问题分析

pushy消息内存堆积

查阅了pushy的官方文档，发现框架为了提高总的tps，本身做了一层消息缓存功能，以下是官方文档摘录。

The APNs server allows for (at the time of this writing) 1,500 notifications in flight at any time. If we hit that limit, Pushy will buffer notifications automatically behind the scenes and send them to the server as in-flight notifications are resolved.

In short, asynchronous operation allows Pushy to make the most of local resources (especially CPU time) by sending notifications as quickly as possible.

然后看了业务代码逻辑，rocketmq消费者消费tps比较高，然后真正推送的时候是直接采用异步的时候推送，这时候导致会存在大量的futuretask回调，而且监听器回调里居然还有while(trysave()){sleep(2000)}方法，导致回调的tps很低，大量的futuretask都积压在内存，伪代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
//发送anps服务器
public void send(final Notification notification) {

  final String topic = notification.getTopic();
  final String deviceToken = notification.getDeviceToken();

  final ApnsPayloadBuilder builder = new ApnsPayloadBuilder();
  builder
    .setAlertTitle(notification.getTitle())
    .setAlertBody(notification.getDescription()).setMutableContent(true)
    .addCustomProperty("*****", String.valueOf(notification.getTraceId()));

  final Map<String, Object> properties = CommonHelper.Json2Map(notification.getPayload());
  setProperties(properties, builder);
  final String payload = builder.buildWithDefaultMaximumLength();
  final Future<PushNotificationResponse<SimpleApnsPushNotification>> notificationResponseFuture =
    client.sendNotification(new SimpleApnsPushNotification(deviceToken, topic, payload));

  notificationResponseFuture.addListener(future -> {
    NotificationStatus status = NotificationStatus.FAILED;
    PushyNotificationService.count.decrementAndGet();
    if (future.isSuccess()) {
      final PushNotificationResponse<SimpleApnsPushNotification> response =
        (PushNotificationResponse<SimpleApnsPushNotification>) future.get();
      if (response.isAccepted()) {
        status = NotificationStatus.RECEIVED;
      } else {
        log.info("failed reason: {}, notification: {}", response.getRejectionReason(),
                 ReflectionToStringBuilder.toString(notification));
        notification.setFailedReason(response.getRejectionReason());
      }
    } else {
      status = NotificationStatus.RETRY;
      final String errorMessage = future.cause().getMessage();
      // 处理 apns 证书过期情况
      if (StringUtil.isNotEmpty(errorMessage) && errorMessage.contains(ERROR_CERT_EXPIRE)) {
        status = NotificationStatus.FAILED;
        notification.setFailedReason(ERROR_CERT_EXPIRE);
      }
      log.warn("pushy send notification failed... {}", errorMessage);
    }
    try{
      notification.setNotificationStatus(status);
      operator.postSendOperate(notification);
    }catch (Exception ex){
      log.error("apns response error",ex);
    }
  });
}

//回调方法
public void postSendOperate(final BatchNotificationWrapper notification) {
  //省略......
  while (!messageService.trySave(msg)) {
    CommonHelper.sleep(2000);
  }
  //省略......
}

最终我们在发送代码里加入限流逻辑和优化回调方法，最终发版上线，观察了1天后还未发现内存异常，不过还需要持续关注，就怕pushy会存在内存泄漏问题。参考pushy最佳实践

threadlocal内存泄漏

发现业务代码中有使用threadlocal操作，但是没有使用remove，这可能会出现堆内存泄漏问题，由于threadlocal使用的ThreadLocal.ThreadLocalMap只有gc的时候回收弱引用。参考深入分析 ThreadLocal 内存泄漏问题.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
static class ThreadLocalMap {

        /**
         * The entries in this hash map extend WeakReference, using
         * its main ref field as the key (which is always a
         * ThreadLocal object).  Note that null keys (i.e. entry.get()
         * == null) mean that the key is no longer referenced, so the
         * entry can be expunged from table.  Such entries are referred to
         * as "stale entries" in the code that follows.
         */
        static class Entry extends WeakReference<ThreadLocal<?>> {
            /** The value associated with this ThreadLocal. */
            Object value;

            Entry(ThreadLocal<?> k, Object v) {
                super(k);
                value = v;
            }
        }

线程泄漏问题

线上环境线程比较发现netty包中的nioEventLoopGroup增长了将近300个线程，占总线程数的40%，分析了项目中除了rocket-mq-clinet，就是apns苹果推送，最终定位到apns推送每一次实例化apnsClient就会new 4个nioEventLoopGroup线程，项目总共有将近30个苹果推送的渠道，如果按照这个算法应该也就4*30=120个nioEventLoopGroup线程，但是实际远远超过这个线程，接下来我们继续看源码中问题。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
Mar  4 11:55:02 pay3 push[13039]: "nioEventLoopGroup-21-4" #8729 prio=10 os_prio=0 tid=0x00007f22e4002800 nid=0x5b0e runnable [0x00007f22ac0c9000]
Mar  4 11:55:02 pay3 push[13039]:    java.lang.Thread.State: RUNNABLE
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:806)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Mar  4 11:55:02 pay3 push[13039]: #011at java.lang.Thread.run(Thread.java:748)
Mar  4 11:55:02 pay3 push[13039]: 
Mar  4 11:55:02 pay3 push[13039]: "nioEventLoopGroup-21-2" #8727 prio=10 os_prio=0 tid=0x00007f22dc13d000 nid=0x5b0c runnable [0x00007f22ab349000]
Mar  4 11:55:02 pay3 push[13039]:    java.lang.Thread.State: RUNNABLE
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c1495e0> (a io.netty.channel.nio.SelectedSelectionKeySet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c1496d0> (a java.util.Collections$UnmodifiableSet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c1495f8> (a sun.nio.ch.EPollSelectorImpl)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:806)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Mar  4 11:55:02 pay3 push[13039]: #011at java.lang.Thread.run(Thread.java:748)
Mar  4 11:55:02 pay3 push[13039]: 
Mar  4 11:55:02 pay3 push[13039]: "nioEventLoopGroup-21-1" #8726 prio=10 os_prio=0 tid=0x00007f24f0024800 nid=0x5b0b runnable [0x00007f22ab838000]
Mar  4 11:55:02 pay3 push[13039]:    java.lang.Thread.State: RUNNABLE
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c16f878> (a io.netty.channel.nio.SelectedSelectionKeySet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c16f968> (a java.util.Collections$UnmodifiableSet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c16f890> (a sun.nio.ch.EPollSelectorImpl)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:806)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Mar  4 11:55:02 pay3 push[13039]: #011at java.lang.Thread.run(Thread.java:748)
Mar  4 11:55:02 pay3 push[13039]: 
Mar  4 11:55:02 pay3 push[13039]: "nioEventLoopGroup-29-4" #7680 prio=10 os_prio=0 tid=0x00007f265c002000 nid=0x54bf runnable [0x00007f22abb3e000]
Mar  4 11:55:02 pay3 push[13039]:    java.lang.Thread.State: RUNNABLE
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c02eec8> (a io.netty.channel.nio.SelectedSelectionKeySet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c02efb8> (a java.util.Collections$UnmodifiableSet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c02eee0> (a sun.nio.ch.EPollSelectorImpl)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:806)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Mar  4 11:55:02 pay3 push[13039]: #011at java.lang.Thread.run(Thread.java:748)
Mar  4 11:55:02 pay3 push[13039]: 
Mar  4 11:55:02 pay3 push[13039]: "nioEventLoopGroup-29-3" #7662 prio=10 os_prio=0 tid=0x00007f2650006800 nid=0x54a4 runnable [0x00007f22ac3cb000]
Mar  4 11:55:02 pay3 push[13039]:    java.lang.Thread.State: RUNNABLE
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c329300> (a io.netty.channel.nio.SelectedSelectionKeySet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c3293f0> (a java.util.Collections$UnmodifiableSet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c329318> (a sun.nio.ch.EPollSelectorImpl)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:806)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Mar  4 11:55:02 pay3 push[13039]: #011at java.lang.Thread.run(Thread.java:748)
Mar  4 11:55:02 pay3 push[13039]: 
Mar  4 11:55:02 pay3 push[13039]: "nioEventLoopGroup-29-2" #7661 prio=10 os_prio=0 tid=0x00007f2654058800 nid=0x54a3 runnable [0x00007f22b8af5000]
Mar  4 11:55:02 pay3 push[13039]:    java.lang.Thread.State: RUNNABLE
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c011ba0> (a io.netty.channel.nio.SelectedSelectionKeySet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c011c90> (a java.util.Collections$UnmodifiableSet)
Mar  4 11:55:02 pay3 push[13039]: #011- locked <0x000000009c011bb8> (a sun.nio.ch.EPollSelectorImpl)
Mar  4 11:55:02 pay3 push[13039]: #011at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:806)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Mar  4 11:55:02 pay3 push[13039]: #011at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Mar  4 11:55:02 pay3 push[13039]: #011at java.lang.Thread.run(Thread.java:748)

最终发现每天定时任务有重新初始化apns通道，但是初始化的时候没关闭原先apns客户端，这才最终导致线程增长不释放问题。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
// spring容器初始化成功调用 和 每天晚上凌晨2点调用
public static void fillDeliveryStrategyMapper(ApplicationContext context) {
  final MessageService messageService = context.getBean(MessageService.class);
  final AsyncUserService asyncUserService = context.getBean(AsyncUserService.class);
  final RocketMQQueueService rocketMQQueueService = context.getBean(RocketMQQueueService.class);
  RuntimeService runtimeService = context.getBean(RuntimeService.class);
  final DeliveryStrategyMapper deliveryStrategyMapper = context
    .getBean(DeliveryStrategyMapper.class);

  final Builder<String, Delivery<NotificationPackage>> builder = ImmutableMap.builder();
  final List<String> registeredAppNames = CommonHelper.getRegisteredApps();

  for (final String appName : registeredAppNames) {
    final PushyRegistry registry = CommonHelper.getPushyRegistry(appName);
    if (null != registry) {
      builder.put(appName + Constants.Channel.PUSHY,
                  new ImmediateDelivery(
                    new PushyNotificationService(runtimeService,registry, messageService, rocketMQQueueService,
                                                 asyncUserService, false)));

      //iso Sandbox
      builder.put(appName + Constants.Channel.IOS_SANDBOX,
                  new ImmediateDelivery(
                    new PushyNotificationService(runtimeService,registry, messageService, rocketMQQueueService,
                                                 asyncUserService, true)));

      continue;
    }
    final String secret = CommonHelper.getAndroidPushProviderProperty(appName, CommonHelper.PUSH_MI_REGISTRY_SECRET);
    if (StringUtils.isNotEmpty(secret)) {
      builder.put(appName + Constants.Channel.MI,
                  new BufferedDelivery(
                    new MiNotificationService(secret, messageService, asyncUserService), 1000));
    }

    final String appKey = CommonHelper.getAndroidPushProviderProperty(appName, CommonHelper.PUSH_UPUSH_REGISTRY_APPKEY);
    final String uPushSecret = CommonHelper.getAndroidPushProviderProperty(appName, CommonHelper.PUSH_UPUSH_REGISTRY_SECRET);
    if (StringUtil.isNotEmpty(appKey, uPushSecret)) {
      builder.put(appName + Constants.Channel.UPUSH,
                  new BufferedDelivery(
                    new UPushNotificationService(appKey, uPushSecret, messageService, asyncUserService),
                    500));
    }

    final String getuiAppId = CommonHelper.getAndroidPushProviderProperty(appName, CommonHelper.PUSH_GETUI_REGISTRY_APP_ID_MATCHER);
    final String getuiAppKey = CommonHelper.getAndroidPushProviderProperty(appName, CommonHelper.PUSH_GETUI_REGISTRY_APP_KEY_MATCHER);
    final String getuiMasterSecret = CommonHelper.getAndroidPushProviderProperty(appName, CommonHelper.PUSH_GETUI_REGISTRY_MASTER_SECRET_MATCHER);
    if (StringUtil.isNotEmpty(getuiAppId, getuiAppKey, getuiMasterSecret)) {
      builder.put(appName + Constants.Channel.GETUI,
                  new BufferedDelivery(new GetuiNotificationService(getuiAppId, getuiAppKey, getuiMasterSecret, messageService, asyncUserService, appName), GetuiChannel.GETUI_MAX_BATCH_SIZE));
    }

  }

  // 初始化所有的推送通道，这里没有关闭以前的创建的客户端
  deliveryStrategyMapper.setMapper(builder.build());

  log.info("push notification delivery strategies: {}",
           ReflectionToStringBuilder.toString(deliveryStrategyMapper));
}

lxd容器线程不能创建问题

由于线上某一台服务器经常出现线程数创建到470的时候，就直接报oom问题，然后触发jsw守护线程重启现象。刚开始我们也调整了lxd的线程数限制调整到4000，但是发现还是一直报错，最终调整容器的UserTasksMax参数。ubuntu文档

1
2
3
4
5
6
7
8
9
10
11
12
Mar 11 17:33:04 pay3 push[16255]: java.lang.OutOfMemoryError: unable to create new native thread
Mar 11 17:33:04 pay3 push[16255]: The JVM has run out of memory.  Restarting JVM.
Mar 11 17:33:04 pay3 push[16255]: #011at java.lang.Thread.start0(Native Method) [na:1.8.0_242]
Mar 11 17:33:04 pay3 push[16255]: #011at java.lang.Thread.start(Thread.java:717) [na:1.8.0_242]
Mar 11 17:33:04 pay3 push[16255]: #011at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[na:1.8.0_242]
Mar 11 17:33:04 pay3 push[16255]: #011at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1378) ~[na:1.8.0_242]
Mar 11 17:33:04 pay3 push[16255]: #011at org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:166) ~[tomcat-coyote.jar:7.0.91]
Mar 11 17:33:04 pay3 push[16255]: #011at org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:146) ~[tomcat-coyote.jar:7.0.91]
Mar 11 17:33:04 pay3 push[16255]: #011at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:761) ~[tomcat-coyote.jar:7.0.91]
Mar 11 17:33:04 pay3 push[16255]: #011at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1304) ~[tomcat-coyote.jar:7.0.91]
Mar 11 17:33:04 pay3 push[16255]: #011at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1260) ~[tomcat-coyote.jar:7.0.91]
Mar 11 17:33:04 pay3 push[16255]: #011at java.lang.Thread.run(Thread.java:748) [na:1.8.0_242]

解决点：

1
2
3
4
UserTasksMax=
Sets the maximum number of OS tasks each user may run concurrently. This controls the
TasksMax= setting of the per-user slice unit, see systemd.resource-control(5) for
details. Defaults to 12288 (12K).

总结

分析这次堆外内存虽然最终定位到问题，总结下出现的问题和原因：

  1. 由于之前的消息队列用kafka，后来切换到rocketmq就出现内存堆外内存增长问题，是因为kafka是每个分区分配一个线程去消费处理，但是rocketmq是多线程消费，每个topic默认是16个queue，是异步拉取消费，在加上apns内部用了内存队列来堆积消息，这就导致了内存暴增，最终导致fullgc问题；
  2. threadlocal内存泄漏问题；
  3. 线程泄漏没有销毁问题；