BTrace是一个可以动态跟踪Java代码执行的工具，网上已经有很多文章介绍，我这里分享一个我在实际工作中排查性能问题的例子。
现象
我的一个REST接口调用非常慢，postman耗时3873 ms，这个接口就是从redis里把一批数据取出来，redis性能很好，理论上不会这么慢，于是用btrace，trace方法调用。
/* BTrace Script Template */
import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace
public class TracingScript {
/* put your code here */
@TLS
private static long startlTime = 0;
@TLS
private static long startmTime = 0;
@TLS
private static long startjTime = 0;
@TLS
private static long startrTime = 0;
@TLS
private static long startbTime = 0;
@OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listSize")
public static void startjMethod() {
startjTime = timeMillis();
}
@OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listSize", location=@Location(Kind.RETURN))
public static void endjMethod() {
println(strcat("listSize method execute time=>", str(timeMillis()-startjTime)));
println("-------------------------------------------");
}
@OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listRange")
public static void startrMethod() {
startrTime = timeMillis();
}
@OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listRange", location=@Location(Kind.RETURN))
public static void endrMethod() {
println(strcat("listRange method execute time=>", str(timeMillis()-startrTime)));
println("-------------------------------------------");
}
@OnMethod(clazz="com.xx.monitoring.api.persistence.MetricRedisDao", method="listMetricByIds")
public static void startbMethod() {
startbTime = timeMillis();
}
@OnMethod(clazz="com.xx.monitoring.api.persistence.MetricRedisDao", method="listMetricByIds", location=@Location(Kind.RETURN))
public static void endbMethod(java.util.List metricIds) {
println("metrcIds.size: " + metricIds.size());
println(strcat("listMetricByIds method execute time=>", str(timeMillis()-startbTime)));
println("-------------------------------------------");
}
@OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsInternal")
public static void startlMethod() {
startlTime = timeMillis();
}
@OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsInternal", location=@Location(Kind.RETURN))
public static void endlMethod() {
println(strcat("listMetricsInternal method execute time=>", str(timeMillis()-startlTime)));
println("-------------------------------------------");
}
@OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsMap")
public static void startmMethod() {
startmTime = timeMillis();
}
@OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsMap", location=@Location(Kind.RETURN))
public static void endmMethod() {
println(strcat("listMetricsMap execute time=>", str(timeMillis()-startmTime)));
println("-------------------------------------------");
}
}
编译：
$ btracec TracingScript.java
开始trace
$ btrace 19416 TracingScript.class
结果：
DEBUG: received com.sun.btrace.comm.MessageCommand@5b6f7412 listSize method execute time=>3 DEBUG: received com.sun.btrace.comm.MessageCommand@27973e9b ------------------------------------------- DEBUG: received com.sun.btrace.comm.MessageCommand@312b1dae listRange method execute time=>18 DEBUG: received com.sun.btrace.comm.MessageCommand@7530d0a ------------------------------------------- DEBUG: received com.sun.btrace.comm.MessageCommand@27bc2616 listRange method execute time=>19 DEBUG: received com.sun.btrace.comm.MessageCommand@3941a79c ------------------------------------------- DEBUG: received com.sun.btrace.comm.MessageCommand@506e1b77 listMetricsInternal method execute time=>4820 DEBUG: received com.sun.btrace.comm.MessageCommand@4fca772d ------------------------------------------- DEBUG: received com.sun.btrace.comm.MessageCommand@9807454 listMetricsMap execute time=>4821
可以看到listMetricsInternal执行了4820毫秒
这个方法就是把metric的id循环从redis取metric bean，初步判断是id太多导致很慢，继续trace
添加方法：
@OnMethod(clazz="com.xx.monitoring.api.persistence.MetricRedisDao", method="listMetricByIds", location=@Location(Kind.RETURN))
void endbMethod(java.util.List<String> metricIds) {
println("metrcIds.size: " + str(metricIds));
println("-------------------------------------------");
}
执行结果：
metrcIds.size: [weblogic.datasource.waiting_for_connection_high_count, weblogic.datasource.leaked_connection_count, weblogic.datasource.active_connections_currentCount, weblogic.threadpool.standby_thread_count, weblogic.threadpool.active_thread_idle_count, weblogic.threadpool.execute_thread_total_count, weblogic.session.open_sessions_current_count, weblogic.session.open_sessions_high_count, weblogic.session.sessions_opened_total_count, weblogic.server.health_state, weblogic.server.activation_time, server.os.kernel_version, server.os.version, server.os.id, server.interfaces.tx, server.interfaces.rx, server.disk.used_percent, server.cpu.load, server.memory.free_percent, server.memory.used_percent, server.cpu.idle, server.cpu.iowait, server.cpu.sys, server.cpu.user, oracle.info.status, oracle.worst.sql, oracle.time_ratio.cpu_time_ratio, oracle.time_ratio.wait_time_ratio, oracle.connection.count, jvm.memory.used, jvm.memory.max, jvm.memory.committed, jvm.thread.total_started_thread_count, jvm.thread.daemon_thread_count, jvm.thread.peak_thread_count, jvm.thread.count, jvm.gc.collection_time, jvm.gc.collection_count, jvm.classsloading.unloaded_class_count, jvm.classsloading.loaded_class_count, jvm.classsloading.total_loaded_class_count, jvm.info.input_arguments, jvm.info.vm_id, jvm.info.vm_version, weblogic.datasource.waiting_for_connection_high_count, weblogic.datasource.leaked_connection_count, weblogic.datasource.active_connections_currentCount, weblogic.threadpool.standby_thread_count, weblogic.threadpool.active_thread_idle_count, weblogic.threadpool.execute_thread_total_count, weblogic.session.open_sessions_current_count, weblogic.session.open_sessions_high_count, weblogic.session.sessions_opened_total_count, weblogic.server.health_state, weblogic.server.activation_time, server.os.kernel_version, server.os.version, serve 还有很多 ...
一共3610个，从redis取一个1ms，那也要3610ms，怪不得。
原因找到了，改代码就很简单了
另外发现BTrace还有一个工具专门分析性能的BTraceUtils.Profiling，代码：
import com.sun.btrace.BTraceUtils;
import com.sun.btrace.Profiler;
import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace class Profiling {
@Property
Profiler swingProfiler = BTraceUtils.Profiling.newProfiler();
@OnMethod(clazz="/com\\.xx\\.monitoring\\.api\\..*/", method="/.*/")
void entry(@ProbeMethodName(fqn=false) String probeMethod) { //fqn是否打印长方法名
BTraceUtils.Profiling.recordEntry(swingProfiler, probeMethod);
}
@OnMethod(clazz="/com\\.xx\\.monitoring\\.api\\..*/", method="/.*/", location=@Location(value=Kind.RETURN))
void exit(@ProbeMethodName(fqn=false) String probeMethod, @Duration long duration) {
BTraceUtils.Profiling.recordExit(swingProfiler, probeMethod, duration);
}
@OnTimer(5000) //每5秒打印一次
void timer() {
BTraceUtils.Profiling.printSnapshot("Performance profile", swingProfiler);
}
}
结果：
Performance profile Block Invocations SelfTime.Total SelfTime.Avg SelfTime.Min SelfTime.Max WallTime.Total WallTime.Avg WallTime.Min WallTime.Max preHandle 1 96000 96000 96000 96000 96000 96000 96000 96000 listSize 1 2231000 2231000 2231000 2231000 2231000 2231000 2231000 2231000 listRange 2 18447000 9223500 23000 18424000 36871000 18435500 18424000 18447000 getMetric 3610 20915000 5793 1000 384000 3805159000 1054060 689000 5752000 getMetricIndexOfId 3610 189140000 52393 19000 930000 189140000 52393 19000 930000 get 3610 3583769000 992733 629000 4758000 3595104000 995873 633000 4787000 <init> 3610 760000 210 0 10000 760000 210 0 10000 setId 3610 1983000 549 0 20000 1983000 549 0 20000 setUnit 3610 2019000 559 0 51000 2019000 559 0 51000 setCreated 3610 2111000 584 0 32000 2111000 584 0 32000 setUpdated 3610 1556000 431 0 26000 1556000 431 0 26000 setValueType 3610 1251000 346 0 19000 1251000 346 0 19000 setDisplayName 3610 1476000 408 0 54000 1476000 408 0 54000 setCustomized 271 179000 660 0 16000 179000 660 0 16000 doFilter 1 22833000 22833000 22833000 22833000 3867649000 3867649000 3867649000 3867649000 listMetricsMap 2 2151000 1075500 49000 2102000 7685645000 3842822500 3842798000 3842847000 listMetricsInternal 1 13000 13000 13000 13000 3839969000 3839969000 3839969000 3839969000 listMetrics 1 2332000 2332000 2332000 2332000 3839956000 3839956000 3839956000 3839956000 listMetricByIds 1 11787000 11787000 11787000 11787000 3816946000 3816946000 3816946000 3816946000 getId 3676 737000 200 0 12000 737000 200 0 12000 isCustomized 66 11000 166 0 1000 11000 166 0 1000 getUnit 66 8000 121 0 1000 8000 121 0 1000 getCreated 66 9000 136 0 1000 9000 136 0 1000 getUpdated 66 9000 136 0 1000 9000 136 0 1000 getValueType 66 14000 212 0 1000 14000 212 0 1000 getDisplayName 66 9000 136 0 1000 9000 136 0 1000 postHandle 1 1803000 1803000 1803000 1803000 1803000 1803000 1803000 1803000
可见getMetric执行了3610次
怎么样，BTrace还是很强大的吧，分析线上问题很方便
相关推荐
总结来说，Btrace和Greys是Java开发者在生产环境中排查问题的有力助手，它们能够帮助我们实时查看代码执行情况，定位性能问题，且无需改动源代码或重启服务。通过熟练掌握这类工具，可以极大地提高问题解决的效率，...
而BTrace则是Oracle公司推出的一个开源项目，允许开发者在运行时对Java应用进行安全的动态代码插入，用于性能监控、故障排查等。 当网络环境不稳定或者无法访问互联网时，我们就需要离线安装BTrace插件。离线安装的...
**BTrace监控远程服务器使用实例** BTrace 是一个强大的、安全的、动态的Java...通过熟练掌握BTrace的使用，可以有效地提升故障排查效率，优化Java应用的性能。记住，合理配置安全策略和权限，确保远程监控的安全性。
BTrace将这种能力引入到了Java世界，使得开发者可以对Java应用程序进行细粒度的性能分析和故障排查。通过BTrace，我们可以追踪方法调用、监控对象创建、检测锁竞争等关键操作，这对于性能优化和问题定位来说极其宝贵...
BTrace是一款强大的Java诊断工具，专用于实时、安全地进行生产环境中的应用程序性能监控和故障排查。它的核心特性在于能够在不中断程序运行的情况下，动态插入代码进行跟踪和分析，这对于理解复杂的系统行为和定位...
【标题】"btrace1.3.9"指的是BTrace工具的一个特定版本，1.3.9，这是一款强大的Java应用程序动态跟踪工具。BTrace利用Java的JVMTI（Java ...无论是对于排查问题还是进行性能优化，BTrace都是一种强大的辅助工具。
在日常的调试维护中，虽然btrace提供了一种非常便利的手段，但我们仍然提倡首先利用日志系统进行问题排查。日志记录了程序运行过程中的详细信息，可以帮助我们理解程序的运行状态，定位错误来源。而btrace则更适用于...
2. 虽然Btrace可以无侵入地跟踪应用程序，但过度使用可能会对性能产生影响，因此应在生产环境谨慎使用。 3. Btrace与特定的JDK版本兼容，本资源包特别提到支持JDK 11。 总的来说，Btrace是一个强大的Java调试和监控...
BTrace工具通常被系统管理员和性能工程师用来找出性能瓶颈，或者在复杂的问题排查过程中收集必要的运行时信息。 【详细说明】BTrace的核心功能包括： 1. **动态探查**：BTrace可以在运行时向Java应用添加探查代码...
此工具在Java 1.5及更高版本上运行，特别地，这里提到的是它在JDK 1.7环境下同样兼容，这意味着开发者可以在Linux系统中利用BTrace对基于JDK 1.7的应用进行实时监控和问题排查。 1. **BTrace原理**： BTrace通过...
5. **广泛的应用**：BTrace适用于各种线上问题的排查，包括性能瓶颈定位、内存泄漏检测、线程状态分析等。 【压缩包内容解析】 - **COPYRIGHT**：通常包含软件的版权信息和使用许可条款，对于BTrace这样的开源软件...
"samples"目录则提供了一些示例，方便用户学习如何使用BTrace进行性能分析和问题定位。 核心部分在于"bin"目录，这里包含了可执行的BTrace命令行工具。通过这些二进制文件，用户可以在Java应用程序运行时动态插入...
总结，BTrace作为一款强大的Java在线调试工具，通过字节码增强技术实现了对运行中的Java应用的实时监控，对于开发人员而言，是进行性能优化和问题排查的得力助手。合理运用BTrace，可以极大地提升线上问题解决的效率...
在上述测试中，通过监控`List`参数和自定义对象，可以帮助理解程序运行时的数据流动和对象状态，对于问题排查和优化非常有价值。 通过深入理解和实践BTrace，开发者可以更有效地诊断和优化Java应用程序，提升系统的...
博文链接：https://tristan-s.iteye.com/blog/1960257 提供了关于 BTrace 使用和理解的详细教程，可以帮助读者更深入地了解如何利用 BTrace 进行问题排查和性能优化。 【标签】：“源码”、“工具” 【知识点详解...
BTrace的全称是"Berkeley Trace"，它基于字节码注入技术，可以实时地、安全地在运行中的Java应用程序上添加监控脚本，帮助我们理解程序的运行状态，定位问题，优化性能。 BTrace的工作原理主要是通过ASM库来动态...
**BTrace：深入理解与应用** BTrace 是一个强大的动态代码跟踪工具，它允许开发者在运行时对Java应用程序进行安全的、低开销的...无论是在排查问题、优化代码还是理解复杂系统的行为，BTrace 都是一个不可或缺的工具。
它允许开发者在运行时对Java应用程序进行性能分析和故障排查，而无需修改或重启应用。BTrace通过其独特的字节码注入技术，为开发者提供了对应用程序的细粒度监控能力。本文将基于提供的"Btrace源代码"进行深入探讨，...
**Btrace 概述** ...结合VisualVM插件，我们可以更直观地管理和分析监控数据，这对于调试、性能优化以及问题排查具有极大的价值。理解Btrace的工作原理和使用方法，对于提升Java开发和运维效率非常有帮助。
通过BTrace，开发者能够深入理解程序的运行状态，定位性能瓶颈，诊断并发问题，以及实施细粒度的日志记录，从而提升应用的性能和稳定性。结合提供的文档和示例，用户可以逐步掌握这个强大的工具，实现高效的问题排查...