本文介绍了常用的性能分析工具和故障排查工具,希望可以帮助开发人员在排查性能问题的时候快速定位到性瓶颈。每个工具都有其优势与劣势,只有更好了解问题所出现的场景,理清解决问题的思路,才能最大化的发挥工具的价值。
0. Introduction
Java 性能优化分为很多个方面,如系统优化、算法优化、代码优化等。代码优化是指开发人员在研发、测试过程中使用性能瓶颈分析工具快速定位出由于编码存在的性能瓶颈问题并持续进行优化。一种很常见的场景是测试同学在对服务进行压测时,无论怎么增加并发应用的 TPS 一直保持在某个值进行左右波动,这个时候要怎么排查呢。为了可以准确获得运行过程中程序的性能数据,性能调优人员和开发者需要使用性能分析(profiling)辅助工具从全局视角来查看系统的运行状况。本文主要介绍通过熟练掌握 JMC、Tprofiler、JProfiler 等各种性能瓶颈分析工具,进而提高定位性能瓶颈、系统故障排查能力。
1. Java Mission Control
JMC(Java 任务控制)是 Java 7u40 新增加的性能监控工具。目前,Oracle Java 官方在今年 5 月份已经公布 Java Mission Control(JMC)的源代码已正式开源,此举得到了 Java 开发社区的高度赞赏。
JMC 源码地址: JMC source code
JMC 工具主要由三个组件构成:Java 进程浏览器、JMX 控制台和 Java Flight 记录器等。
Java 进程浏览器能够利用 Java 自带的 JDP 协议自动发现本地或者远程正在使用的 Java 进程;
JMX 控制台通过 JMX 接口管理监控 JDK,它能够查看堆内存使用情况、CPU 负载等;
Java Flight Recorder 是一个内置在 JDK 中的监测和事件收集框架。收集的事件包括:磁盘 IO、GC、线程 sleep、线程 wait、Socket read/write 等。
下图显示了 JMC 启动后当前机器正在运行中的所有 Java 进程,选择一个进程进行性能监控。
如果使用的操作系统是 Mac 并且 JDK 版本为 1.8,启动 JMC 之后可能会发现操作界面被冷冻住了你没办法进行任何操作。产生这种现象的原因是 JDK 在升级过程中存在一个bug,具体解决方案可以参考:
Jdk1.8 bug
1.1 JFR 内存视图
JFR 模块包含一般信息、内存、代码、线程、IO、系统、事件等视图。其中,JFR 内存视图收集的信息非常丰富,可以获得内测使用量、GC 配置、GC 时间、对象统计时间等统计信息。下图展示了当前 JVM 进程 GC 时间的统计信息。
1.2 JFR 代码视图
JFR 代码视图可以很容易统计出所有 Java 包占 JVM 进程所有方法调用的总时长。该视图很方便查看热点类、热点方法和热点包的调用次数、所占比例等。JFR 还提供了 I/O 视图、线程视图、系统视图从不同角度更好分析当前进程运行情况。
1.3 启动 JFR
Java 飞行记录器(JFR)是一种用于收集关于正在运行的 Java 应用程序的诊断和分析数据的工具。它集成到 Java 虚拟机(JVM)中,几乎不会造成性能开销,因此即使在负载非常大的生产环境中也可以使用它。
- 首先,JVM 进程开启 JFR 功能需要在 JVM 启动参数(Jvm start flags)中增加两个参数
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder
默认情况下,JFR 在 JVM 中是禁用的。要启用 JFR,必须使用 - XX:+FlightRecorder 选项启动 Java 应用程序。因为 JFR 是一个商业特性,仅在基于 Java 平台、标准版(Oracle Java SE Advanced 和 Oracle Java SE Suite)的商业包中可用,所以您还必须使用 - XX:+UnlockCommercialFeatures 选项启用商业特性。
当然,也可以配置 JMC 进行远程监控,在启动 Java 程序时加上如下参数:
-
-Dcom.sun.management.jmxremote
-
-Dcom.sun.management.jmxremote.port=18090
-
-Dcom.sun.management.jmxremote.ssl=false
-
-Dcom.sun.management.jmxremote.authenticate=false
-
-Djava.rmi.server.hostname=192.168.149.184
-
-XX:+UnlockCommercialFeatures
-
-XX:+FlightRecorder
允许其它机器监控该程序,必须指定 -Djava.rmi.server.hostname=,如果不指定该配置,那么就只能在本机监控该程序。
控制监控的授权(让特定的用户才能连接 JMX 服务),需要设置
-Dcom.sun.management.jmxremote.authenticate=true
如果设置为 false 则不需要授权。
授权需要指定两个文件:jmxremote.password 和 jmxremote.access,password 文件主要是配置用户名和密码。
- 其次,选中需要进行性能分析的进程,点击右键选择开启飞行记录器:
1.4 JFR 事件
JFR 记录并保存事件流,JMC 提供不同的视图来分析这些事件,但是 JFR 事件面板(如上图所示)才是分析事件最有效的途径。点击事件,展开堆栈跟踪。
从图中可以看出,在 2 分钟内发生了 4403 次 Hotspot JVM 事件和 161 次 Java Runtime 事件。应用程序有多个线程共消耗 73 毫秒向套接字内写数据(Socket Write);应用程序中多个线程共消耗 120 秒从套接字读取数据(Socket Read)。这看起来并不正常,通过查看这些事件的处理记录可以发现,由多个线程使用阻塞式 I/O 读取请求。这些管理请求的时间间隔通常很长,但这些线程却在 read() 方法内被阻塞,所以导致这些线程读取数据时消耗了过多的时间。
JFR 的事件就如黑匣子一般,通过收集的这些事件的详细信息能够更加深入了解程序的内部运行过程,这是很多其他工具所不具备的。
1.5 实际案例
API Gateway 是一种高并发、高流量的系统,它的主要功能是用于给第三方合作伙伴提供数据与服务的能力。因此,API Gateway 对于处理用户请求的完整链路中每个环节的性能损耗都会非常敏感。
最近,在升级网关的核心功能模块之后与测试同学一起合作对网关的某些 API 接口进行性能压力测试,利用压测机 Jmeter 模拟多用户并发请求。但不管怎么增加并发数,每分钟的请求总量稳定保持在 4 万/min,TPS 也一直在 650 左右波动,而且所有服务器的 CPU、内存、网络、IO 占用率均不高。
针对这种情况,我们首先排除了业务方的性能问题,因此直接对业务方(2 核 8G)发起并发请求,TPS 都可以达到 800 左右的并发数。其次,我们也排除了接入层 SLB、OpenResty 的问题,因为网关未升级核心功能情况下单台网关的 TPS 很容易达到 4000 左右。
因此,根据以上分析基本可以确定性能瓶颈出在网关处理请求的过程中。
在网关的 JVM 启动参数中增加 JFR 启动参数:
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder
使用 JFR 的事件视图点击堆栈跟踪,就可以查看到代码调用链,看到自己的业务代码,从而定位到最耗时的代码位置。
下图很清楚展示了来自客户端每个请求主要的事件都耗费在调用 Redis 读取 API 元信息,每一次读取源信息都需要进行序列化与反序列化,导致平均响应时间增加网关处理请求时间加长,因此 TPS 下降并一直稳定在某个值。解决方案 API 元信息尽可能缓存到本地 JVM 内存,优先从本地内存读取数据减少访问 Redis 频次。
当然系统 TPS 上不去的原因也不能仅仅从单一维度分析,要综合起来多维度进行分析,如网络带宽、连接池、Java 内存管理、HTTP 通信机制、业务逻辑、系统架构(缓存、数据库等)等等。
2. Tprofiler
TProfiler 是淘宝开源的一个可以在生产环境长期使用的性能分析工具。它同时支持剖析和采样两种方式,记录方法执行的时间和次数,生成方法热点、对象热点、线程状态分析等数据,为查找系统性能瓶颈提供数据支持。
TProfiler 在 JVM 启动时把时间采集程序注入到字节码中,整个过程无需修改应用源码。运行时会把数据写到日志文件,一般情况下每小时输出的日志小于 50M。目前 TProfiler 已应用于淘宝的核心 Java 前端系统,部署后低峰期对应用响应时间影响 20% 高峰期对吞吐量大约有 30% 的降低。
2.1 配置部署
- 安装 TProfiler
直接下载完整安装包或者下载源码运行 package.bat 脚本或者执行 mvn assembly:assembly命令生成 tprofiler.jar 即可。 - 配置 profile.properties
profile.properties 作为 tprofiler.jar 的配置文件,可以根据实际情况进行调整。
-
#log file name
-
logFileName = tprofiler.log
-
methodFileName = tmethod.log
-
samplerFileName = tsampler.log
-
#basic configuration items
-
startProfTime = 19:00:00 #开始进行profile的时间
-
endProfTime = 23:00:00 #结束profile的时间
-
eachProfUseTime = 5 #profile时间长度(单位秒)
-
eachProfIntervalTime = 50#两次profile的时间间隔(单位秒)
-
samplerIntervalTime = 20 #两次采样的时间间隔
-
port = 50000
-
debugMode = false
-
needNanoTime = false
-
ignoreGetSetMethod = true
-
#file paths
-
logFilePath = /home/admin/tprofiler/logs/${logFileName}
-
methodFilePath = /home/admin/tprofiler/logs/${methodFileName}
-
samplerFilePath = /home/admin/tprofiler/logs/${samplerFileName}
-
#include & excludes items
-
excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader
-
includePackageStartsWith = com.taobao;com.taobao.common
-
excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject
- 配置 JVM 进程
在 JVM 启动参数中添加,然后重启应用。
-
-javaagent:/home/admin/tprofiler/lib/tprofiler.jar
-
-Dprofile.properties=/home/admin/tprofiler/lib/profile.properties
- 远程操作
-
java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient [192.168.132.*.*] [port] status #远程查看状态操作
-
java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient [192.168.132.*.*] [port] start #远程开始操作
-
java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient [192.168.132.*.*] [port] stop #远程停止操作
-
java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient [192.168.132.*.*] [port] flushmethod #远程刷出方法数据
2.2 TProfiler 性能方法的采集
TProfiler 能够生成日志:tmethod.log、tprofiler.log、tsampler.log。
普通方法、线程信息统计
执行如下命令,会生成 method.log 和 thread.log:
java -cp ../lib/tprofiler-1.0.1.jar com.taobao.profile.analysis.SamplerLogAnalysis tsampler.log method.log thread.log
method.log 文件格式说明:
-
方法信息 采样过程中方法出现次数
-
org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1131) 54
-
org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498) 54
-
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) 36
-
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:44) 36
-
org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:163) 36
-
org.jboss.netty.channel.socket.nio.SelectorUtil.select(SelectorUtil.java:38) 36
-
org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:67) 36
-
com.alibaba.dubbo.remoting.exchange.support.DefaultFuture$RemotingInvocationTimeoutScan.run(DefaultFuture.java:300) 18
-
com.taobao.profile.thread.TimeControlThread.run(TimeControlThread.java:116) 18
-
com.taobao.profile.thread.SamplerThread.run(SamplerThread.java:57) 18
-
com.taobao.profile.thread.TimeControlThread.await(TimeControlThread.java:84) 18
-
com.taobao.profile.thread.InnerSocketThread.run(InnerSocketThread.java:44) 18
-
com.taobao.profile.thread.DataDumpThread.run(DataDumpThread.java:69) 17
-
org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:492) 1
-
org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363) 1
-
com.taobao.profile.thread.DataDumpThread.run(DataDumpThread.java:62) 1
thread.log 文件格式说明:
-
线程信息 采样过程中线程出现次数
-
26 ZkClient-EventThread-26-192.168.150.149:2181 WAITING 18
-
3 Finalizer WAITING 18
-
47 DubboResponseTimeoutScanTimer TIMED_WAITING 18
-
36 New I/O client worker #1-1 RUNNABLE 18
-
29 DubboRegistryFailedRetryTimer-thread-1 TIMED_WAITING 18
-
30 ZkClient-EventThread-30-192.168.150.149:2181 WAITING 18
-
27 main-SendThread(192.168.150.149:2181) RUNNABLE 18
-
31 main-SendThread(192.168.150.149:2181) RUNNABLE 18
-
8 TProfiler-DataDump TIMED_WAITING 18
-
52 DestroyJavaVM RUNNABLE 18
-
12 VM JFR Buffer Thread RUNNABLE 18
-
49 global-client-idle-conn-cleanup-scheduler-4-1 TIMED_WAITING 18
-
5 Signal Dispatcher RUNNABLE 18
-
40 commons-pool-EvictionTimer TIMED_WAITING 18
-
23 main-EventThread WAITING 18
-
10 JFR request timer WAITING 18
-
6 TProfiler-TimeControl TIMED_WAITING 18
-
32 main-EventThread WAITING 18
-
46 jupiter-0-ClientToProxyAcceptor-0 RUNNABLE 18
-
9 TProfiler-Sampler RUNNABLE 18
-
28 main-EventThread WAITING 18
-
2 Reference Handler WAITING 18
-
45 ObjectCleanerThread TIMED_WAITING 18
-
22 main-SendThread(192.168.150.199:2181) RUNNABLE 18
-
19 RMI TCP Accept-0 RUNNABLE 18
-
48 print-cache-job-1 TIMED_WAITING 18
-
7 TProfiler-InnerSocket RUNNABLE 18
-
43 dubbo-remoting-client-heartbeat-thread-2 WAITING 18
-
50 rxnetty-nio-eventloop-2-1 RUNNABLE 18
-
33 DubboSaveRegistryCache-thread-1 WAITING 18
-
42 New I/O client worker #1-2 RUNNABLE 18
-
17 RMI TCP Accept-0 RUNNABLE 18
-
18 RMI TCP Accept-18090 RUNNABLE 18
-
34 DubboClientReconnectTimer-thread-1 WAITING 10
-
54 jupiter-0-ClientToProxyWorker-1 RUNNABLE 10
-
60 jupiter-0-ProxyToServerWorker-1 RUNNABLE 10
-
58 jupiter-0-ProxyToServerWorker-2 RUNNABLE 10
-
53 jupiter-0-ClientToProxyWorker-0 RUNNABLE 10
-
41 DubboClientReconnectTimer-thread-2 TIMED_WAITING 10
-
57 jupiter-0-ProxyToServerWorker-0 RUNNABLE 10
-
55 jupiter-0-ClientToProxyWorker-2 RUNNABLE 10
-
56 jupiter-0-ClientToProxyWorker-3 RUNNABLE 10
-
59 jupiter-0-ProxyToServerWorker-3 RUNNABLE 10
-
41 DubboClientReconnectTimer-thread-2 WAITING 8
-
34 DubboClientReconnectTimer-thread-1 TIMED_WAITING 8
-
37 DubboClientHandler-192.168.149.183:20880-thread-1 TIMED_WAITING 3
-
35 NettyClientBoss-thread-1 TIMED_WAITING 2
-
44 DubboClientHandler-192.168.150.149:20892-thread-1 TIMED_WAITING 2
-
35 NettyClientBoss-thread-1 TERMINATED 1
- top 热点方法、热点对象信息统计
执行如下命令,生成 topmethod.log 和 topobject.log 文件
java -cp ../lib/tprofiler-1.0.1.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log topmethod.log topobject.log
topmethod.log 文件格式说明:
-
方法信息 执行次数 平均执行时间 全部执行时间
-
cn/com/company/xqy/framework/cacheframework/rediscache/RedisFactory:getJedisCache:107 750 7 5451
-
cn/com/company/xqy/framework/cacheframework/rediscache/ShardedJedisClient:checkObjectKeyExisted:243 516 3 1524
-
cn/com/company/xqy/framework/cacheframework/rediscache/ShardedJedisClient:get:180 563 3 1493
-
cn/com/company/xqy/framework/cacheframework/rediscache/ShardedJedisClient:getString:839 572 2 1199
-
cn/com/company/xqy/framework/cacheframework/rediscache/ShardedJedisClient:incr:1144 353 2 727
-
cn/com/company/xqy/jupiter/gateway/netty/ClientToProxyHandler:channelRead0:357 356 2 646
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/pre/RateLimiterRequestFilter:doFilter:114 358 1 533
-
cn/com/company/xqy/framework/cacheframework/rediscache/ShardedJedisClient:ttl:1176 214 2 447
-
cn/com/company/xqy/jupiter/gateway/netty/ClientToProxyHandler$2:onCompleted:354 263 1 316
-
cn/com/company/xqy/framework/cacheframework/rediscache/RedisUtil:unseriallize:78 80 3 258
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/pre/AuthenticationFilter:doFilter:126 310 1 237
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/HttpRequestFilterChain:doFilter:72 358 0 137
-
cn/com/company/xqy/jupiter/gateway/component/cache/service/VaultCacheServiceImpl:getAppSecretByAppKey:52 237 0 73
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender:writeRequest:183 25 2 56
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/ProxyToServerHandler:channelRead0:70 266 0 45
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/log/TraceUtils:createTraceId:39 1 44 44
-
cn/com/company/xqy/jupiter/gateway/util/ComponentUtil:getRedisConfig:52 1 44 44
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender:sendRequest:98 50 1 40
-
cn/com/company/xqy/jupiter/gateway/util/ToString:toString:20 7 5 37
-
cn/com/company/xqy/framework/log/LoggerUtils:info:31 13 2 29
-
cn/com/company/xqy/jupiter/gateway/netty/HttpProxyServer$1:initChannel:142 12 2 28
-
cn/com/company/xqy/jupiter/gateway/netty/uri/PatternRequest:matchingPattern:53 9 2 22
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender:sendRequestWithNewChannel:124 9 2 19
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/servlet/NettyHttpServletRequest:getParameter:114 4 4 15
-
cn/com/company/xqy/framework/log/LoggerUtils:format:150 5 3 14
-
cn/com/company/xqy/jupiter/gateway/component/cache/service/ApiAuthSerivceImpl:checkApiAuth:54 271 0 13
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/pre/AuthenticationFilter:getAppSecret:188 239 0 11
-
cn/com/company/xqy/jupiter/gateway/netty/HttpProxyServer:newHttpServerCodec:171 3 3 9
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/pre/AuthenticationFilter:buildParams:246 5 2 8
-
cn/com/company/xqy/jupiter/gateway/component/compatible/CompatibleRequestUtil:fetchParameterModel:127 7 1 7
-
cn/com/company/xqy/jupiter/gateway/netty/filter/HttpFiltersRunner:clientToProxyRequest:35 358 0 7
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/FilterUtil:getHeaderValue:30 1 6 6
-
cn/com/company/xqy/jupiter/gateway/util/PathUtils:getRegularPath:27 2 3 5
-
cn/com/company/xqy/jupiter/gateway/netty/uri/ExtendedAntPathMatcher:match:36 2 3 5
-
cn/com/company/xqy/framework/cacheframework/rediscache/RedisFactory:returnResource:136 3 2 5
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/lb/WeightedRoundRobinLoadBalance:gcd:39 2 2 4
-
cn/com/company/xqy/jupiter/gateway/component/security/sign/HmacSHA256Signature:sign:38 2 2 4
-
cn/com/company/xqy/jupiter/gateway/netty/ClientToProxyHandler:channelInactive:395 14 0 4
-
cn/com/company/xqy/jupiter/gateway/netty/channel/Channels:isChannelValid:32 1 4 4
-
cn/com/company/xqy/jupiter/gateway/netty/channel/ChannelManager:tryToOfferChannelToPool:142 1 3 3
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/ProxyToServerHandler:channelRead0:24 266 0 3
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender:printProxyToServerLog:215 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/uri/UrlPathUtils:getCanonicalizedPath:31 3 1 2
-
cn/com/company/xqy/jupiter/gateway/component/cache/RouteCacheComponent:getAllApiConfigs:225 355 0 2
-
cn/com/company/xqy/jupiter/gateway/component/SpringContextHolder:getBean:20 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/servlet/NettyHttpServletRequest:getHeader:162 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/lb/Server:hashCode:169 1 2 2
-
cn/com/company/xqy/jupiter/client/utils/UrlUtils:normalizedPath:62 1 2 2
-
cn/com/company/xqy/framework/cacheframework/rediscache/RedisFactory:getShardedJedisPool:111 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/ClientToProxyHandler:checkPathValidity:378 10 0 2
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/log/TraceLogContext:getTraceIdForLog:80 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/ClientToProxyHandler:channelRead0:54 356 0 2
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyResponseFuture:<init>:50 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/filter/HttpFiltersAdapter:<init>:29 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender:sendRequestWithOpenChannel:142 25 0 1
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/HttpRequestUtils:isJsonRequest:62 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/lb/WeightedRoundRobinLoadBalance:select:96 2 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/lb/WeightedRoundRobinLoadBalance:getGCDForServers:54 2 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/HttpProxyServer$1:initChannel:130 12 0 0
-
cn/com/company/xqy/jupiter/gateway/component/compatible/CompatibleRequestUtil:getParameterAppKey:24 5 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/channel/ChannelUtils:getTraceIdForLog:32 1 0 0
-
cn/com/company/xqy/jupiter/gateway/component/compatible/CompatibleRequestUtil:getParameterVersion:64 1 0 0
-
cn/com/company/xqy/jupiter/gateway/component/security/sign/AbstractSignature:sign:57 2 0 0
-
cn/com/company/xqy/jupiter/gateway/component/security/sign/AbstractSignature:sign:46 2 0 0
-
cn/com/company/xqy/jupiter/gateway/component/compatible/CompatibleRequestUtil:getParameterTimestamp:54 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/pre/ParameterValidationFilter:doFilter:74 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/SimpleChannelFutureListener:operationComplete:8 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/SimpleChannelFutureListener:operationComplete:18 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender$2:onSuccess:175 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/HttpProxyServer:access$200:38 3 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/filter/chain/request/pre/AuthenticationFilter:computeSign:165 2 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/filter/HttpFiltersRunner:<init>:22 1 0 0
-
cn/com/company/xqy/jupiter/gateway/util/ComponentUtil:getRedisCacheClient:48 1 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyRequestSender:sendRequest:58 50 0 0
-
cn/com/company/xqy/framework/cacheframework/rediscache/ShardedJedisClient:isExist:227 516 0 0
-
cn/com/company/xqy/jupiter/gateway/netty/filter/HttpFiltersProviderAdapter:filterRequest:13 1 0 0
topobject.log 文件格式说明:
-
方法信息 执行次数 平均执行时间 全部执行时间
-
cn/com/company/xqy/jupiter/gateway/netty/upstream/NettyResponseFuture:<init>:50 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/filter/HttpFiltersAdapter:<init>:29 1 2 2
-
cn/com/company/xqy/jupiter/gateway/netty/filter/HttpFiltersRunner:<init>:22 1 0 0
这是压测多次时随机挑选的一次结果。热点方法和热点代码尤其值得我们关注,因此及其有可能是代码瓶颈所在。这些热点代码一般要么是平均响应时间高一些,要是产生的临时对象会多一些。
3. Jprofiler
JProfiler 是由 ej-technologies 公司开发的一款性能瓶颈分析工具。它是一款优秀的商业软件,功能非常丰富,因此具备一些免费软件所不具备的功能。Jprofiler 提供的主要功能有内存视图、CPU 视图、线程视图、堆遍历器(Heap Walker)等。
3.1 Jprofiler 使用
CPU 视图可以查看各个函数的 CPU 占用时间。Hot Spots 显示消耗时间最多的方法的列表,它不仅给出了单个函数的 CPU 使用时间和方法调用次数,同时还能显示函数调用堆栈信息,方便定位问题。
在线程视图可以统计并查询当前 JVM 所有线程的运行状态,线程持有锁的状态并且可 dump 线程。
4. Arthas
Arthas 是阿里最近刚刚开源的 Java 生成环境诊断工具。
Arthas 支持在 Linux/Unix/Mac 等平台上进行一键安装,现在处于试用于反馈阶段,感兴趣的同学可以自己研究试用。
5.Conclusion
本文介绍了常用的性能分析工具和故障排查工具,希望可以帮助开发人员在排查性能问题的时候快速定位到性瓶颈。每个工具都有其优势与劣势,只有更好了解问题所出现的场景,理清解决问题的思路,才能最大化的发挥工具的价值。