Java 性能调优

线上调试

Java 性能监控工具

线上调试的典型场景譬如:

  • 程序在稳定运行了,可是实现的功能点了没反应。
  • 为了修复 Bug 而上线的新版本,上线后发现 Bug 依然在,却想不通哪里有问题?
  • 想到可能出现问题的地方,却发现那里没打日志,没法在运行中看到问题,只能加了日志输出重新打包——部署——上线
  • 程序功能正常了,可是为啥响应时间这么慢,在哪里出现了问题?
  • 程序不但稳定运行,而且功能完美,但跑了几天或者几周过后,发现响应速度变慢了,是不是内存泄漏了?

如果瓶颈点在应用层和系统层均呈现出多变量分布,建议此时使用 JProfiler 等工具对应用进行 Profiling,获取应用的综合性能信息(注:Profiling 指的是在应用运行时,通过事件(Event-based)、统计抽样(Sampling Statistical)或植入附加指令(Byte-Code instrumentation)等方法,收集应用运行时的信息,来研究应用行为的动态分析方法)。譬如,可以对 CPU 进行抽样统计,结合各种符号表信息,得到一段时间内应用内的代码热点。

调试工具

常见内置工具的使用

# 查看堆内对象的分布 Top 50(定位内存泄漏)
$ jmap –histo:live $pid | sort-n -r -k2 | head-n 50
# 按线程状态统计线程数(加强版)
$ jstack $pid | grep java.lang.Thread.State:|sort|uniq -c | awk '{sum+=$1; split($0,a,":");gsub(/^[ \t]+|[ \t]+$/, "", a[2]);printf "%s: %s\n", a[2], $1}; END {printf "TOTAL: %s",sum}';
# 查看最消耗 CPU 的 Top10 线程机器堆栈信息
$ show-busy-java-threads

jstack

jstack 命令主要用于调试 Java 程序运行过程中的线程堆栈信息,可以用于检测死锁,进程耗用 CPU 过高报警问题的排查。

$ jstack
Usage:
    jstack [-l] <pid>
    jstack -F [-m] [-l] <pid>
Options:
    -F  强制dump线程堆栈信息. 用于进程hung住,jstack <pid>命令没有响应的情况
    -m  同时打印java和本地(native)线程栈信息,m是mixed mode的简写
    -l  打印锁的额外信息Copy to clipboardErrorCopied

典型用法

jstack 的典型用法如下:

  • qmq 是部署在 Tomcat 中的应用名
    $ ps -ef | grep qmq | grep -v grepCopy to clipboardErrorCopied
    
  • 拿到进程号,例如上面对应的是 3192
  • 第二步找出该进程内最耗费 CPU 的线程,可以使用 ps -Lfp pid 或者 ps -mp pid -o THREAD, tid, time 或者 top -Hp pid。例如用第三个 top -Hp 3192:
    Tasks: 123 total, 0 running, 123 sleeping, 0 stopped, 0 zombie
    Cpu(s): 0.3%us, 0.4%sy, 0.0%ni, 99.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
    Mem: 3922688k total, 3272588k used, 650100k free, 432768k buffers
    Swap: 4194296k total, 0k used, 4194296k free, 596488k cached
    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    3494 tomcat 20 0 4905m 1.1g 11m S 0.3 28.4 0:51.91 java
    3551 tomcat 20 0 4905m 1.1g 11m S 0.3 28.4 4:46.32 java
    3588 tomcat 20 0 4905m 1.1g 11m S 0.3 28.4 0:07.35 java
    3192 tomcat 20 0 4905m 1.1g 11m S 0.0 28.4 0:00.00 java
    3194 tomcat 20 0 4905m 1.1g 11m S 0.0 28.4 0:00.82 javaCopy to clipboardErrorCopied
    
  • TIME 列就是各个 Java 线程耗费的 CPU 时间,CPU 时间最长的是线程 ID 为 3551 的线程,用 printf "%x\n" 3551 得到 ddf
  • sudo -u Tomcat jstack 3192 | grep ddf
    "New I/O worker #30" daemon prio=10 tid=0x00007f44fd525800 nid=0xde4 runnable [0x00007f4530ddf000]
    "DubboResponseTimeoutScanTimer" daemon prio=10 tid=0x00007f44fca88000 nid=0xddf waiting on condition [0x00007f45322e5000]Copy to clipboardErrorCopied
    

线程信息详解

jstack 命令会打印出所有的线程,包括用户自己启动的线程和 jvm 后台线程,我们主要关注的是用户线程,如:

$ jstack 15525
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.65-b01 mixed mode):
"elasticsearch[Native][merge][T#1]" #98 daemon prio=5 os_prio=0 tid=0x00007f031c009000 nid=0x4129 waiting on condition [0x00007f02f61ee000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000eea589f0> (a org.elasticsearch.common.util.concurrent.EsExecutors$ExecutorScalingQueue)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
    at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
    at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
....Copy to clipboardErrorCopied

线程 dump 信息说明:

  • elasticsearch[Native][merge][T#1] 是我们为线程起的名字
  • daemon 表示线程是否是守护线程
  • prio 表示我们为线程设置的优先级
  • os_prio 表示的对应的操作系统线程的优先级,由于并不是所有的操作系统都支持线程优先级,所以可能会出现都置为 0 的情况
  • tid 是 Java 中为这个线程的 id
  • nid 是这个线程对应的操作系统本地线程 id,每一个 Java 线程都有一个对应的操作系统线程
  • wait on condition 表示当前线程处于等待状态,但是并没列出具体原因
  • java.lang.Thread.State: WAITING (parking) 也是表示的处于等待状态,括号中的内容说明了导致等待的原因,例如这里的 parking 说明是因为调用了 LockSupport.park 方法导致等待

java.lang.Thread.State

一个 Thread 对象可以有多个状态,在 java.lang.Thread.State 中,总共定义六种状态。

  • New:线程刚刚被创建,也就是已经 new 过了,但是还没有调用 start()方法,jstack 命令不会列出处于此状态的线程信息。
  • RUNNABLE:RUNNABLE 这个名字很具有欺骗性,很容易让人误以为处于这个状态的线程正在运行。事实上,这个状态只是表示,线程是可运行的。我们已经无数次提到过,一个单核 CPU 在同一时刻,只能运行一个线程。
  • BLOCKED:线程处于阻塞状态,正在等待一个 monitor lock。通常情况下,是因为本线程与其他线程公用了一个锁。其他在线程正在使用这个锁进入某个 synchronized 同步方法块或者方法,而本线程进入这个同步代码块也需要这个锁,最终导致本线程处于阻塞状态。
  • WAITING:等待状态,调用以下方法可能会导致一个线程处于等待状态:Object.wait 不指定超时时间、Thread.join with no timeout、LockSupport.park #java.lang.Thread.State: WAITING (parking)。
    • 例如:对于 wait()方法,一个线程处于等待状态,通常是在等待其他线程完成某个操作。本线程调用某个对象的 wait()方法,其他线程处于完成之后,调用同一个对象的 notify 或者 notifyAll()方法。Object.wait()方法只能够在同步代码块中调用。调用了 wait()方法后,会释放锁。
  • TIMED_WAITING:线程等待指定的时间,对于以下方法的调用,可能会导致线程处于这个状态:
    • Thread.sleep #java.lang.Thread.State: TIMED_WAITING (sleeping)
    • Object.wait 指定超时时间 #java.lang.Thread.State: TIMED_WAITING (on object monitor)
    • Thread.join with timeout
    • LockSupport.parkNanos #java.lang.Thread.State: TIMED_WAITING (parking)
    • LockSupport.parkUntil #java.lang.Thread.State: TIMED_WAITING (parking)
    • TERMINATED
  • 线程终止。说明,对于 java.lang.Thread.State: WAITING (on object monitor)和 java.lang.Thread.State: TIMED_WAITING (on object monitor),对于这两个状态,是因为调用了 Object 的 wait 方法(前者没有指定超时,后者指定了超时),由于 wait 方法肯定要在 syncronized 代码中编写,因此肯定是如类似以下代码导致:
    synchronized(obj) {
            // .........
            obj.wait();
            // .........
    }Copy to clipboardErrorCopied
    

死锁

在 Java 5 中加强了对死锁的检测。线程 Dump 中可以直接报告出 Java 级别的死锁,如下所示:

Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x0003f334 (object 0x22c19f18, a java.lang.Object),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x0003f314 (object 0x22c19f20, a java.lang.Object),
which is held by "Thread-1"Copy to clipboardErrorCopied

nid

每个线程都有一个 tid 和 nid,tid 是 Java 中这个线程的编号,而 nid(native id)是对应操作系统线程 id。有的时候,我们会收到报警,说服务器,某个进程占用 CPU 过高,肯定是因为某个 Java 线程有耗 CPU 资源的方法。

jstat

  • 如下所示为 jstat 的命令格式:
    $ jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]Copy to clipboardErrorCopied
    
  • 如下表示分析进程 id 为 31736 的 gc 情况,每隔 1000ms 打印一次记录,打印 10 次停止,每 3 行后打印指标头部:
    $ jstat -gc -h3 31736 1000 10Copy to clipboardErrorCopied
    

jstat -gc

$ jstat -gc xxxxCopy to clipboardErrorCopied

其对应的指标含义如下:

参数 描述
S0C 年轻代中第一个 survivor(幸存区)的容量 (字节)
S1C 年轻代中第二个 survivor(幸存区)的容量 (字节)
S0U 年轻代中第一个 survivor(幸存区)目前已使用空间 (字节)
S1U 年轻代中第二个 survivor(幸存区)目前已使用空间 (字节)
EC 年轻代中 Eden(伊甸园)的容量 (字节)
EU 年轻代中 Eden(伊甸园)目前已使用空间 (字节)
OC Old 代的容量 (字节)
OU Old 代目前已使用空间 (字节)
PC Perm(持久代)的容量 (字节)
PU Perm(持久代)目前已使用空间 (字节)
YGC 从应用程序启动到采样时年轻代中 gc 次数
YGCT 从应用程序启动到采样时年轻代中 gc 所用时间(s)
FGC 从应用程序启动到采样时 old 代(全 gc)gc 次数
FGCT 从应用程序启动到采样时 old 代(全 gc)gc 所用时间(s)
GCT 从应用程序启动到采样时 gc 用的总时间(s)

jstat -gcutil

查看 gc 的统计信息

$ jstat -gcutil xxxxCopy to clipboardErrorCopied

其对应的指标含义如下:

参数 描述
S0 年轻代中第一个 survivor(幸存区)已使用的占当前容量百分比
S1 年轻代中第二个 survivor(幸存区)已使用的占当前容量百分比
E 年轻代中 Eden(伊甸园)已使用的占当前容量百分比
O old 代已使用的占当前容量百分比
P perm 代已使用的占当前容量百分比
YGC 从应用程序启动到采样时年轻代中 gc 次数
YGCT 从应用程序启动到采样时年轻代中 gc 所用时间(s)
FGC 从应用程序启动到采样时 old 代(全 gc)gc 次数
FGCT 从应用程序启动到采样时 old 代(全 gc)gc 所用时间(s)
GCT 从应用程序启动到采样时 gc 用的总时间(s)

jstat -gccapacity

$ jstat -gccapacity xxxx1Copy to clipboardErrorCopied

其对应的指标含义如下:

参数 描述
NGCMN 年轻代(young)中初始化(最小)的大小 (字节)
NGCMX 年轻代(young)的最大容量 (字节)
NGC 年轻代(young)中当前的容量 (字节)
S0C 年轻代中第一个 survivor(幸存区)的容量 (字节)
S1C 年轻代中第二个 survivor(幸存区)的容量 (字节)
EC 年轻代中 Eden(伊甸园)的容量 (字节)
OGCMN old 代中初始化(最小)的大小 (字节)
OGCMX old 代的最大容量 (字节)
OGC old 代当前新生成的容量 (字节)
OC Old 代的容量 (字节)
PGCMN perm 代中初始化(最小)的大小 (字节)
PGCMX perm 代的最大容量 (字节)
PGC perm 代当前新生成的容量 (字节)
PC Perm(持久代)的容量 (字节)
YGC 从应用程序启动到采样时年轻代中 gc 次数
FGC 从应用程序启动到采样时 old 代(全 gc)gc 次数

其他命令

  1. 查看年轻代对象的信息及其占用量。
    jstat -gcnewcapacity xxxx1Copy to clipboardErrorCopied
    
  2. 查看老年代对象的信息及其占用量。
    jstat -gcoldcapacity xxxx1Copy to clipboardErrorCopied
    
  3. 查看年轻代对象的信息
    jstat -gcnew xxxx1Copy to clipboardErrorCopied
    
  4. 查看老年代对象的信息
    jstat -gcold xxxx
    

埋点与插桩

非侵入式埋点

运行时代码诊断,首先需要考虑的就是如何将埋点代码嵌入至业务代码中;常见做法主要有四种:侵入式埋点、运行时增强、编译时增强、中间件增强,后三种都属于非侵入式埋点,埋点性能逐步提升。

  • 侵入式埋点:每个业务方都需要主动感知或唤起埋点代码,仅适用于小范围内部产品,不宜大范围推广。
  • 运行时增强:程序运行时动态拦截,如 Spring AOP、jvm-sandbox。优点是动态可插拔,控制灵活;缺点是有运行时额外开销。
  • 编译时增强:程序编译时进行增强,如 AspectJ、ASM。优点是几乎没有运行时额外开销;缺点是需要额外的构建步骤,启动比较慢。
  • 中间件增强:在各个中间件服务中嵌入埋点代码。优点是原生代码,没有任何额外开销;缺点是需使用统一的中间件服务。

调用拦截

调用拦截的目的是为了明确线程监听的对象与生命周期 。传统的线程诊断,由于没有明确的监听对象与生命周期,只能进行全局线程的随机监听,不但浪费了大量的系统资源,还经常遗漏关键调用的线程信息。

性能诊断

性能诊断主要有插桩(Instrumentation)和采样(Sampling)两种实现方式,前者开销较高,后者结果有一定误差。

  • 插桩法(Instrumentation),需要在每个方法前后添加埋点,计算耗时,优点是结果准确,缺点是开销较高,需要明确目标函数,代码结构也会发生一定变化,很多在线诊断工具,如 Arthas 都是采用的这种方法。
  • 采样法(Sampling),则是周期性获取 JVM 运行栈快照,然后通过比对方法在快照集(Snapshot Set)中出现的次数来粗略估计其运行时间。每次快照生成均需等待 JVM 运行到安全点(Safe Point),因此,运行结果有一定误差,不过,性能开销要远低于插桩法,而且能够获取完整线程栈,无需事先指定目标函数。主流的 Java Profiler 都是采用的 Sampling 方式。