tt
方法执行数据的时空隧道，记录下指定方法每次调用的入参和返回信息，并能对这些不同的时间下调用进行观测
watch 虽然很方便和灵活，但需要提前想清楚观察表达式的拼写，这对排查问题而言要求太高，因为很多时候我们并不清楚问题出自于何方，只能靠蛛丝马迹进行猜测。
这个时候如果能记录下当时方法调用的所有入参和返回值、抛出的异常会对整个问题的思考与判断非常有帮助。
于是乎，TimeTunnel 命令就诞生了。
| 命令选项 | 描述 |
|---|---|
| -d, --delete | 删除指定编号的时间片段，配合-i使用 |
| --delete-all | 删除所有的时间片段 |
| --exclude-class-pattern <pattern> | 排除class模式 |
| -x, --expand <level> | 扩展对象层级，默认1 |
| -i, --index <index> | 查看指定编号的时间片段信息 |
| -n, --limits <number> | 监控执行次数 |
| -l, --list | 列出所有时间片段 |
| --listenerId <id> | 特殊的监控id |
| -p, --play | 重播指定编号的时间片段，配合-i使用 |
| -E, --regex | 开启正则匹配，默认为通配符匹配 |
| --reply-interval <number> | 重播间隔(ms)，默认1000 |
| --reply-times <number> | 重播次数 |
| -s, --search-express <express> | 通过ognl表达式搜索时间片段 |
| -M, --size-Limit <number> | 最大字节数限制，默认10*1024*1024字节 |
| -t, --time-tunnel | 记录方法调用时间片段 |
| -v, --verbose | 打印debug信息 |
| -w, --watch-express | 针对某一特定时间片段的观察表达式 |
| -h, --help | 帮助 |
| <class-pattern> | 类匹配模式 |
| <method-pattern> | 方法匹配模式 |
| <condition-express> | ognl条件表达式 |
示例
记录时间片段
记录时间片段表格列说明
| 字段 | 描述 |
|---|---|
| INDEX | 时间片段编号，每一次方法调用都会有一个编号的时间片段对应 |
| TIMESTAMP | 方法执行时间戳 |
| COST(ms) | 方法执行耗时 |
| IS-RET | 是否以正常返回值结束 |
| IS-EXP | 是否以异常结束 |
| OBJECT | 执行对象的哈希值，非jvm内存地址 |
| CLASS | 执行的类名 |
| METHOD | 执行的方法名 |
# 记录方法时间片段
[arthas@20276]$ tt -t demo.MathGame primeFactors
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 20 ms, listenerId: 23
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1015 2023-03-30 17:48:36 0.0891 false true 0x7d6f77cc MathGame primeFactors
1016 2023-03-30 17:48:37 0.0268 false true 0x7d6f77cc MathGame primeFactors
[arthas@20276]$ tt -t demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 19 ms, listenerId: 24
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1017 2023-03-30 17:48:42 0.5945 true false 0x7d6f77cc MathGame run
1018 2023-03-30 17:48:43 1.4688 true false 0x7d6f77cc MathGame run
# 记录特定次数时间片段
[arthas@20276]$ tt -t demo.MathGame print -n 3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 20 ms, listenerId: 26
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1021 2023-03-30 17:49:07 0.4295 true false NULL MathGame print
1022 2023-03-30 17:49:10 1.3362 true false NULL MathGame print
1023 2023-03-30 17:49:15 0.1693 true false NULL MathGame print
Command execution times exceed limit: 3, so command will exit. You can set it with -n option.
# 记录类的所有方法时间片段
[arthas@20276]$ tt -t demo.MathGame *
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 5) cost in 21 ms, listenerId: 31
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1032 2023-03-30 17:55:39 0.1241 false true 0x7d6f77cc MathGame primeFactors
1033 2023-03-30 17:55:39 1.289 true false 0x7d6f77cc MathGame run
1034 2023-03-30 17:55:40 0.5011 true false 0x7d6f77cc MathGame primeFactors
1035 2023-03-30 17:55:40 0.7882 true false NULL MathGame print
1036 2023-03-30 17:55:40 2.1853 true false 0x7d6f77cc MathGame run
查看/搜索时间片段
# 查看所有时间片段
[arthas@20276]$ tt -l
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1026 2023-03-30 17:53:15 1.6528 true false 0x7d6f77cc MathGame run
1027 2023-03-30 17:53:16 1.2994 true false 0x7d6f77cc MathGame run
1028 2023-03-30 17:53:30 0.4793 true false NULL MathGame print
1029 2023-03-30 17:53:31 1.2506 true false NULL MathGame print
1030 2023-03-30 17:53:40 0.0826 false true 0x7d6f77cc MathGame primeFactors
1031 2023-03-30 17:53:41 0.1833 true false 0x7d6f77cc MathGame primeFactors
Affect(row-cnt:6) cost in 0 ms.
# 查看特定时间片段
[arthas@20276]$ tt -i 1026
INDEX 1026
GMT-CREATE 2023-03-30 17:53:15
COST(ms) 1.6528
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
RETURN-OBJ null
Affect(row-cnt:1) cost in 2 ms.
# 通过ognl表达式搜索时间片段
[arthas@20276]$ tt -s "method.name == 'run'"
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1026 2023-03-30 17:53:15 1.6528 true false 0x7d6f77cc MathGame run
1027 2023-03-30 17:53:16 1.2994 true false 0x7d6f77cc MathGame run
1033 2023-03-30 17:55:39 1.289 true false 0x7d6f77cc MathGame run
1036 2023-03-30 17:55:40 2.1853 true false 0x7d6f77cc MathGame run
1039 2023-03-30 17:55:41 2.2021 true false 0x7d6f77cc MathGame run
1042 2023-03-30 17:55:42 0.6956 true false 0x7d6f77cc MathGame run
1045 2023-03-30 17:55:43 2.2639 true false 0x7d6f77cc MathGame run
1047 2023-03-30 17:56:23 3.3399 true false 0x7d6f77cc MathGame run
Affect(row-cnt:8) cost in 5 ms.
# 使用观察表达式查看时间片段
[arthas@20276]$ tt -i 1026 -w 'target.illegalArgumentCount'
@Integer[2742]
Affect(row-cnt:1) cost in 0 ms.
注意
- ThreadLocal信息丢失
很多框架偷偷的将一些环境变量信息塞到了发起调用线程的 ThreadLocal 中，由于调用线程发生了变化， 这些ThreadLocal线程信息无法通过Arthas保存，所以这些信息将会丢失。 一些常见的情况比如：鹰眼的TraceId等。- 引用对象发生变化
需要强调的是tt命令是将当前环境的对象引用保存起来，但仅仅也只能保存一个引用而已。如果方法内部对入参进行了变更， 或者返回的对象经过了后续的处理，那么在tt查看的时候将无法看到当时最准确的值(tt只是快照)。这也是为什么watch命令存在的意义。
重播时间片段
# 重播一次
[arthas@20276]$ tt -i 1026 -p
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:02:16
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 0.6742
RETURN-OBJ null
Time fragment[1026] successfully replayed 1 times.
# 重播多次
[arthas@20276]$ tt -i 1026 -p --replay-times 3
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:03:33
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 0.1273
RETURN-OBJ null
Time fragment[1026] successfully replayed 1 times.
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:03:34
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 2.5326
RETURN-OBJ null
Time fragment[1026] successfully replayed 2 times.
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:03:35
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 1.1731
RETURN-OBJ null
Time fragment[1026] successfully replayed 3 times.
# 指定频率重播多次
[arthas@20276]$ tt -i 1026 -p --replay-times 3 --replay-interval 100
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:06:17
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 0.4988
RETURN-OBJ null
Time fragment[1026] successfully replayed 1 times.
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:06:17
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 2.5694
RETURN-OBJ null
Time fragment[1026] successfully replayed 2 times.
RE-INDEX 1026
GMT-REPLAY 2023-03-30 18:06:17
OBJECT 0x7d6f77cc
CLASS demo.MathGame
METHOD run
IS-RETURN true
IS-EXCEPTION false
COST(ms) 1.3101
RETURN-OBJ null
Time fragment[1026] successfully replayed 3 times.
删除时间片段
# 删除指定编号的时间片段
[arthas@20276]$ tt -i 1026 -d
Time fragment[1026] successfully deleted.
Affect(row-cnt:1) cost in 0 ms.
# 删除所有时间片段
[arthas@20276]$ tt --delete-all
Time fragments are cleaned.
Affect(row-cnt:21) cost in 0 ms.