# Java运维事件处理

# 运维事件发生-服务部署过程中卡死

# 事件描述

由于系统测试环境迁移,需要在新环境部署一个jar包,部署过程中仅依赖jdk环境。本来挺简单的一个事情,这个服务之前也迁移过,迁移是我做的,按说照之前的文档操作一下就行。然而这次操作却遇到了一个异常诡异的问题。服务启动过程中卡死,不打日志不报错不挂掉。

# 事件处理

如何安装jdk以及验证这里就不介绍了,安装完jdk之后,到jar包的目录启动服务。服务正常启动就部署完成了,然而这次服务却并未启动完成。

# 这里主机名做了修改,不在这里显示业务系统真实的主机名
[root@test215100 filedepot]# cd /app/imodule/service/filedepot
[root@test215100 filedepot]# sh service-filedepot.sh start
# 查看日志,发现日志打印到某一行之后就再也不打印了
[root@test215100 filedepot]# tail -500f log.txt
[INFO] 2024-01-30 18:55:40,822 method:
using logger: com.alibaba.dubbo.common.logger.log4j.Log4jLoggerAdapter
2024-01-30 18:55:40.828  INFO 11451 --- [           main] a.b.d.c.e.WelcomeLogoApplicationListener : 

 :: Dubbo Spring Boot (v0.2.0) : https://github.com/apache/incubator-dubbo-spring-boot-project
 :: Dubbo (v2.6.2) : https://github.com/apache/incubator-dubbo
 :: Google group : dev@dubbo.incubator.apache.org

2024-01-30 18:55:40.834  INFO 11451 --- [           main] e.OverrideDubboConfigApplicationListener : Dubbo Config was overridden by externalized configuration {dubbo.application.name=imodule-filedepot, dubbo.protocol.name=dubbo, dubbo.protocol.port=20802, dubbo.registry.address=zookeeper://10.1.1.4:2181}

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.6.3)

[INFO] 2024-01-30 18:55:40,950 method:org.springframework.boot.StartupInfoLogger.logStarting(StartupInfoLogger.java:55)
Starting ImoduleServiceApplication v1.1.0-SNAPSHOT using Java 1.8.0_92 with PID 11451 (/app/imodule/service/filedepot/imodule-filedepot-service.jar started by imodule in /app/imodule/service/filedepot)
[INFO] 2024-01-30 18:55:40,953 method:org.springframework.boot.SpringApplication.logStartupProfileInfo(SpringApplication.java:637)
No active profile set, falling back to default profiles: default
[INFO] 2024-01-30 18:55:41,704 method:org.springframework.data.repository.config.RepositoryConfigurationDelegate.registerRepositoriesIn(RepositoryConfigurationDelegate.java:132)
Bootstrapping Spring Data MongoDB repositories in DEFAULT mode.
[INFO] 2024-01-30 18:55:41,720 method:org.springframework.data.repository.config.RepositoryConfigurationDelegate.registerRepositoriesIn(RepositoryConfigurationDelegate.java:201)
Finished Spring Data repository scanning in 8 ms. Found 0 MongoDB repository interfaces.
[INFO] 2024-01-30 18:55:41,722 method:org.springframework.data.repository.config.RepositoryConfigurationDelegate.registerRepositoriesIn(RepositoryConfigurationDelegate.java:132)
Bootstrapping Spring Data MongoDB repositories in DEFAULT mode.
[INFO] 2024-01-30 18:55:41,724 method:org.springframework.data.repository.config.RepositoryConfigurationDelegate.registerRepositoriesIn(RepositoryConfigurationDelegate.java:201)
Finished Spring Data repository scanning in 1 ms. Found 0 MongoDB repository interfaces.
[INFO] 2024-01-30 18:55:41,725 method:org.springframework.data.repository.config.RepositoryConfigurationDelegate.registerRepositoriesIn(RepositoryConfigurationDelegate.java:132)
Bootstrapping Spring Data MongoDB repositories in DEFAULT mode.
[INFO] 2024-01-30 18:55:41,727 method:org.springframework.data.repository.config.RepositoryConfigurationDelegate.registerRepositoriesIn(RepositoryConfigurationDelegate.java:201)
Finished Spring Data repository scanning in 1 ms. Found 0 MongoDB repository interfaces.
[INFO] 2024-01-30 18:55:41,736 method:com.alibaba.dubbo.config.spring.context.annotation.DubboConfigBindingRegistrar.registerDubboConfigBean(DubboConfigBindingRegistrar.java:121)
The dubbo config bean definition [name : com.alibaba.dubbo.config.ApplicationConfig#0, class : com.alibaba.dubbo.config.ApplicationConfig] has been registered.
[INFO] 2024-01-30 18:55:41,738 method:com.alibaba.dubbo.config.spring.context.annotation.DubboConfigBindingRegistrar.registerDubboConfigBindingBeanPostProcessor(DubboConfigBindingRegistrar.java:145)
The BeanPostProcessor bean definition [com.alibaba.dubbo.config.spring.beans.factory.annotation.DubboConfigBindingBeanPostProcessor] for dubbo config bean [name : com.alibaba.dubbo.config.ApplicationConfig#0] has been registered.
[INFO] 2024-01-30 18:55:41,738 method:com.alibaba.dubbo.config.spring.context.annotation.DubboConfigBindingRegistrar.registerDubboConfigBean(DubboConfigBindingRegistrar.java:121)
The dubbo config bean definition [name : com.alibaba.dubbo.config.RegistryConfig#0, class : com.alibaba.dubbo.config.RegistryConfig] has been registered.
[INFO] 2024-01-30 18:55:41,738 method:com.alibaba.dubbo.config.spring.context.annotation.DubboConfigBindingRegistrar.registerDubboConfigBindingBeanPostProcessor(DubboConfigBindingRegistrar.java:145)
The BeanPostProcessor bean definition [com.alibaba.dubbo.config.spring.beans.factory.annotation.DubboConfigBindingBeanPostProcessor] for dubbo config bean [name : com.alibaba.dubbo.config.RegistryConfig#0] has been registered.
[INFO] 2024-01-30 18:55:41,739 method:com.alibaba.dubbo.config.spring.context.annotation.DubboConfigBindingRegistrar.registerDubboConfigBean(DubboConfigBindingRegistrar.java:121)
The dubbo config bean definition [name : com.alibaba.dubbo.config.ProtocolConfig#0, class : com.alibaba.dubbo.config.ProtocolConfig] has been registered.
[INFO] 2024-01-30 18:55:41,739 method:com.alibaba.dubbo.config.spring.context.annotation.DubboConfigBindingRegistrar.registerDubboConfigBindingBeanPostProcessor(DubboConfigBindingRegistrar.java:145)
The BeanPostProcessor bean definition [com.alibaba.dubbo.config.spring.beans.factory.annotation.DubboConfigBindingBeanPostProcessor] for dubbo config bean [name : com.alibaba.dubbo.config.ProtocolConfig#0] has been registered.
2024-01-30 18:55:42.139  INFO 11451 --- [           main] c.c.f.f.i.p.DefaultApplicationProvider   : App ID is set to imodule-filedepot-service by app.id property from /META-INF/app.properties
2024-01-30 18:55:42.141  INFO 11451 --- [           main] c.c.f.f.i.p.DefaultServerProvider        : Environment is set to [DEV] by JVM system property 'env'.
2024-01-30 18:55:42.141  INFO 11451 --- [           main] c.c.f.f.i.p.DefaultServerProvider        : Data Center is set to [UAT-88] by JVM system property 'idc'.

服务现在这个状态实在是让人头大,不报错,不挂掉,不往下继续执行,真的是绝了。尝试了多次杀掉进程再重启后发现是徒劳无功。再重试就意义不大了,还是尝试分析问题,解决问题来的实际。查看系统的内存和cpu使用情况。

# 内存这块没看到异常,测试环境主机8G内存,这个java服务本身就用512M,这里看不出问题
[root@test215100 filedepot]# free -h
             total       used       free     shared    buffers     cached
Mem:          7.6G       660M       7.0G       200K        17M       361M
-/+ buffers/cache:       280M       7.3G
Swap:          15G         0B        15G

# 查看cpu使用情况,发现java进程的cpu使用明显异常,占了一个核心的cpu的100%。对于cpu使用异常的情况,可以分析火焰图去定位原因。
[root@test215100 filedepot]# top
PID USER PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+ COMMAND
11451 imodule      20   0  2959m 513m  15m S  100.0  6.6   1:33.01 java

操作系统层面的内存和cpu也看过了,接下来就只能到jvm层面去看了,我能想到的是:
通过jstat -gc pid查看gc的情况,可以看到jvm一直在做gc操作:

通过jmap -dump:format=b,file=/app/head01310854.hprof pid指令生成堆转储信息,使用JProfiler分析:

可以看到此时创建的线程并不多,主要是main线程里一堆的dubbo相关的方法调用。

通过jamp -heap pid查看堆的使用情况:

# 这条指令多次调用,每次Eden的数据都不一样,说明一直在做YGC
[imodule@test215100 app]$ jmap -heap 11451
Attaching to process ID 11451, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.92-b14

using thread-local object allocation.
Parallel GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 536870912 (512.0MB)
   NewSize                  = 178782208 (170.5MB)
   MaxNewSize               = 178782208 (170.5MB)
   OldSize                  = 358088704 (341.5MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 177733632 (169.5MB)
   used     = 156407096 (149.16143035888672MB)
   free     = 21326536 (20.33856964111328MB)
   88.00084386954968% used
From Space:
   capacity = 524288 (0.5MB)
   used     = 196608 (0.1875MB)
   free     = 327680 (0.3125MB)
   37.5% used
To Space:
   capacity = 524288 (0.5MB)
   used     = 0 (0.0MB)
   free     = 524288 (0.5MB)
   0.0% used
PS Old Generation
   capacity = 358088704 (341.5MB)
   used     = 86785784 (82.76537322998047MB)
   free     = 271302920 (258.73462677001953MB)
   24.235834035133372% used

7271 interned Strings occupying 660528 bytes.
[imodule@hkdcl215100 app]$ jmap -heap 11451
Attaching to process ID 11451, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.92-b14

using thread-local object allocation.
Parallel GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 536870912 (512.0MB)
   NewSize                  = 178782208 (170.5MB)
   MaxNewSize               = 178782208 (170.5MB)
   OldSize                  = 358088704 (341.5MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 177733632 (169.5MB)
   used     = 53320728 (50.850608825683594MB)
   free     = 124412904 (118.6493911743164MB)
   30.000359189193862% used
From Space:
   capacity = 524288 (0.5MB)
   used     = 196608 (0.1875MB)
   free     = 327680 (0.3125MB)
   37.5% used
To Space:
   capacity = 524288 (0.5MB)
   used     = 0 (0.0MB)
   free     = 524288 (0.5MB)
   0.0% used
PS Old Generation
   capacity = 358088704 (341.5MB)
   used     = 86834936 (82.81224822998047MB)
   free     = 271253768 (258.68775177001953MB)
   24.249560243039667% used

7271 interned Strings occupying 660528 bytes.

通过jstack pid指令打印Java进程的栈的使用情况:

# 通过jstack生成栈信息,然后重定向到jstack.log文件中
[imodule@test215100 bin]$ jstack pid > /app/jstack.log
[imodule@test215100 bin]$ cat /app/jstack.log
# 这里也可以看到一堆dubbo相关的内容
2024-01-30 20:42:05
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.92-b14 mixed mode):

"Attach Listener" #13 daemon prio=9 os_prio=0 tid=0x00007f6a5c001000 nid=0x40aa waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007f6a8c18e800 nid=0x2cc8 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f6a8c183000 nid=0x2cc7 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f6a8c181800 nid=0x2cc6 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f6a8c17e800 nid=0x2cc5 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f6a8c17d000 nid=0x2cc4 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f6a8c14a000 nid=0x2cc3 in Object.wait() [0x00007f6a76bf4000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000e03b8448> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
	- locked <0x00000000e03b8448> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f6a8c145800 nid=0x2cc2 in Object.wait() [0x00007f6a76cf5000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000e03b84e0> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000000e03b84e0> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007f6a8c008800 nid=0x2cbc runnable [0x00007f6a91b3a000]
   java.lang.Thread.State: RUNNABLE
	at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
	at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
	at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
	at java.net.InetAddress.getLocalHost(InetAddress.java:1500)
	- locked <0x00000000e0258e98> (a java.lang.Object)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:188)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:193)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:220)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:220)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.error(FailsafeLogger.java:134)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:222)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:193)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:220)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:193)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:220)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:220)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:193)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	...
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress0(NetUtils.java:193)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalAddress(NetUtils.java:180)
	at com.alibaba.dubbo.common.utils.NetUtils.getLocalHost(NetUtils.java:146)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.appendContextMessage(FailsafeLogger.java:40)
	at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:110)

"VM Thread" os_prio=0 tid=0x00007f6a8c13d800 nid=0x2cc1 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f6a8c01d800 nid=0x2cbd runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f6a8c01f800 nid=0x2cbe runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f6a8c021800 nid=0x2cbf runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f6a8c023000 nid=0x2cc0 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f6a8c191800 nid=0x2cc9 waiting on condition 

JNI global references: 877

分析到这里,除了能看出来main线程里一直在做dubbo相关的操作,然后导致gc以外其他啥也看不出来,正常情况下,系统是要先去访问apollo配置中心,读取配置数据的,现在并没有看到访问配置中心和读取配置的情况。咨询了一个朋友,说是可以在服务器上安装Arthas(阿尔萨斯)来分析,还可以用debug模式启动jar包,然后在本地远程断点调试JVM,同样,也可以走读源码,对相关的关键节点做AOP增强,打印一些关键日志,这就有3种方式可以调试了,到这个时候已经很晚了,先下班,让这个进程先跑一晚上,看看明天是个啥情况。

一大早回来,第一时间查看进程,发现还是老样子,cpu100%,疯狂gc,打了关键日志,这就很惊喜了,赶紧看看。

关键的这一行**[DUBBO] Could not get local host ip address,will use 127.0.0.1 instead.. **,摇了个负责系统的同事看了下,猜测可能是DNS无法通过主机名解析到ip地址导致的,尝试在/etc/hosts中添加主机名的ip地址解析,如下:

[root@test215138 bin]# cat /etc/hosts
127.0.0.1   localhost localhost.localdomain localhost4 localhost4.localdomain4
::1         localhost localhost.localdomain localhost6 localhost6.localdomain6
10.6.1.1 test215138

修改完这个配置之后再重启服务,服务正常运行,问题解决。

参考资料

对于cpu使用率100%的情况,一般情况都是生成一些cpu的数据,把数据转换成火焰图去分析。这里因为没实际操作过,且这个问题分析火焰图可能意义不是太大,就没实操,仅记录一些资料。
1.linux perf生成火焰图,火焰图:全局视野的Linux性能剖析 (opens new window)
2.火焰图生成与分析 (opens new window)
对于java进程的分析,可以通过在服务器上部署Arthas进行分析:
1.Arthas(阿尔萨斯) 的安装与使用 (opens new window)
对于测试环境的java进程,我们同样可以在本地进行调试,只需要在启动jar包的时候开启debug调试功能即可,记住,jvm也是允许你调试的。
1.JVM 断点调试和远程调试 (opens new window)

# 原因分析

正常情况下,代码执行的先后顺序是先加载apollo配置,读取到配置后,会将配置缓存到一个文件路径中,现在并没有看到apollo相关的操作,而是直接看到dubbo一直在请求,说明apollo的相关配置也出了问题,查看源码,看到如下配置:

可以看到Apollo的注解是首先被执行的,这个注解的处理器具体在哪里有时间再细看一下,推测这个注解的处理器并没有完成它的功能,也没报错(异常原因同样是主机名解析ip地址的问题),Spring就接着往下执行了。

# 运维事件发生-生产环境OOM(Heap内存参数设置过小)

# 事件描述

生产环境docker容器中的java进程OOM,分析原因后发现是Heap内存参数设置过小导致。

# 事件处理

发版完成后的验证阶段,生产环境突然开始报错,报错的原因是后端某个服务不可用。该服务基于docker容器部署,到环境上查看docker容器,发现容器还在运行,进入容器查看java进程,发现进程消失。查找相关日志,发现java进程出现了OOM。
获取OOM后jvm生成的hprof堆转储文件,使用JProfiler进行分析。

确认了dump无异常后,查看thread dump,往下滚动,看到有个关键线程OOM。

看到线程中的nio关键字,我下意识以为是nio操作了什么大文件导致直接内存不够用出现OOM,查了下发现不是这么回事。这里的nio实际上是指通过tomcat请求创建的线程。
经过一段时间的了解,发现ThreadDump指的是每个线程的Dump堆内存使用情况,与Current Object Set一起分析堆,可以说,现在出现OOM的原因就是堆内存不够,这个就是结论。
问题是为啥才用了400MB就堆内存不够了呢,这个太诡异了,查看jar包的启动参数,差点吐血身亡。其中最关键的堆大小分配参数-Xms256m -Xmx256m,仅仅分配了256m,一个生产环境的服务不应该只分配这么点的堆内存。调整参数为-Xms2048m -Xmx2048m后问题解决。服务不再出现OOM报错。

# 运维事件发生-生产环境OOM(MetaSpace内存参数设置过小)

# 事件描述

生产环境docker容器中的java进程OOM,分析原因后发现是MetaSpace内存参数设置过小导致。

# 事件处理

一大早,业务反馈生产环境企业微信侧自建应用入口无法访问系统,分析相关日志定位,报错的原因是后端某个服务不可用。该服务基于docker容器部署,到环境上查看docker容器,发现容器还在运行,进入容器查看java进程,发现进程消失。查找相关日志,发现java进程出现了OOM。
获取OOM后jvm生成的hprof堆转储文件,使用JProfiler进行分析。


堆内存这块看不出什么问题,看日志里的报错,可以看到MetaSpace元空间的报错信息:

查看进程的jvm启动参数,-XX:MetaspaceSize=128m,-XX:MaxMetaspaceSize=128m,这两个元空间的参数设置的太小,修改为512m即可。验证后没有再出现OOM。问题解决。

# 运维事件发生-生产环境OOM(Heap堆内存溢出)

# 事件描述

生产环境docker容器中的java进程OOM,分析原因后发现是堆内存溢出。

# 事件处理

生产环境OOM,已经生成了相关的hprof文件,获取到堆转储文件后,使用Jprofiler工具分析。
查看线程栈情况,可以看到有一个线程触发了OOM。

查看堆栈情况,可以看到此时堆栈大小为2107M

查看java进程启动的堆分配信息,可以看到,分配的堆内存大小为-Xms2048m -Xmx2048m,堆内存固定位2048M,因此这次OOM是一个典型的堆内存溢出。

分析堆中的大文件,发现hibernate的一个方法很大,几乎占了近2个G的内存,百度了一下,找到一个文档hibernate QueryPlanCache 引发的heap区内存溢出 (opens new window)。文章里讲的很详细,问题产生的原因是Hibernate会缓存sql,使用了in语句,混用占位符和字符拼接均会导致堆内存过大,最终触发OOM,这里参照文章定位及优化即可。

# 运维事件发生-应用服务不打印日志

# 事件描述

业务反馈某个不常用的测试环境通过API网关调用接口报错(业务性报错),需要网关系统协同分析。

# 事件处理

按说这种业务性的报错API网关不需要关注,但是这个业务场景是A(网关)->B系统接口->C(本项目组的另外一个系统),B系统接口报错不要紧,关键是它报的是C提供异常(B系统和C系统通过dubbo调用)。这就必须要一起看了。
首先看接口调用的请求及响应信息,响应状态码200,响应体{"data":null,"retCode":"000001","retMsg":"文件上传FTP失败"},这个经B系统抛出来的C系统的错误就很奇怪了,登录C系统主机查看日志,没看到任何异常。没有异常为啥B系统要报C系统的错呢。
通过网关查看B系统服务的真实IP端口,因为是测试环境,C系统的数据库组件也部署在相同主机上,因此直接登录操作系统查看。
在主机上查看相应端口,发现服务正常运行,通过ps指令找到对应进程的jar包,找到jar包中的log4j文件,进而找到具体的日志目录。这个时候就看到一个诡异的事情了,今天的error,info,warn,debug日志均是0kb大小。因此无法查看B系统的报错日志。
明明服务起的好好的,调用也会返回,为啥就是不打日志呢?看到这里真的是脑瓜子嗡嗡的,也不是自己的服务,一度怀疑找错了日志文件目录,查看应用的启动脚本,nohup java -jar $JAR_NAME > /dev/null 2>&1 &,这一块看起来很可疑,是不是把应用日志重定向到/dev/null垃圾桶了呢,问了下同事,也不是,这个脚本的意思只是把nohup的信息重定向到/dev/null,不影响系统自身的日志。
要不是对应服务负责人今天请假不在了,早摇起来让他去看了,今天服务相关负责人看了一眼,说是磁盘空间满了,真的是绝了,亏我分析半天。这里仅记录一下,关于对应系统负责人是怎么分析出磁盘空间满了的,就不得而知了。

# 运维事件发生-Springboot项目不打印启动日志

# 事件描述

最近生产环境我负责的服务出现了磁盘空间85%使用率的告警,经定位排查,发现是有两个服务的日志文件分别是100G以及200G,十分的诡异,经仔细分析启动脚本,发现启动脚本使用如下:

[root@test215138 bin]#
nohup java -Xms512m -Xmx512m -jar  -Dfile.encoding=UTF-8  test.jar > log.log 2>&1 &

这个脚本诡异的地方在于把进程的正常日志和报错日志多重定向到了当前目录下的log.log文件,另外一个进程也同理。如果直接删除这些大文件,并不能释放磁盘空间(因文件本身被进程占用,虽然文件可以删除,但是磁盘空间并不会释放)。
我们来接着说上面的脚本有什么问题,下面我们看一个正常的脚本:

[root@test215138 bin]#
nohup java -Xms512m -Xmx512m -jar  -Dfile.encoding=UTF-8  test.jar > /dev/null 2>&1 &

可以看到正常的启动脚本会将进程产生的日志重定向到/dev/null,也就是垃圾桶。实在是不理解我这个服务为什么将进程日志重定向到一个文件,而且这个文件越来越大,最终磁盘空间不足触发告警。
接下来去看应用日志,发现应用日志文件夹下存在10个log文件,分别是log.log,log1.log...log9.log,且每个日志文件大小11M,这个也是诡异的不行。
查看项目源码的提交记录,发现项目初期的开发负责人还在,咨询之后反馈的结果是这个项目本身不怎么需要看日志,因此配置了日志在10个文件里循环覆盖的策略。
考虑对该服务进行优化,调整日志文件生成策略,改成每天生成一个日志文件的策略,因此,需要修改日志文件的配置。该服务用的日志策略是log4j,修改完配置后在测试环境启动服务,查看进程是否存在,查看http端口是否正常使用,通过postman验证业务接口是否正常,业务正常。当天干的头晕,赶紧溜了(此时一个呆瓜还没有注意到他遗漏了一个天大的问题)。
第二天回来公司验证,发现日志正常归档,修改十分成功,提交测试,走流程,等待预生产发布。
很快就到了预生产发布环节,将代码部署到预生产环境,启动项目,查看进程发现存活,查看端口,发现端口不存在???我的端口呢,看看日志是谁偷了。这一看不得了,日志文件里压根没有springboot的启动日志。这个发现直接把我吓成了一个sb,马上上生产,项目挂了,挂了还连日志都看不到,这尼玛是什么情况呀。
这时候总算知道为啥前面给生产埋坑(大日志文件)的同学为啥这么玩了,8成也是踩了项目不打印日志的坑才将/dev/null改成log.log的吧。尝试修改回去log.log,果然在这个文件里看到了springboot的启动日志,同时看到了项目报错原因。项目报错看了日志直接就解决了,这个不难,问题是,谁偷了我的启动日志?
一开始怀疑是日志文件配置有问题,log4j说实话我是用的真的少,我实际参与的项目都是用的logback,当然也有用log4j的,问题在于这些文件都是写一次用一世,过久了就要看看注释,这个项目还偏偏日志配置一行注释不写,各种查资料,生啃了几个小时,把log4j的东西重新捡起来,写demo各种尝试,反正启动日志就是出不来。
查资料突然看到springboot默认使用logback作为日志方案,就感觉眼前一亮,8成是这个原因。在跑了多个demo之后,终于重现了问题,且在demo里修复了问题,没错,就是因为我的项目升级成了springboot,但是项目负责人又因为各种原因没修改log4j的日志配置文件(我猜也是没注意到,8成也是项目跑起来先看进程,后看端口占用,跟着就怼业务接口去了),然后后续运维同学可能又不是太懂开发/没权限改代码/没时间分析这个问题的根因,干脆把进程日志重定向到log.log就完事了,反正能看到springboot启动日志没报错就行。

# 事件处理

因本版本剩余时间有限,若修改日志组件必然涉及到pom文件中jar包依赖的改动,故本版本暂不处理,后续版本将项目日志组件从log4j升级到logback即可从根本上解决这个异常。