-
Notifications
You must be signed in to change notification settings - Fork 1.2k
TimeTunnel
ulysses edited this page Nov 19, 2019
·
4 revisions
时间隧道命令是我在使用watch命令进行问题排查的时候衍生出来的想法。watch虽然很方便和灵活，但需要提前想清楚观察表达式的拼写，这对排查问题而言要求太高，因为很多时候我们并不清楚问题出自于何方，只能靠蛛丝马迹进行猜测。
这个时候如果能记录下当时方法调用的所有入参和返回值、抛出的异常会对整个问题的思考与判断非常有帮助。
于是乎，TimeTunnel命令就诞生了。
-
基本用法
对于一个最基本的使用来说，就是记录下当前方法的每次调用环境现场。
ga?>tt -t -n 3 *Test print Press Ctrl+D or Ctrl+X to abort. Affect(class-cnt:1 , method-cnt:1) cost in 115 ms. +----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+ | INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD | +----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+ | 1007 | 2015-07-26 12:23:21 | 138 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print | +----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+ | 1008 | 2015-07-26 12:23:22 | 143 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print | +----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+ | 1009 | 2015-07-26 12:23:23 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print | +----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+ ga?>
-
命令参数解析
-
-ttt命令有很多个主参数，
-t就是其中之一。这个参数的表明希望记录下类*Test的print方法的每次执行情况。 -
-n 3当你执行一个调用量不高的方法时可能你还能有足够的时间用
CTRL+D中断tt命令记录的过程，但如果遇到调用量非常大的方法，瞬间就能将你的JVM内存撑爆。此时你可以通过
-n参数指定你需要记录的次数，当达到记录次数时greys会主动中断tt命令的记录过程，避免人工操作无法停止的情况。
-
-
表格字段说明
表格字段 字段解释 INDEX 时间片段记录编号，每一个编号代表着一次调用，后续tt还有很多命令都是基于此编号指定记录操作，非常重要。 TIMESTAMP 方法执行的本机时间，记录了这个时间片段所发生的本机时间 COST(ms) 方法执行的耗时 IS-RET 方法是否以正常返回的形式结束 IS-EXP 方法是否以抛异常的形式结束 OBJECT 执行对象的 hashCode()，注意，曾经有人误认为是对象在JVM中的物理内存地址，但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体CLASS 执行的类名 METHOD 执行的方法名 -
条件表达式
不知道大家是否有在使用过程中遇到以下困惑
- greys似乎很难区分出重载的方法
- 我只需要观察特定参数，但是tt却全部都给我记录了下来
从
1.6.0.6版本之后，应广大妇女群众的要求，我增加了条件表达式，这样你可以通过简单的条件表达式解决上边的困惑。条件表达式也是用
groovy来编写，核心的判断对象依然是Advice对象。除了
tt命令之外，watch、trace、stack命令也都支持条件表达式-
解决方法重载
tt -t *Test print params[0].length==1通过制定参数个数的形式解决不同的方法签名，如果参数个数一样，你还可以这样写
tt -t *Test print 'params[1].class == Integer.class' -
解决指定参数
tt -t *Test print params[0].mobile=="13989838402"
-
构成条件表达式的
Advice对象前边看到了很多条件表达式中，都适用了
params[0]，但这个变量的含义是什么呢？又都有多少个这种变量呢？其实这个变量的表达式的所有参数都来自于一个greys中通用的通知对象
Advice，它的代码结构如下public class Advice { private final ClassLoader loader; private final Class<?> clazz; private final GaMethod method; private final Object target; private final Object[] params; private final Object returnObj; private final Throwable throwExp; private final boolean isBefore; private final boolean isThrow; private final boolean isReturn; // getter/setter }
这里列一个表格来说明不同变量的含义
变量名 变量解释 loader 本次调用类所在的ClassLoader clazz 本次调用类的Class引用 method 本次调用方法反射引用 target 本次调用类的实例 params 本次调用参数列表，这是一个数组，如果方法是无参方法则为空数组 returnObj 本次调用返回的对象。当且仅当 isReturn==true成立时候有效，表明方法调用是以正常返回的方式结束。如果当前方法无返回值void，则值为nullthrowExp 本次调用抛出的异常。当且仅当 isThrow==true成立时有效，表明方法调用是以抛出异常的方式结束。isBefore 辅助判断标记，当前的通知节点有可能是在方法一开始就通知，此时 isBefore==true成立，同时isThrow==false和isReturn==false，因为在方法刚开始时，还无法确定方法调用将会如何结束。isThrow 辅助判断标记，当前的方法调用以抛异常的形式结束。 isReturn 辅助判断标记，当前的方法调用以正常返回的形式结束。 所有变量都可以在表达式中直接使用，如果在表达式中编写了不符合Groovy脚本语法或者引入了不在表格中的变量，则一律当成
false来处理。 -
特别提醒
因为在默认的Console实现上采用了JLine的原因，JLine对
!当成了特殊字符来处理，所以在greys默认控制台的输入中，如果需要输入!的地方，需要替换成\!例如
tt -t *Test print params[0]\!=null但如果是telnet上去的，则不受此影响，你可以照常书写
tt -t *Test print params[0]!=null
当你用tt记录了一大片的时间片段之后，你希望能从中筛选出自己需要的时间片段，这个时候你就需要对现有记录进行检索。
假设我们有这些记录
ga?>tt -l
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1000 | 2015-07-26 01:16:27 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1001 | 2015-07-26 01:16:27 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1002 | 2015-07-26 01:16:28 | 119 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1003 | 2015-07-26 01:16:28 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1004 | 2015-07-26 12:21:56 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1005 | 2015-07-26 12:21:57 | 138 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1006 | 2015-07-26 12:21:58 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
Affect(row-cnt:7) cost in 2 ms.
ga?>
我需要筛选出printAddress方法的调用信息
ga?>tt -s method.name=="printAddress"
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1001 | 2015-07-26 01:16:27 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1003 | 2015-07-26 01:16:28 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
Affect(row-cnt:2) cost in 55 ms.
ga?>
你需要一个-s参数。同样的，搜索表达式的核心对象依旧是Advice对象。
对于具体一个时间片的信息而言，你可以通过-i参数后边跟着对应的INDEX编号查看到他的详细信息。
ga?>
ga?>tt -i 1003
+-----------------+------------------------------------------------------------------------------------------------------+
| INDEX | 1003 |
+-----------------+------------------------------------------------------------------------------------------------------+
| GMT-CREATE | 2015-07-26 01:16:28 |
+-----------------+------------------------------------------------------------------------------------------------------+
| COST(ms) | 0 |
+-----------------+------------------------------------------------------------------------------------------------------+
| OBJECT | 0x42cc13a0 |
+-----------------+------------------------------------------------------------------------------------------------------+
| CLASS | GaOgnlUtilsTest |
+-----------------+------------------------------------------------------------------------------------------------------+
| METHOD | printAddress |
+-----------------+------------------------------------------------------------------------------------------------------+
| IS-RETURN | false |
+-----------------+------------------------------------------------------------------------------------------------------+
| IS-EXCEPTION | true |
+-----------------+------------------------------------------------------------------------------------------------------+
| PARAMETERS[0] | Address@53448f87 |
+-----------------+------------------------------------------------------------------------------------------------------+
| THROW-EXCEPTION | java.lang.RuntimeException: test |
| | at GaOgnlUtilsTest.printAddress(Unknown Source) |
| | at GaOgnlUtilsTest.<init>(Unknown Source) |
| | at GaOgnlUtilsTest.main(Unknown Source) |
+-----------------+------------------------------------------------------------------------------------------------------+
Affect(row-cnt:1) cost in 1 ms.
ga?>
当你少少做了一些调整之后，你可能需要前端系统重新触发一次你的调用，此时得求爷爷告奶奶的需要前端配合联调的同学再次发起一次调用。而有些场景下，这个调用不是这么好触发的。
tt命令由于保存了当时调用的所有现场信息，所以我们可以自己主动对一个INDEX编号的时间片自主发起一次调用，从而解放你的沟通成本。此时你需要-p参数。
ga?>tt -i 1003 -p
+-----------------+---------------------------------------------------------------------------------------------------------+
| RE-INDEX | 1003 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| GMT-REPLAY | 2015-07-26 17:29:51 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| OBJECT | 0x42cc13a0 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| CLASS | GaOgnlUtilsTest |
+-----------------+---------------------------------------------------------------------------------------------------------+
| METHOD | printAddress |
+-----------------+---------------------------------------------------------------------------------------------------------+
| PARAMETERS[0] | Address@53448f87 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| IS-RETURN | false |
+-----------------+---------------------------------------------------------------------------------------------------------+
| IS-EXCEPTION | true |
+-----------------+---------------------------------------------------------------------------------------------------------+
| THROW-EXCEPTION | java.lang.RuntimeException: test |
| | at GaOgnlUtilsTest.printAddress(GaOgnlUtilsTest.java:78) |
| | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) |
| | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) |
| | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) |
| | at java.lang.reflect.Method.invoke(Method.java:483) |
| | at com.github.ompc.greys.util.GaMethod.invoke(GaMethod.java:81) |
| | at com.github.ompc.greys.command.TimeTunnelCommand$6.action(TimeTunnelCommand.java:592) |
| | at com.github.ompc.greys.server.DefaultCommandHandler.execute(DefaultCommandHandler.java:175) |
| | at com.github.ompc.greys.server.DefaultCommandHandler.executeCommand(DefaultCommandHandler.java:83) |
| | at com.github.ompc.greys.server.GaServer$4.run(GaServer.java:329) |
| | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) |
| | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) |
| | at java.lang.Thread.run(Thread.java:745) |
+-----------------+---------------------------------------------------------------------------------------------------------+
replay time fragment[1003] success.
Affect(row-cnt:1) cost in 3 ms.
ga?>
你会发现结果虽然一样，但调用的路径发生了变化，有原来的程序发起变成了greys自己的内部线程发起的调用了。
-
需要强调的点
-
ThreadLocal信息丢失
很多框架偷偷的将一些环境变量信息塞到了发起调用线程的ThreadLocal中，由于调用线程发生了变化，这些ThreadLocal线程信息无法通过greys保存，所以这些信息将会丢失。
一些常见的CASE比如：鹰眼的TraceId等。
-
引用的对象
需要强调的是，
tt命令是将当前环境的对象引用保存起来，但仅仅也只能保存一个引用而已。如果方法内部对入参进行了变更，或者返回的对象经过了后续的处理，那么在tt查看的时候将无法看到当时最准确的值。这也是为什么watch命令存在的意义。
-