此处不再赘述Arthas的安装，直接上使用技巧
1. 查看线程信息
thread
查看当前线程信息，查看线程的堆栈
参数说明
| 参数名称 | 参数说明 |
|---|---|
| id | 线程id |
| [n:] | 指定最忙的前N个线程并打印堆栈 |
| [b] | 找出当前阻塞其他线程的线程 |
[i <value>] | 指定cpu占比统计的采样间隔，单位为毫秒 |
1) 查看当前所有线程
thread
输出
2) 查看当前最忙的前n个线程并打印堆栈
thread -n 2
输出
$ thread -n 2
"http-nio-8080-exec-1" Id=147 cpuUsage=18% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
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.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
"http-nio-8080-exec-25" Id=180 cpuUsage=18% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
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.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
3) 显示指定id线程的运行堆栈
thread 180
输出
$ thread 180
"http-nio-8080-exec-25" Id=180 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
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.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
4) 找出阻塞其他线程的线程
thread -b
输出
$ thread -b
No most blocking thread found!
Affect(row-cnt:0) cost in 64 ms.
注意， 目前只支持找出synchronized关键字阻塞住的线程， 如果是java.util.concurrent.Lock， 目前还不支持。
2. 反编译已加载类的源码
反编译指定已加载类的源码
jad 命令将 JVM 中实际运行的 class 的 byte code 反编译成 java 代码，便于你理解业务逻辑；
- 在 Arthas Console 上，反编译出来的源码是带语法高亮的，阅读更方便
- 当然，反编译出来的 java 代码可能会存在语法错误，但不影响你进行阅读理解
参数说明
| 参数名称 | 参数说明 |
|---|---|
| class-pattern | 类名表达式匹配 |
[c:] | 类所属 ClassLoader 的 hashcode |
| [E] | 开启正则表达式匹配，默认为通配符匹配 |
1) 直接反编译查看源码
jad com.esell.*.DeviceAdSweepCodeController
输出
$ jad com.esell.*.DeviceAdSweepCodeController
ClassLoader:
+-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-sun.misc.Launcher$ExtClassLoader@317e9c3c
Location:
file:/home/admin/app/c4237202-afae-4d8b-9dad-e788cb42d7fb/es-yxfbp-main-1.0.0.jar!/BOOT-INF/lib/es-yxfbp-gw-1.0.0-SNAPSHOT.jar!/
/*
* Decompiled with CFR 0_132.
*
* Could not load the following classes:
* cn.hutool.core.thread.ThreadUtil
* com.alibaba.fastjson.JSONObject
* com.esell.annotation.RequestParameter
* com.esell.annotation.Validation
* com.esell.message.domestic.SimpleApiRequest
* com.esell.v2.device.controller.DeviceAdSweepCodeController$1
* com.esell.v2.device.model.dto.DeviceAdSweepCodeDto
* com.esell.v2.device.service.DeviceAdSweepCodeService
* javax.servlet.http.HttpServletResponse
* org.slf4j.Logger
* org.slf4j.LoggerFactory
* org.springframework.beans.factory.annotation.Autowired
* org.springframework.web.bind.annotation.GetMapping
* org.springframework.web.bind.annotation.RequestMapping
* org.springframework.web.bind.annotation.RestController
*/
package com.esell.v2.device.controller;
import cn.hutool.core.thread.ThreadUtil;
import com.alibaba.fastjson.JSONObject;
import com.esell.annotation.RequestParameter;
import com.esell.annotation.Validation;
import com.esell.message.domestic.SimpleApiRequest;
import com.esell.v2.device.controller.DeviceAdSweepCodeController;
import com.esell.v2.device.model.dto.DeviceAdSweepCodeDto;
import com.esell.v2.device.service.DeviceAdSweepCodeService;
import java.io.IOException;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
@RestController
@RequestMapping(value={"/device/ad/sweep"})
public class DeviceAdSweepCodeController {
private static final Logger log = LoggerFactory.getLogger(DeviceAdSweepCodeController.class);
@Autowired
private DeviceAdSweepCodeService deviceAdSweepCodeService;
@GetMapping(value={"/add.shtml"})
@Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
JSONObject jsonObject = new JSONObject();
DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
response.sendRedirect(reqData.getRedirect());
}
static /* synthetic */ DeviceAdSweepCodeService access$000(DeviceAdSweepCodeController x0) {
return x0.deviceAdSweepCodeService;
}
static /* synthetic */ Logger access$100() {
return log;
}
}
Affect(row-cnt:1) cost in 544 ms.
2) 反编绎时只显示源代码
默认情况下，反编译结果里会带有ClassLoader信息，通过--source-only选项，可以只打印源代码。
jad --source-only com.esell.*.DeviceAdSweepCodeController
输出
/*
* Decompiled with CFR 0_132.
*
* Could not load the following classes:
* cn.hutool.core.thread.ThreadUtil
* com.alibaba.fastjson.JSONObject
* com.esell.annotation.RequestParameter
* com.esell.annotation.Validation
* com.esell.message.domestic.SimpleApiRequest
* com.esell.v2.device.controller.DeviceAdSweepCodeController$1
* com.esell.v2.device.model.dto.DeviceAdSweepCodeDto
* com.esell.v2.device.service.DeviceAdSweepCodeService
* javax.servlet.http.HttpServletResponse
* org.slf4j.Logger
* org.slf4j.LoggerFactory
* org.springframework.beans.factory.annotation.Autowired
* org.springframework.web.bind.annotation.GetMapping
* org.springframework.web.bind.annotation.RequestMapping
* org.springframework.web.bind.annotation.RestController
*/
package com.esell.v2.device.controller;
import cn.hutool.core.thread.ThreadUtil;
import com.alibaba.fastjson.JSONObject;
import com.esell.annotation.RequestParameter;
import com.esell.annotation.Validation;
import com.esell.message.domestic.SimpleApiRequest;
import com.esell.v2.device.controller.DeviceAdSweepCodeController;
import com.esell.v2.device.model.dto.DeviceAdSweepCodeDto;
import com.esell.v2.device.service.DeviceAdSweepCodeService;
import java.io.IOException;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
@RestController
@RequestMapping(value={"/device/ad/sweep"})
public class DeviceAdSweepCodeController {
private static final Logger log = LoggerFactory.getLogger(DeviceAdSweepCodeController.class);
@Autowired
private DeviceAdSweepCodeService deviceAdSweepCodeService;
@GetMapping(value={"/add.shtml"})
@Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
JSONObject jsonObject = new JSONObject();
DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
response.sendRedirect(reqData.getRedirect());
}
static /* synthetic */ DeviceAdSweepCodeService access$000(DeviceAdSweepCodeController x0) {
return x0.deviceAdSweepCodeService;
}
static /* synthetic */ Logger access$100() {
return log;
}
}
3) 反编绎时指定方法
jad com.esell.*.DeviceAdSweepCodeController sweep
输出
$ jad com.esell.*.DeviceAdSweepCodeController sweep
ClassLoader:
+-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-sun.misc.Launcher$ExtClassLoader@317e9c3c
Location:
file:/home/admin/app/c4237202-afae-4d8b-9dad-e788cb42d7fb/es-yxfbp-main-1.0.0.jar!/BOOT-INF/lib/es-yxfbp-gw-1.0.0-SNAPSHOT.jar!/
@GetMapping(value={"/add.shtml"})
@Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
JSONObject jsonObject = new JSONObject();
DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
response.sendRedirect(reqData.getRedirect());
}
Affect(row-cnt:1) cost in 354 ms.
4) 反编绎时指定classloader
当有多个 ClassLoader 都加载了这个类时，jad 命令会输出对应 ClassLoader 实例的 hashcode，然后你只需要重新执行 jad 命令，并使用参数 -c 就可以反编译指定 ClassLoader 加载的那个类了；如下
$ jad *DeviceAdSweepCodeController
Found more than one class for: *DeviceAdSweepCodeController, Please use jad -c <hashcode> *DeviceAdSweepCodeController
HASHCODE CLASSLOADER
7c75222b +-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-sun.misc.Launcher$ExtClassLoader@317e9c3c
7c75222b +-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-sun.misc.Launcher$ExtClassLoader@317e9c3c
Affect(row-cnt:0) cost in 24 ms.
使用-c即可进入相应的源码查看
jad -c 7c75222b *DeviceAdSweepCodeController
5) 反编绎输出到指定目录
需要使用--source-only
jad --source-only com.esell.gw.yxfbp.rew.adv.controller.AdvController > /usr/local/arthas/file/AdvController.java
3. 使用Arthas进行线上热更新
redefine
加载外部的
.class文件，redefine jvm已加载的类。
参数说明
| 参数名称 | 参数说明 |
|---|---|
| [c:] | ClassLoader的hashcode |
| [p:] | 外部的.class文件的完整路径，支持多个 |
1) 热部署class文件
首先在本地将需要热更新的java文件编译成class文件，上传到服务器，在arthas进程中执行以下命令
redefine /usr/local/arthas/file/AdvController.class
输出如下语句则为热更新成功
要确定更改内容是否已经部署到服务器，可采用反编译命令获取源文件查看
jad --source-only com.esell.gw.yxfbp.rew.adv.controller.AdvController > /usr/local/arthas/file/AdvController.java
下载后通过 vi AdvController.java查看，在命令模式下使用 /字符串 查看对应内容，按下小写n，向下查找 ，按下大写N，向上查找
重点提醒
redefine的限制
- 不允许新增加field/method
- 正在跑的函数，没有退出不能生效，比如下面新增加的
System.out.println，只有run()函数里的会生效
public class MathGame {
public static void main(String[] args) throws InterruptedException {
MathGame game = new MathGame();
while (true) {
game.run();
TimeUnit.SECONDS.sleep(1);
// 这个不生效，因为代码一直跑在 while里
System.out.println("in loop");
}
}
public void run() throws InterruptedException {
// 这个生效，因为run()函数每次都可以完整结束
System.out.println("call run()");
try {
int number = random.nextInt();
List<Integer> primeFactors = primeFactors(number);
print(number, primeFactors);
} catch (Exception e) {
System.out.println(String.format("illegalArgumentCount:%3d, ", illegalArgumentCount) + e.getMessage());
}
}
4. 对方法的调用进行性能监控
方法执行监控
对匹配 class-pattern／method-pattern的类、方法的调用进行监控。
monitor 命令是一个非实时返回命令.
实时返回命令是输入之后立即返回，而非实时返回的命令，则是不断的等待目标 Java 进程返回信息，直到用户输入 Ctrl+C 为止。
服务端是以任务的形式在后台跑任务，植入的代码随着任务的中止而不会被执行，所以任务关闭后，不会对原有性能产生太大影响，而且原则上，任何Arthas命令不会引起原有业务逻辑的改变。
监控的维度说明
| 监控项 | 说明 |
|---|---|
| timestamp | 时间戳 |
| class | Java类 |
| method | 方法（构造方法、普通方法） |
| total | 调用次数 |
| success | 成功次数 |
| fail | 失败次数 |
| rt | 平均RT |
| fail-rate | 失败率 |
参数说明
方法拥有一个命名参数 [c:]，意思是统计周期（cycle of output），拥有一个整型的参数值
| 参数名称 | 参数说明 |
|---|---|
| class-pattern | 类名表达式匹配 |
| method-pattern | 方法名表达式匹配 |
| [E] | 开启正则表达式匹配，默认为通配符匹配 |
[c:] | 统计周期，默认值为120秒 |
1) 对方法在指定周期内的调用进行性能监控
monitor -c 10 com.esell.v2.device.controller.DeviceBaseController listDevice
输出
2) 对多个方法在指定周期的调用进行性能监控
需要注意的是此处只能使用全类名而不能使用通配符
monitor -c 10 -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search
输出
5. 查看方法中每个节点的耗时
trace
方法内部调用路径，并输出方法路径上的每个节点上耗时
trace 命令能主动搜索 class-pattern／method-pattern(可使用通配符) 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
参数说明
| 参数名称 | 参数说明 |
|---|---|
| class-pattern | 类名表达式匹配 |
| method-pattern | 方法名表达式匹配 |
| condition-express | 条件表达式 |
| [E] | 开启正则表达式匹配，默认为通配符匹配 |
[n:] | 命令执行次数 |
#cost | 方法执行耗时 |
首先需要使用arthas进入相应的jvm进程
1) 查看到方法各节点的耗时
使用 trace 类名 方法 在客户端访问此方法即可
trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd
或
trace *PublishManager updateAd
输出可以看到方法的总耗时，以及每个节点的耗时
$ trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 279 ms.
`---ts=2019-07-23 10:44:44;thread_name=http-nio-8080-exec-3;id=a1;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
`---[19562.263654ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
+---[0.023008ms] java.lang.Integer:intValue() #76
+---[7.961462ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
+---[0.015249ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
+---[42.933313ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
`---[19508.385811ms] java.util.List:forEach() #81
2) 过滤掉jvm函数的耗时
使用 trace 类名 方法 -j 加入 -j 参数过滤掉jvm函数
trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd -j
输出
$ trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd -j
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 206 ms.
`---ts=2019-07-23 10:48:38;thread_name=http-nio-8080-exec-20;id=bb;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
`---[16762.507405ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
+---[3.685484ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
+---[0.013117ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
`---[26.934144ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
3) 对多个类的多个方法进行追踪
使用 trace -E 类名|全类名 方法|方法 加入 -E 来对多个类的多个方法进行追踪，注意此处不能使用通配符
trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice
输出
$ trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 511 ms.
`---ts=2019-07-23 11:45:21;thread_name=http-nio-8080-exec-54;id=dd;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
`---[15607.698171ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
+---[0.020851ms] java.lang.Integer:intValue() #76
+---[3.550901ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
+---[0.014086ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
+---[16.370718ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
`---[15586.764431ms] java.util.List:forEach() #81
`---ts=2019-07-23 11:45:40;thread_name=http-nio-8080-exec-56;id=df;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
`---[249.902613ms] com.esell.v2.device.controller.DeviceBaseController:listDevice()
+---[3.444852ms] com.esell.yxf.common.util.LoggerMainBuilderUtils:requestLog() #230
+---[0.011863ms] com.esell.message.SimpleApiRequest:getPayload() #234
+---[0.054789ms] com.alibaba.fastjson.JSONObject:toJavaObject() #234
+---[0.064045ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:copyNew() #234
+---[0.00505ms] com.esell.message.SimpleApiRequest:getString() #235
+---[0.036919ms] java.lang.String:replaceAll() #236
+---[0.002666ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:setSortField() #237
+---[1.288203ms] com.esell.util.SessionUtils:findUser() #240
+---[0.007632ms] com.esell.api.account.bean.AccountBean:getCrmCode() #241
+---[0.0048ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:setCrmCode() #241
+---[0.0156ms] com.esell.api.account.bean.type.AccountUtils:remitCheckPermission() #244
+---[0.003174ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:getNotBind() #253
+---[200.227842ms] com.esell.v2.device.service.DeviceBaseService:search() #265
+---[0.021341ms] com.esell.spring.boot.starter.mybatis.plugin.pagination.PaginationBean:getData() #267
+---[0.011263ms] com.esell.message.SimpleApiRequest:getArray() #270
+---[0.006812ms] java.util.ArrayList:<init>() #271
+---[0.004011ms] com.esell.util.SessionUtils:current() #272
+---[0.008421ms] com.esell.session.Session:getLanguage() #272
+---[0.030655ms] java.util.Optional:ofNullable() #273
+---[0.032682ms] java.util.Collections:emptyList() #273
+---[0.007926ms] java.util.Optional:orElse() #273
+---[0.052993ms] java.util.List:forEach() #273
+---[42.130235ms] java.util.List:forEach() #295
+---[0.018547ms] com.esell.spring.boot.starter.mybatis.plugin.pagination.PaginationBean:toPagination() #311
+---[0.017203ms] com.esell.gw.yxfbp.common.PaginationApiResponse:<init>() #311
`---[0.961965ms] com.esell.yxf.common.util.LoggerMainBuilderUtils:responseLog() #313
4) 筛选指定耗时的方法
很多时候我们只想看到某个方法的rt大于某个时间之后的trace结果，现在Arthas可以按照方法执行的耗时来进行过滤了，例如trace *StringUtils isBlank '#cost>100'表示当执行时间超过100ms的时候，才会输出trace的结果。
trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice '#cost > 15607'
输出
$ trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice '#cost > 15607'
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 1179 ms.
`---ts=2019-07-23 11:47:21;thread_name=http-nio-8080-exec-60;id=e5;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
`---[19575.706387ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
+---[0.00811ms] java.lang.Integer:intValue() #76
+---[2.816689ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
+---[0.035768ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
+---[29.068075ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
`---[19542.923598ms] java.util.List:forEach() #81
重点提醒
trace能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。
trace命令只会trace匹配到的函数里的子调用，并不会向下trace多层。因为trace是代价比较贵的，多层trace可能会导致最终要trace的类和函数非常多
6. 对方法执行数据的观测
watch
方法执行数据观测
让你能方便的观察到指定方法的调用情况。能观察到的范围为：返回值、抛出异常、入参
参数说明
watch 的参数比较多，主要是因为它能在 4 个不同的场景观察对象
| 参数名称 | 参数说明 |
|---|---|
| class-pattern | 类名表达式匹配 |
| method-pattern | 方法名表达式匹配 |
| express | 观察表达式 |
| condition-express | 条件表达式 |
| [b] | 在方法调用之前观察 |
| [e] | 在方法异常之后观察 |
| [s] | 在方法返回之后观察 |
| [f] | 在方法结束之后(正常返回和异常返回)观察 |
| [E] | 开启正则表达式匹配，默认为通配符匹配 |
| [x:] | 指定输出结果的属性遍历深度，默认为 1 |
对于观察表达式，单个可以这么写 "params"，多个则是"{params,returnObj,throwExp}"，只要是一个合法的 ognl 表达式，都能被正常支持。更多的表达式变量请参考表达式核心变量中关于该节点的描述。
同时对于Arthas中ognl表达式的更多特殊例子可参考 Arthas的一些特殊用法文档说明
特别说明：
- watch 命令定义了4个观察事件点，即
-b方法调用前，-e方法异常后，-s方法返回后，-f方法结束后 - 4个观察事件点
-b、-e、-s默认关闭，-f默认打开，当指定观察点被打开后，在相应事件点会对观察表达式进行求值并输出 - 这里要注意
方法入参和方法出参的区别，有可能在中间被修改导致前后不一致，除了-b事件点params代表方法入参外，其余事件都代表方法出参 - 当使用
-b时，由于观察事件点是在方法调用前，此时返回值或异常均不存在 -x表示遍历深度，可以调整来打印具体的参数和结果内容，默认值是1
1) 查看方法的请求参数和返回参数
-x 参数的值可根据实际参数的遍历深度进行设置，如果需要查看resultObj的具体值，可以调整-x的值
watch *DeviceBaseController listDevice "{params,returnObj}" -x 2
输出，可以看到result中有两个结果，第一个是请求参数，第二个是返回参数
$ watch *DeviceBaseController listDevice "{params,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 833 ms.
ts=2019-07-24 11:56:39; [cost=311.854619ms] result=@ArrayList[
@Object[][
@SimpleApiRequest[{"sign":"b3d98718d6ceff8c1668c43592019cf2","appid":"Jvddh8LKdLwmZ3cw","version":"1.3","sequence":1563940597279,"timestamp":1563940597279,"payload":"{\"page\":1,\"size\":10,\"uuid\":\"\",\"group-id\":\"\",\"gatherId\":\"\",\"name\":\"\",\"open\":\"\",\"district-code\":\"\",\"status\":\"\",\"phone-number\":\"\"}"}],
@RequestFacade[org.apache.catalina.connector.RequestFacade@68db1322],
],
@PaginationApiResponse[
serialVersionUID=@Long[4126749321937797939],
],
]
2) 查看方法的参数的指定属性
SimpleApiRequest的结构
{
appId: "..........",
sign: "...........",
...,
payload: {
"uuid": "123456",
}
}查看请求的uuid值
watch *DeviceBaseController listDevice "{params[0].payload.uuid,returnObj}" -x 2
输出，可看到uuid为519073369656
$ watch *DeviceBaseController listDevice "{params[0].payload.uuid,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 757 ms.
ts=2019-07-24 12:01:08; [cost=147.622644ms] result=@ArrayList[
@String[ 519073369656],
@PaginationApiResponse[
serialVersionUID=@Long[4126749321937797939],
],
]
3) 根据条件过滤
当请求参数的uuid为519073369656才输出
watch *DeviceBaseController listDevice "{params[0],returnObj}" "params[0].payload.uuid=='519073369656'" -x 2
输出
$ watch *DeviceBaseController listDevice "{params[0],returnObj}" "params[0].payload.uuid=='519073369656'" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 794 ms.
ts=2019-07-24 12:04:27; [cost=79.459047ms] result=@ArrayList[
@SimpleApiRequest[
serialVersionUID=@Long[7777957270454431721],
],
@PaginationApiResponse[
serialVersionUID=@Long[4126749321937797939],
],
]
4) 查看异常的输出
watch *TemplateV2ServiceImpl addTemplate "throwExp" -e -x 2
输出
$ watch *TemplateV2ServiceImpl addTemplate "throwExp" -e -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 439 ms.
ts=2019-07-24 12:45:12; [cost=64.79821ms] result=@ArrayList[
com.esell.exception.EsellException: 互动按钮跳转未设置，请退出重新编辑 [DEBUG: 互动按钮跳转未设置，请退出重新编辑]
.............................
5) 筛选指定耗时的方法
大于10ms的耗时才被输出
watch *TemplateV2ServiceImpl addTemplate "params" -x 2 '#cost>10'
输出，耗时103.519568ms
shell $ watch *TemplateV2ServiceImpl addTemplate "params" -x 2 '#cost>10'
Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:2) cost in 313 ms. ts=2019-07-24 12:49:49; [cost=103.519568ms]
result=@Object[][ @TemplateV2SearchDto[ templateId=null, name=@String[1111jjjj], accountId=@Integer[86], crmCode=@String[C1804111843], width=@Integer[1920], height=@Integer[1080], pageList=@String[[{"slotNum":1,"name":"页面1","page":[{"openRtb":"0","componentId":1261,"src":"","h":200,"type":"slot","materialId":"","templateId":8089,"slotName":"广告位1","adSwitchType":"0","w":3":702,"rtbCpm":"0","y":602,"slotId":11379,"zIndex":1}],"id":1001}]], groupGuid=null, scaleRatio=@String[1], tempCover=@ArrayList[isEmpty=false;size=1], components=@ArrayList[isEmpty=false;size=1], ], ]6) 对多个类的多个方法的参数进行查看
注意此处不能使用通配符
watch -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search 'params[0].payload' -x 3
输出
$ watch -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search 'params[0].payload' -x 3
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 577 ms.
ts=2019-07-24 15:20:39; [cost=11.840307ms] result=@JSONObject[
@String[size]:@Integer[8],
@String[name]:@String[],
@String[page]:@Integer[1],
]
ts=2019-07-24 15:20:41; [cost=344.565606ms] result=@JSONObject[
@String[phone-number]:@String[],
@String[size]:@Integer[10],
@String[group-id]:@String[],
@String[gatherId]:@String[],
@String[name]:@String[],
@String[page]:@Integer[1],
@String[district-code]:@String[],
@String[uuid]:@String[],
@String[open]:@String[],
@String[status]:@String[],
]
7. 获取不同时间方法执行的记录
方法执行数据的时空隧道，记录下指定方法每次调用的入参和返回信息，并能对这些不同的时间下调用进行观测
watch 虽然很方便和灵活，但需要提前想清楚观察表达式的拼写，这对排查问题而言要求太高，因为很多时候我们并不清楚问题出自于何方，只能靠蛛丝马迹进行猜测。
这个时候如果能记录下当时方法调用的所有入参和返回值、抛出的异常会对整个问题的思考与判断非常有帮助。
于是乎，TimeTunnel 命令就诞生了。
-
命令参数解析
-
-ttt 命令有很多个主参数，
-t就是其中之一。这个参数的表明希望记录下类*Test的print方法的每次执行情况。 -
-n 3当你执行一个调用量不高的方法时可能你还能有足够的时间用
CTRL+C中断 tt 命令记录的过程，但如果遇到调用量非常大的方法，瞬间就能将你的 JVM 内存撑爆。此时你可以通过
-n参数指定你需要记录的次数，当达到记录次数时 Arthas 会主动中断tt命令的记录过程，避免人工操作无法停止的情况。 -
表格字段说明
| 表格字段 | 字段解释 |
|---|---|
| INDEX | 时间片段记录编号，每一个编号代表着一次调用，后续tt还有很多命令都是基于此编号指定记录操作，非常重要。 |
| TIMESTAMP | 方法执行的本机时间，记录了这个时间片段所发生的本机时间 |
| COST(ms) | 方法执行的耗时 |
| IS-RET | 方法是否以正常返回的形式结束 |
| IS-EXP | 方法是否以抛异常的形式结束 |
| OBJECT | 执行对象的hashCode()，注意，曾经有人误认为是对象在JVM中的内存地址，但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体 |
| CLASS | 执行的类名 |
| METHOD | 执行的方法名 |
-
条件表达式
不知道大家是否有在使用过程中遇到以下困惑
-
Arthas 似乎很难区分出重载的方法
-
我只需要观察特定参数，但是 tt 却全部都给我记录了下来
条件表达式也是用
OGNL来编写，核心的判断对象依然是Advice对象。除了tt命令之外，watch、trace、stack命令也都支持条件表达式。 -
解决方法重载
tt -t *Test print params.length==1通过制定参数个数的形式解决不同的方法签名，如果参数个数一样，你还可以这样写
tt -t *Test print 'params[1] instanceof Integer' -
解决指定参数
tt -t *Test print params[0].mobile=="13989838402" -
构成条件表达式的
Advice对象前边看到了很多条件表达式中，都使用了
params[0]，有关这个变量的介绍，请参考表达式核心变量
1) 获取方法的调用记录
tt -t *.DeviceBaseController listDevice
输出
2) 根据条件过滤
条件表达式也是用 OGNL 来编写，核心的判断对象依然是 Advice 对象。除了 tt 命令之外，watch、trace、stack 命令也都支持条件表达式。
tt -t *.DeviceBaseController listDevice 'params[0].payload.uuid==519'
输出
3) 获取之前的调用记录
tt -l
输出
4) 根据条件从调用记录中筛选
你需要一个 -s 参数。同样的，搜索表达式的核心对象依旧是 Advice 对象。
tt -s 'method.name == "listDevice"'
输出
5) 查看方法的具体调用信息
对于具体一个时间片的信息而言，你可以通过 -i 参数后边跟着对应的 INDEX 编号查看到他的详细信息。可以通过-x来查看更深层详细的参数输出
tt -i 1002
输出
6) 对方法重新调用
当你稍稍做了一些调整之后，你可能需要前端系统重新触发一次你的调用，此时得求爷爷告奶奶的需要前端配合联调的同学再次发起一次调用。而有些场景下，这个调用不是这么好触发的。
tt 命令由于保存了当时调用的所有现场信息，所以我们可以自己主动对一个 INDEX 编号的时间片自主发起一次调用，从而解放你的沟通成本。此时你需要 -p 参数。通过 --replay-times 指定 调用次数，通过 --replay-interval 指定多次调用间隔(单位ms, 默认1000ms)
tt -i 1002 -p
输出
你会发现结果虽然一样，但调用的路径发生了变化，有原来的程序发起变成了 Arthas 自己的内部线程发起的调用了。
注意
-
ThreadLocal 信息丢失
很多框架偷偷的将一些环境变量信息塞到了发起调用线程的 ThreadLocal 中，由于调用线程发生了变化，这些 ThreadLocal 线程信息无法通过 Arthas 保存，所以这些信息将会丢失。
一些常见的 CASE 比如：鹰眼的 TraceId 等。
-
引用的对象
需要强调的是，
tt命令是将当前环境的对象引用保存起来，但仅仅也只能保存一个引用而已。如果方法内部对入参进行了变更，或者返回的对象经过了后续的处理，那么在tt查看的时候将无法看到当时最准确的值。这也是为什么watch命令存在的意义。
欢迎关注公众号，后续文章更新通知，一起讨论技术问题 。
2846
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
