Jade Dungeon

监控工具

基本JVM监控工具

远程监控启动参数

被监控的程序要添加监控启动参数:

-Djava.rmi.server.hostname=172.16.7.10
-Dcom.sun.management.jmxremote.port=9001
-Dcom.sun.management.jmxremote.ssl=false
-Dcom.sun.management.jmxremote.authenticate=false

MyEclipse启动Tomcat可以加在Tomcat的JDK->Optional Java VM arguments里。

虚拟机进程(jps)

jps命令,显示虚拟机执行的主类与LVMID(本虚拟机唯一ID)。对本地单个虚拟机来说 LVMID与OS进程号一样,多个虚拟机只能用jps来看LVMID。

jps [options] [host]

参数:

-m 显示传给main方法的参数
-l 主类的全名
-v 显示JVM参数
-q 不输出类名、Jar名和传入main方法的参数
root@ubuntu:/# jps -m -l
2458 org.artifactory.standalone.main.Main /usr/local/artifactory-2.2.5/etc/jetty.xml
29920 com.sun.tools.hat.Main -port 9998 /tmp/dump.dat
3149 org.apache.catalina.startup.Bootstrap start
30972 sun.tools.jps.Jps -m -l
8247 org.apache.catalina.startup.Bootstrap start
25687 com.sun.tools.hat.Main -port 9999 dump.dat
21711 mrf-center.jar

进程状态(jstat)

语法格式如下:

jstat [ generalOption | outputOptions vmid [interval[s|ms] [count]] ]
  • vmid是Java虚拟机ID,在Linux/Unix系统上一般就是进程ID。
  • interval是采样时间间隔。
  • count是采样数目。

比如下面输出的是GC信息,采样时间间隔为250ms,采样数为4:

root@ubuntu:/# jstat -gc 21711 250 4
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT   
192.0  192.0   64.0   0.0    6144.0   1854.9   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649
192.0  192.0   64.0   0.0    6144.0   1972.2   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649
192.0  192.0   64.0   0.0    6144.0   1972.2   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649
192.0  192.0   64.0   0.0    6144.0   2109.7   32000.0     4111.6   55296.0 25472.7  

S0 S1 E O P代表两个Sivivor、Eden、老年代、永久代的使用比。

YGC YGCT FGC FGCT GCT启动以来新生代与老生代GC次数与耗时、总GC耗时。

S0C、S1C、S0U、S1U Survivor 0/1区容量(Capacity)和使用量(Used)
EC、EU Eden区容量和使用量
OC、OU 年老代容量和使用量
PC、PU 永久代容量和使用量
YGC、YGT 年轻代GC次数和GC耗时
FGC、FGCT Full GC次数和Full GC耗时
GCT GC总耗时

结合JVM内存模型:

  • 堆内存 = 年轻代 + 年老代 + 永久代
  • 年轻代 = Eden区 + 两个Survivor区(From和To)

配置信息

jinfo查看配置参数。-flag 参数名查看参数默认值,java -XX:+PrintFlagsFinal 也可以。 -sysprops 属性名显示虚拟机System.getProperties()

内存转储(jmap)

jmap输出内存转储文件。基本格式:

jmap [option] pid
jmap [option] executable core
jmap [option] [server-id@]remote-hostname-or-ip

如果运行在64位JVM上,可能需要指定-J-d64命令选项参数。

常用参数:

-J-d64 在64位jvm上可能需要指定
-dump -dump:[live,]format=b,file=文件名Live则只要存活对象
-finalizerinfo 显示F-Queue中等待finalize方法的对象
-heap 详细堆信息、回收器类型、参数配置、分代状况
-histo 堆中对象统计信息,包括类=实例数量和合计容量
-permstat 以ClassLoader为统计口径显示永久代内存状态
-F VM线程对-dump 选项没有响应时,用来强制生成dump快照

还有一些其他的小技巧:

  • 启动参数-XX:+HeapDumpOnOutOfMemoryError在内存耗尽时转储;
  • -XX:+HeapDumpOnCtrlBreak在按键Control+Break时生成;
  • linux下kill -3「恐吓」一下VM;

例,生成转储文件:

$ jmap -dump:live,format=b,file=tmp.dmp 14101
Dumping heap to /home/morgan/tmp/tmp.dmp ...
File exists

例,打印进程的类加载器和类加载器加载的持久代对象信息。输出类加载器名称、对象 是否存活(不可靠)、对象地址、父类加载器、已加载的类大小等信息:

jmap -permstat 21711

例,使用jmap -heap pid查看进程堆内存使用情况,包括使用的GC算法、堆配置参数和 各代中堆内存使用情况。比如下面的例子:

root@ubuntu:/# jmap -heap 21711
Attaching to process ID 21711, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 20.10-b01
 
using thread-local object allocation.
Parallel GC with 4 thread(s)
 
Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 2067791872 (1972.0MB)
   NewSize          = 1310720 (1.25MB)
   MaxNewSize       = 17592186044415 MB
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 8
   PermSize         = 21757952 (20.75MB)
   MaxPermSize      = 85983232 (82.0MB)
 
Heap Usage:
PS Young Generation
Eden Space:
   capacity = 6422528 (6.125MB)
   used     = 5445552 (5.1932830810546875MB)
   free     = 976976 (0.9317169189453125MB)
   84.78829520089286% used
From Space:
   capacity = 131072 (0.125MB)
   used     = 98304 (0.09375MB)
   free     = 32768 (0.03125MB)
   75.0% used
To Space:
   capacity = 131072 (0.125MB)
   used     = 0 (0.0MB)
   free     = 131072 (0.125MB)
   0.0% used
PS Old Generation
   capacity = 35258368 (33.625MB)
   used     = 4119544 (3.9287033081054688MB)
   free     = 31138824 (29.69629669189453MB)
   11.683876009235595% used
PS Perm Generation
   capacity = 52428800 (50.0MB)
   used     = 26075168 (24.867218017578125MB)
   free     = 26353632 (25.132781982421875MB)
   49.73443603515625% used
   ....

使用jmap -histo[:live] pid查看堆内存中的对象数目、大小统计直方图,如果带上 live则只统计活对象,如下:

root@ubuntu:/# jmap -histo:live 21711 | more
 
 num     #instances         #bytes  class name
----------------------------------------------
   1:         38445        5597736  <constMethodKlass>
   2:         38445        5237288  <methodKlass>
   3:          3500        3749504  <constantPoolKlass>
   4:         60858        3242600  <symbolKlass>
   5:          3500        2715264  <instanceKlassKlass>
   6:          2796        2131424  <constantPoolCacheKlass>
   7:          5543        1317400  [I
   8:         13714        1010768  [C
   9:          4752        1003344  [B
  10:          1225         639656  <methodDataKlass>
  11:         14194         454208  java.lang.String
  12:          3809         396136  java.lang.Class
  13:          4979         311952  [S
  14:          5598         287064  [[I
  15:          3028         266464  java.lang.reflect.Method
  16:           280         163520  <objArrayKlassKlass>
  17:          4355         139360  java.util.HashMap$Entry
  18:          1869         138568  [Ljava.util.HashMap$Entry;
  19:          2443          97720  java.util.LinkedHashMap$Entry
  20:          2072          82880  java.lang.ref.SoftReference
  21:          1807          71528  [Ljava.lang.Object;
  22:          2206          70592  java.lang.ref.WeakReference
  23:           934          52304  java.util.LinkedHashMap
  24:           871          48776  java.beans.MethodDescriptor
  25:          1442          46144  java.util.concurrent.ConcurrentHashMap$HashEntry
  26:           804          38592  java.util.HashMap
  27:           948          37920  java.util.concurrent.ConcurrentHashMap$Segment
  28:          1621          35696  [Ljava.lang.Class;
  29:          1313          34880  [Ljava.lang.String;
  30:          1396          33504  java.util.LinkedList$Entry
  31:           462          33264  java.lang.reflect.Field
  32:          1024          32768  java.util.Hashtable$Entry
  33:           948          31440  [Ljava.util.concurrent.ConcurrentHashMap$HashEntr

class name是对象类型,形式为[L+类名或其他对象:

B byte
C char
D double
F float
I int
J long
Z boolean
[ 数组,如[I表示int[]

分析转储文件(jhat)

有一个很常用的情况是用jmap把进程内存使用情况dump到文件中,再用jhat分析查看。 jmap进行dump命令格式如下:

jmap -dump:format=b,file=dumpFileName

例,对上面进程ID为21711进行Dump:

root@ubuntu:/# jmap -dump:format=b,file=/tmp/dump.dat 21711     
Dumping heap to /tmp/dump.dat ...
Heap dump file created

dump出来的文件可以用MAT、VisualVM等工具查看,这里用jhat查看。

jhat分析dump文件,分析完后会启动一个小Http服务器:

$ jhat tmp.dmp
Reading from tmp.dmp...
Dump file created Sun Aug 11 15:01:22 CST 2013
Snapshot read, resolving...
Resolving 29341 objects...
Chasing references, expect 5 dots.....
Eliminating duplicate references.....
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

可以用浏览器查看http://localhost:7000/,还可以用对象查询语言(OQL)查询。

注意如果Dump文件太大,可能需要加上-J-Xmx512m参数指定最大堆内存。

另外还可以指定所在的端口,即:

jhat -J-Xmx512m -port 9998 /tmp/dump.dat

然后就可以在浏览器中输入主机地址:9998查看了:

跟踪堆栈(jstat)

jstack生成VM当前的线程快照(一般称为threaddumpjavacore文件),查看各线程 的调用堆栈。

jstack [option] vmid
jstack [option] executable core
jstack [option] [server-id@]remote-hostname-or-ip

常用参数:

-F 正常请求无响应时,强制输出堆栈
-l 加上锁信息
-m 对于本地调用,显示C/C++栈

例子:

$ jstack -l 14101
2013-08-11 16:37:22
Full thread dump OpenJDK 64-Bit Server VM (23.7-b01 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f4c64001000 nid=0x3eda waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

...

"main" prio=10 tid=0x00007f4c8800d000 nid=0x3716 in Object.wait() [0x00007f4c8f808000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000c2cbf198> (a org.mortbay.thread.QueuedThreadPool$Lock)
	at java.lang.Object.wait(Object.java:503)
	at org.mortbay.thread.QueuedThreadPool.join(QueuedThreadPool.java:298)
	- locked <0x00000000c2cbf198> (a org.mortbay.thread.QueuedThreadPool$Lock)
	at org.mortbay.jetty.Server.join(Server.java:332)
	at runjettyrun.Bootstrap.main(Bootstrap.java:98)

   Locked ownable synchronizers:
	- None

"VM Thread" prio=10 tid=0x00007f4c880a7800 nid=0x371d runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f4c8801b000 nid=0x371b runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f4c8801d000 nid=0x371c runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f4c8812d000 nid=0x373d waiting on condition 

JNI global references: 1963

java.lang.Thread类的方法getAllStackTraces()方法也可以取得部分线程堆栈信息, 如一个jsp页面就可以查看当前应用的堆栈:

<%@ page import="java.util.Map"%>
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
<title>threads</title>
</head>
<body>
	<pre>
<%
	for (Map.Entry<Thread, StackTraceElement[]> stackTrackEntry : Thread
			.getAllStackTraces().entrySet()) //
	{
		Thread thread = (Thread) stackTrackEntry.getKey();
		StackTraceElement[] stack = (StackTraceElement[]) stackTrackEntry
				.getValue();
		if (thread.equals(Thread.currentThread())) {
			continue;
		}
		out.print("\nThread: " + thread.getName() + "\n");
		for (StackTraceElement element : stack) {
			out.print("\t" + element + "\n");
		}
	}
%>
</pre>
</body>
</html>

另一个场景的例子:

jstack可以定位到线程堆栈,根据堆栈信息我们可以定位到具体代码,所以它在JVM性能 调优中使用得非常多。下面我们来一个实例找出某个Java进程中最耗费CPU的Java线程并 定位堆栈信息,用到的命令有ps、top、printf、jstack、grep。

第一步先找出Java进程ID,我部署在服务器上的Java应用名称为mrf-center,得到进程 ID为21711

root@ubuntu:/# ps -ef | grep mrf-center | grep -v grep
root     21711     1  1 14:47 pts/3    00:02:10 java -jar mrf-center.jar

第二步找出该进程内最耗费CPU的线程,可以使用方法有三个:

  • ps -Lfp pid
  • ps -mp pid -o THREAD, tid, time
  • top -Hp pid

我这里用第三个,可以看到占用CPU时间(TIME)最多的是PID为21742的线程:

top - 12:34:34 up  1:52,  1 user,  load average: 0.63, 1.21, 1.19
Tasks: 154 total,   2 running, 150 sleeping,   0 stopped,   2 zombie
Cpu(s): 27.6%us,  3.4%sy,  0.0%ni, 68.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4013476k total,  3190956k used,   822520k free,   335480k buffers
Swap:  1951740k total,       20k used,  1951720k free,  1497056k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                       
21742 morgan    20   0 4185m 395m  41m R   52 10.1   1:12.24 plugin-containe               
 1121 root      20   0  505m 134m  14m S    8  3.4   9:09.35 Xorg                          
 2301 morgan     9 -11  473m 6380 3956 S    3  0.2   2:25.49 pulseaudio                    
10691 morgan    20   0 17344 1336  960 R    1  0.0   0:00.05 top                           
 2203 morgan    20   0  165m  15m 6936 S    0  0.4   0:05.57 awesome                       
    1 root      20   0 24604 2572 1340 S    0  0.1   0:00.79 init                          
    2 root      20   0     0    0    0 S    0  0.0   0:00.00 kthreadd                      
    3 root      20   0     0    0    0 S    0  0.0   0:00.28 ksoftirqd/0                   
    6 root      RT   0     0    0    0 S    0  0.0   0:00.26 migration/0                   
    7 root      RT   0     0    0    0 S    0  0.0   0:00.02 watchdog/0                    
    8 root      RT   0     0    0    0 S    0  0.0   0:00.31 migration/1                   
   10 root      20   0     0    0    0 S    0  0.0   0:00.27 ksoftirqd/1                   
   12 root      RT   0     0    0    0 S    0  0.0   0:00.02 watchdog/1                    
   13 root       0 -20     0    0    0 S    0  0.0   0:00.00 cpuset                        
   14 root       0 -20     0    0    0 S    0  0.0   0:00.00 khelper                       
   15 root      20   0     0    0    0 S    0  0.0   0:00.00 kdevtmpfs                     
   16 root       0 -20     0    0    0 S    0  0.0   0:00.00 netns                         
   18 root      20   0     0    0    0 S    0  0.0   0:00.01 sync_supers                   
   19 root      20   0     0    0    0 S    0  0.0   0:00.00 bdi-default                   
   20 root       0 -20     0    0    0 S    0  0.0   0:00.00 kintegrityd                   
   21 root       0 -20     0    0    0 S    0  0.0   0:00.00 kblockd                       
   22 root       0 -20     0    0    0 S    0  0.0   0:00.00 ata_sff                       
   23 root      20   0     0    0    0 S    0  0.0   0:00.00 khubd                         
   24 root       0 -20     0    0    0 S    0  0.0   0:00.00 md                            

注意进程号21742的十六进制值为54ee,下面会用到:

$ printf "%x\n" 21742
54ee

下一步终于轮到jstack上场了,它用来输出进程21711的堆栈信息,然后根据线程号的 十六进制值grep,如下:

root@ubuntu:/# jstack 21711 | grep 54ee
"PollIntervalRetrySchedulerThread" prio=10 tid=0x00007f950043e000 nid=0x54ee in Object.wait() [0x00007f94c6eda000]

可以看到CPU消耗在PollIntervalRetrySchedulerThread这个类的Object.wait()

查找源代码,定位到下面的代码:

// Idle wait
getLog().info("Thread [" + getName() + "] is idle waiting...");
schedulerThreadState = PollTaskSchedulerThreadState.IdleWaiting;
long now = System.currentTimeMillis();
long waitTime = now + getIdleWaitTime();
long timeUntilContinue = waitTime - now;
synchronized(sigLock) {
    try {
        if(!halted.get()) {
            sigLock.wait(timeUntilContinue);
        }
    } 
    catch (InterruptedException ignore) {
    }
}

它是轮询任务的空闲等待代码,上面的sigLock.wait(timeUntilContinue)就对应了 前面的Object.wait()

CPU占用(hprof)

hprof表示 Heap/CPU Profiling Tool。能够展现CPU使用率,统计堆内存使用情况。

语法格式如下:

java -agentlib:hprof[=options] ToBeProfiledClass
java -Xrunprof[:options] ToBeProfiledClass
javac -J-agentlib:hprof[=options] ToBeProfiledClass

完整的命令选项如下:

Option Name and Value Description Default
--------------------- ----------- -------
heap=dump/sites/all heap profiling all
cpu=samples/times/old CPU usage off
monitor=y/n monitor contention n
format=a/b text(txt) or binary output a
file=<file> write data to file java.hprof[.txt]
net=<host>:<port> send data over a socket off
depth=<size> stack trace depth 4
interval=<ms> sample interval in ms 10
cutoff=<value> output cutoff point 0.0001
lineno=y/n line number in traces? y
thread=y/n thread in traces? n
doe=y/n dump on exit? y
msa=y/n Solaris micro state accounting n
force=y/n force output to <file> y
verbose=y/n print messages about dumps y

来几个官方指南上的实例。

CPU Usage Sampling Profiling(cpu=samples)的例子:

每隔20毫秒采样CPU消耗信息,堆栈深度为3,生成的profile文件名称是java.hprof.txt,在当前目录。

java -agentlib:hprof=cpu=samples,interval=20,depth=3 Hello

CPU Usage Times Profiling(cpu=times)的例子,它相对于CPU Usage Sampling Profile 能够获得更加细粒度的CPU消耗信息,能够细到每个方法调用的开始和结束,它的实现使用 字节码注入技术(BCI):

javac -J-agentlib:hprof=cpu=times Hello.java

Heap Allocation Profiling(heap=sites)的例子:

javac -J-agentlib:hprof=heap=sites Hello.java

Heap Dump(heap=dump)的例子,它比上面的Heap Allocation Profiling能生成更详细的 Heap Dump信息:

javac -J-agentlib:hprof=heap=dump Hello.java

虽然在JVM启动参数中加入-Xrunprof:heap=sites参数可以生成CPU/Heap Profile文件, 但对JVM性能影响非常大,不建议在线上服务器环境使用。

GC日志文件工具

为什么要有日志文件

日志文件的好处是能够用于取证分析,可以使用户免于为了再现问题而不得不再执行一次代码(如果是一个罕见的生产环境错误,那么重现并不容易)。

另外,它们包含的信息比针对内存的JMX MXBeans所能提供的信息更多,且不说轮询JMX本身会引入一系列GC问题。

工具

  • HP JMeter(用Google查询一下)—— 免费,非常可靠,但不再提供支持/功能增强
  • GCViewer —— 免费,开源,但界面有点丑
  • GarbageCat —— 名字最好听
  • IBM GCMV —— 支持J9
  • jClarity Censum —— 界面最美观,而且最有用——不过,这是我们的偏见!

JConsole

JConsole在open JDK与Oracle JDK里都有。运行后直接IP:Port监控系统占用。

VisualVM

Oracle JDK中自带;Open JDK中没有,要另外下载。

如果用的是windows,要注意不能把环境变量中的%TMP%目录指定为fat格式分区下。 或是添加启动参数:

-XX:+PerfBypassFileSystemCheck

安装插件:Tools->Plugin

添加远程应用:左边菜单Remote->Add Remote Host...->Add JMX Connextion...

界面主要标签页

Overview:主要java运行环境与参数。

Monitor:资源占用。常用来检查PermGen的占用情况来调整最合适的PermGen大小。

Threads:用色彩表示线程的活动情况。绿色为活动的线程。"Details"页中显示饼图。

Samper:统计应用中各方法占用的资源。点击"CPU"开始统计,"Stop"结束。 可以通过底部的输入框查找指定的方法。

核心转储

转储:

  • 方法一:左边的Application区域右键菜单
  • 方法二:应用的Monitor标签->Heap Dump

读取转储文件: File->Load

性能分析

Profiler标签页中有CPU和内存性能分析。点击"CPU"开始统计,"Stop"结束。可以 通过底部的输入框查找指定的方法。

JDK1.5以后Client模式下加入并自动启用了类共享(多JVM情况下共享rt.jar以节约资源 优化性能),在这里用Profiler性能分析会引起程序崩溃。要用-Xshare:off关闭共享 优化。

例子:Spring/Hibernate应用性能调优

使用Visual VM:

  1. 运行你的应用程序
  2. 选择 Sampler
  3. 点击Settings复选框
  4. 选择 Profile only packages,同时引入下面的包:
    • your.application.packages.*
    • org.hibernate.*
    • org.springframework.*
    • your.database.driver.package, for example oracle.*
  5. Click Sample CPU

一个典型「数据库约束」应用的CPU性能分析应该像这样:

图示

我们可以看到 Java进程的客户端花费了56%的时间用来等待数据库通过网络返回结果。

这是个好的标志,它显示了是什么让数据库查询应用变慢的。32.7%的Hibernate反射调用 可以正常运行所以没什么可以改进的。

第一步优化:获得运行基线

做优化的第一步是定义一个基线运行的程序。我们需要确定一组有效的输入数据使程序 通过一个类似于生产输出的典型执行类。

主要的区别在于,基线运行应该在更短的时间内运行,作为一个指导方针的执行时间, 5到10分钟是一个理想的时间。

如何得到一个好的基线?

一个好的基线应该有以下特点:

  • 功能正确
  • 在类型方面输入数据类似于输出数据
  • 能在很短的时间内完成
  • 基线运行的优化可以进行推广

良好的基线能事半功倍。

怎样会得到一个糟糕的基线?

例如,在批处理调用一个通信系统的数据记录中,获取前 10,000 条记录是错误的方法。

原因是这前10,000个数据可能是语音通话,而这些未知的错误可能是由于以短信的方式 来处理导致的。大量采用这些记录会导致产生一个错误的基线,由此错误的结论就产生了 。

SQL日志和查询计时

SQL查询的执行时间可以收集用于log4jdbc。如何使用log4jdbc收集SQL查询

查询执行时间衡量的是Java客户端,它包括往返到数据库的网络。SQL查询日志是像这样的 :

16 avr. 2014 11:13:48 | SQL_QUERY /* insert your.package.YourEntity */ insert into YOUR_TABLE (...) values (...) {executed in 13 msec}

好的语句本身也是一个不错的信息来源 –他们允许轻松地识别频繁的查询类型。

SQL日志可以找出哪些指标

SQL 日志可以回答下列问题:

  • 执行最慢的查询是什么?
  • 最常见的查询是什么?
  • 生成主键的时间量是多少?
  • 有数据可以受益于缓存吗?

如何解析SQL日志

可能对于大量日志唯一可行的选择是使用命令行工具。这种方法的优点是非常灵活的。

写一个脚本或命令后我们可以提取主要指标。只要你觉得合适任何命令行工具都是可以。

频繁应用 Quick-Wins

Quick-wins 能识别Spring/Hibernate应用中的常见问题并找到相应的解决方案。

Quick-win 技巧 1:减少主键生成开销

在‘insert-intensive’的进程中,主键生成策略的选择非常重要。一种常见的生成id的方法 是用数据库序列,通常每个表进行插入数据的时候避免争用一个同一资源。

问题是如果插入50条记录,我们想避免为了获得50条记录的id而造成的网络往返对 数据库的消耗,这会导致大部分时间保持Java进程挂起。

Hibernate通常是如何处理的呢?

Hibernate提供了新的优化后的ID生成器来避免这个问题。这就是序列,一个 HiLo id 生成器是在默认情况下使用的。这是HiLo序列发生器如何工作的:

  • 一旦调用一个序列和1000个(高值的)
  • 像这样来计算 50 个id的序列:
    1. 1000 * 50 + 0 = 50000
    2. 1000 * 50 + 1 = 50001
    3. 1000 * 50 + 49 = 50049, 最低值 (50)
    4. 调用更高的序列值 1001 … 等等 …

从一个序列的调用中可以看出,生产50个键可以减少很多网络传输所造成的开销。

这些新的主键优化的产生默认是基于Hibernate 4的,同时也可以在必要时将 hibernate.id.new_generator_mappings设置为false来关掉它。

为什么生成主键依旧是个问题?

问题就是,如果你宣布主键生成策略是AUTO,优化后仍然是关闭的状态, 这样的话您的 应用程序最终会调用大量的序列。

为了确保新的优化生成器处于运行状态,保证使用SEQUENCE策略而不是AUTO:

@Id
@GeneratedValue(strategy = GenerationType.SEQUENCE, 
		generator = "your_key_generator")
private Long id;

通过这个简单的改变,有10%-20%的范围可以改善,这可以在基本上没有修改代码的情况下 在‘insert-intensive’应用程序中采用。

Quick-win 技巧 2:使用JDBC批处理插入/更新

对于批处理程序,JDBC驱动程序通常提供优化来减少网络流量,这就是‘JDBC 批量插入/ 更新’。当使用这些的时候,驱动级别的插入/更新在发送到数据库前被排入队列。

当达到阈值后整个批处理队列语句一次性发送到数据库。这可以防止驱动逐条发送语句, 这可以进行多网络传输。

这是工厂配置的实体管理来激活插入/更新的批处理:

<prop key="hibernate.jdbc.batch_size">100</prop>
<prop key="hibernate.order_inserts">true</prop>
<prop key="hibernate.order_updates">true</prop>

只配置JDBC批处理的大小是不能正常工作的。这是因为JDBC驱动程序只有当接收到插入/ 更新完全相同的表时才会进行批处理插入操作。

如果新表收到一条插入语句,那么JDBC驱动会在开始对新表进行批处理操作前首先刷新 前一张表的批处理语句。

如果使用Spring批处理的话,一个类似的功能是隐式地进行使用。这种优化可以很容易地 完成30% 到 40%的‘insert intensive’程序,而无需改动一行代码。

Quick-win 技巧 3:定期刷新和清理Hibernate会话

当添加/修改数据库的数据时,Hibernate保持了一个已经存在的实体版本的会话,以防 在会话关闭之前进行修改。

但是很多时候,一定在数据库中有匹配的插入时我们就可以安全地丢弃实体。这在Java 客户机进程中释放了内存,防止长时间运行Hibernate会话所导致的性能问题。

像这样长时间运行的会话应该尽可能被阻止,但是由于某种原因需要它们的话就应该包含 内存是如何消耗的:

entityManager.flush();
entityManager.clear();

flush将触发插入新实体从而发送到数据库。clear 则从会话释放新的实体。

Quick-win 技巧 4 :减少Hibernate过多的dirty-checking

Hibernate使用内部的一种机制来保持记录修改的实体的方式就叫做 dirty-checking。 这种机制不是基于实体的equals和hashcode方法的类。

Hibernate能让dirty-checking的性能成本降至最低,dirty-check只会在需要的时候出现 ,但是这种机制也是有代价的,它有更多的表和列。

在应用做任何优化前,最重要的是测量使用VisualVM所耗费的dirty-checking的成本。

如何避免dirty-checking?

我们所知道的Spring事务方法是只读的,dirty-checking可以像这样来关闭:

@Transactional(readOnly=true)
public void someBusinessMethod() {
    ....
}

另一种避免dirty-checking的方式是使用Hibernate无状态会话, 文档有详细描述

Quick-win 技巧 5:搜寻 「差的」 查询计划

在最慢的查询列表里进行检查来看他们是否有良好的查询计划。最常见的「差劲的」 查询计划是:

  • 全表扫描:表完全地被扫描是因为经常缺少索引或者过时的表统计。
  • 笛卡尔连接:这意味着几张表进行笛卡儿积后的结果正在进行计算。检查正在丢失的 连接条件,或者可以通过将一个步骤分为几步来完成可以避免发生这个问题。

Quick-win 技巧 6:检查错误的提交时间间隔

如果你是正在做批处理,那么提交间隔会在性能结果上产生很大的影响, 能达到10-100倍 甚至更多。

确认提交间隔是所预期的(通常是Spring批处理作业的100-1000倍)。参数配置错误的 情况时有发生。

Quick-win 技巧 7:使用二级查询缓存

如果某些数据被确定为合格缓存,设置Hibernate缓存

总结

为了解决应用程序性能问题,最重要的操作是收集一些指标来找到当前的瓶颈是什么。

不给定指标的话几乎不可能在有意义的时间内发现是什么导致问题发生的。

同时,许多但并非所有 ‘数据库-驱动’ 的表现缺陷可以避免在最先使用的Spring Batch框架的应用中发生。