BTrace实战：不重启JVM也能精准定位线上疑难杂症

在生产环境碰到一个接口偶尔超时日志里又没有把关键分支打出来代码翻来覆去看了好几轮也找不出问题所在。这种时候BTrace 往往能把我从“改代码-发版-复现-再抓瞎”的死循环里直接拽出来。简单讲BTrace 是一款 JVM 动态追踪工具可以在不重启应用、不提前埋点的情况下向运行中的 Java 进程注入追踪代码把方法入参、返回值、调用耗时、异常堆栈等信息实时抓出来。它特别适合排查那些本地无法复现、日志覆盖不到、重启代价又极高的线上疑难杂症不管你是后端开发、运维还是做性能调优只要用 Java 技术栈我都建议把 BTrace 放进你的线上工具箱。这篇文章我会从它的核心原理聊起再给出一套可以直接抄作业的脚本模板最后把我这几年用 BTrace 踩过的坑、总结出的经验一起整理出来。没有太多基础的同学照着第二、三章的步骤跑一遍基本就能上手。1. BTrace 是什么它到底能帮我解决什么问题1.1 为什么“动态注入”比“改代码加日志”高效得多很多时候线上问题难排查不是问题本身复杂而是你根本看不到现场。就拿我前段时间遇到的一个订单状态异常来说用户反馈订单被错误取消代码里只在入口和出口打了日志中间状态机走了哪个分支完全没记录。虽然日志量不小但关键路径是黑的。本地想模拟同样的数据构建环境、造数、复现条件样样都费劲。按照老办法我只能在代码里补一堆log.info提测、走发布流程、等线上再出问题然后去日志平台捞数据。一套下来一两个小时是常事更麻烦的是加了日志可能改变原有的行为时序让问题更难复现。而 BTrace 的思路是完全另一条路它通过 JVM 的 Attach 机制动态附加到目标进程利用字节码增强技术在方法入口、出口、异常抛出点“临时插入”探针代码把你想看的参数、返回值、耗时、堆栈实时打出来。整个过程不需要改业务代码也不需要重启应用相当于在汽车行驶途中装了个行车记录仪而不是把车停下来拆开发动机查线。1.2 典型适用场景和不太适合的场景我平时用 BTrace 最多的是这几类场景接口慢查询定位某个接口偶发超时直接抓方法耗时分布定位到最耗时的下游调用。方法入参与返回值回溯日志里没记录的关键参数通过 BTrace 在运行中抓出来。异常路径分析方法内部到底抛了什么异常、在哪个调用点抛出的结合堆栈一眼就能看明白。聚合统计想统计某类方法的调用量、总耗时、最大耗时不需要逐个打日志用聚合功能直接汇总。调用关系梳理一个方法进去之后实际调了哪些方法在代码梳理不清时用Kind.CALL可以快速拉出调用链。但 BTrace 不是万能的。它本质上是个“定向诊断工具”不是长周期监控方案。如果要做持续的性能监控、接口成功率告警应该交给 APM、Prometheus 这类体系去做如果只是线程池状态、堆内存快照jstack、jstat、JFR 反而更轻量。还有一个容易被忽略的点BTrace 不适合做“全量追踪”比如匹配到上百个类、所有方法都注入探针那性能开销会很感人后面我会专门讲这个问题。2. 运行原理BTrace 是怎么做到“不改代码就追踪”的2.1 Attach API 与 Instrumentation给 JVM 打补丁的底层机制BTrace 能实现动态追踪依赖的是 JVM 自身提供的两套能力Attach API和Instrumentation。先讲 Attach。Java 从 JDK 5 开始就支持在运行时把代理程序挂载到已经运行的 JVM 上。简单说目标 JVM 在启动时会开启一个用于运行时扩展的机制外部进程只要找到对应的 PID就可以通过 Attach API 请求它加载一个 jar 包。BTrace 利用这个机制把自己编译好的 agent 注入到目标 JVM 内部。再讲 Instrumentation。agent 被加载后会拿到一个Instrumentation实例它能调用retransformClasses方法重新转换已经加载的类。这个“转换”不是修改磁盘上的 class 文件而是在 JVM 的内存里对类的字节码做增强。BTrace 内部使用 ASM 字节码操作框架在你指定的方法入口、出口、异常抛出点插入探针逻辑。整个过程对业务代码是无感知的等追踪结束后被临时增强的类还可以再恢复原状。用一个比较直观的类比你住在一个小区里BTrace 就是物业临时在单元门口加装了一个人脸识别摄像头只看进出记录不改动你的房间结构。摄像头拆掉之后一切恢复原样。2.2 为什么 BTrace 脚本被“限制”反而更安全有一件事新手容易忽略BTrace 脚本一旦运行其实是跑在目标 JVM 进程内部的。如果没有限制那它和一段任意注入的恶意代码没什么区别写错一行脚本就可能导致线上应用崩溃。所以 BTrace 从设计上就对脚本做了严格的安全沙箱约束。BTrace 脚本里不允许随便new对象不允许调用目标业务类的方法也不允许写无限循环大部分操作只能通过BTraceUtils提供的内置函数完成。你写脚本时本质上是在描述“我想在哪个位置、打印什么信息”而不是在写一段完整的 Java 程序。刚开始我会觉得这些限制很烦用久了才明白正是这些限制保证了动态注入在重负载的生产环境里也相对可靠。万一脚本真的写出了问题顶多是追踪逻辑异常退出不至于把业务逻辑一起带崩。2.3 和 Arthas、JFR、自研 Agent 的横向对比很多同学会问既然有 Arthas为什么还要学 BTrace这两个工具确实有重叠但侧重点不同。工具是否需要重启侵入性上手难度最适合的场景jstack / jstat否极低低线程快照、GC 等即时信息JFR / JMC否低中长时间性能 profilingBTrace否中动态注入需要脚本能力方法级定向追踪、自动化诊断脚本Arthas否中低交互命令线上快速交互式排查自研 Agent启动时中高平台统一埋点、全量链路如果你喜欢交互式命令行trace、watch、stack这些命令打起来确实很爽Arthas 的上手成本更低但 BTrace 的优势在于脚本化你可以把一段追踪逻辑保存成.java文件纳入代码仓库管理下次遇到类似问题直接复用也能通过命令行参数实现半自动化的诊断。我在团队内部就把几个常用诊断场景做成了标准化 BTrace 脚本排查效率提升非常明显。3. 快速上手从下载到第一个追踪脚本3.1 环境准备与安装步骤BTrace 的安装其实非常简单本质上就是下载、解压、配置环境变量。第一步到 BTrace 的 GitHub Releases 页面下载对应版本的二进制压缩包。这里要注意版本选择Java 8 环境推荐使用 BTrace 2.x新版本对 JDK 9 的模块化支持更好如果你还在维护特别老的 JDK 6/7 环境可能只能选择 1.x 分支。第二步解压到固定目录然后把bin目录加进PATH。比如我习惯放在/opt/btrace下面然后在~/.bashrc里加一行export BT_HOME/opt/btrace export PATH$BT_HOME/bin:$PATH第三步验证环境。执行btrace -version能看到版本信息就说明基本就绪。这里有个容易踩的坑如果机器上装了多个 JDK一定要确保当前JAVA_HOME指向的版本和要追踪的 Java 进程兼容否则后面 attach 阶段会报各种奇怪错误。3.2 一个最简单的 Entry 追踪脚本我现在用一个最简单的脚本演示怎么在方法入口打印一条信息。假设目标进程里有一个demo.HelloWorld类方法main是入口。先写脚本import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TraceMain { OnMethod(clazz demo.HelloWorld, method main) public static void onMain() { println(enter main method); } }然后查找目标进程的 PIDjps -l假设输出里有12345 demo.HelloWorld直接运行btrace 12345 TraceMain.java这时候观察目标进程的控制台或者 BTrace 所在终端的输出当main方法被调用时就会打印出enter main method。这里要强调一个细节clazz和method的写法是全限定名。如果你的类名带包路径不要只写HelloWorld要写demo.HelloWorld。如果方法有重载可以在注解里通过type指定参数类型来精确定位这一点在实战中会经常用到。3.3 btracec 预编译的作用和使用时机BTrace 安装目录下还有一个btracec命令它是脚本预编译器。你可以先执行btracec TraceMain.java脚本语法有问题会直接在这里暴露出来编译通过后会产生对应的 class 文件然后再用btrace 12345 TraceMain.class去 attach。实际使用中直接运行.java文件也没问题BTrace 内部会自动编译。那btracec的典型场景是哪个我一般用于脚本在发布前的语法校验以及在自动化脚本里先编译好、再循环 attach 多个不同 JVM 进程时复用同一份 class避免每次重复编译。4. 高频场景直接抄这几个脚本模板4.1 方法入参、返回值与耗时统计这是排查接口问题最常用、也最应该先掌握的模板。假设我想追踪com.example.api.OrderController.submit这个方法的入参、返回值和耗时就可以这样写import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TraceOrderSubmit { TLS private static long startNanos; OnMethod(clazz com.example.api.OrderController, method submit) public static void onEntry() { startNanos timeNanos(); println(strcat(enter submit at , str(timeMillis()))); } OnMethod(clazz com.example.api.OrderController, method submit, location Location(Kind.RETURN)) public static void onReturn(Return Object result, Duration long duration) { println(strcat(submit cost(ms) , str(duration / 1000000))); println(strcat(return , str(result))); } OnMethod(clazz com.example.api.OrderController, method submit, location Location(Kind.ERROR)) public static void onError(Duration long duration, Thrown Throwable e) { println(strcat(submit error cost(ms) , str(duration / 1000000))); println(strcat(exception , str(e))); Threads.jstack(); } }这里有几个关键点需要解释一下。Duration默认单位是纳秒我习惯先除以 1000000 转成毫秒再输出。Return只能用在Kind.RETURN的监听方法上如果目标方法返回void就不能声明这个参数。Thrown则用来捕获异常对象只在Kind.THROW或Kind.ERROR位置有效。为什么这里用TLS记录开始时间因为OnMethod的不同位置是独立回调方法互相之间没有局部变量可传只能通过线程本地变量把“进入时间”保存下来供后面的返回回调读取。这能保证在多线程并发调用下数据不会串线。4.2 异常路径与堆栈定位有时候问题不是“慢”而是“错得莫名其妙”。如果怀疑某个方法内部抛了异常但又不知道具体在哪一层抛的可以用这个模板import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TraceException { OnMethod(clazz com.example.service.OrderService, method createOrder, location Location(Kind.THROW)) public static void onThrow(Self Object self, Thrown Throwable e) { println(strcat( throw from createOrder: , str(e))); Threads.jstack(); } }Kind.THROW会在方法内部产生异常时触发而不是等到方法向外抛的时候。这个区别很重要如果你用Kind.RETURN配合判断返回值异常在内部被 catch 掉就不会暴露了用Kind.THROW则能直接命中异常产生的位置。Threads.jstack()会打印当前线程完整堆栈适合快速定位异常是从哪条调用链钻进来的。4.3 批量正则匹配与聚合统计还有一类很实用的场景不想只追一个方法而是想统计某个包下所有接口方法的调用量、总耗时、最慢耗时。BTrace 的聚合能力派上用场了。import com.sun.btrace.annotations.*; import com.sun.btrace.aggregation.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TopMethodCost { private static Aggregation aggregation Aggregations.newAggregation(AggregationFunction.SUM); OnMethod(clazz /com\\.example\\.api\\..*/, method /.*/, location Location(Kind.RETURN)) public static void onReturn(Duration long duration, ProbeClassName String cn, ProbeMethodName String mn) { String key strcat(cn, strcat(., mn)); Aggregations.addToAggregation(aggregation, Aggregations.newAggregationKey(key), duration); } OnEvent public static void onEvent() { Aggregations.printAggregation(API cost, aggregation); } }这种脚本里clazz和method都支持正则表达式但要注意是完整匹配所以必须写成/com\\.example\\.api\\..*/而不是com.example.api.*。ProbeClassName和ProbeMethodName会动态注入实际匹配到的类名和方法名这样聚合结果的 key 才是准确的。脚本运行后想查看聚合结果时在 BTrace 所在终端按一次CtrlC就会触发OnEvent方法把当前聚合结果打印出来并退出。这种方法相比每条都打印对目标进程的性能影响小得多。4.4 跨方法跟踪与线程本地变量有些问题需要看一条链路里的多个方法。比如进入OrderController.submit后内部调用了OrderService.doCreate而doCreate里又调用了StockClient.deduct。如果给每个方法都单独打印耗时看不出整体时间花在哪这时可以用TLS做一个跨方法的“秒表”。import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TraceChain { TLS private static long begin; OnMethod(clazz com.example.api.OrderController, method submit) public static void entrySubmit() { begin timeNanos(); println( begin submit ); } OnMethod(clazz com.example.service.OrderService, method doCreate, location Location(Kind.RETURN)) public static void returnCreate() { long costMs (timeNanos() - begin) / 1000000; println(strcat(doCreate return, total so far(ms) , str(costMs))); } OnMethod(clazz com.example.client.StockClient, method deduct, location Location(Kind.RETURN)) public static void returnDeduct() { long costMs (timeNanos() - begin) / 1000000; println(strcat(deduct return, total so far(ms) , str(costMs))); } }TLS的本质是一个线程本地变量。BTrace 脚本不能直接使用ThreadLocal但通过这个注解声明的静态字段运行时会被自动处理成线程隔离的存储空间。这样即使多个请求线程同时在跑每个线程读到的begin都是自己线程写入的值不会串数据。5. 脚本语法与关键选项一次讲清5.1 常用注解参数速查表我整理了平时最常用的一组注解和函数方便你写脚本时对照。注解 / 函数用途备注BTrace标记脚本入口类脚本主类必须加OnMethod定义方法监控点支持clazz、method正则Location指定监控方位Kind.ENTRY、Kind.RETURN、Kind.THROW等Self获取方法当前实例实例方法可用Return获取方法返回值仅Kind.RETURN可用Duration获取方法耗时默认纳秒RETURN/ERROR可用ProbeClassName动态获取匹配类名正则匹配多个类时很有用ProbeMethodName动态获取匹配方法名正则匹配多个方法时很有用Thrown获取异常对象Kind.THROW/ERROR可用TLS线程本地变量跨回调方法传递数据BTraceUtils.println打印输出类似System.out.printlnBTraceUtils.str转字符串数字、对象安全转字符串BTraceUtils.strcat字符串拼接沙箱内推荐使用BTraceUtils.timeNanos获取纳秒时间计时常用BTraceUtils.Threads.jstack打印当前线程堆栈异常定位利器5.2 Location 支持的几种监控位置Location决定探针插在方法的哪个位置。不用每种都用但了解全貌能帮你写出更精准的脚本。KIND.ENTRY方法入口最常用。适合记录进入时间、入口参数。KIND.RETURN方法正常返回适合拿返回值、算耗时。KIND.THROW方法内部抛出异常时触发适合异常路径分析。KIND.ERROR方法抛出异常且没有内部捕获也就是异常传播出方法时触发。KIND.CALL监控方法内部调用了哪些方法可以指定clazz和method继续缩小范围。KIND.LINE精确到行号触发适合怀疑某一行代码有问题时使用但开销较大线上慎用。5.3 命令行参数与脚本复用BTrace 命令行的基础用法是btrace pid 脚本文件但实战中我会给命令加上输出文件避免追踪日志淹没在终端里btrace -o /tmp/trace_$(date %s).log pid TraceOrderSubmit.java这样输出会直接落到文件里方便事后分析。脚本本身也支持命令行参数通过脚本的main方法接收。比如说我想写成“追踪指定类名的指定方法”就可以这样写import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TraceGeneric { OnMethod(clazz clazz, method method) public static void onMethod(ProbeClassName String cn, ProbeMethodName String mn) { println(strcat(cn, strcat(., mn))); } }运行时传入参数btrace pid TraceGeneric.java com.example.OrderService createOrderclazz、method这种写法会从命令行参数里读取值让一份脚本模板适配多个排查场景。5.4 如何控制注入开销BTrace 虽然强大但对性能的影响是真实存在的。我控制注入开销有三个原则第一匹配范围尽量小。能用精确类名就不用正则能精确到方法就不用/.*/。大面积正则匹配会让 BTrace 对大量类做字节码转换影响类加载和 JIT 编译。第二输出频率尽量低。高频方法如果每个调用都printlnI/O 开销会非常惊人。这种场景优先用聚合把统计结果在内存里汇总最后一次性输出。第三用完立即退出。追踪逻辑本身有开销长时间挂着不仅拿不到更多有效信息还可能影响目标应用性能。拿到需要的数据后按CtrlC或者通过事件方法调用exit()退出不要让它一直挂着。6. 线上踩坑实录这些问题我基本都遇到过6.1 attach 失败最常见的启动报错刚接触 BTrace 时我遇到最多的就是 attach 失败。现象是运行命令后报类似Unable to attach to target process的错误。遇到这个报错我先检查三件事目标进程是不是真的存在PID 有没有找对。用jps -l确认。运行 BTrace 的用户和目标进程用户是否一致。跨用户 attach 通常会被拒绝我通常用和 Java 应用相同的用户执行 BTrace。是不是在容器环境里。Docker 容器里目标进程和 BTrace 进程的 PID 空间可能不一致需要进入同一个容器或者用--pid指定宿主机 PID 的方式处理。另外JDK 9 的模块化对 attach 机制有限制如果目标 JVM 启动参数里禁用了动态代理或 attach 能力也会失败这时候需要检查启动脚本。6.2 脚本编译没问题运行后却没有任何输出这个问题比 attach 失败更隐蔽。脚本能跑起来但目标方法被调用时什么也不打印。我一般按这个顺序排查类名、方法名是否写对了全限定名。特别是接口实现类如果你追踪的是接口但实际调用的是实现类方法就要写实现类的类名。方法有没有被 JIT 内联。某些极短的热点方法会被 JVM 内联字节码注入点可能不在你预期位置。这种情况可以把-XX:CompileCommanddontinline加给目标进程但生产环境重启成本高我更倾向于同时追踪调用方方法间接观察。脚本是否真的 attach 成功。可以用 BTrace 的-v参数打开详细日志确认探针是否注册成功。6.3 注入后目标应用出现明显卡顿BTrace 本身设计是尽量轻量的但脚本写得不好照样能把线上应用拖垮。有一回我为了抓一个偶发问题匹配了某个业务包下所有类的所有方法结果注入后目标应用的 QPS 直接掉了三成。问题就出在匹配范围太大每个方法调用都被插入探针逻辑原本该被 JIT 优化掉的方法也没法优化了。那次之后我给自己定了一条规矩线上 BTrace 脚本的追踪点控制在 5 个以内能用Kind.RETURN就不用Kind.CALL能用聚合就少打日志。6.4 中文乱码和日志找不到BTrace 输出中文乱码多半是编码问题。脚本文件本身要用 UTF-8 编码保存目标 JVM 的默认字符集也要能和终端对上。如果输出到文件建议用-o指定文件名时给到绝对路径避免相对路径在不同工作目录下找不着日志。6.5 常见问题速查表现象可能原因处理方式attach 失败PID 错误 / 用户不一致 / 容器隔离确认jps -l、切换用户、进入容器执行运行无输出类名不匹配 / 方法被内联 / 脚本未生效检查全限定名、用-v看日志目标应用变卡匹配范围太大 / 打印太频繁缩小正则、使用聚合、减少监听点中文乱码脚本编码与目标 JVM 编码不一致统一 UTF-8确认终端编码输出日志找不到相对路径问题使用绝对路径-o /tmp/xxx.logCtrlC 不退出脚本没有OnEvent或事件未触发在脚本中处理OnEvent或直接 kill BTrace 进程7. 生产环境使用纪律与我的几点心得7.1 上线前先问自己三个问题现在遇到线上问题我不会第一时间掏出 BTrace而是先想清楚三件事第一是不是已经有现成监控数据可以回答这个问题。如果监控图上已经能看出是哪个下游接口慢直接去看下游服务的日志和指标不需要动针注入。第二注入范围是不是已经压到最小。与其匹配一个大包不如先用jstack看清楚现场有了大致判断再写脚本精准追踪。第三退出机制是不是已经想好。脚本会持续输出多久多久能拿到足够信息是CtrlC手动退出还是自动超时这些在运行前就要想清楚。7.2 给追踪加上“自动收尾”无人值守或长时间的诊断我一般用两种方式收尾第一种是脚本内部超时退出。通过事件或定时机制触发exit()import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; BTrace public class TraceTimeout { OnTimer(30000) public static void timeout() { println(30s timeout, exit); exit(0); } }第二种是外部用timeout命令限制 BTrace 进程生命周期timeout 60 btrace pid TraceOrderSubmit.java这样即使忘记手动退出最多跑 60 秒。7.3 把常用脚本沉淀成团队资产使用 BTrace 几年下来我发现真正有长期价值的不是某一次排查的临时脚本而是沉淀下来的一套模板和最佳实践。我建议你在团队里建立一个btrace-scripts目录把接口耗时、异常追踪、聚合统计、参数回溯这些常用脚本按场景整理好统一用 Git 管理。每个脚本文件顶部写清楚适用场景、匹配范围、风险提示。这样新人遇到问题时不用从零开始写脚本直接拿模板改两个类名就能用。排查效率的提升比想象中大得多。用 BTrace 这几年我最大的体会是它把“线上不可观测”这个问题往前推了一大步。但它终究是诊断工具不是监控方案。真正靠谱的线上排查体系应该是监控告警做第一层筛选日志平台做第二层定位BTrace 这类工具在关键时刻做定向突破。工具越强大使用越克制这是我踩过不少坑之后最想对你强调的一点。下次再遇到日志覆盖不到、本地又复现不了的线上问题别急着发版先想想 BTrace 能不能帮你直接看见真相。