企业级线上故障排查思路

最新推荐文章于 2024-07-25 14:31:34 发布

不要飞升

最新推荐文章于 2024-07-25 14:31:34 发布

阅读量902

点赞数 9

分类专栏：学校里学不到的杂七杂八文章标签： java 实习

本文链接：https://blog.csdn.net/qq_45477639/article/details/140621862

版权

学校里学不到的杂七杂八专栏收录该内容

3 篇文章 0 订阅

订阅专栏

线上故障排查思路

WARNING

简介：有哪些常见的线上故障？如何快速定位问题？本文详细总结工作中的经验，从服务器、Java应用、数据库、Redis、网络和业务六个层面分享线上故障排查的思路和技巧。较长，同学们可收藏后再看。

线上定位问题时，主要靠监控和日志。一旦超出监控的范围，则排查思路很重要，按照流程化的思路来定位问题，能够让我们在定位问题时从容、淡定，快速的定位到线上的问题。

在这里插入图片描述

一、服务器

1、磁盘

问题现象： 当磁盘容量不足的时候，应用时常会抛出如下的异常信息：

java.io.IOException: 磁盘空间不足

或者类似如下警告信息：

在这里插入图片描述

排查思路：【1】利用df -h查询磁盘状态： 可知/路径下占用量最大。

参数	说明
-a	列出所有文件系统
-h	使用人类可读的样式，按照1024的进制
-H	和-h一致，按照 1000的进制

在这里插入图片描述

参数	说明
Filesystem	文件系统
Size	容量
Used	使用量
Avail	可用量
Use%	使用率

【2】利用du -sh \*查看文件夹大小： 可知root文件夹占用空间最大，然后层层递推找到对应的最大的一个或数个文件夹。

参数	说明
-s	仅显示总值
-h	使用人类可读的样式，按照1024的进制

在这里插入图片描述

【3】利用ls -lh查看文件大小： 可以找到最大的文件是日志文件，然后使用rm指令进行移除以释放磁盘。

启动参数	说明
-l	仅显示总值
-h	使用人类可读的样式，按照1024的进制

进程内指令参数	说明
H	以线程的维度进行查看
N	按照`pid`进行排序
M	按照内存使用率进行排序
P	按照`CPU`使用率进行排序

在这里插入图片描述

2、CPU 过高

问题现象： 当CPU过高的时候，接口性能会快速下降，同时监控也会开始报警。

排查思路：【1】利用top查询CPU使用率最高的进程: 从而可以得知pid为14201的进程使用CPU最高。

参数	说明
-n	指定top结果输出的次数
-p	指定需要查看的进程pid

在这里插入图片描述

参数	说明
PID	进程ID
USER	进程所有者的用户名称
PR	进程的动态优先级
NI	进程的静态优先级
VIRT	使用的虚拟内存数量
RES	使用的物理内存数量
SHR	使用的共享内存数量
S	进程状态：D:不可中断的睡眠状态 R:运行 S:睡眠 T:跟踪/停止 Z：僵尸进程
%CPU	使用的cpu使用率
%MEM	使用的内存使用率
TIME+	进程使用的cpu累计时长
COMMAND	启动进程使用的命令行

二、应用层面

1、Tomcat 假死案例

发现问题： 监控平台发现某个Tomcat节点已经无法采集到数据，连上服务器查看服务器进程还在，netstat -anop|grep 8001端口也有监听，查看日志打印时断时续。

在这里插入图片描述

查询日志： 查看NG日志，发现有数据进入到当前服务器（有8001和8002两个Tomcat），NG显示8002节点访问正常，8001节点有404错误打印，说明Tomcat已经处于假死状态，这个Tomcat已经不能正常工作了。

过滤Tomcat节点的日志，发现有OOM的异常,但是重启后，有时候Tomcat挂掉后，又不会打印如下OOM的异常：

TopicNewController.getTopicSoftList() error="Java heap space 
From class java.lang.OutOfMemoryError"appstore_apitomcat

获取内存快照： 在一次OOM发生后立刻抓取内存快照,需要执行命令的用户与JAVA进程启动用户是同一个，否则会有异常：

/data/program/jdk/bin/jmap -dump:live,format=b,file=/home/www/jmaplogs/jmap-8001-2.bin 18760

ps -ef|grep store.cn.xml|grep -v grep|awk '{print $2}'|xargs /data/program/jdk-1.8.0_11/bin/jmap -dump:live,format=b,file=api.bin

内存dump文件比较大，有1.4G，先压缩，然后拉取到本地用7ZIP解压。linux压缩dump为.tgz。在windows下用7zip需要经过2步解压：

.bin.tgz---.bin.tar--.bin

分析内存快照文件: 使用Memory Analyzer解析dump文件，发现有很明显的内存泄漏提示。

在这里插入图片描述

点击查看详情，发现定位到了代码的具体某行，一目了然：

在这里插入图片描述

查看shallow heap与retained heap能发现生成了大量的Object(810325个对象)，后面分析代码发现是上报softItem对象超过300多万个对象，在循环的时候，所有的数据全部保存在某个方法中无法释放，导致内存堆积到1.5G，从而超过了JVM分配的最大数，从而出现OOM。

在这里插入图片描述

java.lang.Object[810325] @ 0xb0e971e0

在这里插入图片描述

不要在线上使用jmap手动抓取内存快照，其一系统OOM时手工触发已经来不及，另外在生成dump文件时会占用系统内存资源，导致系统崩溃。只需要在JVM启动参数中提取设置如下参数，一旦OOM触发会自动生成对应的文件，用MAT分析即可。

# 内存OOM时，自动生成dump文件 
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/

如果Young GC比较频繁，5S内有打印一条，或者有Old GC的打印，代表内存设置过小或者有内存泄漏，此时需要抓取内存快照进行分享。

2、应用 CPU过高

问题发现： 监控告警提示

在这里插入图片描述

查找问题进程: 利用top查到占用cpu最高的进程pid为14，结果图如下：

在这里插入图片描述

查找问题线程: 利用top -H -p查看进程内占用cpu最高线程，从下图可知，问题线程主要是activeCpu Thread，其pid为417。

在这里插入图片描述

查询线程详细信息:
● 首先利用printf "%x n"将tid换为十六进制：xid。
● 再利用jstack | grep nid=0x -A 10查询线程信息(若进程无响应，则使用jstack -f)，信息如下：

在这里插入图片描述

分析代码： 由上一步可知该问题是由CpuThread.java类引发的，故查询项目代码，获得如下信息：根据代码和日志分析，可知是由于限制值max太大，致使线程长时间循环执行，从而导致问题出现。

public class CpuThread extends Thread {
    private int max = Integer.MAX_VALUE;
    private long sleepTime;

    public CpuThread(String name, long sleepTime){
        setName(name);
        this.sleepTime = sleepTime;
    }

    @Override
    public void run() {
        int i = 0;

        while(true) {
            try {
                Thread.sleep(sleepTime);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            i = i++;
            if (i >= max) {
                return
            }
        }
    }
}

三、MySql

1、死锁

发现问题： 最近线上随着流量变大，突然开始报如下异常，即发生了死锁问题：

Deadlock found when trying to get lock; try restarting transaction ;

问题分析：【1】查询事务隔离级别： 利用select @@tx_isolation命令获取到数据库隔离级别信息：

MySQL [(none)]> select @@tx_isolation
+-------------------+
|  @@tx_isolation   |
+-------------------+
|  READ-COMMITTED   |
+-------------------+

【2】查询数据库死锁日志： 利用show engine innodb status命令获取到如下死锁信息：

在这里插入图片描述

由上可知，是由于两个事物对这条记录同时持有S锁(共享锁)的情况下，再次尝试获取该条记录的X锁(排它锁)，从而导致互相等待引发死锁。

【3】分析代码： 根据死锁日志的SQL语句，定位获取到如下伪代码逻辑：

@Transactional(rollbackFor = Exception.class)
void saveOrUpdate(MeetingInfo info) {
    // insert ignore into table values (...)
    int result = mapper.insertIgnore(info);
    if (result>0) {
       return;
    }
    // update table set xx=xx where id = xx
    mapper.update(info);
}

【4】获得结论： 分析获得产生问题的加锁时序如下，然后修改代码实现以解决该问题。

在这里插入图片描述

2、慢 SQL

发现问题： 应用TPS下降，并出现SQL执行超时异常或者出现了类似如下的告警信息，则常常意味着出现了慢SQL。

在这里插入图片描述

问题分析：分析执行计划： 利用explain指令获得该SQL语句的执行计划，根据该执行计划，可能有两种场景。
■ SQL不走索引或扫描行数过多等致使执行时长过长。
■ SQL没问题，只是因为事务并发导致等待锁，致使执行时长过长。

【1】场景一：优化SQL: 通过增加索引，调整SQL语句的方式优化执行时长，例如下的执行计划：

在这里插入图片描述

该SQL的执行计划的type为ALL，同时根据以下type语义，可知无索引的全表查询，故可为其检索列增加索引进而解决。

在这里插入图片描述

【2】场景二：查询当前使用情况: 可以通过查看如下3张表做相应的处理

-- 当前运行的所有事务
select *  from information_schema.innodb_trx;
-- 当前出现的锁
SELECT * FROM information_schema.INNODB_LOCKS;
-- 锁等待的对应关系
select *  from information_schema.INNODB_LOCK_WAITS;

在这里插入图片描述

查看事务锁类型索引的详细信息：lock_table字段能看到被锁的索引的表名，lock_mode可以看到锁类型是X锁,lock_type可以看到是行锁record。

在这里插入图片描述

分析： 根据事务情况，得到表信息，和相关的事务时序信息：

DROP TABLE IF EXISTS `emp`;
CREATE TABLE `emp` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`salary` int(10) DEFAULT NULL,
`name` varchar(255) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `idx_name` (`name`(191)) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=6 DEFAULT CHARSET=utf8mb4;

A事物锁住一条记录，不提交，B事物需要更新此条记录，此时会阻塞，如下图是执行顺序：

在这里插入图片描述

解决方案：
【1】修改方案： 由前一步的结果,分析事务间加锁时序，例如可以通过tx_query字段得知被阻塞的事务SQL,trx_state得知事务状态等，找到对应代码逻辑，进行优化修改。
【2】临时修改方案： trx_mysql_thread_id是对应的事务sessionId，可以通过以下命令杀死长时间执行的事务，从而避免阻塞其他事务执行。

kill 105853

3、连接数过多

发现问题： 常出现too many connections异常,数据库连接到达最大连接数。

解决方案： 通过set global max_connections=XXX增大最大连接数。先利用show processlist获取连接信息，然后利用kill杀死过多的连。常用脚本如下：

#排序数据库连接的数目 
mysql -h127.0.0.0.1 -uabc_test -pXXXXX -P3306 -A -e 'show processlist'| awk '{print $4}'|sort|uniq -c|sort -rn|head -10

四、Redis

在这里插入图片描述

1、内存告警

时常会出现下述异常提示信息：

OOM command not allowed when used memory

设置合理的内存大小： 设置maxmemory和相对应的回收策略算法，设置最好为物理内存的3/4，或者比例更小，因为redis复制数据等其他服务时，也是需要缓存的。以防缓存数据过大致使redis崩溃，造成系统出错不可用。

【1】通过redis.conf配置文件指定

maxmemory xxxxxx

【2】通过命令修改

config set  maxmemory xxxxx

设置合理的内存淘汰策略：

在这里插入图片描述

通过redis.conf配置文件指定

maxmemory-policy allkeys-lru

【3】查看大key：有工具的情况下：安装工具dbatools redisTools，列出最大的前N个key

/data/program/dbatools-master/redisTools/redis-cli-new -h <ip> -p <port> --bigkeys --bigkey-numb 3

得到如下结果:

Sampled 122114 keys in the keyspace!
Total key length in bytes is 3923725 (avg len 32.13)


Biggest string Key Top   1  found 'xx1' has 36316 bytes
Biggest string Key Top   2  found 'xx2' has 1191 bytes
Biggest string Key Top   3  found 'xx3' has 234 bytes
Biggest   list Key Top   1  found 'x4' has 204480 items
Biggest   list Key Top   2  found 'x5' has 119999 items
Biggest   list Key Top   3  found 'x6' has 60000 items
Biggest    set Key Top   1  found 'x7' has 14205 members
Biggest    set Key Top   2  found 'x8' has 292 members
Biggest    set Key Top   3  found 'x,7' has 21 members
Biggest   hash Key Top   1  found 'x' has 302939 fields
Biggest   hash Key Top   2  found 'xc' has 92029 fields
Biggest   hash Key Top   3  found 'xd' has 39634 fields

原生命令为：

/usr/local/redis-3.0.5/src/redis-cli -c -h <ip> -p <port> --bigkeys

分析rdb文件中的全部key/某种类型的占用量：

rdb -c memory dump.rdb -t list -f dump-formal-list.csv

查看某个key的内存占用量：

[root@iZbp16umm14vm5kssepfdpZ redisTools]# redis-memory-for-key  -s <ip> -p <port> x
Key             x
Bytes               4274388.0
Type                hash
Encoding            hashtable
Number of Elements      39634
Length of Largest Element   29

无工具的情况下可利用以下指令评估key大小：

debug object key

2、Redis的慢命令

设置Redis的慢命令的时间阈值(单位：微妙)

【1】通过redis.conf配置文件方式

# 执行时间大于多少微秒(microsecond，1秒 = 1,000,000 微秒)的查询进行记录。
slowlog-log-lower-than 1000

# 最多能保存多少条日志
slowlog-max-len 200

【2】通过命令方式

slowlog get

查看Redis的慢命令

slowlog get

3、连接过多

【1】通过redis.conf配置文件指定最大连接数

maxclients 10000

【2】通过命令修改

config set maxclients xxx

4、线上Redis节点挂掉一个之后的处理流程

【1】查看节点状态： 执行cluster nodes后发现会有一个节点dead

[rgp@iZ23rjcqbczZ ~]$ /data/program/redis-3.0.3/bin/redis-cli -c -h <ip> -p <port>
ip:port> cluster nodes
9f194f671cee4a76ce3b7ff14d3bda190e0695d5 m1 master - 0 1550322872543 65 connected 10923-16383
a38c6f957f2706f269cf5d9b628586a9372265e9 s1 slave 9f194f671cee4a76ce3b7ff14d3bda190e0695d5 0 1550322872943 65 connected
77ce43ec23f25f77ec68fe71ae3cb799e7300c6d s2 slave 03d72a3a5050c85e280e0bbeb687056b84f10077 0 1550322873543 63 connected
03d72a3a5050c85e280e0bbeb687056b84f10077 m2 master - 0 1550322873343 63 connected 5461-10922
5799070c6a63314296f3661b315b95c6328779f7 :0 slave,fail,noaddr 6147bf416ef216b6a1ef2f100d15de4f439b7352 1550320811474 1550320808793 49 disconnected
6147bf416ef216b6a1ef2f100d15de4f439b7352 m3 myself,master - 0 0 49 connected 0-5460

【2】移除错误节点：

（1）一开始执行如下的删除操作失败，需要针对于每一个节点都执行cluster forget：

ip:port> cluster forget 61c70a61ad91bbac231e33352f5bdb9eb0be6289
CLUSTER FORGET <node_id> 从集群中移除 node_id 指定的节点

（2）删除挂掉的节点：

[rgp@iZ23rjcqbczZ ~]$ /data/program/redis-3.0.3/bin/redis-trib.rb del-node m3 b643d7baa69922b3fdbd1e25ccbe6ed73587b948
>>> Removing node b643d7baa69922b3fdbd1e25ccbe6ed73587b948 from cluster m3
>>> Sending CLUSTER FORGET messages to the cluster...
>>> SHUTDOWN the node.

（3）清理掉节点配置目录下的rdb aof nodes.conf等文件，否则节点的启动会有如下异常：

[ERR] Node s3 is not empty. Either the node already knows other nodes (check with CLUSTER NODES) or contains some key in database 0.

【3】恢复节点：

（1）后台启动Redis某个节点：

/data/program/redis-3.0.3/bin/redis-server /data/program/redis-3.0.3/etc/7001/redis.conf &

（2）将该节点添加进集群：

[root@iZ23rjcqbczZ rgp]# /data/program/redis-3.0.3/bin/redis-trib.rb add-node  --slave --master-id 6147bf416ef216b6a1ef2f100d15de4f439b7352 s3 m3
>>> Adding node s3 to cluster m3
>>> Performing Cluster Check (using node m3)
M: 6147bf416ef216b6a1ef2f100d15de4f439b7352 m3
   slots:0-5460 (5461 slots) master
   0 additional replica(s)
M: 9f194f671cee4a76ce3b7ff14d3bda190e0695d5 m1
   slots:10923-16383 (5461 slots) master
   1 additional replica(s)
S: a38c6f957f2706f269cf5d9b628586a9372265e9 s1
   slots: (0 slots) slave
   replicates 9f194f671cee4a76ce3b7ff14d3bda190e0695d5
S: 77ce43ec23f25f77ec68fe71ae3cb799e7300c6d s2
   slots: (0 slots) slave
   replicates 03d72a3a5050c85e280e0bbeb687056b84f10077
M: 03d72a3a5050c85e280e0bbeb687056b84f10077 m2
   slots:5461-10922 (5462 slots) master
   1 additional replica(s)
[OK] All nodes agree about slots configuration.
>>> Check for open slots...
>>> Check slots coverage...
[OK] All 16384 slots covered.
>>> Send CLUSTER MEET to node s3 to make it join the cluster.
Waiting for the cluster to join..
>>> Configure node as replica of m3.
[OK] New node added correctly.

● s3:本次待添加的从节点ip：port
● m3:主节点的ip：port
● 6147bf416ef216b6a1ef2f100d15de4f439b7352：主节点编号

五、网络

排查流程

现象出现： 在非压测或者高峰期的情况下，突然出现大量的503等错误码，页面无法打开。

查看是否遭受了DOS攻击： 当Server上有大量半连接状态且源IP地址是随机的，则可以断定遭到SYN攻击了，使用如下命令可以让之现行。

netstat -n|grep SYN_RECV

查看TCP连接状态：

【1】首先利用以下查看tcp总连接数，判断连接数是否正常：

netstat -nat | grep -i "80" | wc -l

【2】然后利用如下命令判断各个状态的连接数是否正常：

netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'

【3】根据上述信息，如果TIME_WAIT状态数量过多，可利用如下命令查看连接CLOSE_WAIT最多的IP地址，再结合业务分析问题：

netstat -n|grep TIME_WAIT|awk '{print $5}'|awk -F: '{print $1}'|sort|uniq -c|sort -nr|head -10

六、业务异常日志

出现问题： 主要是通过业务日志监控主动报警或者是查看错误日志被动发现：

在这里插入图片描述

日志分析： 日志格式如下：

<property name="METRICS_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS}|${APP_NAME}|%X{className}|%X{methodName}|%X{responseStatus}|%X{timeConsume}|%X{traceId}|%X{errorCode}|%msg%n"/>


 <property name="ERROR_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%X{traceId}|${APP_NAME}|%serverIp|%X{tenantId}|%X{accountId}|%thread|%logger{30}|%msg%n"/>


<!--日志格式 时间|级别|链路id|应用名|服务器ip|租户id|用户id|线程名称|logger名称|业务消息 -->
<property name="BIZ_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%X{traceId}|${APP_NAME}|%serverIp|%X{tenantId}|%X{accountId}|%thread|%logger{30}|%msg%n"/>

在日志文件中检索异常： 利用如下命令可获得异常的详细信息

cat error.log|grep -n " java.lang.reflect.InvocationTargetException"

在这里插入图片描述

根据日志格式和日志信息，可获得traceId为489d71fe-67db-4f59-a916-33f25d35cab8，然后利用以下指令获取整个流程的日志信息：

cat biz.log |grep -n '489d71fe-67db-4f59-a916-33f25d35cab8'

在这里插入图片描述

代码分析： 然后根据上述流程日志找到对应的代码实现，然后进行具体的业务分析。

不要飞升

关注

9
点赞
踩
12

收藏

觉得还不错? 一键收藏
0
评论
企业级线上故障排查思路

一旦超出监控的范围，则排查思路很重要，按照流程化的思路来定位问题，能够让我们在定位问题时从容、淡定，快速的定位到线上的问题。上有大量半连接状态且源IP地址是随机的，则可以断定遭到SYN攻击了，使用如下命令可以让之现行。个对象，在循环的时候，所有的数据全部保存在某个方法中无法释放，导致内存堆积到。类引发的，故查询项目代码，获得如下信息：根据代码和日志分析，可知是由于限制值。的打印，代表内存设置过小或者有内存泄漏，此时需要抓取内存快照进行分享。过高的时候，接口性能会快速下降，同时监控也会开始报警。
复制链接

扫一扫