Java-debug-tool
github:https://github.com/pandening/Java-debug-tool
Java-debug-tool 是什么?
Java-debug-tool 是一个适用于JVM的在线动态调试工具,可以用来追踪方法调用、度量代码性能、监控系统指标等。
运行要求
java 8 +
注意事项
在使用Java-debug-tool之前,请确保已经阅读并了解了Java-debug-tool的注意事项:
- 确保你已经在线下环境使用,并对Java-debug-tool已经有清晰的认知;
- 禁止对递归函数进行调试;
- 不建议对具有循环的方法进行调试,损耗是巨大的,如果循环次数未知,或者循环次数较大(比如10次),则禁止调试(后续会优化,以本文档为准);
- Agent挂载和动态字节码增强均会对目标JVM产生性能损耗,在使用Java-debug-tool进行调试之前,确保已将调试机器的流量调小;
安装 Java-debug-tool
下载 & 安装 Java-debug-tool
wget https://github.com/pandening/storm-ml/releases/download/8.0/javadebug-tool-install.shsh javadebug-tool-install.sh
挂载到目标JVM
./javadebug-agent-launch.sh pid@ip:port ./javadebug-agent-launch.sh pid@ip./javadebug-agent-launch.sh pid
如果没有指定端口,则默认端口号为:11234.
启动调试客户端
./javadebug-client-launch.sh ./javadebug-client-launch.sh ip:port
Java-debug-tool使用方法
Java-debug-tool命令使用详解
Java-debug-tool是一种支持方法级别动态追踪的技术工具,它具备动态获取方法执行视图的能力,提供了非常丰富的调试信息以供开发人员对问题进行快速排查;Java-debug-tool命令具有非常高的聚合性,使用一个命令可以获取到的信息非常多;如何记住命令参数是一个亟待解决的问题,下面将对每个命令从基础到高级用法进行详细介绍,以期能使开发人员可以灵活使用Java-debug-tool来进行问题排查。
在目标JVM中查找类
findClass 命令用来在目标JVM中查找一个类的信息,这是本文介绍的命令中最简单最直接的一个命令,它的用法很简单,指定一个类名即可实现信息获取,当然,简单的命令却可以获取到非常重要的信息,下面罗列出了该命令可以获取到的类的相关信息。
- 类是否已经被加载;
- 加载类的类加载器;
- 类来源的资源包(jar包);
- 类包含的方法列表;
- 类包含的内部类列表;
下面是几种使用该命令的样式:
直接指定类全限定名进行查找;
fc -class java.lang.String
指定类名进行查找;
fc -class String
使用正则进行匹配;
fc -r java.lang.*
当匹配了多个类的时候,默认返回匹配到的前10个类的信息,当然可以指定需要返回的类的数量;
fc -class String -l 2
这个命令非常简单,可以在处理一些类冲突等问题的时候使用,这个简单的命令还会和获取方法运行时视图的命令息息相关,这一点后续再谈,下面是一张运行该命令的展示图:
查找类命令
动态获取方法执行视图
这是Java-debug-tool中最为复杂,也是最为有用的命令,这个命令的特点是使用起来非常简单,但是想要发挥它真正的威力,或者是排查一些复杂问题的场景下还是需要学习一下,下面就从最简单的用法开始,逐步深入的介绍这个命令的精华所在。 在此之前,先简单描述一下该命令能输出一些什么样的调试信息,或者说,Java-debug-tool获取到的方法执行视图具体是什么样子的:
方法执行视图
方法执行视图可以获取到的信息如下:
- 正在调试的方法信息(类.方法 调用线程);
- 方法调用堆栈;
- 调试耗时,包括对目标JVM造成的STW时间;
- 方法入参,包括入参的类型及参数值;
- 方法的执行路径;
- 代码执行耗时;
- 局部变量信息;
- 方法返回结果;
- 方法抛出的异常;
- 对象字段值快照;
下面,就由浅入深的介绍一下该命令的具体使用方法:
我只想获取一次目标方法的执行视图
好吧,这是最简单的命令使用方法,也是开启动态获取方法执行视图旅行的开始:
mt -c io.javadebug.agent.Agent -m loadField
-c参数指定需要观察的类(全限定名),-m参数指定需要观察的具体的方法,这样就可以完成一次方法执行视图的获取。 当然,某些情况下可能会出现意外,更为复杂的场景先不考虑,一个比较明显的意外就是当目标方法重载了该怎么办?这个时候Java-debug-tool无法确定需要获取哪一个方法的执行视图,本次调试只能以失败告终,这个时候,上面介绍的fc命令就派上用场了,是否还记得fc命令可以获取到类的方法列表,看下面标红的信息(每个方法下面都会有),这个信息是方法的“签名”信息,每个方法都独一无二,当方法重载的情况下,只需要将方法”签名“指定为-d参数,即可顺利完成命令调试。
获取到的方法签名
就像这样:
mt -c io.javadebug.agent.Agent -m loadField -d (Ljava/lang/String;)[B
这种入门级的命令使用下,Java-debug-tool是无法确定你的调试意图的,所以只要方法被调用了,就会结束调试,将获取到的方法执行视图返回给你,所以,你需要掌握更多的关于该命令的技能,才能向Java-debug-tool表达你明确的调试意图。
我想要获取一次正常返回结果的目标方法执行视图
这其实也不算一种明确的调试意图,只是告诉Java-debug-tool起码我需要的是一次方法正常返回值的执行视图,而那些抛出异常的方法执行视图需要过滤掉。-t参数用于指定你的调试意图,这种”方法正常返回结果“的调试意图形象的称为"return":
mt -c io.javadebug.agent.Agent -m loadField -t return
看起来也比较简单,没有特别难理解的地方,虽然简单,却是你使用Java-debug-tool发出的第一个具备自主调试意图的命令,你主动告诉Java-debug-tool,我需要一次方法正常退出的执行视图,如果你觉得这种体验非常奇妙,那么接下来的命令使用将打开你新世界的大门。
我想要获取一次抛出异常的目标方法执行视图
与”方法正常退出“相比,”方法抛出异常“貌似更符合我们进行问题排查的场景描述,更具有针对性,毕竟,方法大多数情况下都是正常退出的,而抛出异常则认为方法无法处理(主动抛出异常),或者遇到了运行时异常(被动抛出),抛出异常的频率应该是极低的甚至是需要避免的,因而获取一次”方法抛出异常“的方法执行视图貌似更有价值,下面是向Java-debug-tool发出这种调试意图的命令样式:
mt -c io.javadebug.agent.Agent -m loadField -t throw
看起来除了-t变成了"throw"之外,和”方法正常退出“没有什么区别,确实如此,Java-debug-tool期望使用极简的命令实现复杂的功能,这种简洁对于快速排查问题是有必要的。
我想要获取一次抛出了指定异常的目标方法执行视图
上面提到,方法抛出异常的原因有多种多样,不仅如此,抛出的异常类型也是多种多样的,在一些极端情况下,该死的方法频繁的抛出了多种不同的异常,搞得每次使用"throw"都无法获取到抛出某种类型的异常的方法执行视图,真是伤脑筋,还好Java-debug-tool考虑到了这种情况,在上一小节的基础上,只需要再指定一个参数-e即可实现这种获取”抛出指定异常“的方法执行视图,就像这样:
mt -c io.javadebug.agent.Agent -m loadField -t throw -e java.lang.NullPointerException
就像这个命令描述的一样,我想要获取一次抛出了”java.lang.NullPointerException“这种异常的方法执行视图,这样一看,我们的调试意图已经非常明确了。
我想要记录一些方法执行信息,稍后再进行分析
有时候我们需要收集多种情况的方法调用,对比分析得出结论,这种情况下”record“模式就派上用场了,当然该模式的用处不仅如此,后面再细说。”record“模式和它的名字一样,就是用来记录方法调用的,它的工作就是根据参数来记录方法执行视图,以供后面进行分析,目前分析这里还没有任何功能支持(比如对比多次方法调用视图),只能通过开发者自己进行分析。该命令首先需要记录执行视图,之后才能打开记录的视图进行分析,下面是记录方法执行视图的命令样式:
mt -c io.javadebug.agent.Agent -m loadField -t record -n 10 -time 5
-n参数可以指定需要录制的视图数量,-time参数指定需要执行录制的时间限制,只要其中一个条件满足,命令就会停止工作。上面这条命令的含义是说,对loadFile方法录制最多10次视图,执行时间限制在5秒,当然,-n参数和-time参数都是可选的,默认最多录制10条,最多录制10秒。录制完成之后,就可以对这些方法执行视图进行分析了,下面是挑选某一个视图的命令样式:
mt -c io.javadebug.agent.Agent -m loadField -t record -u 0
使用-u参数指定一个数字,这个数字就代表视图在存储时的数组下标,上面这条命令的含义是说,将刚才录制好的第0号视图调出来我分析一下,录制的流量会长期有效,这一点需要特别注意。
我想要获取一次特定参数的目标方法执行视图
就像上面说到的一样,大多数情况下,方法是正常退出的,问题就是虽然方法正常退出了,但是结果却不符合我们的预期,当然,这种时候使用上面提到的最为基础的命令即可进行一些问题排查,但是方法执行的路径和方法的入参强关联在一起,所以在调试的时候,特别希望能指定具体的参数来获取方法视图,这种场景Java-debug-tool描述为观察:”watch“,它的含义是等待某种事情发生的时候进行回调,更进一步,我们希望能获取到特定参数的方法执行视图。这种场景有点小复杂,但是不至于特别复杂,除了-t参数指定为”watch“之外,我们需要做的就是写一个Spring表达式,并通过-i参数告诉Java-debug-tool,这个表达式用来匹配参数,关于Spring表达式相关的技术,可以参考Spring Expression Language。不要太紧张,我们只需要非常少的表达式的知识即可实现我们筛选参数的目标。下面,我们就来实战一下:
mt -c io.javadebug.agent.Agent -m loadField -t watch -i #p0!=null&p1.length>0&&p2.getA().equals("Java-debug-tool")
Java-debug-tool已经将目标方法的参数列表名称编码处理,选定参数使用p开头,后面拼接上参数在参数列表中的顺序id(从0开始);比如p0选择的是方法的第一个参数,p2则是第三个参数,以此类推。 例子中的表达式的含义是:匹配这样一个方法调用,这个方法调用时,第一个参数不为null,并且第二个参数的length属性大于0(猜测是数组的长度大于0),并且第三个参数的a属性值为"Java-debug-tool"。 到此,我们貌似掌握了Java-debug-tool所有精华的部分,看起来到目前为止我们还没有遇到一个需要非常复杂的输入才能进行调试的场景,下面就来填补一下这个空缺,来点有意思的。
我想要触发一次目标方法执行
考虑一个场景,有一种参数执行完方法退出时不符合我们的预期,我们应该怎么使用Java-debug-tool来进行动态调试呢?"watch",这是目前为止大家能够想到的最为有力的方法,但是困难总是非常多的,恰好这种符合要求的参数执行的频率非常低,所以往往我们执行了很多次"watch"之后依然没有拿到结果,而是得到一个"命令执行超时"的可恶响应,这种情况下文会提到一种解决方案,本小节介绍一个更厉害的方法,你可以让方法按照你的预期参数执行一次,并且是立即执行。 这就有点意思了,和"watch"不一样的是,你可以得到一种”立即执行“的响应,不需要苦苦的等待甚至得到诸多”命令执行超时“的下场,这种模式称之为"custom",和名字一样,它是你自己私人定制的,这种场景稍微有点复杂,可以说是Java-debug-tool所有命令场景中最为复杂的,所以下面花点篇幅详细介绍一下,当然,Java-debug-tool很希望你永远用不到这个功能。
- 第一种获取方法”立即执行“效果的方法简单粗暴,它需要你将方法的参数提前进行编码,并将编码好的参数列表告诉Java-debug-tool,Java-debug-tool拿到参数之后就会在自己的线程内部发起一次方法调用,你需要清楚的知道,这种”立即执行“的代价很高,需要你充分考虑自己的调试场景,判断是否需要这么大张旗鼓的弄。参数列表编码的方法可以参考”io.javadebug.core.JacksonUtils“这个类中的serialize方法,下面是一个例子:
mt -c io.javadebug.agent.Agent -m loadField -t custom -i encoded-params
- 第二种方法则有趣得多,当然也具备一定的操作难度,上文中提到了"record"这种模式的调试技术,它可以记录一些方法执行数据,然后慢慢分析这些方法执行视图来发现问题所在,"record"的另外一种使用场景就是通过记录起来的方法调用参数,稍加改造后再发起一次方法调用。这种方法需要你已经执行过"record"模式,否则无法完成。假设已经执行过"record"了,那么接下来首先要做的就是通过-u参数指定需要改造的参数,-u参数在上文介绍”record“的时候已经介绍过,就不再介绍;
mt -c io.javadebug.agent.Agent -m loadField -t custom -u 1
当然,这种用法的意义不大,因为我们在介绍"record"的时候已经介绍过已经记录的请求可以随时查看,这种用法只是重新发起了一次请求罢了;Java-debug-tool提供了一种称为”claw script“的脚本语言来对选择的参数进行改造,这种脚本非常简单,没有学习成本,当然它能做的事情也非常有限,下面是这种"claw script"可以实现的功能:
- 对于参数是基本类型的,直接赋新值
p0 = "string" p1 = "100" p2 = "1.234"
- 对于参数是数组、list、set的,并且元素是基本类型的参数,直接赋值:
p0 = "[[1], [2], [3]]" p2 = "[[a], [b], [c]]" p3 = "[[1.23] [2.34] [3.45]]"
- 对于对象,属性是基本类型的,可以赋值:
p0.a = "100" p1.a.b = "Java-debug-tool"
除了这三种情况,其他赋值不支持。”claw script“的语法非常简单,p+参数列表顺序即可指定具体的参数,然后”=“代表需要赋值,值需要使用双引号包裹起来,数组、list、set的值需要使用"[]"包裹起来,每一个元素再使用"[]"括起来即可,对于对象赋值,直接使用字段名字即可。了解了”claw script“,下面来看看如何来进行命令发送。 你依然可以使用-u参数指定需要变更哪一个记录好的参数列表(默认是第一个记录),之后通过-claw参数指定一个参数列表变更脚本,即可实现:
mt -c io.javadebug.agent.Agent -m loadField -t custom -u 0 -claw p0="100",p1.a="1.234"
至此,你已经掌握了如何主动发起方法调用的方法了。这种情况下,一般通过两个人来完成调试,一个人执行该命令发起一次方法调用,而另外一个人则使用"watch"模式等待这次方法调用,这种团队协作模式还可以扩展到多人调试模式,一个人模拟方法调用,其他多个人观察方法执行视图,对此作出分析,集思广益快速排出问题。 如果没有那么多人配合你进行调试,那该怎么办呢?一个可行的办法是另外开一个窗口,使用"watch"模式等待即将模拟的方法调用,然后执行模拟方法执行命令,另外一个窗口中就会获取到方法执行视图信息,之后就可以进行问题排查了。Java-debug-tool提供了一种”自导自演“的调试方法,可以在发起方法调用的窗口中获取到方法的执行视图,下面就来介绍这种方法。
我想要触发一次目标方法执行,并且获取到该执行视图
通过上面的介绍,其实如何实现这种”自导自演“的技术已经非常明确了,Java-debug-tool要求你通过-e参数来提供一个Spring表达式,来匹配你即将发起调用的参数列表,实现上,Java-debug-tool将使用”watch“的套路来匹配方法调用:
mt -c io.javadebug.agent.Agent -m loadField -t custom -u 0 -claw p0="100",p1.a="1.234" -e #p0==100&&p1.getA().equals(1.234)
这样,你就可以在同一个窗口中拿到发起调用之后的方法执行视图了。
只有当某一行代码被执行了才返回
这其实也是一种意图,这个功能可以单独使用,也可以在watch/return/throw这几个模式下使用,单独使用时,模式为line,配合其他模式使用时,通过参数"tl"指定一个代码行号,如果输入的代码行号不合法,则Java-debug-tool有权利拒绝执行你的调试命令;
mt -c class -m method -t line -i lineNo
or
mt -c class -m method -t watch -i exp -tl lineNo
我只想看某一行的信息,不要方法执行的完整视图
其实Java-debug-tool的核心命令使用已经介绍完成,本小节包括下面的小节中介绍的都是一些”周边“功能。 考虑某种场景,你的目标方法非常长(几千行),那么方法执行的视图将非常长,这种时候找到具体的某一行的相关信息可不简单,这个时候,Java-debug-tool提供了一个参数可以来拯救你的视觉:
mt -c io.javadebug.agent.Agent -m loadField -l 10,12,50
-l参数用于指定需要输出调试信息的代码行号,比如上面的样例中,我们指定了仅需要输出视图中第10、12和50行的信息,其他行的信息不需要。
需要注意的是,这个功能和前一小节中提到的执行某一行代码才返回的功能是不一样的,前者是需要执行了指定的代码行才会返回,而本小节的功能仅仅是说只输出指定的行号的调试结果,这一点需要特别注意,不要对该功能产生什么误解;
当某一行的变量信息符合某种要求的时候才停止
和 "tl" 参数配合使用,使用 "te" 参数指定spring表达式,p + 数字(从0开始)表示指定的代码行上的变量,和watch里面的spring表达式含义一致,"te" 相当于是 "tl" 参数的增强,表示执行了 "tl" 指定的代码行,并且这一行的变量信息符合某种要求的时候才停止调试;
我想要对比方法执行前后的对象字段值
默认情况下,Java-debug-tool的方法视图包括方法执行前的对象字段值信息,如果你有需求需要在方法执行结束后查看对象字段值信息,那么可以使用一个特殊的参数-s来指定:
mt -c io.javadebug.agent.Agent -m loadField -s fd
这样,你就可以获取到方法执行前后的目标对象(或者类的静态字段)的字段信息。
我想指定调试命令的运行时间
上面提到如果我们需要”watch“的参数迟迟得不到匹配,那么就会得到可恶的”命令执行超时“的响应,如果你的心狠一点,那么指定一个命令执行超时时间是可以在一定程度上避免这种情况的发生的:
mt -c io.javadebug.agent.Agent -m loadField -t watch -i #p0==100 -timeout 100
-timeout用于指定命令执行的超时时间,只要指定了合法的值,Java-debug-tool就不会使用它的”两阶段超时协议“对你的命令进行干预,比如上面的样例代表我允许这个命令最多执行100秒,当然可能不是精确的100秒,因为Java-debug-tool的超时检测是有一定间隔的。
类热替换及回滚
类热替换是指在运行时将类的字节码替换掉,使得某些方法的行为发生改变,Java-debug-tool支持这种替换,并且操作起来非常简单:
rdf -p [className1:class1Path className1:class2Path]
类回滚在Java-debug-tool中指将类的字节码回退到最初的版本,无论是方法执行视图获取,还是类热替换,都会更新类的字节码,如果想要回退到原来的版本,则执行类回滚命令即可实现:
back -c ClassName,ClassName
这样,类就会和原来一模一样的工作了。
性能数据获取
thread命令
thread命令可以获取到JVM运行时的线程相关信息,目前Java-debug-tool提供两种信息,一种称为topN busy thread,另外一种是获取指定状态的线程信息:
- thread -top n
thread -top 2---------------------------------------------------------------------------------------------Command :thRound :2ClientId :10001ClientType :client:0Version :version:1CommandCost :110 (ms)STW_Cost :0 (ms)Time: : Mon Dec 23 12:10:08 CST 2019---------------------------------------------------------------------------------------------"Update-Scheduler-44-thread-1" Id=99 TIMED_WAITING cpu consume pct = 23% Status = TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@18589627 at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@18589627 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) 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)"java-debug-business-execute-thread-1" Id=400 RUNNABLE cpu consume pct = 21% Status = RUNNABLE at sun.management.ThreadImpl.getThreadInfo1(Native Method) at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:172) at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:139) at io.javadebug.core.command.perf.ThreadUtils.getThreadStackTrace(ThreadUtils.java:254) at io.javadebug.core.command.perf.ThreadCommand.handleTopNBusyThreadReq(ThreadCommand.java:118) at io.javadebug.core.command.perf.ThreadCommand.execute(ThreadCommand.java:82) at io.javadebug.core.handler.CommandHandler.handleCommand(CommandHandler.java:884) at io.javadebug.core.handler.CommandHandler.access$300(CommandHandler.java:120) at io.javadebug.core.handler.CommandHandler$4.execute(CommandHandler.java:617) at io.javadebug.core.handler.StopAbleRunnable.run(StopAbleRunnable.java:101) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)---------------------------------------------------------------------------------------------
- thread -status R,W,TW,B
th -status R---------------------------------------------------------------------------------------------Command :thRound :4ClientId :10001ClientType :client:0Version :version:1CommandCost :341 (ms)STW_Cost :0 (ms)Time: : Mon Dec 23 12:11:00 CST 2019---------------------------------------------------------------------------------------------"Signal Dispatcher" Id=5 RUNNABLE Status = RUNNABLE"Attach Listener" Id=50 RUNNABLE Status = RUNNABLE"JavaDebug-NettyServer-Boss-Worker-1" Id=390 RUNNABLE Status = RUNNABLE (in native) at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62) at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:756) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:411) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) at java.lang.Thread.run(Thread.java:745)"JavaDebug-NettyServer-EventLoop-Worker-2" Id=399 RUNNABLE Status = RUNNABLE (in native) at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62) at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:756) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:411) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) at java.lang.Thread.run(Thread.java:745)....
两种模式均可获取到线程的堆栈信息,topN busy模式下还可以看到线程占用的CPU时间占比;
cputime命令
cputime这个命令一开始只是为了获取到JVM在运行时的CPU消耗时间,但目前已经演变成获取JVM运行时性能数据的重要命令,它可以获取到包括CPU消耗时间、每秒上下文切换数等性能数据,使用方法比较简单:
ct -o csv -pr [qps]
-pr参数可以不指定,如果指定了,则会将每请求消耗的CPU时间计算出来;下面是获取到的数据展示:
---------------------------------------------------------------------------------------------命令 :ct命令执行Round :4客户端ID :10000客户端类型 :client:1协议版本 :version:1命令耗时 :31088 (ms)STW时间 :0 (ms)---------------------------------------------------------------------------------------------time;usr_ms;sys_ms;avg_usr_ms;avg_sys_ms;nivc_switch_per_sec;nvc_switch_per_sec0;2382.877;822.423;2467.859;844.902;39566;01;2600.853;871.493;2467.859;844.902;40607;02;2388.155;837.615;2467.859;844.902;44943;03;2437.694;841.379;2467.859;844.902;42330;04;2460.567;831.047;2467.859;844.902;42071;05;2488.811;866.828;2467.859;844.902;44123;06;2489.881;858.724;2467.859;844.902;43364;07;2515.122;834.155;2467.859;844.902;40659;08;2451.552;847.450;2467.859;844.902;42707;09;2465.109;834.627;2467.859;844.902;43187;010;2431.755;832.445;2467.859;844.902;39040;011;2439.897;839.241;2467.859;844.902;39886;012;2486.892;858.117;2467.859;844.902;47247;013;2367.548;823.389;2467.859;844.902;42589;014;2425.888;844.716;2467.859;844.902;44078;015;2378.448;798.451;2467.859;844.902;40246;016;2493.273;851.729;2467.859;844.902;39161;017;2399.780;817.940;2467.859;844.902;40146;018;2488.381;841.304;2467.859;844.902;40812;019;2422.649;843.157;2467.859;844.902;42935;020;2407.553;833.911;2467.859;844.902;41078;021;2573.902;857.470;2467.859;844.902;42127;022;2465.398;845.037;2467.859;844.902;41124;023;2460.814;828.538;2467.859;844.902;40826;024;2435.089;845.302;2467.859;844.902;42519;025;2457.967;855.893;2467.859;844.902;44206;026;2464.219;842.923;2467.859;844.902;40828;027;2653.804;903.895;2467.859;844.902;41220;028;2648.289;906.308;2467.859;844.902;41753;029;2539.227;846.505;2467.859;844.902;38800;0---------------------------------------------------------------------------------------------
可以将这些数据复制到一个csv文件中,就可以使用表格应用进行数据分析了;
自动化压测任务
Java-debug-tool目前支持使用wrk来进行自动化压力测试,并收集压测过程中的性能数据,这个过程是自动化的;使用方法如下:
- 第一步,需要在目标JVM上将Agent启动起来(参考javadebug-agent-launch.sh);
- 第二步,修改脚本wrk_auto_benchmark.sh中的相关参数,然后启动该脚本即可开始进行自动化压测任务;
完成后可以在输出的数据文件中获取到压测相关数据,比如:
---------------------------------------------------------------------------------------------命令 :ct命令执行Round :1客户端ID :10000客户端类型 :client:1协议版本 :version:1命令耗时 :32068 (ms)STW时间 :0 (ms)---------------------------------------------------------------------------------------------time;usr_ms;sys_ms;avg_usr_ms;avg_sys_ms;nivc_switch_per_sec;nvc_switch_per_sec0;734.134;250.487;773.960;261.970;7773;01;801.212;269.599;773.960;261.970;8270;02;748.510;247.528;773.960;261.970;6935;03;774.844;261.660;773.960;261.970;7977;04;779.654;255.044;773.960;261.970;6754;05;723.072;248.906;773.960;261.970;7047;06;820.681;282.503;773.960;261.970;10114;07;645.057;221.698;773.960;261.970;8234;08;822.068;269.626;773.960;261.970;7596;09;823.711;278.303;773.960;261.970;8237;010;773.915;257.265;773.960;261.970;7741;011;778.453;268.891;773.960;261.970;10030;012;742.778;252.428;773.960;261.970;8136;013;826.913;338.282;773.960;261.970;8585;014;778.857;267.881;773.960;261.970;8916;015;833.772;277.005;773.960;261.970;7853;016;825.108;277.563;773.960;261.970;8302;017;770.903;250.806;773.960;261.970;6282;018;843.271;271.170;773.960;261.970;7132;019;748.033;251.384;773.960;261.970;7196;020;744.455;243.919;773.960;261.970;7761;021;683.231;236.441;773.960;261.970;7422;022;740.329;261.148;773.960;261.970;8424;023;817.417;282.299;773.960;261.970;9396;024;792.802;277.079;773.960;261.970;8718;025;828.899;284.463;773.960;261.970;8980;026;690.319;238.504;773.960;261.970;8799;027;794.382;268.700;773.960;261.970;9465;028;696.255;242.315;773.960;261.970;9501;029;776.179;262.256;773.960;261.970;8758;0---------------------------------------------------------------------------------------------Running 1m test @ http://localhost:8080/api/perf/v2 1 threads and 100 connections Thread Stats Avg Stdev Max +/- Stdev Latency 157.37ms 24.46ms 642.38ms 99.29% Req/Sec 647.37 293.27 1.01k 46.58% Latency Distribution 50% 155.03ms 75% 156.76ms 90% 158.71ms 99% 168.55ms 38298 requests in 1.00m, 251.21MB read Socket errors: connect 0, read 3, write 0, timeout 0Requests/sec: 637.18Transfer/sec: 4.18MB---------------------------------------------------------------------------------------------命令 :ct命令执行Round :2客户端ID :10000客户端类型 :client:1协议版本 :version:1命令耗时 :31150 (ms)STW时间 :0 (ms)---------------------------------------------------------------------------------------------time;usr_ms;sys_ms;avg_usr_ms;avg_sys_ms;nivc_switch_per_sec;nvc_switch_per_sec0;1422.616;486.753;1371.416;465.940;19053;01;1395.776;483.464;1371.416;465.940;16768;02;1364.906;468.093;1371.416;465.940;19776;03;1373.824;473.600;1371.416;465.940;20257;04;1395.230;476.288;1371.416;465.940;19962;05;1373.637;473.033;1371.416;465.940;20230;06;1271.321;461.279;1371.416;465.940;20601;07;1326.957;450.383;1371.416;465.940;19281;08;1380.019;470.222;1371.416;465.940;21080;09;1366.264;464.790;1371.416;465.940;20030;010;1298.920;431.147;1371.416;465.940;18209;011;1343.620;459.891;1371.416;465.940;19534;012;1413.430;484.164;1371.416;465.940;20145;013;1337.866;442.507;1371.416;465.940;17832;014;1347.746;453.561;1371.416;465.940;18300;015;1344.458;455.293;1371.416;465.940;18358;016;1410.628;476.886;1371.416;465.940;18409;017;1400.451;483.767;1371.416;465.940;21533;118;1380.016;467.360;1371.416;465.940;19495;019;1373.083;466.722;1371.416;465.940;20081;020;1383.511;478.139;1371.416;465.940;20822;021;1373.221;465.873;1371.416;465.940;18044;022;1380.141;474.802;1371.416;465.940;20312;023;1471.870;482.301;1371.416;465.940;17088;024;1296.227;431.302;1371.416;465.940;17609;025;1262.651;419.564;1371.416;465.940;19318;026;1373.892;460.087;1371.416;465.940;18774;027;1382.340;467.936;1371.416;465.940;20585;028;1417.670;456.670;1371.416;465.940;20243;029;1540.185;513.103;1371.416;465.940;21204;0---------------------------------------------------------------------------------------------Running 1m test @ http://localhost:8080/api/perf/v2 1 threads and 200 connections Thread Stats Avg Stdev Max +/- Stdev Latency 154.52ms 11.50ms 453.24ms 98.55% Req/Sec 1.30k 309.18 2.02k 78.57% Latency Distribution 50% 153.12ms 75% 154.10ms 90% 155.87ms 99% 170.85ms 77537 requests in 1.00m, 508.30MB read Socket errors: connect 0, read 104, write 0, timeout 0 Non-2xx or 3xx responses: 48Requests/sec: 1291.12Transfer/sec: 8.46MB---------------------------------------------------------------------------------------------命令 :ct命令执行Round :3客户端ID :10000客户端类型 :client:1协议版本 :version:1命令耗时 :31114 (ms)STW时间 :0 (ms)---------------------------------------------------------------------------------------------time;usr_ms;sys_ms;avg_usr_ms;avg_sys_ms;nivc_switch_per_sec;nvc_switch_per_sec0;1941.490;660.804;2000.086;681.199;31573;01;1844.148;631.323;2000.086;681.199;29569;02;1862.370;621.631;2000.086;681.199;29807;03;1809.424;630.995;2000.086;681.199;31884;04;1886.063;652.542;2000.086;681.199;30477;05;1921.721;644.464;2000.086;681.199;27768;06;2071.838;707.471;2000.086;681.199;31769;07;1894.563;656.626;2000.086;681.199;31027;08;2018.893;697.685;2000.086;681.199;31390;09;2042.309;697.253;2000.086;681.199;31124;010;2011.373;684.438;2000.086;681.199;32248;011;2160.444;748.734;2000.086;681.199;33186;012;2160.373;696.990;2000.086;681.199;24885;313;2074.237;702.727;2000.086;681.199;32950;014;2029.643;703.800;2000.086;681.199;32987;015;1950.156;675.433;2000.086;681.199;31358;016;1984.916;679.103;2000.086;681.199;30985;017;1927.420;660.709;2000.086;681.199;31766;018;1955.132;660.601;2000.086;681.199;27598;019;2039.749;690.580;2000.086;681.199;30093;020;2096.644;714.700;2000.086;681.199;30132;021;2052.463;669.589;2000.086;681.199;28180;222;2046.927;703.009;2000.086;681.199;31418;023;2058.988;721.248;2000.086;681.199;34699;024;2014.296;690.955;2000.086;681.199;34123;025;1991.359;659.830;2000.086;681.199;26344;026;2070.508;687.293;2000.086;681.199;27522;027;2053.150;698.491;2000.086;681.199;31325;028;2035.073;696.464;2000.086;681.199;33523;029;1966.603;698.452;2000.086;681.199;34477;0---------------------------------------------------------------------------------------------Running 1m test @ http://localhost:8080/api/perf/v2 1 threads and 300 connections Thread Stats Avg Stdev Max +/- Stdev Latency 153.92ms 3.98ms 219.56ms 94.00% Req/Sec 1.94k 290.35 2.73k 74.20% Latency Distribution 50% 152.85ms 75% 153.83ms 90% 156.02ms 99% 170.84ms 115438 requests in 1.00m, 757.20MB read Socket errors: connect 0, read 250, write 2, timeout 0Requests/sec: 1920.76Transfer/sec: 12.60MB---------------------------------------------------------------------------------------------命令 :ct命令执行Round :4客户端ID :10000客户端类型 :client:1协议版本 :version:1命令耗时 :31088 (ms)STW时间 :0 (ms)---------------------------------------------------------------------------------------------time;usr_ms;sys_ms;avg_usr_ms;avg_sys_ms;nivc_switch_per_sec;nvc_switch_per_sec0;2382.877;822.423;2467.859;844.902;39566;01;2600.853;871.493;2467.859;844.902;40607;02;2388.155;837.615;2467.859;844.902;44943;03;2437.694;841.379;2467.859;844.902;42330;04;2460.567;831.047;2467.859;844.902;42071;05;2488.811;866.828;2467.859;844.902;44123;06;2489.881;858.724;2467.859;844.902;43364;07;2515.122;834.155;2467.859;844.902;40659;08;2451.552;847.450;2467.859;844.902;42707;09;2465.109;834.627;2467.859;844.902;43187;010;2431.755;832.445;2467.859;844.902;39040;011;2439.897;839.241;2467.859;844.902;39886;012;2486.892;858.117;2467.859;844.902;47247;013;2367.548;823.389;2467.859;844.902;42589;014;2425.888;844.716;2467.859;844.902;44078;015;2378.448;798.451;2467.859;844.902;40246;016;2493.273;851.729;2467.859;844.902;39161;017;2399.780;817.940;2467.859;844.902;40146;018;2488.381;841.304;2467.859;844.902;40812;019;2422.649;843.157;2467.859;844.902;42935;020;2407.553;833.911;2467.859;844.902;41078;021;2573.902;857.470;2467.859;844.902;42127;022;2465.398;845.037;2467.859;844.902;41124;023;2460.814;828.538;2467.859;844.902;40826;024;2435.089;845.302;2467.859;844.902;42519;025;2457.967;855.893;2467.859;844.902;44206;026;2464.219;842.923;2467.859;844.902;40828;027;2653.804;903.895;2467.859;844.902;41220;028;2648.289;906.308;2467.859;844.902;41753;029;2539.227;846.505;2467.859;844.902;38800;0---------------------------------------------------------------------------------------------Running 1m test @ http://localhost:8080/api/perf/v2 1 threads and 400 connections Thread Stats Avg Stdev Max +/- Stdev Latency 157.26ms 11.90ms 377.28ms 92.23% Req/Sec 2.49k 469.17 3.39k 80.17% Latency Distribution 50% 153.29ms 75% 155.97ms 90% 165.24ms 99% 215.04ms 147514 requests in 1.00m, 0.94GB read Socket errors: connect 0, read 479, write 0, timeout 0Requests/sec: 2455.46Transfer/sec: 16.11MBRunning 1m test @ http://localhost:8080/api/perf/v2 1 threads and 500 connections Thread Stats Avg Stdev Max +/- Stdev Latency 169.07ms 31.81ms 404.91ms 94.07% Req/Sec 1.41k 0.86k 3.08k 62.86% Latency Distribution 50% 158.54ms 75% 171.43ms 90% 186.79ms 99% 332.80ms 4960 requests in 4.02s, 32.52MB read Socket errors: connect 0, read 534, write 1, timeout 0 Non-2xx or 3xx responses: 3Requests/sec: 1232.97Transfer/sec: 8.08MB
using wrk tool and java-debug-tool to do the benchmark; Example: ${SELF} -b, benchmark url [url] the target benchmark url; -i, remote-ip [ip address] the remote java-debug-tool tcp server ip address, the default is localhost; -p, remote-port [port number] the remote java-debug-tool tcp server port number, the default is 11234; -h, http-port [http server listen on] the http server listen on, the default is 10234; -c, init-clients [an number] the init clients size, the default is 100; -t, total-clients [an number] the target clients size, the default is 1000; -s, step-clients [an number] the step by step increment clients size, the default is 100; -d, duration [an number with unit (s -> seconds| m -> minutes) ref: wrk] step duration; -w, wrk-command [the wrk path] the path to the wrk command -u, help print the usage -f, file [the file name] the output file name
目前可以获取到包括QPS、TP数据、错误以及CPU消耗时间,进程上下文切换等数据;