Arthas 使用 watch 命令观察返回值、抛出异常、入参

案例代码

package com.example.arthas.controller;

@Slf4j
@RestController
public class Test111Controller {

    @Value("${config.maxConn}")
    private Integer maxConn;

    @GetMapping("/test1")
    public Result test1(@RequestParam String key) throws InterruptedException {
        log.info("test1111111111111#{}", key);
        if ("ccc".equals(key)) {
            throw new RuntimeException("custom exception");
        }
        if ("bbb".equals(key)) {
            Thread.sleep(1000);
        }
        key = "ddd";
        List<String> list = (List<String>) CollectionUtils.arrayToList(new String[]{"aaa", "bbb", "ccc", key});
        return Result.builder().msg("success#" + maxConn).data(list).build();
    }

}

@Data
@Builder
@NoArgsConstructor
@AllArgsConstructor
public class Result {

    private int code;
    private String msg;
    private Object data;

}

watch 命令

默认观察方法退出后入参、类成员变量、返回值的情况。

watch 全路径类名 方法名

-x：指定输出结果的属性遍历深度，默认为1。

可以看到Result中的data字段其实List集合，因为设置的遍历深度为2，所以只输出到Result的data（List）的成员变量。

-n：限定捕捉次数，-n 1表示捕捉到一次就停止捕捉。

location=AtExit：表示观察的是退出后的参数情况。

watch com.example.arthas.controller.Test111Controller test1 -x 2 -n 1

输出：

curl http://127.0.0.1:8080/test1?key=aaa

[arthas@23612]$ watch com.example.arthas.controller.Test111Controller test1 -x 2 -n 1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 22 ms, listenerId: 1
method=com.example.arthas.controller.Test111Controller.test1 location=AtExit
ts=2021-02-12 09:45:08; [cost=3.303678ms] result=@ArrayList[
    @Object[][
        @String[ddd],
    ],
    @Test111Controller[
        log=@Logger[Logger[com.example.arthas.controller.Test111Controller]],
        maxConn=@Integer[100],
    ],
    @Result[
        code=@Integer[0],
        msg=@String[success#100],
        data=@ArrayList[isEmpty=false;size=4],
    ],
]
Command execution times exceed limit: 1, so command will exit. You can set it with -n option.

watch 观察指定入参和返回值

添加ognl表达式："{params,returnObj}"。

watch com.example.arthas.controller.Test111Controller test1 "{params,returnObj}" -x 3

输出：

curl http://127.0.0.1:8080/test1?key=aaa

[arthas@23612]$ watch com.example.arthas.controller.Test111Controller test1 "{params,returnObj}" -x 3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 29 ms, listenerId: 2
method=com.example.arthas.controller.Test111Controller.test1 location=AtExit
ts=2021-02-12 09:52:55; [cost=2.012585ms] result=@ArrayList[
    @Object[][
        @String[ddd],
    ],
    @Result[
        code=@Integer[0],
        msg=@String[success#100],
        data=@ArrayList[
            @String[aaa],
            @String[bbb],
            @String[ccc],
            @String[ddd],
        ],
    ],
]

watch 观察进入方法前和退出方法后

-b：观察进入方法前参数的情况。

-s：观察退出方法后参数的情况。

可以看到location=AtEnter和location=AtExit

watch com.example.arthas.controller.Test111Controller test1 "{params,returnObj}" -x 3 -b -s

输出：

curl http://127.0.0.1:8080/test1?key=aaa

[arthas@24280]$ watch com.example.arthas.controller.Test111Controller test1 "{params,returnObj}" -x 3 -b -s
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 70 ms, listenerId: 3
method=com.example.arthas.controller.Test111Controller.test1 location=AtEnter
ts=2021-02-12 10:09:46; [cost=0.849065ms] result=@ArrayList[
    @Object[][
        @String[aaa],
    ],
    null,
]
method=com.example.arthas.controller.Test111Controller.test1 location=AtExit
ts=2021-02-12 10:09:46; [cost=5.237757880806502E9ms] result=@ArrayList[
    @Object[][
        @String[ddd],
    ],
    @Result[
        code=@Integer[0],
        msg=@String[success#100],
        data=@ArrayList[
            @String[aaa],
            @String[bbb],
            @String[ccc],
            @String[ddd],
        ],
    ],
]

watch 观察发生异常

添加ognl表达式："{params,throwExp}"。

-e：观察方法异常之后参数及异常情况。

watch com.example.arthas.controller.Test111Controller test1 "{params,throwExp}" -x 3 -e

输出：

curl http://127.0.0.1:8080/test1?key=ccc

[arthas@24076]$ watch com.example.arthas.controller.Test111Controller test1 "{params,throwExp}" -x 3 -e
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 67 ms, listenerId: 4
method=com.example.arthas.controller.Test111Controller.test1 location=AtExceptionExit
ts=2021-02-12 10:55:47; [cost=0.505599ms] result=@ArrayList[
    @Object[][
        @String[ccc],
    ],
    java.lang.RuntimeException: custom exception
        at com.example.arthas.controller.Test111Controller.test1(Test111Controller.java:24)
        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:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
,
]

watch 观察耗时超过 1000 毫秒的情况

#cost>1000：按耗时大于1000毫秒进行过滤。

注意：添加-b参数表示耗时计算只统计到入参阶段就结束了，往往都被过滤掉了。

watch com.example.arthas.controller.Test111Controller test1 "{params,returnObj}" "#cost>1000" -x 3

输出：

curl http://127.0.0.1:8080/test1?key=bbb

[arthas@21776]$ watch com.example.arthas.controller.Test111Controller test1 "{params,returnObj}" "#cost>1000" -x 3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 31 ms, listenerId: 5
method=com.example.arthas.controller.Test111Controller.test1 location=AtExit
ts=2021-02-12 11:09:57; [cost=1001.225813ms] result=@ArrayList[
    @Object[][
        @String[ddd],
    ],
    @Result[
        code=@Integer[0],
        msg=@String[success#100],
        data=@ArrayList[
            @String[aaa],
            @String[bbb],
            @String[ccc],
            @String[ddd],
        ],
    ],
]

watch 观察入参数等于指定值的情况

使用'params[0] == "ddd"'表示入参的第一个参数等于ddd的情况。

watch com.example.arthas.controller.Test111Controller test1 '{params,returnObj}' 'params[0] == "ddd"' -x 3 -b -s

输出：

curl http://127.0.0.1:8080/test1?key=ddd

[arthas@21776]$ watch com.example.arthas.controller.Test111Controller test1 '{params,returnObj}' 'params[0] == "ddd"' -x 3 -b -s
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 32 ms, listenerId: 6
method=com.example.arthas.controller.Test111Controller.test1 location=AtEnter
ts=2021-02-12 11:27:19; [cost=0.01792ms] result=@ArrayList[
    @Object[][
        @String[ddd],
    ],
    null,
]
method=com.example.arthas.controller.Test111Controller.test1 location=AtExit
ts=2021-02-12 11:27:19; [cost=5.242410807753551E9ms] result=@ArrayList[
    @Object[][
        @String[ddd],
    ],
    @Result[
        code=@Integer[0],
        msg=@String[success#100],
        data=@ArrayList[
            @String[aaa],
            @String[bbb],
            @String[ccc],
            @String[ddd],
        ],
    ],
]

备注

watch命令进行观察，会对原始类进行加强，织入统计代码，使用stop停止Arthas会自动使用reset命令对已加强的类进行还原，以免浪费性能。

参考

https://arthas.aliyun.com/doc/watch.html