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.

注意

  1. ThreadLocal信息丢失
    很多框架偷偷的将一些环境变量信息塞到了发起调用线程的 ThreadLocal 中,由于调用线程发生了变化, 这些ThreadLocal线程信息无法通过Arthas保存,所以这些信息将会丢失。 一些常见的情况比如:鹰眼的TraceId等。
  2. 引用对象发生变化
    需要强调的是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.