2022-07-15 22:37:32 +08:00
|
|
|
|
# tt
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
2020-08-07 18:28:00 +08:00
|
|
|
|
[`tt`在线教程](https://arthas.aliyun.com/doc/arthas-tutorials.html?language=cn&id=command-tt)
|
2020-08-07 17:42:54 +08:00
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
::: tip
|
|
|
|
|
方法执行数据的时空隧道,记录下指定方法每次调用的入参和返回信息,并能对这些不同的时间下调用进行观测
|
|
|
|
|
:::
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
`watch` 虽然很方便和灵活,但需要提前想清楚观察表达式的拼写,这对排查问题而言要求太高,因为很多时候我们并不清楚问题出自于何方,只能靠蛛丝马迹进行猜测。
|
|
|
|
|
|
|
|
|
|
这个时候如果能记录下当时方法调用的所有入参和返回值、抛出的异常会对整个问题的思考与判断非常有帮助。
|
|
|
|
|
|
|
|
|
|
于是乎,TimeTunnel 命令就诞生了。
|
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
## 使用参考
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
### 启动 Demo
|
2018-12-04 16:12:25 +08:00
|
|
|
|
|
2021-03-17 17:49:21 +08:00
|
|
|
|
启动[快速入门](quick-start.md)里的`math-game`。
|
2018-12-04 16:12:25 +08:00
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
### 记录调用
|
2018-12-04 16:12:25 +08:00
|
|
|
|
|
|
|
|
|
对于一个最基本的使用来说,就是记录下当前方法的每次调用环境现场。
|
|
|
|
|
|
|
|
|
|
```bash
|
|
|
|
|
$ tt -t demo.MathGame primeFactors
|
|
|
|
|
Press Ctrl+C to abort.
|
|
|
|
|
Affect(class-cnt:1 , method-cnt:1) cost in 66 ms.
|
|
|
|
|
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
|
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
|
1000 2018-12-04 11:15:38 1.096236 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1001 2018-12-04 11:15:39 0.191848 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1002 2018-12-04 11:15:40 0.069523 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1003 2018-12-04 11:15:41 0.186073 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1004 2018-12-04 11:15:42 17.76437 true false 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
```
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
2023-02-09 17:03:19 +08:00
|
|
|
|
### 指定 Class 最大匹配数量
|
2023-02-09 17:02:45 +08:00
|
|
|
|
|
|
|
|
|
```bash
|
|
|
|
|
$ tt -t -m 1 demo.MathGame primeFactors
|
|
|
|
|
Press Q or Ctrl+C to abort.
|
|
|
|
|
Affect(class count:1 , method count:1) cost in 130 ms, listenerId: 1.
|
|
|
|
|
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
|
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
|
1000 2022-12-25 19:41:45 2.629929 true false 0x3bf400 MathGame primeFactors
|
|
|
|
|
1001 2022-12-25 19:41:55 0.146161 false true 0x3bf400 MathGame primeFactors
|
|
|
|
|
```
|
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
- 命令参数解析
|
|
|
|
|
|
|
|
|
|
- `-t`
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
tt 命令有很多个主参数,`-t` 就是其中之一。这个参数的表明希望记录下类 `*Test` 的 `print` 方法的每次执行情况。
|
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
- `-n 3`
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
当你执行一个调用量不高的方法时可能你还能有足够的时间用 `CTRL+C` 中断 tt 命令记录的过程,但如果遇到调用量非常大的方法,瞬间就能将你的 JVM 内存撑爆。
|
|
|
|
|
|
|
|
|
|
此时你可以通过 `-n` 参数指定你需要记录的次数,当达到记录次数时 Arthas 会主动中断 tt 命令的记录过程,避免人工操作无法停止的情况。
|
2023-02-09 17:03:19 +08:00
|
|
|
|
|
2023-02-09 17:02:45 +08:00
|
|
|
|
- `-m 1`
|
2023-02-09 17:03:19 +08:00
|
|
|
|
|
|
|
|
|
通过 `-m` 参数指定 Class 匹配的最大数量,防止匹配到的 Class 数量太多导致 JVM 挂起,默认值是 50。
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
- 表格字段说明
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
| 表格字段 | 字段解释 |
|
|
|
|
|
| --------- | --------------------------------------------------------------------------------------------------------------------------------- |
|
|
|
|
|
| INDEX | 时间片段记录编号,每一个编号代表着一次调用,后续 tt 还有很多命令都是基于此编号指定记录操作,非常重要。 |
|
|
|
|
|
| TIMESTAMP | 方法执行的本机时间,记录了这个时间片段所发生的本机时间 |
|
|
|
|
|
| COST(ms) | 方法执行的耗时 |
|
|
|
|
|
| IS-RET | 方法是否以正常返回的形式结束 |
|
|
|
|
|
| IS-EXP | 方法是否以抛异常的形式结束 |
|
|
|
|
|
| OBJECT | 执行对象的`hashCode()`,注意,曾经有人误认为是对象在 JVM 中的内存地址,但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体 |
|
|
|
|
|
| CLASS | 执行的类名 |
|
|
|
|
|
| METHOD | 执行的方法名 |
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
- 条件表达式
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
不知道大家是否有在使用过程中遇到以下困惑
|
|
|
|
|
|
|
|
|
|
- Arthas 似乎很难区分出重载的方法
|
|
|
|
|
- 我只需要观察特定参数,但是 tt 却全部都给我记录了下来
|
|
|
|
|
|
|
|
|
|
条件表达式也是用 `OGNL` 来编写,核心的判断对象依然是 `Advice` 对象。除了 `tt` 命令之外,`watch`、`trace`、`stack` 命令也都支持条件表达式。
|
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
- 解决方法重载
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
`tt -t *Test print params.length==1`
|
|
|
|
|
|
|
|
|
|
通过制定参数个数的形式解决不同的方法签名,如果参数个数一样,你还可以这样写
|
|
|
|
|
|
|
|
|
|
`tt -t *Test print 'params[1] instanceof Integer'`
|
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
- 解决指定参数
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
`tt -t *Test print params[0].mobile=="13989838402"`
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
- 构成条件表达式的 `Advice` 对象
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
前边看到了很多条件表达式中,都使用了 `params[0]`,有关这个变量的介绍,请参考[表达式核心变量](advice-class.md)
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
### 检索调用记录
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
当你用 `tt` 记录了一大片的时间片段之后,你希望能从中筛选出自己需要的时间片段,这个时候你就需要对现有记录进行检索。
|
|
|
|
|
|
|
|
|
|
假设我们有这些记录
|
|
|
|
|
|
2018-12-04 16:12:25 +08:00
|
|
|
|
```bash
|
2018-09-07 16:16:05 +08:00
|
|
|
|
$ tt -l
|
2018-12-04 16:12:25 +08:00
|
|
|
|
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
|
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
|
1000 2018-12-04 11:15:38 1.096236 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1001 2018-12-04 11:15:39 0.191848 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1002 2018-12-04 11:15:40 0.069523 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1003 2018-12-04 11:15:41 0.186073 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1004 2018-12-04 11:15:42 17.76437 true false 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
9
|
|
|
|
|
1005 2018-12-04 11:15:43 0.4776 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
Affect(row-cnt:6) cost in 4 ms.
|
2018-09-07 16:16:05 +08:00
|
|
|
|
```
|
|
|
|
|
|
2018-12-04 16:12:25 +08:00
|
|
|
|
我需要筛选出 `primeFactors` 方法的调用信息
|
|
|
|
|
|
|
|
|
|
```bash
|
|
|
|
|
$ tt -s 'method.name=="primeFactors"'
|
|
|
|
|
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
|
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
|
1000 2018-12-04 11:15:38 1.096236 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1001 2018-12-04 11:15:39 0.191848 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1002 2018-12-04 11:15:40 0.069523 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1003 2018-12-04 11:15:41 0.186073 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
1004 2018-12-04 11:15:42 17.76437 true false 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
9
|
|
|
|
|
1005 2018-12-04 11:15:43 0.4776 false true 0x4b67cf4d MathGame primeFactors
|
|
|
|
|
Affect(row-cnt:6) cost in 607 ms.
|
2018-09-07 16:16:05 +08:00
|
|
|
|
```
|
|
|
|
|
|
|
|
|
|
你需要一个 `-s` 参数。<span style="color:red;">同样的,搜索表达式的核心对象依旧是 `Advice` 对象。</span>
|
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
### 查看调用信息
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
对于具体一个时间片的信息而言,你可以通过 `-i` 参数后边跟着对应的 `INDEX` 编号查看到他的详细信息。
|
|
|
|
|
|
2018-12-04 16:12:25 +08:00
|
|
|
|
```bash
|
2018-09-07 16:16:05 +08:00
|
|
|
|
$ tt -i 1003
|
2018-12-04 16:12:25 +08:00
|
|
|
|
INDEX 1003
|
|
|
|
|
GMT-CREATE 2018-12-04 11:15:41
|
|
|
|
|
COST(ms) 0.186073
|
|
|
|
|
OBJECT 0x4b67cf4d
|
|
|
|
|
CLASS demo.MathGame
|
|
|
|
|
METHOD primeFactors
|
|
|
|
|
IS-RETURN false
|
|
|
|
|
IS-EXCEPTION true
|
|
|
|
|
PARAMETERS[0] @Integer[-564322413]
|
|
|
|
|
THROW-EXCEPTION java.lang.IllegalArgumentException: number is: -564322413, need >= 2
|
|
|
|
|
at demo.MathGame.primeFactors(MathGame.java:46)
|
|
|
|
|
at demo.MathGame.run(MathGame.java:24)
|
|
|
|
|
at demo.MathGame.main(MathGame.java:16)
|
|
|
|
|
|
|
|
|
|
Affect(row-cnt:1) cost in 11 ms.
|
2018-09-07 16:16:05 +08:00
|
|
|
|
```
|
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
### 重做一次调用
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
|
|
|
|
当你稍稍做了一些调整之后,你可能需要前端系统重新触发一次你的调用,此时得求爷爷告奶奶的需要前端配合联调的同学再次发起一次调用。而有些场景下,这个调用不是这么好触发的。
|
|
|
|
|
|
2019-02-13 14:02:44 +08:00
|
|
|
|
`tt` 命令由于保存了当时调用的所有现场信息,所以我们可以自己主动对一个 `INDEX` 编号的时间片自主发起一次调用,从而解放你的沟通成本。此时你需要 `-p` 参数。通过 `--replay-times` 指定
|
2022-07-15 22:37:32 +08:00
|
|
|
|
调用次数,通过 `--replay-interval` 指定多次调用间隔(单位 ms, 默认 1000ms)
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
2018-12-04 16:12:25 +08:00
|
|
|
|
```bash
|
|
|
|
|
$ tt -i 1004 -p
|
|
|
|
|
RE-INDEX 1004
|
|
|
|
|
GMT-REPLAY 2018-12-04 11:26:00
|
|
|
|
|
OBJECT 0x4b67cf4d
|
|
|
|
|
CLASS demo.MathGame
|
|
|
|
|
METHOD primeFactors
|
|
|
|
|
PARAMETERS[0] @Integer[946738738]
|
|
|
|
|
IS-RETURN true
|
|
|
|
|
IS-EXCEPTION false
|
2019-02-13 14:02:44 +08:00
|
|
|
|
COST(ms) 0.186073
|
2018-12-04 16:12:25 +08:00
|
|
|
|
RETURN-OBJ @ArrayList[
|
|
|
|
|
@Integer[2],
|
|
|
|
|
@Integer[11],
|
|
|
|
|
@Integer[17],
|
|
|
|
|
@Integer[2531387],
|
|
|
|
|
]
|
|
|
|
|
Time fragment[1004] successfully replayed.
|
|
|
|
|
Affect(row-cnt:1) cost in 14 ms.
|
2018-09-07 16:16:05 +08:00
|
|
|
|
```
|
|
|
|
|
|
2020-10-24 12:08:12 +08:00
|
|
|
|
你会发现结果虽然一样,但调用的路径发生了变化,由原来的程序发起变成了 Arthas 自己的内部线程发起的调用了。
|
2018-09-07 16:16:05 +08:00
|
|
|
|
|
2022-08-09 18:42:39 +08:00
|
|
|
|
### 观察表达式
|
2021-01-11 15:47:07 +08:00
|
|
|
|
|
|
|
|
|
`-w, --watch-express` 观察时空隧道使用`ognl` 表达式
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
- 使用[表达式核心变量](advice-class.md)中所有变量作为已知条件编写表达式。
|
2021-01-11 15:47:07 +08:00
|
|
|
|
|
|
|
|
|
```bash
|
|
|
|
|
[arthas@10718]$ tt -t demo.MathGame run -n 5
|
|
|
|
|
Press Q or Ctrl+C to abort.
|
|
|
|
|
Affect(class count: 1 , method count: 1) cost in 56 ms, listenerId: 1
|
|
|
|
|
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
|
|
|
|
|
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
|
1000 2021-01-08 21:54:17 0.901091 true false 0x7699a589 MathGame run
|
|
|
|
|
[arthas@10718]$ tt -w 'target.illegalArgumentCount' -x 1 -i 1000
|
|
|
|
|
@Integer[60]
|
|
|
|
|
Affect(row-cnt:1) cost in 7 ms.
|
|
|
|
|
```
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
- 获取类的静态字段、调用类的静态方法
|
2021-01-11 15:47:07 +08:00
|
|
|
|
|
|
|
|
|
```bash
|
|
|
|
|
[arthas@10718]$ tt -t demo.MathGame run -n 5
|
|
|
|
|
Press Q or Ctrl+C to abort.
|
|
|
|
|
Affect(class count: 1 , method count: 1) cost in 56 ms, listenerId: 1
|
|
|
|
|
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
|
|
|
|
|
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
|
1000 2021-01-08 21:54:17 0.901091 true false 0x7699a589 MathGame run
|
|
|
|
|
[arthas@10718]$ tt -w '@demo.MathGame@random.nextInt(100)' -x 1 -i 1000
|
|
|
|
|
@Integer[46]
|
|
|
|
|
```
|
|
|
|
|
|
|
|
|
|
注意这里使用 `com.taobao.arthas.core.advisor.Advice#getLoader`加载,使用精确`classloader` [ognl](ognl.md)更好。
|
|
|
|
|
|
2022-07-15 22:37:32 +08:00
|
|
|
|
高级用法 [获取 spring context 调用 bean 方法](https://github.com/alibaba/arthas/issues/482)
|
2021-01-11 15:47:07 +08:00
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
- 需要强调的点
|
|
|
|
|
|
|
|
|
|
1. **ThreadLocal 信息丢失**
|
|
|
|
|
|
|
|
|
|
很多框架偷偷的将一些环境变量信息塞到了发起调用线程的 ThreadLocal 中,由于调用线程发生了变化,这些 ThreadLocal 线程信息无法通过 Arthas 保存,所以这些信息将会丢失。
|
2022-07-15 22:37:32 +08:00
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
一些常见的 CASE 比如:鹰眼的 TraceId 等。
|
2022-07-15 22:37:32 +08:00
|
|
|
|
|
2018-09-07 16:16:05 +08:00
|
|
|
|
2. **引用的对象**
|
|
|
|
|
|
2019-01-17 10:04:43 +08:00
|
|
|
|
需要强调的是,`tt` 命令是将当前环境的对象引用保存起来,但仅仅也只能保存一个引用而已。如果方法内部对入参进行了变更,或者返回的对象经过了后续的处理,那么在 `tt` 查看的时候将无法看到当时最准确的值。这也是为什么 `watch` 命令存在的意义。
|