JVM性能分析神器async-profiler - 玩转JVM

2019/04/19 22:41
阅读数 72

async-profiler可以跟踪以下类型的事件:

  • CPU性能分析
  • 硬件和软件性能计数器,比如缓存遗漏、分支遗漏、页面错误、上下文切换等等。
  • Java堆中的分配
  • 满足锁尝试,包括Java对象监视器和重入锁

如何使用:

[root@mvxl52738 async-profiler]# ./profiler.sh
Usage: ./profiler.sh [action] [options] <pid>
Actions:
  start               开始分析并立即返回
  stop               停止分析
  status            打印分析状态
  list               目标JVM支持的列表分析事件
  collect          在指定的时间内收集概要文件然后停止(默认动作)
Options:
  -e event          分析事件: cpu|alloc|lock|cache-misses etc.
  -d duration      分析持续时间,以秒为单位
  -f filename      将输出转储到文件
  -i interval         采样间隔,纳秒
  -j jstackdepth  最大Java栈深度
  -b bufsize        帧缓冲区大小
  -t                      每一个堆栈跟踪都将以一个线程处理
  -s                     简单的类名而不是FQN
  -o fmt[,fmt...]    输出格式: summary|traces|flat|collapsed|svg|tree|jfr

示例:    ./profiler.sh -d 30 -f profile.svg 3456
         ./profiler.sh start -i 999000 jps
         ./profiler.sh stop -o summary,flat jps

在Linux 4.6中,使用来自非根进程的perf_events来捕获内核调用堆栈需要设置两个运行时变量。您可以使用sysctl设置它们,或者如下所示:

# perf_event_paranoid用于限制访问性能计数器的权限
# 0:仅允许访问用户空间的性能计数器
# 1:内核与用户空间的性能计数器都可以访问
# 2:仅允许访问特殊的CPU数据(不包括跟踪点)
# -1:不限制
[root@mvxl52738 ~]# echo 1 > /proc/sys/kernel/perf_event_paranoid
# 是否启用kptr_restrice,此功能为安全性功能,用于屏蔽内核指针。
# 0:该特性被完全禁止;
[root@mvxl52738 ~]# echo 0 > /proc/sys/kernel/kptr_restrict

CPU性能分析

# 默认情况下,分析频率是100赫兹(每10毫秒的CPU时间)。下面是打印到Java应用程序终端的输出示例:
[root@mvxl52738 async-profiler]# ./profiler.sh start 57951
[root@mvxl52738 async-profiler]# ./profiler.sh stop 57951
--- Execution profile ---
Total samples:         3
Non-Java:              1 (33.33%)

Frame buffer usage:    0.0026%

--- 10492147 ns (33.57%), 1 sample
  [ 0] finish_task_switch_[k]
  [ 1] __schedule_[k]
  [ 2] schedule_[k]
  [ 3] futex_wait_queue_me_[k]
  [ 4] futex_wait_[k]
  [ 5] do_futex_[k]
  [ 6] sys_futex_[k]
  [ 7] system_call_fastpath_[k]
  [ 8] pthread_cond_timedwait@@GLIBC_2.3.2
  [ 9] os::sleep(Thread*, long, bool)
  [10] JVM_Sleep
  [11] java.lang.Thread.sleep
  [12] com.alibaba.dubbo.remoting.exchange.support.DefaultFuture$RemotingInvocationTimeoutScan.run
  [13] java.lang.Thread.run

--- 10407032 ns (33.30%), 1 sample
  [ 0] java_lang_Thread::set_thread_status(oopDesc*, java_lang_Thread::ThreadStatus)
  [ 1] java.lang.Thread.sleep
  [ 2] com.alibaba.dubbo.remoting.exchange.support.DefaultFuture$RemotingInvocationTimeoutScan.run
  [ 3] java.lang.Thread.run

--- 10351666 ns (33.12%), 1 sample
  [ 0] CompactibleFreeListSpace::free() const
  [ 1] CompactibleFreeListSpace::used() const
  [ 2] PerfLongVariant::sample()
  [ 3] StatSamplerTask::task()
  [ 4] PeriodicTask::real_time_tick(int)
  [ 5] WatcherThread::run()
  [ 6] java_start(Thread*)
  [ 7] start_thread

          ns  percent  samples  top
  ----------  -------  -------  ---
    10492147   33.57%        1  finish_task_switch_[k]
    10407032   33.30%        1  java_lang_Thread::set_thread_status(oopDesc*, java_lang_Thread::ThreadStatus)
    10351666   33.12%        1  CompactibleFreeListSpace::free() const

# 或者
[root@mvxl52738 async-profiler]# ./profiler.sh -d 30 57951

锁对象查看 -e lock

类型对象生成统计 -e alloc

[root@mvxl52738 async-profiler]# ./profiler.sh start  -e alloc 57951
Started [alloc] profiling
[root@mvxl52738 async-profiler]# ./profiler.sh stop  -e alloc 57951
--- Execution profile ---
Total samples:         5

Frame buffer usage:    0.0062%

--- 2798312 bytes (56.41%), 1 sample
  [ 0] byte[]
  [ 1] java.lang.StringCoding$StringEncoder.encode
  [ 2] java.lang.StringCoding.encode
  [ 3] java.lang.StringCoding.encode
  [ 4] java.lang.String.getBytes
  [ 5] com.alibaba.rocketmq.remoting.protocol.RemotingSerializable.encode
  [ 6] com.alibaba.rocketmq.client.impl.MQClientAPIImpl.sendHearbeat
  [ 7] com.alibaba.rocketmq.client.impl.factory.MQClientInstance.sendHeartbeatToAllBroker
  [ 8] com.alibaba.rocketmq.client.impl.factory.MQClientInstance.sendHeartbeatToAllBrokerWithLock
  [ 9] com.alibaba.rocketmq.client.impl.factory.MQClientInstance$4.run
  [10] java.util.concurrent.Executors$RunnableAdapter.call
  [11] java.util.concurrent.FutureTask.runAndReset
  [12] java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301
  [13] java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run
  [14] java.util.concurrent.ThreadPoolExecutor.runWorker
  [15] java.util.concurrent.ThreadPoolExecutor$Worker.run
  [16] java.lang.Thread.run

--- 1610928 bytes (32.48%), 3 samples
  [ 0] char[]
  [ 1] java.lang.AbstractStringBuilder.<init>
  [ 2] java.lang.StringBuilder.<init>
  [ 3] com.alibaba.dubbo.remoting.transport.DecodeHandler.decode
  [ 4] com.alibaba.dubbo.remoting.transport.DecodeHandler.received
  [ 5] com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run
  [ 6] java.util.concurrent.ThreadPoolExecutor.runWorker
  [ 7] java.util.concurrent.ThreadPoolExecutor$Worker.run
  [ 8] java.lang.Thread.run

--- 551112 bytes (11.11%), 1 sample
  [ 0] char[]
  [ 1] java.util.Arrays.copyOf
  [ 2] java.lang.AbstractStringBuilder.ensureCapacityInternal
  [ 3] java.lang.AbstractStringBuilder.append
  [ 4] java.lang.StringBuilder.append
  [ 5] com.meicloud.ecu.fc.impl.utils.RespPackUtil.execInvokeService
  [ 6] com.meicloud.ecu.fc.impl.facade.impl.OrderReportFacadeImpl.selectItem
  [ 7] com.alibaba.dubbo.common.bytecode.Wrapper4.invokeMethod
  [ 8] com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke
  [ 9] com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke
  [10] com.alibaba.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke
  [11] com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke
  [12] com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke
  [13] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [14] com.alibaba.dubbo.monitor.support.MonitorFilter.invoke
  [15] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [16] com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke
  [17] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [18] com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke
  [19] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [20] com.alibaba.dubbo.rpc.filter.ContextFilter.invoke
  [21] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [22] com.alibaba.dubbo.rpc.filter.GenericFilter.invoke
  [23] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [24] com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke
  [25] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [26] com.alibaba.dubbo.rpc.filter.EchoFilter.invoke
  [27] com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke
  [28] com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply
  [29] com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest
  [30] com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received
  [31] com.alibaba.dubbo.remoting.transport.DecodeHandler.received
  [32] com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run
  [33] java.util.concurrent.ThreadPoolExecutor.runWorker
  [34] java.util.concurrent.ThreadPoolExecutor$Worker.run
  [35] java.lang.Thread.run

       bytes  percent  samples  top
  ----------  -------  -------  ---
     2798312   56.41%        1  byte[]
     2162040   43.59%        4  char[]

作为java-agent启动

# event=alloc 代替 -e alloc  , file=profile.svg 代替 -f profile.svg 
java -agentpath:/tmp/async-profiler/build/libasyncProfiler.so=start,svg,file=profile.svg

可视化火焰图像

[root@mvxl52738 async-profiler]# ./profiler.sh  -d 180 -f /tmp/flamegraph.svg 57951 --title fc

横条越长,代表占用的cpu时间是最多

火焰图
展开阅读全文
打赏
0
0 收藏
分享
加载中
更多评论
打赏
0 评论
0 收藏
0
分享
返回顶部
顶部