，Java在线排错利器一、背景描述前段时间urs升级了新的远程cookie验证方式。功能上线后，发现涉及用户cookie验证的接口有时会报接口超时。通过埋日志的方式，确认与urs提供的jar包中新的验证方式有关。通过反编译我们可以看到，相关方法的执行过程涉及参数验证、参数组装、远程访问验证、本地验证等步骤。哪一步错了？一种方式是请urs帮忙提供一个新的jar包，在关键步骤添加日志，记录执行时间。另一种方法是使用一些在线分析工具。显然第二种方式更方便快捷。本文主要介绍两款在线排错工具：Btrace和Greys。2.工具介绍Btrace和Grays都比较适合排查生产环境的问题，都属于“事后工具”，即服务已经上线，不能再通过嵌入分析打印日志等方法。这时候就可以使用这些工具来跟踪代码执行耗时、堆栈情况等，其原理是基于动态字节码修改技术（Hotswap），实现java程序在运行时的跟踪和替换。利用JavaSE6Instrumentation的新特性。使用场景分析哪些方法慢，查询具体故障点；查看方法参数和返回值；查看对象属性等；Btrace和GreysBtrace和Grays都是工具。本文通过实例介绍如何使用，不会自己介绍，如果想了解更多可以直接进入以下链接：Btrace类型介绍https://github.com/btraceio/btrace/wikiGrays介绍https://yq.aliyun.com/articles/23903.实例-使用工具排查urs新提供了远程cookie验证jar包，关键方法是远程调用方法CookieDecoder.requestDecode(**)，我们主要跟踪这个方法。3.1使用Btrace由于我们的tomcat在appuser用户下，为了有相应的权限，我们的操作都是在appuser用户下进行的。大致步骤是：下载并解压btrace工具；编写监控脚本；设置jdk/btrace环境变量，上传脚本，编译获取tomcat进程号，开始监控查看详情具体操作：（1）下载btrace工具btrace-bin-1.3.9。tgz并解压（2）编写监控脚本（java代码UrsInterfaceCalls.java），即需要监控的具体类和方法1234567891011121314151617181920212223242526272829303132333435@BTrace//Remark1publicclassUrsInterfaceCalls{/2*MonitoringDecoder{/2*MonitoringDecoder这段代码用于中间requestDecode方法的执行时间，如果执行时间大于500ms，则打印耗时和堆栈*@paramduration*/@OnMethod(clazz="com.netease.urs.CookieDecoder",method="requestDecode",location=@Location(Kind.RETURN))//备注2publicstaticvoidrequestDecode(@Durationlongduration){//备注3//备注4if(duration/1000000>500){println("==CookieDecoderrequestDecodespend:"+duration/1000000+"ms");jstack();}}/***这段代码用于监控CustomHttpComponent中execute方法的执行时间，如果执行时间大于500ms，打印耗时和栈*@paramduration*/@OnMethod(clazz="com.netease.urs.http.CustomHttpComponent",method="execute",location=@Location(Kind.RETURN))publicstaticvoidexecute(@Durationlongduration){if(duration/1000000>500){println("==ursCookieHttpdoExecutespend:"+duration/1000000+"ms");jstack();}}}简单说明一下这个监控类，写两个监控方法：一个是监控CookieDecoder.requestDecode()的执行时间，如果大于500ms，则打印日志，打印相关堆栈；另一个监控CustomHttpComponent.execute()的执行时间备注1：添加注释@BTrace，表示该脚本将使用btrace相关函数；备注2：拦截方法定义，@OnMethod可以指定clazz,me??thod,location。这就构成了在什么时候（locationdecision）监控某个类/某个类下的某个方法/某个方法（methoddecision）（clazzdecision）。1@OnMethod(clazz="com.netease.urs.CookieDecoder",method="requestDecode",location=@Location(Kind.RETURN))表示监听CookieDecoder.requestDecode(),执行后(location=@Location(Kind.RETURN)执行相关操作备注3：@Duration表示方法的执行时间，单位纳秒。Remark4：只打印耗时超过500ms的信息和栈，防止大部分记录被打印出来。方法注解说明@OnMethod：指定在什么情况下应该触发使用当前注解的方法：claszz属性指定要匹配的类的全限定类名，可以使用正则表达式；method属性指定要匹配的方法名，可以使用正则表达式表达式；类型属性void(java.lang.String)可用于匹配：publicvoidfuncName(Stringparam)方法输入参数；location属性用@Location表示，匹配clazz和method条件，在method中执行何时执行脚本（before,after,exception,line,amethodcall）@OnTimer：指定一个定时任务@OnExit：脚本运行时触发Sys.exit(code)@OnError:当脚本运行并抛出异常时触发@OnEvent:当脚本运行时，Ctrl+C可以发送事件@OnLowMemory:让你指定一个阈值，内存低于阈值触发@OnProbe：可以用一个xml文件来描述何时触发方法方法参数注解说明@Self：目标对象本身@Retrun：目标程序方法的返回值（Kind.RETURN)@ProbeClassName：目标类名@ProbeMethodName：目标方法名@targetInstance：@Location指定的clazz，方法的目标（Kind.CALL）@targetMethodOrField：@Location指定的clazz，目标方法或字段方法（Kind.CALL）@Duration：目标方法执行时间，单位纳秒，需与Kind.RETURN或Kind.ERROR一起使用（3）设置jdk/btrace环境变量1234567exportJAVA_HOME=/home/jdk1.8.0exportJRE_HOME=/home/jdk1。8.0/jreexport类路径=.:${JAVA_HOME}/lib:${JRE_HOME}/libexportPATH=$JAVA_HOME/bin:$PATHexportBTRACE_HOME=/home/appuser/bTraceexportPATH=$BTRACE_HOME/bin:$PATH上传监控脚本UrsInterfaceCalls.java到服务器；可以使用btracec预编译保证代码正确（4）获取tomcat的执行进程号psaux|grep"/fa.163.com"（5）进入UrsInterfaceCalls.java所在目录，启动btrace监控,并监控指定进程号19504（即jvm进程号）1shbtrace-p202119054UrsInterfaceCalls.java-p2021：指定一个端口号，防止多次执行造成端口冲突；19054:需要监听的进程号ursInterfaceCalls.java:监听脚本(6)检查结果如果方法执行超过500ms，则打印日志，同时打印堆栈；12345678910111213141516==CookieDecoderrequestDecode花费：525mscom.netease.urs.CookieDecoder.requestDecode(CookieDecoder.java:64)com.netease.urs.ntescode.validate_cookie_online(ntescode.java:49)com.netease.common.util..CookieUtil.getUserInfoFromUrsRemoteCookie(CookieUtil.java:317)com.netease.lottery.service.util.CookieUtilServiceImpl.getUserInfoFromUrsRemoteCookie(CookieUtilServiceImpl.java:88)com.netease.lottery.service.util.CookieUtilServiceImpl$$FastClassByCGLIB$$1bd66cf1.invoke(<生成>)org.springframework.cglib.proxy.MethodProxy.调用（MethodProxy.java:204）.....org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run（NioEndpoint.java:1708）java.util.concurrent.ThreadPoolExecutor.runWorker（ThreadPoolExecutor.java:1142)java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)java.lang.Thread.run(Thread.java:745)如果要定位具体耗时，需要为每个关键方法添加监控脚本。但是一次只能监控一个方法，不像Btrace可以同时监控多个方法。使用过程大致步骤：下载Grays工具并解压，安装；设置jdk环境变量获取tomcat进程号，启动监控查看详情具体步骤：（1）下载最新版Greys，解压后执行安装命令1sh./install-local.sh（2）设置环境变量1234exportJAVA_HOME=/home/jdk1.8.0exportJRE_HOME=/home/jdk1.8.0/jreexportCLASSPATH=.:${JAVA_HOME}/lib:${JRE_HOME}/libexportPATH=$JAVA_HOME/bin:$PATH（3）查询jvm的进程号，进入greys安装目录，启动greys1./greys.sh1043710437是jvm的进程号（4）启动后，可以使用交互命令来指定类和方法是分析了。使用帮助查看各种命令。(5)使用trace命令跟踪指定类和方法的执行时间、参数、返回值；使用helptrace查询使用方法。例如：跟踪CookieDecoder类中方法requestDecode()方法的执行时间超过500ms：1trace-n2com.netease.urs.CookieDecoderrequestDecode'#cost>500'-n2:表示只打印2退出前的次数（以防止屏幕滑动并影响性能）；com.netease.urs.CookieDecoder:监听器类名requestDecode:监听方法名'#cost>500':打印条件是执行超过500ms后，会显示：123ga?>trace-n2com.netease.urs.CookieDecoderrequestDecode'#cost>10'PressCtrl+Dtoabort.Affect(class-cnt:1,method-cnt:2)costin262ms.意思是动态修改一个类，监听两个方法（比如方法重载），修改耗时262ms。如果满足条件，我们将看到打印结果：12345678910111213141516171819202122232425262728293031`---+Tracingfor:thread_name="http-nio-8003-exec-8"thread_id=0x7a;is_daemon=true;priority=5;`---+[5283,5283ms]com.netease.urs.CookieDecoder:requestDecode()+---[1,0ms]java.lang.System:nanoTime()+---[2,1ms]org.apache.http.client.methods.HttpPost:
