Skip to content

TimeTunnel

ulysses edited this page Nov 19, 2019 · 4 revisions

TimeTunnel(时间隧道)

命令介绍

时间隧道命令是我在使用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?>
  • 命令参数解析

    • -t

      tt命令有很多个主参数,-t就是其中之一。这个参数的表明希望记录下类*Testprint方法的每次执行情况。

    • -n 3

      当你执行一个调用量不高的方法时可能你还能有足够的时间用CTRL+D中断tt命令记录的过程,但如果遇到调用量非常大的方法,瞬间就能将你的JVM内存撑爆。

      此时你可以通过-n参数指定你需要记录的次数,当达到记录次数时greys会主动中断tt命令的记录过程,避免人工操作无法停止的情况。

  • 表格字段说明

    表格字段 字段解释
    INDEX 时间片段记录编号,每一个编号代表着一次调用,后续tt还有很多命令都是基于此编号指定记录操作,非常重要。
    TIMESTAMP 方法执行的本机时间,记录了这个时间片段所发生的本机时间
    COST(ms) 方法执行的耗时
    IS-RET 方法是否以正常返回的形式结束
    IS-EXP 方法是否以抛异常的形式结束
    OBJECT 执行对象的hashCode(),注意,曾经有人误认为是对象在JVM中的物理内存地址,但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体
    CLASS 执行的类名
    METHOD 执行的方法名
  • 条件表达式

    不知道大家是否有在使用过程中遇到以下困惑

    1. greys似乎很难区分出重载的方法
    2. 我只需要观察特定参数,但是tt却全部都给我记录了下来

    1.6.0.6版本之后,应广大妇女群众的要求,我增加了条件表达式,这样你可以通过简单的条件表达式解决上边的困惑。

    条件表达式也是用groovy来编写,核心的判断对象依然是Advice对象。

    除了tt命令之外,watchtracestack命令也都支持条件表达式

    • 解决方法重载

      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,则值为null
    throwExp 本次调用抛出的异常。当且仅当isThrow==true成立时有效,表明方法调用是以抛出异常的方式结束。
    isBefore 辅助判断标记,当前的通知节点有可能是在方法一开始就通知,此时isBefore==true成立,同时isThrow==falseisReturn==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自己的内部线程发起的调用了。

  • 需要强调的点

    1. ThreadLocal信息丢失

      很多框架偷偷的将一些环境变量信息塞到了发起调用线程的ThreadLocal中,由于调用线程发生了变化,这些ThreadLocal线程信息无法通过greys保存,所以这些信息将会丢失。

      一些常见的CASE比如:鹰眼的TraceId等。

    2. 引用的对象

      需要强调的是,tt命令是将当前环境的对象引用保存起来,但仅仅也只能保存一个引用而已。如果方法内部对入参进行了变更,或者返回的对象经过了后续的处理,那么在tt查看的时候将无法看到当时最准确的值。这也是为什么watch命令存在的意义。

You can’t perform that action at this time.