线上基础问题排查常用手册

2024-03-01 08:38:04

线上基础问题排查常用手册

问题分类

业务问题

日志排查
代码逻辑排查
配置排查

性能问题

接口问题
JVM问题
Redis问题
MySQL问题
系统问题

实施手段

日志排查

阿里云

参考： https://help.aliyun.com/document_detail/29060.html?spm=5176.2020520112.2.1.28bb34c0daZmJB

短语查询
	查询包含foo的词
	"foo"
使用模糊查询	
	查询包含foo前缀的词	
	foo*
使用全文查询	
	查询任何字段中包含foot的日志	
	foot
使用字段查询	
	查询message字段包含foot的日志	
	message:foot
使用数字范围查询	
	查询status范围在400（包含）到499（包含）
	（注意，数值查询，需要把字段定义成long或double类型）	
	status in [400 499] 或者 status ≥400 and status ≤499
组合查询	
	查询status范围在400（包含）到499（包含），并且message包含foot	
	status ≥400 and status ≤499 and message:foot

本地日志

# 本地日志可能非常大，所以正常需要根据需要来过滤数据
# 如果直接打开超大文件，可能会导致一些问题，比如： 假死
# 指定显示行数
cat test.log | tail -n 20 # 显示20行

# 查找包括Exception字符串的行
cat test.log | grep "Exception"
# 指定行数，避免过大
cat test.log | grep "Exception" | tail -n 20
# and 查找包括Exception与java:81
cat test.log | grep "Exception" | grep "java:81"
# or 查找包括Exception或RequestMappingHandlerAdapter
cat test.log | grep -E "Exception|RequestMappingHandlerAdapter"

# 统计相关
# 统计Exception数量 
cat test.log | grep "Exception" | wc -l

代码逻辑排查

本地代码

单元测试
请求回放
断点

线上代码

# arthas 下载&安装祥见附录1
# jad 参考: https://arthas.gitee.io/jad.html
# 功能：反编译代码。 可以直观的确认当前运行版本代码
# 解决：提交了，不知道为什么没有作用？
jad com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor
# 将编译代码输出
jad com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor > /tmp/APIHandlerInterceptor.java

配置排查

# arthas 下载&安装祥见附录1
# 解决：配置没有生效？ 现在有配置是什么样的？

静态配置类&枚举类

# arthas 下载&安装祥见附录1
# ognl 参考: https://arthas.gitee.io/ognl.html
ognl "@com.nascent.ecrpsaas.openplatform.enums.GlobalsEnums@SYSTEM_ERROR.getMsg()"

获取SpringBean对象

比如项目中，配置了一个SpringBean对象

<!-- activeMq的连接池 -->
<bean id="pooledConnectionFactory" class="org.apache.activemq.pool.PooledConnectionFactory">
    <property name="connectionFactory" ref="targetConnectionFactory"/>
    <!--连接池的最大连接数-->
    <property name="maxConnections" value="${activemq.pool.max-connections}"/>
</bean>

获取对应的pooledConnectionFactory当前配置

# 获取任何一个请求对象，因为都会存在对应的SpringContext容器
tt -n 1 -t org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter invokeHandlerMethod
# 特别强调： 这里在正式环境中，添加-n来指定次数,且应该设置成1。
# 否则当你执行一个调用量不高的方法时可能你还能有足够的时间用 CTRL+C 中断 tt 命令记录的过程，但如果遇到调用量非常大的方法，瞬间就能将你的 JVM 内存撑爆。
# 通过tt的回放能力，获取容器内的Bean
# 随意请求一个地址，只需要被Spring拦截
# 如：http://localhost:9091/openApi/sentinel/flowRules

此时，如果使用ognl可以得到target(当前被调用对象)。因为这个对象是由SpringContext管理的，所以可以获取得容器信息。

tt -i 1003 -w 'target.getApplicationContext().getBean("pooledConnectionFactory")'
# 获取最大连接数
tt -i 1003 -w 'target.getApplicationContext().getBean("pooledConnectionFactory").maxConnections'

接口问题

响应时间

# arthas 下载&安装祥见附录1
# 解决：接口响应慢？哪个环节慢？
# trace 参考: https://arthas.gitee.io/trace.html
trace com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor preHandle -n 1
# 特别强调： 这里在正式环境中，添加-n来指定次数

# 根据方法用时过滤
trace com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor preHandle -n 1 '#cost>10'
# 该过滤是过滤整个方法的用时，而不是指过滤方法内的调用方法用时

trace 的问题在于，

无法支持重载方法

无法直接定位方法下的方法

入参与响应结果跟踪

# arthas 下载&安装祥见附录1
# 解决：调用参数与响应结果跟踪。
# tt 参考: https://arthas.gitee.io/tt.html
# 表达式变量祥见附录2
tt -n 1 -t com.nascent.ecrpsaas.openapi.controller.customer.CustomerController getCustomerInfo4ThirdParty
# 请求参数
tt -i <tt-index> -w 'params'
# 响应结果
tt -i <tt-index> -w 'returnObj'

JVM问题

CPU

查看CPU占用

top

如果CPU一直过高，并且不见回落。则需要排查进程要关线程的状态。

线程跟踪

# 查看进程内最耗费CPU的线程
top -Hp <pid>

如何排查对应的线程问题？需要结合jstack

jstack

跟踪所有线程

jstack 1 | more

该命令可以查看出当前JVM中的线程情况。

主要关注以下三个状态：

• WAITING：进入等待状态
    • 方式：wait/join/park方法进入无限等待，通过notify/notifyAll/unpark唤醒；
• TIMED_WAITING：与WAITING类似。
	• 方式：a. 给定等待时间的wait/join/park
	• 方法；b. sleep方法；
• BLOCKED：被动进入等待状态
	• 方式：进入Synchronized块；

线程状态数量统计

jstack 1 | grep "State: WAITING" | wc -l

查看特定线程的状态信息

查看线程Id=65的线程信息

# 转义进程Id为16进制
printf '%x\n' 65 # 41
jstack 1 | grep 41

jstack排查死循环线程Demo

package com.nascent.test.thread;

public class DeadLockTest {

    private static final Object obj1 = new Object();
    private static final Object obj2 = new Object();

    public static void main(String[] args) {
        Thread thread = new Thread(() -> {
            synchronized (obj1) {
                try {
                    Thread.sleep(200);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (obj2) {
                    System.out.println("t1");
                }
            }
        });
        Thread thread2 = new Thread(() -> {
            synchronized (obj2) {
                try {
                    Thread.sleep(200);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (obj1) {
                    System.out.println("t2");
                }
            }
        });
        thread.setName("test-1");
        thread2.setName("test-2");
        thread.start();
        thread2.start();
        try {
            thread.join();
            thread2.join();
        } catch (Throwable e) {
            e.printStackTrace();
        }
        System.out.println("finish");
    }
}

排查过程

jps -l #找到进程Id 
# 22316 com.nascent.test.thread.DeadLockTest
jstack 22316

统计某线程数量

cat /proc/<pid>/status | grep Threads
jstack <pid> | grep "Druid-ConnectionPool" | wc -l

Arthas排查CPU占用

thread -n 3列举出当前三个占用CPU最高的线程

IBM JCA

官网：https://www.ibm.com/support/pages/ibm-thread-and-monitor-dump-analyzer-java-tmda

Summary

IBM Thread and Monitor Dump Analyzer for Java (TMDA) is tool that allows identification of hangs, deadlocks, resource contention, and bottlenecks in Java thread dumps.

Steps

Download jca*.jar: https://public.dhe.ibm.com/software/websphere/appserv/support/tools/jca/jca467.jar
Open a terminal or command prompt and change directory to where you downloaded the JAR file.
Ensure that Java is on your PATH to run the tool.
Launch the tool: java -jar jca*.jar

The simplest way to request a thread dump on POSIX-based systems such as Linux is to send the kill -3 signal which non-destructively pauses the JVM, creates the thread dump, and the JVM continues (the pause is usually a few hundred milliseconds at most). For example (replace ${PID} with the process ID of the Java process):

kill -3 ${PID}

For other methods of requesting thread dumps and other operating systems, see the Related Information links at the bottom.

Additional Information

During the runtime of a Java™ process, it may not respond predictably and may seem to hang up for a long time or until JVM shutdown occurs. It is not easy to determine the root cause of these sorts of problems. By triggering one or more thread dumps when a Java process does not respond, it is possible to collect diagnostic information related to the JVM and a Java application captured at particular points during execution (note that another common cause of Java slowdowns is garbage collection, in which case you should review verbose garbage collection). For example, the information can be about the operating system, the application environment, threads, native stacks, locks, and memory. The exact contents are dependent on the platform and JVM on which the application is running.

Here is a screenshot of TMDA showing a single thread dump (the left half shows all threads in the thread dump), sorting by stack depth descending (as stack depth often correlates with non-idleness), and showing a thread stack that is suspicious (on the right half):

On some platforms, and in some cases, javacores are known as javadumps. The code that creates javacores is part of the JVM. One can control it by using environment variables and run-time switches. By default, a javacore occurs when the JVM terminates unexpectedly. A javacore can also be triggered by sending specific signals to the JVM. Although thread dumps are present in HotSpot JVMs (sent to stderr instead of a javacore.txt file), the content of javacores produced by the J9 JVM (IBM Java, OpenJ9) is much more rich.

This tool analyzes each thread and provides diagnostic information such as current thread information, the signal that caused the javacore, Java heap information (maximum Java heap size, initial Java heap size, garbage collector counter, allocation failure counter, free Java heap size, and allocated Java heap size), number of runnable threads, total number of threads, number of monitors locked, and deadlock information.

IBM Thread and Monitor Dump Analyzer for Java compares each javacore and provides process ID information for threads, time stamp of the first javacore, time stamp of the last javacore, number of garbage collections per minute, number of allocation failures per minute, time between the first javacore and the last javacore, number of hang suspects, and list of hang suspects.

This tool also compares all monitor information in javacores and detects deadlock and resource contention or monitor bottlenecks, if there are any.

案例

线上正式环境的DruidDataSource创建巨多问题

排查过程：

1、查看`Druid`相关的线程情况

jstack 1 | grep "Druid-ConnectionPool" | wc -l

结果：

查看线程：jstack 1 | grep "Druid-ConnectionPool" | more

存在大量的Druid-ConnectionPool-Create与Druid-ConnectionPool-Destroy线程。

但是，分析DruidDataSource源码，这些线程只有在DruidDataSource被创建的时候，才会有一个对应线程。

可以初步怀疑多数据源的设置可能存在问题。

2、分析多数据源代码发现可能问题

AbstractRoutingRepositoryService

//数据源缓存对存对象
private Map<String, JdbcTemplate> jdbcTemplateCache
			= new LruHashMap<String, JdbcTemplate>(10);
//初始化判断逻辑
private JdbcTemplate getJdbcTemplate(String source) {
    if (!exists(source)) {
        createJdbcTemplate(source);
    }

    return jdbcTemplateCache.get(source);
}
synchronized private void createJdbcTemplate(String source) {
    if (!exists(source)) {
        DataSource dataSource = createDataSource(source);
        if (dataSource == null) {
            throw new IllegalAccessError("无法获取数据库连接");
        } else {
            JdbcTemplate jdbcTemplate = new JdbcTemplate(dataSource);
            jdbcTemplate.afterPropertiesSet();
            jdbcTemplateCache.put(source, jdbcTemplate);
        }

    }
}

LruHashMap的实现原理

//基于LinkedHashMap的removeEldestEntry方法实现。
//<p>The {@link #removeEldestEntry(Map.Entry)} method may be overridden to
//impose a policy for removing stale mappings automatically when new mappings
//are added to the map.
protected boolean removeEldestEntry(java.util.Map.Entry<K, V> eldest) {
    return size() > maxCapacity;
}

3、校验可能性

如何校验？

本地将LruHashMap的值，修改为2，表示只允许同时存在2个连接池。

然后，能过arthas的ognl表达式来调用方法，创建连接池。如果创建超过3个连接池，则会出现多个的Druid-ConnectionPool-Create与Druid-ConnectionPool-Destroy线程。

校验：

AbstractRoutingRepositoryService

private Map<String, JdbcTemplate> jdbcTemplateCache
    //修改为2
    = new LruHashMap<String, JdbcTemplate>(2);

# arthas 下载&安装祥见附录1
# 获取任何一个请求对象，因为都会存在对应的SpringContext容器
tt -n 1 -t org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter invokeHandlerMethod
# 特别强调： 这里在正式环境中，添加-n来指定次数,且应该设置成1。
# 否则当你执行一个调用量不高的方法时可能你还能有足够的时间用 CTRL+C 中断 tt 命令记录的过程，但如果遇到调用量非常大的方法，瞬间就能将你的 JVM 内存撑爆。
# 通过tt的回放能力，获取容器内的Bean
# 随意请求一个地址，只需要被Spring拦截
# 如：http://localhost:9091/openApi/sentinel/flowRules

就可以监听到tt的数据。（注：arthas的使用参考：https://arthas.gitee.io/)

再次强调 -n = 1

这样，就可以使用tt -i来获取SpringContext

如下，获取对应当前LruHashMap中已经缓存的数据源数量

多数据源的配置：

<bean id="RepositoryService" class="com.nascent.ecrpsaas.core.repository.MultRoutingRepositoryService">
    <constructor-arg>
        <map>
            <entry key="" value-ref="dataSource"></entry>
        </map>
    </constructor-arg>
    <property name="dataSourceConfig" ref="dataSourceConfig" />
</bean>

tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").jdbcTemplateCache.keySet()'

使用ognl来调用进行强制初始化

tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").getJdbcTemplate("10000146")'

再来查看缓存对象

[arthas@16016]$ tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").jdbcTemplateCache.keySet()'
@LinkedKeySet[
    @String[10000146],
]
# 查看当前的Druid-ConnectionPool-情况

因为开放平台首先启动的时候，会创建一个数据源。但是这个启动时的数据源不会放置到缓存中。

上面新创建的这个数据源，则会放置到缓存中。所以，应该是存在2个对应的连接池。

再来创建

tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").getJdbcTemplate("10000111")'
tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").jdbcTemplateCache.keySet()'
@LinkedKeySet[
    @String[10000146],
    @String[10000111],
]

确认数据源对象创建：

tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").getJdbcTemplate("10000186")'

查看对应的缓存

tt -i 1000 -w 'target.getApplicationContext().getBean("RepositoryService").jdbcTemplateCache.keySet()'
@LinkedKeySet[
    @String[10000111],
    @String[10000186],
]
# 上一个缓存是
@LinkedKeySet[
    @String[10000146],
    @String[10000111],
]
# 也就是说，146被驱逐了。 但是Druid-ConnectionPool并不会被释放。

内存

常见OOM发生原因

堆溢出

java.lang.OutOfMemoryError: Java heap space

代码中可能存在大对象分配

可能存在内存泄露，导致在多次GC之后，还是无法找到一块足够大的内存容纳当前对象。
永久代/元空间溢出

存放了被虚拟机加载的类信息、常量、静态变量、JIT编译后的代码等

java.lang.OutOfMemoryError: PermGen space
java.lang.OutOfMemoryError: Metaspace

运行期间生成了大量的代理类，导致方法区被撑爆，无法卸载

应用长时间运行，没有重启
方法栈溢出

java.lang.OutOfMemoryError : unable to create new native Thread

创建的了大量的线程导致的

JVM相关配置：

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/dump.hprof

正常情况下，JVM需要配置相关的OOM时dump，防止OOM时没有较好的分析依据。

需要注意的是，如果环境分配的内存较大，dump出来的文件大小会写内存大小一致。

如32G内存，dump出来的文件大小也要为32G。

在K8S容器中，需要注意文件的保存位置，防止保存在POD内，并且POD重启（或者策略驱逐）导致文件丢失。

知识点： OOM并不会导致容器直接无法服务。发生OOM，说明该线程正在申请内存，受影响的线程局限于抛出异常的线程（daemon子线程除外）。而其他线程已经有足够内存，不需要再额外申请，所以不会受影响。且OOM后，受影响的线程因异常而退出，只被该线程所持有的资源不可达后，GC自动回收资源。

jmap

top

如果在观察的时候，%MEN一直往上增，但是基本不见回落（GC时无法回收），则表示此时，在大量的创建对象，并且对象一直被持有，无法被GC回收，有可能发生了内存泄露问题。

此时，需要结合jmap 来排查问题。

 jps -l # 查看JAVA相关进程

查看堆空间

jmap -heap <pid>

统计存活对象

注意：该操作会导致触发一次FullGC（STW），并暂停服务（ＳＴＷ）。非必要时勿操作！

jmap -histo:live <pid>
#或者，导出全部对象。该操作不会引发FullGC。但是也会暂停服务
jmap -histo <pid>

导出堆栈

注意：该操作会导致触发一次FullGC，并暂停服务。非必要时勿操作！

 jmap -dump:live,format=b,file=dump.hprof <pid>
 #live 是指只导出存活对象
 # 或者
 jmap -dump:format=b,file=dump.hprof <pid>

JVM相关配置：

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/dump.hprof

堆栈分析 - MAT

华为云WIKI: https://devcloud.huaweicloud.com/wiki/project/96925512d846436f86c09ffd9160744d/wiki/view/doc/703899

行为数据
- Histogram 直方图 - 类数量列表
- Dominator Tree 支配树 - 类引用关系
- Top Consumers 跟直方图相似 - 按包分组
- Duplicate Classes 重复类 - 被不同ClassLoader加载的类
报表数据
- Leak Suspects 可疑泄露
- Top Consumers 占用总堆1%以上的报表

Histogram 类个数直方图

展示某个特定类的对象个数和每个对象使用的内存

可以通过正则表达式来过滤，更好的专注在关注的对象上。

Shallow Heap

Shallow Heap是指对象本身占用的内存大小，不包括它的引用对象。
针对非数组类型的对象，它的大小就是对象与它所有的成员变量大小的总和。
针对数组类型的对象，它的大小是数组元素对象的大小总和。

Retained Heap

Retained Heap = 当前对象大小 + 当前对象直接或间接引用的对象的大小总和。

相当于对象被GC之后，可以从Heap上释放的内存大小。

（注：实际释放的内存大小需要根据是否有被GCRoot引用，是否可回收影响）

Retained Heap大小有两种不同的计算方式。

Calculate Minimum Retained Size(quick approx…) 快速估算
Calculate Precise Retained Size 精确计算

Dominator tree 支配树，对象引用关系树

如果所有指向对象Y的路径都经过对象X，则认为对象X支配对象Y。

Top Consumers 内存消耗排行

Leak Suspects 可疑泄露报告

显示MAT发现的可能导致内存泄漏的地方，和用于分析这些发现的工具和图表的链接。

Immediate Dominators 查看类的支配树（直接引用）

在直方图Histogram中，可以查看特定类的支配树。!在这里插入图片描述

Path to GC Roots 查看GC Roots引用链

with all references 查看所有的引用链
exclude weak references 过滤弱引用
exclude soft references 过滤软引用
exclude phantom references 过滤虚引用
exclude weak/soft references 过滤弱/软引用
exclude phantom/soft references 过滤虚/软引用
exclude phantom/weak references 过滤虚/弱引用
exclude phantom/weak/soft etc. references 过滤虚/弱/软引用
- exclude custom fields… 自定义过滤

with outgoing references 我引用了谁

with incoming references 谁引用了我

GC

堆主要组成

GC日志

# GC日志指令
-XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:<filename>
# GC日志对性能的影响极小，在生产环境也可以开启
# 触发条件： 1、自动 2、监控工具强制调用 3、jmap -histo:live pid

建议设置

看懂GC日志

日志分析 - GcViewer

GCViewer 是一个Sun/Oralce, IBN, HP和BEA的JAVA虚拟机GC日志可以视工具。

（点我下载）)

GC统计信息

内存统计信息

暂停信息

线程使用问题

线上容器服务一直重启，但是未抛出OOM的hprof文件，导出线程堆栈分析。

线程数据大量的TIME_WAITING，线程分组存在大量的OkHttp连接。

排查代码发现是对OkHttp的使用不合理导致的：

每次请求接口时，都会创建一个DefaultOpenClient，而该在在构造函数中会创建OkHttpClient:

导致，每个请求都相应的创建一个OkHttpClient的连接池：

所以，导致了OkHttp的连接池大量的堆积，CPU占满，无法及时响应健康监控一直重启。

jinfo

主要关注JVM的相关信息。

# jinfo <pid>
jinfo 1
# 会输超多信息
# 虚拟机信息
JVM version is 25.252-b09
# 系统配置属性
Java System Properties:
java.vendor = Oracle Corporation
sun.java.launcher = SUN_STANDARD
catalina.base = /usr/local/tomcat
...
java.vm.name = OpenJDK 64-Bit Server VM
ignore.endorsed.dirs =
file.encoding = UTF-8
java.specification.version = 1.8
# JVM配置
Non-default VM flags: -XX:CICompilerCount=2 
-XX:InitialHeapSize=3145728000 
-XX:MaxHeapSize=3145728000 
-XX:MaxNewSize=1048576000 
-XX:MinHeapDeltaBytes=524288 
-XX:NewSize=1048576000 
-XX:OldSize=2097152000 
-XX:-OmitStackTraceInFastThrow 
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops 
-XX:+UseParallelGC
Command line:  -javaagent:/home/admin/.opt/ArmsAgent/arms-bootstrap-1.7.0-SNAPSHOT.jar 
-Darms.licenseKey=cmmsmf4y87@9634a50d2fa7317-Darms.appName=ts-ecrp-open 
-Darms.agent.env=ACSK8S -Darms.agent.args= 
-Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties 
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager 
-XX:-OmitStackTraceInFastThrow -Xms3000m -Xmx3000m -Djdk.tls.ephemeralDHKeySize=2048 
-Djava.protocol.handler.pkgs=org.apache.catalina.webresources 
-Dorg.apache.catalina.security.SecurityListener.UMASK=0027 
-Dignore.endorsed.dirs= -Dcatalina.base=/usr/local/tomcat 
-Dcatalina.home=/usr/local/tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp

或者查看特定JVM参数

jinfo -flags <pid> # 查看所有的JVM flag
jinfo -flag NewSize <pid> # 查看JVM -XX:NewSize 的数据
# 如上，会输出如： -XX:NewSize=1048576000

jstat

对Java应用程序的资源和性能进行实时的命令行的监控，包括了对Heap size和垃圾回收状况的监控。

# 查看GC情况
jstat -gc 1 3000
# jstat -options 查看所有支持的option
-class # 显示ClassLoad的相关信息
-compiler # 显示JIT编译的相关信息
-gc # 显示和gc相关的堆信息
-gccapacity # 显示各个代的容量以及使用情况
-gccause # 显示垃圾回收的相关信息（同-gcutil）,同时显示最后一次或当前正在发生的垃圾回收的诱因
-gcmetacapacity # 显示metaspace的大小
-gcnew # 显示新生代信息
-gcnewcapacity # 显示新生代大小和使用情况 
-gcold # 显示老年代和永久代的信息
-gcoldcapacity # 显示老年代的大小
-gcutil # 显示垃圾收集信息
-printcompilation # 输出JIT编译的方法信息

jstack

导出线程堆栈：jstack 1 > jstack.log
分析线程状态：grep --no-group-separator -A 1 java.lang.Thread.State jstack.log | awk 'NR%2==0' | sort | uniq -c | sort -nr

Redis常见问题排查

参考: https://redis.io

中文参考: http://doc.redisfans.com/index.html

性能相关的数据指标

# 连接到Redis中
# 参考: https://redis.io/commands/info
info

info命令输出的数据可分为10个类别，分别是：

server 一般 Redis 服务器信息
clients 已连接客户端信息
**memory **内存信息
persistence RDB 和 AOF 的相关信息
stats 一般统计信息
replication 主/从复制信息
cpu CPU 计算量统计信息
commandstats Redis 命令统计信息
cluster Redis 集群信息
keyspace 数据库相关的统计信息

# 查看内存使用
info memory

used_memory_rss：从操作系统上显示已经分配的内存总量。

mem_fragmentation_ratio：内存碎片率。

used_memory_lua： Lua脚本引擎所使用的内存大小。

mem_allocator：在编译时指定的Redis使用的内存分配器，可以是libc、jemalloc、tcmalloc。

Linux服务器导致的性能问题（不常见）

因内存交换引起的性能问题

内存使用率是Redis服务最关键的一部分。如果一个Redis实例的内存使用率超过可用最大内存 (used_memory > 可用最大内存)，那么操作系统开始进行内存与swap空间交换，把内存中旧的或不再使用的内容写入硬盘上（硬盘上的这块空间叫Swap分区），以便腾出新的物理内存给新页或活动页(page)使用。

在硬盘上进行读写操作要比在内存上进行读写操作，时间上慢了近5个数量级，内存是0.1μs单位、而硬盘是10ms。如果Redis进程上发生内存交换，那么Redis和依赖Redis上数据的应用会受到严重的性能影响。通过查看used_memory指标可知道Redis正在使用的内存情况，如果used_memory>可用最大内存，那就说明Redis实例正在进行内存交换或者已经内存交换完毕。管理员根据这个情况，执行相对应的应急措施。

响应延迟

# 延迟时间
redis-cli --latency -h 127.0.0.1 -p 6379
# 以毫秒为单位测量Redis的响应延迟时间，正常的延迟是0.3左右

连接数量过多排查

client list

大Key

redis-cli --bigkeys

慢日志

# 对执行时间大于多少微秒(microsecond，1秒 = 1,000,000 微秒)的查询进行记录
# 执行以下命令将让 slow log 记录所有查询时间大于等于 100 微秒的查询
CONFIG SET slowlog-log-slower-than 100
# slow log 最多能保存多少条日志
# 让 slow log 最多保存 1000 条日志：
CONFIG SET slowlog-max-len 1000
# 查看 slow log
slowlog get
# 指定数量 
slowlog get 100
# 清空日志
slowlog reset

案例

# 一次Redis调用需要用时30ms+
# 慢日志
slowlog get

1986
1594090501
12167
GET
queryCompany:ecrp-crm:60000004
1985
1594086857
17038
KEYS
common:async:task:1594086837001369981*
1984
1594086836
16905
KEYS
common:async:task::wxMaSubmitAudit
1983
1594086191
17367
KEYS
common:async:task:1594086170959324176
1982
1594086181
11236
GET
queryCompany:ecrp-crm:60000004
1981
1594086170
16413
KEYS
common:async:task::wxMaUpload
1980
1594086170
17145
KEYS
common:async:task::wxMaDeploy
1979
1594086150
17003
KEYS
common:async:task:1594086130033133350*
1978
1594086130
17165
KEYS
common:async:task:*:wxMaSubmitAudit
1977
1594081141
11675
GET
queryCompany:ecrp-crm:60000004

# 初步怀疑是Keys导致了Redis响应缓慢
# 排查发现Keys是商城后台在特定情况下使用的，使用较少，应该基本不影响
redis-cli --latency -h <host> -p <port>
# 发现延迟达到10ms+
# 通过监控平台，发现CPU接近100%，每秒并发操作12W+
info clients
# 连接数只有1200+左右
info commandstats
# 命令统计， 发现Ping次数达到
# cmdstat_ping:calls=878105367911,usec=818766996940,usec_per_call=0.93
# 再次统计
info commandstats
# 将二个数据相加，可以大概得到每秒的相差数量。
# 当初的问题ping每分钟达到400W+

排查项目Redis相关使用

项目中并没有直接PING命令

<property name="testOnBorrow" value="true" />
<property name="testOnReturn" value="true" />
<property name="testWhileIdle" value="true" />

发现问题

如果设置了testOnBorrow则从连接池拿出连接都都会执行一次PingPong

同理，设置了testOnReturn时，归还连接时也会执行一次PingPong

解决：

<property name="testOnBorrow" value="false" />
<property name="testOnReturn" value="false" />
<property name="testWhileIdle" value="true" />

MySQL常见问题排查

慢SQL - Explain

字段意义
• id SELECT识别符。这是SELECT查询序列号。这个不重要,查询序号即为sql语句执行的顺序
• select_type select类型
    • SIMPLE 进行不需要Union操作或不含子查询的简单select查询时，
    响应查询语句的select_type 即为simple，无论查询语句是多么复杂，
    执行计划中select_type为simple的单位查询一定只有一个
    • PRIMARY 一个需要Union操作或含子查询的select查询执行计划中，
    位于最外层的select_type即为primary。
    与simple一样，select_type为primary的单位select查询也只存在1个
    • union 由union操作联合而成的单位select查询中，除第一个外，
    第二个以后的所有单位select查询的select_type都为union。
    union的第一个单位select的select_type不是union，而是DERIVED。
    它是一个临时表，用于存储联合（Union）后的查询结果
    • DEPENDENT UNION dependent 与UNION select_type一样，
    dependent union出现在union或union all 形成的集合查询中。
    此处的dependent表示union或union all联合而成的单位查询受外部影响
    • union result union result为包含union结果的数据表
• table 表名
• type 连接类型，有多个参数，先从最佳类型到最差类型介绍 也是本篇的重点
    • const，表最多有一个匹配行，const用于比较primary key 或者unique索引。
    因为只匹配一行数据，所以很快，也可以理解为最优化的索引，常数查找
    • eq_ref 对于eq_ref的解释，mysql手册是这样说的:”对于每个来自于前面的表的行组合，从该表中读取一行。
    除了const类型，这可能是最好的联接类型”
    • ref 对于每个来自于前面的表的行组合，所有有匹配索引值的行将从这张表中读取。
    如果联接只使用键的最左边的前缀，或如果键不是UNIQUE或PRIMARY KEY
    （换句话说，如果联接不能基于关键字选择单个行的话），则使用ref。
    如果使用的键仅仅匹配少量行，该联接类型是不错的
    • ref_or_null 该联接类型如同ref，但是添加了MySQL可以专门搜索包含NULL值的行。
    在解决子查询中经常使用该联接类型的优化
    • index_merge 该联接类型表示使用了索引合并优化方法。
    在这种情况下，key列包含了使用的索引的清单，key_len包含了使用的索引的最长的关键元素
    • unique_subquery
    • index_subquery
    • range 给定范围内的检索，使用一个索引来检查行
    • index 该联接类型与ALL相同，除了只有索引树被扫描。这通常比ALL快，因为索引文件通常比数据文件小。
    （也就是说虽然all和Index都是读全表，但index是从索引中读取的，而all是从硬盘中读的）
    • ALL 对于每个来自于先前的表的行组合，进行完整的表扫描。
    如果表是第一个没标记const的表，这通常不好，并且通常在它情况下很差。
    通常可以增加更多的索引而不要使用ALL，使得行能基于前面的表中的常数值或列值被检索出
• possible_keys 提示使用哪个索引会在该表中找到行，不太重要
• keys 指明MYSQL查询使用的索引
• key_len MYSQL使用的索引长度
• ref 显示使用哪个列或常数与key一起从表中选择行
• rows 显示MYSQL执行查询的行数，数值越大越不好，说明没有用好索引
• Extra 该列包含MySQL解决查询的详细信息

美团技术团队分享 https://www.jb51.net/article/75438.htm

索引优化

覆盖索引

'Using Index'的意思是“覆盖索引”。

一个包含查询所需字段的索引称为“覆盖索引”

MySQL只需要通过索引就可以返回查询所需要的数据，而不必在查到索引之后进行回表操作，减少IO，提高了效率。

# 索引
# AK_out_nick_platform	out_nick, platform	UNIQUE
SELECT SQL_NO_CACHE es_party_time, out_nick, platform 
from kd_all_customer order by id desc limit 1000

SELECT SQL_NO_CACHE out_nick, platform 
from kd_all_customer order by id desc limit 1000

索引选择性

# 索引选择性=索引基数/数据总数
# 索引基数
# show index from 表名 # cardinality
# 索引选择性平均数值组越接近1就越有可能利用索引

索引不优

明明有索引，但是不走索引？

两个同样结构的语句一个没有用到索引的问题？

原因：二叉树索引本来最适合的就是点查询，和小范围的range查询，
当预估返回的数据量超过一定比例( 大概在预估的查询量达到总量的30%，没找到实际文档 )的时候，
再根据索引一条一条去查就慢了，反而不如全表扫描快了。

索引的最左原则

例如联合索引有三个索引字段（A,B,C）

查询条件：

（A，，）— 会使用索引

（A，B，）— 会使用索引

（A，B，C）— 会使用索引

（，B，C）— 不会使用索引

（，，C）— 不会使用索引

系统问题

内存SWAP

当应用程序要请求新的内存页的时候，如果已经没有足够的物理内存，就会把目前物理内存中的一部分空间释放出来，以供当前运行的程序使用。

这部分被释放的空间可能属于某一个程序，并且所谓的释放，是把这部分内存页存放到SWAP空间。

如果这个程序是活跃的，那么当它的内存页被存放到SWAP之后，下一刻它又要用到这一部分，那么就又要把这一部分换入内存中，这个时候，系统就要把其它程序的内存页换出到SWAP中，腾出空间给它。

反复如此，就会造成性能的问题。

所以如果频繁使用到SWAP来换出换入内存，那么就意味着负载过高，或者物理内存不够。

文件句柄数

并发调优时，往往需要预先调优linux参数，其中修改linux最大文件句柄数是最常修改的参数之一。

linux最大文件句柄数为1024个。当你的服务器在大并发达到极限时，就会报出“too many open files”。

最终排查手册

日志、经验、怀疑!!

附录1： arthas 安装&启动

# 官方文档： https://arthas.gitee.io/
# https://arthas.aliyun.com/doc/download.html
# Linux基础环境： apt-get install wget tini unzip vim procps -y
# 下载安装
wget -qO /tmp/arthas.zip "https://maven.aliyun.com/repository/public/com/taobao/arthas/arthas-packaging/3.2.0/arthas-packaging-3.2.0-bin.zip" && \
mkdir -p /opt/arthas && \
unzip /tmp/arthas.zip -d /opt/arthas && \
rm /tmp/arthas.zip
# 启动
java -jar /opt/arthas/arthas-boot.jar

问题：com.sun.tools.attach.AttachNotSupportedException: Unable to get pid of LinuxThreads manager thread

docker问题，需要执行：

RUN apk add --no-cache tinit
ENTRYPOINT ["/sbin/tini","--"]

附录2：arthas ognl表达式核心变量

# 官方文档： https://arthas.gitee.io/
# 参考: https://arthas.gitee.io/advice-class.html

变量名	变量解释
loader	本次调用类所在的 ClassLoader
clazz	本次调用类的 Class 引用
method	本次调用方法反射引用
target	本次调用类的实例
params	本次调用参数列表，这是一个数组，如果方法是无参方法则为空数组
returnObj	本次调用返回的对象。当且仅当 `isReturn==true` 成立时候有效，表明方法调用是以正常返回的方式结束。如果当前方法无返回值 `void`，则值为 null
throwExp	本次调用抛出的异常。当且仅当 `isThrow==true` 成立时有效，表明方法调用是以抛出异常的方式结束。
isBefore	辅助判断标记，当前的通知节点有可能是在方法一开始就通知，此时 `isBefore==true` 成立，同时 `isThrow==false` 和 `isReturn==false`，因为在方法刚开始时，还无法确定方法调用将会如何结束。
isThrow	辅助判断标记，当前的方法调用以抛异常的形式结束。
isReturn	辅助判断标记，当前的方法调用以正常返回的形式结束。

附录3：arthas 常用功能

# 官方文档： https://arthas.gitee.io/

trace-性能排查

# 参考: https://arthas.gitee.io/trace.html
trace -n 1 com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor preHandle
# 强调： 在生产环境时， 必须先把-n带上

比较有问题的是，如果方法复杂度过高，会导致无法Agent进去。同时，目前无法支持重载方法。

stack-调用路径跟踪

# 参考： https://arthas.gitee.io/stack.html
tack -n 1 com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor preHandle
# 尽量不用，如果调用链非常长，可能会出生产事故。
# 强调： 在生产环境时， 必须先把-n带上

tt - 时空隧道

记录下指定方法每次调用的入参和返回信息，并能对这些不同的时间下调用进行观测

# 参考： https://arthas.gitee.io/tt.html
tt -n 3 -t com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor preHandle
# 强调： 在生产环境时， 必须先把-n带上

上文中的 arthas获取SpringContext的Bean信息就是利用tt的调用信息，然后使用ognl表达式获取的。

查看请求信息

#tt -i <index>
tt -i 1000

获取对象中的配置信息

tt -i 1000 -w 'target'

调用

tt -i 1000 -w 'target.requestNonce'

jad - 反编译指定已加载类的源码

解决：我改了呀，但是不知道为什么没有作用？

jad --source-only com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor > /tmp/APIHandlerInterceptor.java
# 直接看
# jad --source-only com.nascent.ecrpsaas.openapi.interceptor.APIHandlerInterceptor

反编译之后的源码：

mc & redefine - 动态更新代码

不支持vi处理： apt-get install vim -y

编辑类，并保存成功之后，启动arthas

# 查找类对应的加载器
sc -d *APIHandlerInterceptor | grep classLoaderHash
# 输出:  classLoaderHash   726a17c4
# 内存编译代码
mc -c 726a17c4 /tmp/APIHandlerInterceptor.java -d /tmp
# 需要注意的是，JAVA的泛型在编译之后会被擦除。所以，最合适的方法就是将本地代码上传。
# 而不是基于反编译之后的代码来修改。
# 输出: Memory compiler output:
#      /tmp/com/nascent/ecrpsaas/openapi/interceptor/APIHandlerInterceptor.class
# 更行热替换
redefine /tmp/com/nascent/ecrpsaas/openapi/interceptor/APIHandlerInterceptor.class
# 输出： redefine success, size: 1

profile - 火焰图

查看支持的action: profiler actions

查看支持的event: profilter list

内存分配: alloc
cpu : cpu
方法：class.method
时钟信号：wall

使用：

profilter start / profilter start --event cpu

停止：

profitler stop

默认情况下，生成的结果保存到应用的工作目录下的arthas-output目录。可以通过 --file参数来指定输出结果路径。

$ profiler stop --file /tmp/output.svg
profiler output file: /tmp/output.svg
OK

默认情况下，结果文件是svg格式，如果想生成html格式，可以用--format参数指定：

$ profiler stop --format html
profiler output file: /tmp/test/arthas-output/20191125-143329.html
OK

或者在--file参数里用文件名指名格式。比如--file /tmp/result.html 。

附录4：docker linux 安装基础命令

apt-get install wget tini unzip vim procps -y

线上基础问题排查常用手册

问题分类

业务问题

性能问题

实施手段

阿里云

本地日志

本地代码

线上代码

静态配置类&枚举类

获取SpringBean对象

响应时间

入参与响应结果跟踪

CPU

查看CPU占用

线程跟踪

jstack

跟踪所有线程

线程状态数量统计

查看特定线程的状态信息

jstack排查死循环线程Demo

统计某线程数量

Arthas排查CPU占用

IBM JCA

Summary

Steps

Additional Information

案例

1、查看Druid相关的线程情况

2、分析多数据源代码发现可能问题

3、校验可能性

内存

常见OOM发生原因

jmap

查看堆空间

统计存活对象

导出堆栈

堆栈分析 - MAT

Histogram 类个数直方图

Dominator tree 支配树，对象引用关系树

Top Consumers 内存消耗排行

Leak Suspects 可疑泄露报告

Immediate Dominators 查看类的支配树（直接引用）

Path to GC Roots 查看GC Roots引用链

with outgoing references 我引用了谁

with incoming references 谁引用了我

GC

堆主要组成

相关参数

GC日志

建议设置

看懂GC日志

日志分析 - GcViewer

GC统计信息

内存统计信息

暂停信息

线程使用问题

jinfo

jstat

jstack

因内存交换引起的性能问题

响应延迟

连接数量过多排查

大Key

慢日志

案例

慢SQL - Explain

索引优化

覆盖索引

索引不优

索引的最左原则

内存SWAP

文件句柄数

最终排查手册

附录1： arthas 安装&启动

附录2：arthas ognl表达式核心变量

附录3：arthas 常用功能

trace-性能排查

stack-调用路径跟踪

tt - 时空隧道

1、查看`Druid`相关的线程情况