运维:你们 JAVA 服务怎么又又又又出问题了!内存降不下来!

在上次在运维老哥友好的和我沟通之后,还消停没几天,今天又来找(问候)我了……

运维:这个服务也是你们的吧,你看这个 JAVA 进程,内存占用都快 3 个 G 了,这机器才 4G,你们堆才配置 2G,都要告警了!这次是真的内存泄露了吧,不是我无知了吧!

又来搞事情……这大哥是对我有意见吗?有了上次的经验,这回更自信了。还是按照惯例,先怼回去

我:“不可能,我们服务非常稳定,不会有这种问题!”

运维:你这哪来的自信和勇气?梁静茹给的吗?你先回去查查再装

看来大哥这回是有备而来啊,难道真是出问题了?有点慌了……

不过还是不能怂,先敷衍下运维老哥,找个借口回去先偷摸查查监控看看

我:行,我待会看看,我先去跟人开个会啊……

分析监控数据

这个服务的堆内存配置的是 2G,历史内存也确实达到过 2G,虽然现在 used 才几百兆……看起来也没啥问题

再加上一些 VM 自己的开销,一共占用 2 个多 G……好像也说的过去

然后我又找到了运维大哥,(友好的)沟通一下……

我:和上次一样啊,没什么区别,上次都解释过那个内存管理的机制了,你咋还说我们有问题?

运维: 你看你们这个服务,配置的是 CMS+ParNew 垃圾回收器吧,上次是你说的这个回收器组合下会释放内存给操作系统吧?那怎么还占用 2G,释放到哪去了?

我:虽然上回测试结果是会释放,但还有一些其他的说法,说是空闲时会增量释放,而且释放成本这么高,不释放又怎么样?

运维:你这话不是打自己脸么?上回说能释放,现在没释放你也说正常,你是不是觉得我傻?

运维大哥好像看出了我是在狡辩……

不释放也正常啊,释放成本这么高,释放后还得重新申请,重新组织内存结构balabalabala……

这话说的我自己都没底气……毕竟上次才测试过 CMS+ParNew 确实会释放,只是时间问题

运维:你继续狡辩,这服务的内存照这个趋势,估计要不要明天就得 OOM,然后系统再给你来个 OOM Killer 的绝杀,你可就开心了!

我:没问题的,这个内存正常,自己的服务,我还能不了解嘛

此时我已经有点不安了,大哥说的有道理啊,万一 OOM Killer了,可不完蛋了!

我:我晚点有空再仔细看看,应该没啥问题,你先忙你的,放心!

上服务器查实时指标

打发走了运维老哥之后,我仔细思考了一会。这内存的数据好像确实不太正常,这个服务属于那种后端应用,虽然业务复杂,但只是给业务大佬们用。不过这个内存占用确实有点说不过去啊,到底内存跑哪去了……

还是数据说话吧,上主机上找找看有没有什么线索

  1. 内存 - ok
  2. CPU 利用率 - ok
  3. CPU 负载 - ok

也没什么异常,CPU 利用率和负载啥的都很低……到底问题出在哪?

这么一点点<typo id="typo-1209" data-origin="的" ignoretag="true">的</typo>看指标太费劲了,还是拿 Arthas 看吧,JVM 相关的指标它基本都显示,比较全:

[arthas@20727]$ dashboard

Memory                    used    total    max     usage    GC
heap                      498M     1963M    1963M   25.1%    gc.ps_scavenge.count          3
ps_eden_space             98M      512M     512M    19.5%    gc.ps_scavenge.time(ms)       44
ps_survivor_space         0K      87040K   87040K  0.00%    gc.ps_marksweep.count         1
ps_old_gen                39M     1365M    1365M   2.88%    gc.ps_marksweep.time(ms)      87
nonheap                   32M     180M      -1      17.7%
code_cache                10M      50M      240M    20%
metaspace                 20M     128M      -1      15.6%
compressed_class_space    2M      2M       1024M   0.25%

看起来JVM 级别的内存也没啥问题,再看看线程呢:

[arthas@20727]$ thread

Threads Total: 9831, NEW: 0, RUNNABLE: 8, BLOCKED: 0, WAITING: 9789, TIMED_WAITING: 2, TERMINATED: 0, Internal threads
: 17

wc,这什么玩意!快 1w 个线程!还基本上都是 WAITING!

赶紧看看这些 WAITING 的线程都是些啥:

ead --state WAITING

ID   NAME                          GROUP          PRIORITY  STATE     %CPU      DELTA_TIM TIME      INTERRUPT DAEMON
# 此处省略 9000+ 行……
9822 pool-9813-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9823 pool-9814-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9824 pool-9815-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9825 pool-9816-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9826 pool-9817-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9827 pool-9818-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9828 pool-9819-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9829 pool-9820-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9830 pool-9821-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9831 pool-9822-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9832 pool-9823-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9833 pool-9824-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9834 pool-9825-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9835 pool-9826-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9836 pool-9827-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9837 pool-9828-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9838 pool-9829-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9839 pool-9830-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9840 pool-9831-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false

看到这个线程名,我也大概明白了,一定是哪个小天才在代码里下毒。

从线程名称来看,肯定是线程池里的线程嘛,而且是默认的线程名生成规则。线程池里的线程都是通过 ThreadFactory 来创建的,而默认的 ThreadFactory 生成规则就是这样:

DefaultThreadFactory() {
    SecurityManager s = System.getSecurityManager();
    group = (s != null) ? s.getThreadGroup() :
    Thread.currentThread().getThreadGroup();

    // 前缀,每一个新的 ThreadFactory 都有一个新的前缀
    // 每一个线程池,都只有一个 ThreadFactory
    namePrefix = "pool-" +
        poolNumber.getAndIncrement() +
        "-thread-";
}

public Thread newThread(Runnable r) {

    // 每个线程都会使用 factory的前缀,然后加上自增的线程数
    Thread t = new Thread(group, r,
                          namePrefix + threadNumber.getAndIncrement(),
                          0);
    if (t.isDaemon())
        t.setDaemon(false);
    if (t.getPriority() != Thread.NORM_PRIORITY)
        t.setPriority(Thread.NORM_PRIORITY);
    return t;
}

所以这个问题,肯定是哪个小天才,在代码里每次都新建线程池,然后还不 shutdown 导致的!随便找个线程,看看它的 stack:

"pool-1-thread-1" Id=10 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@6ba7592
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@6ba7592
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

实锤了,就是每次 new 线程池不 shutdown……现在只需要找到创建线程池的地方,再翻翻提交记录,就可以知道是哪个小天才了……

但代码这么多,想找到这个新建线程池的地方还是有点麻烦的,搜代码可不太方便。这里还是用 Arthas 来看看,stack 一看就知道

不过如果这里直接 stack ThreadPoolExecutor#execute 方法的话,干扰信息可能太多了,毕竟调用 execute 的地方太多,不好抓到重点

所以还是 stack 线程池初始化的方法比较好:

[arthas@20727]$ stack java.util.concurrent.ThreadPoolExecutor <init>

Affect(class count: 0 , method count: 0) cost in 4 ms, listenerId: 5
No class or method is affected, try:
1\. Execute `sm CLASS_NAME METHOD_NAME` to make sure the method you are tracing actually exists (it might be in your parent class).
2\. Execute `options unsafe true`, if you want to enhance the classes under the `java.*` package.
3\. Execute `reset CLASS_NAME` and try again, your method body might be too large.
4\. Check arthas log: /home/jiangxin/logs/arthas/arthas.log
5\. Visit https://github.com/alibaba/arthas/issues/47 for more details.

这……是不支持吗?

Arthas 的增强策略是比较保守的,部分系统级别的类它不做增强,java.* 包下的类默认是不增强的,需要手动开启才行:

[arthas@20727]$ options unsafe true

 NAME    BEFORE-VALUE  AFTER-VALUE
-----------------------------------
 unsafe  false         true

再次执行 stack 之后,可以用了。过了两分钟之后,终于有一次调用:

ts=2021-06-12 12:04:03;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@4e0e2f2a
    @java.util.concurrent.ThreadPoolExecutor.<init>()
        at java.util.concurrent.Executors.newFixedThreadPool(Executors.java:89)
        at XXXService.sendSms(XXXService.java:782)
        //...

终于找到了这个骚操作代码……它是这么写的:

ExecutorService executorService = Executors.newFixedThreadPool(8);

executorService.submit(smsTask);

//...

和我猜测的一样,果然是每次 new,然后还不 shutdown。

这也能和上面的情况对上了,多出的内存占用是因为这小一万个线程……而且这些线程池没有任务需要执行的话,线程肯定是 WAITING 状态,也不会占用 CPU 的利用率,负载有不会有影响。不仔细还真看不出问题 ,还是得结合各种指标来看,综合分析。

解决这个问题倒简单,让写这个屎代码的人去改了,然后拉出去祭天。

可是运维大哥那边……已经装出去了,这下脸可是丢完了。上次好不容易挣回来的面子,这次啥都没了

[图片上传失败...(image-841cb5-1628920441734)]

给运维的交代

我:服务确实有点问题,我们发个紧急修复版本,晚上上线就能解决了

运维:你不是说没问题么?自信哪去了

我:这不是没吃早饭,饿的头发昏,脑子不够清醒……没看出来问题,我的锅我的锅

运维:肯定是你们的屎山代码导致的,没事也搞搞 code review ,查查代码,以后少出这种低级问题,不然我一天到晚处理你们这些破事不得烦死了

没想到这运维还喘起来了,给点面子就要上天……不过谁让我理亏呢,只能应下

我:对对对,我们以后一定多搞 code review,加强代码审查,避免这种屎代码再提交上去,影响生产。不给大佬添麻烦

作者:空无
链接:https://juejin.cn/post/6973808359614971918

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,711评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,079评论 3 387
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 159,194评论 0 349
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,089评论 1 286
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,197评论 6 385
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,306评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,338评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,119评论 0 269
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,541评论 1 306
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,846评论 2 328
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,014评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,694评论 4 337
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,322评论 3 318
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,026评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,257评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,863评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,895评论 2 351

推荐阅读更多精彩内容