1. View thread information

thread

Parameter description

Parameter name	Parameter description
id	Thread id
[n:]	Specify the busiest first N threads and print the stack
[b]	Find out which threads are currently blocking other threads
[i <value>]	Specifies the sampling interval for cpu percentage statistics, in milliseconds

1) View all current threads

thread

output

2) View the top n currently busy threads and print the stack

thread -n 2

output

$ thread -n 2
"http-nio-8080-exec-1" Id=147 cpuUsage=18% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
    at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
    at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    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)


"http-nio-8080-exec-25" Id=180 cpuUsage=18% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
    at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
    at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    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)

3) Displays the run stack for the specified id thread

thread 180

output

$ thread 180
"http-nio-8080-exec-25" Id=180 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
    at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
    at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    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)

4) Find threads that block other threads

thread -b

output

$ thread -b
No most blocking thread found!
Affect(row-cnt:0) cost in 64 ms.        

Note that currently only the threads blocked by the synchronized keyword are supported. If it is java.util.concurrent.Lock, it is not currently supported.

2. Decompile the source code of the loaded class

The jad command decompiles the byte code of the class actually running in the JVM into java code, which is convenient for you to understand the business logic;

• On the Arthas Console, the decompiled source code is highlighted with syntax, making it easier to read
• Of course, decompiled java code may have syntax errors, but they will not affect your reading comprehension

Parameter description

Parameter name	Parameter description
class-pattern	Class name expression match
[c:]	hashcode of ClassLoader to which class belongs
[E]	Turn on regular expression matching, default to wildcard matching

1) Direct decompilation to view source code

jad com.esell.*.DeviceAdSweepCodeController

output

$ jad com.esell.*.DeviceAdSweepCodeController

ClassLoader:                                                                                                                                                                                                  
+-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                             
  +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                                 
    +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                               

Location:                                                                                                                                                                                                     
file:/home/admin/app/c4237202-afae-4d8b-9dad-e788cb42d7fb/es-yxfbp-main-1.0.0.jar!/BOOT-INF/lib/es-yxfbp-gw-1.0.0-SNAPSHOT.jar!/                                                                              

/*
 * Decompiled with CFR 0_132.
 * 
 * Could not load the following classes:
 *  cn.hutool.core.thread.ThreadUtil
 *  com.alibaba.fastjson.JSONObject
 *  com.esell.annotation.RequestParameter
 *  com.esell.annotation.Validation
 *  com.esell.message.domestic.SimpleApiRequest
 *  com.esell.v2.device.controller.DeviceAdSweepCodeController$1
 *  com.esell.v2.device.model.dto.DeviceAdSweepCodeDto
 *  com.esell.v2.device.service.DeviceAdSweepCodeService
 *  javax.servlet.http.HttpServletResponse
 *  org.slf4j.Logger
 *  org.slf4j.LoggerFactory
 *  org.springframework.beans.factory.annotation.Autowired
 *  org.springframework.web.bind.annotation.GetMapping
 *  org.springframework.web.bind.annotation.RequestMapping
 *  org.springframework.web.bind.annotation.RestController
 */
package com.esell.v2.device.controller;

import cn.hutool.core.thread.ThreadUtil;
import com.alibaba.fastjson.JSONObject;
import com.esell.annotation.RequestParameter;
import com.esell.annotation.Validation;
import com.esell.message.domestic.SimpleApiRequest;
import com.esell.v2.device.controller.DeviceAdSweepCodeController;
import com.esell.v2.device.model.dto.DeviceAdSweepCodeDto;
import com.esell.v2.device.service.DeviceAdSweepCodeService;
import java.io.IOException;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequestMapping(value={"/device/ad/sweep"})
public class DeviceAdSweepCodeController {
    private static final Logger log = LoggerFactory.getLogger(DeviceAdSweepCodeController.class);
    @Autowired
    private DeviceAdSweepCodeService deviceAdSweepCodeService;

    @GetMapping(value={"/add.shtml"})
    @Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
    public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
        JSONObject jsonObject = new JSONObject();
        DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
        ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
        response.sendRedirect(reqData.getRedirect());
    }

    static /* synthetic */ DeviceAdSweepCodeService access$000(DeviceAdSweepCodeController x0) {
        return x0.deviceAdSweepCodeService;
    }

    static /* synthetic */ Logger access$100() {
        return log;
    }
}

Affect(row-cnt:1) cost in 544 ms.

2) Only the source code is displayed when decompiling

By default, the decompilation result will contain ClassLoader information. With the -- source only option, you can print only the source code.

jad --source-only com.esell.*.DeviceAdSweepCodeController

output

/*
 * Decompiled with CFR 0_132.
 * 
 * Could not load the following classes:
 *  cn.hutool.core.thread.ThreadUtil
 *  com.alibaba.fastjson.JSONObject
 *  com.esell.annotation.RequestParameter
 *  com.esell.annotation.Validation
 *  com.esell.message.domestic.SimpleApiRequest
 *  com.esell.v2.device.controller.DeviceAdSweepCodeController$1
 *  com.esell.v2.device.model.dto.DeviceAdSweepCodeDto
 *  com.esell.v2.device.service.DeviceAdSweepCodeService
 *  javax.servlet.http.HttpServletResponse
 *  org.slf4j.Logger
 *  org.slf4j.LoggerFactory
 *  org.springframework.beans.factory.annotation.Autowired
 *  org.springframework.web.bind.annotation.GetMapping
 *  org.springframework.web.bind.annotation.RequestMapping
 *  org.springframework.web.bind.annotation.RestController
 */
package com.esell.v2.device.controller;

import cn.hutool.core.thread.ThreadUtil;
import com.alibaba.fastjson.JSONObject;
import com.esell.annotation.RequestParameter;
import com.esell.annotation.Validation;
import com.esell.message.domestic.SimpleApiRequest;
import com.esell.v2.device.controller.DeviceAdSweepCodeController;
import com.esell.v2.device.model.dto.DeviceAdSweepCodeDto;
import com.esell.v2.device.service.DeviceAdSweepCodeService;
import java.io.IOException;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequestMapping(value={"/device/ad/sweep"})
public class DeviceAdSweepCodeController {
    private static final Logger log = LoggerFactory.getLogger(DeviceAdSweepCodeController.class);
    @Autowired
    private DeviceAdSweepCodeService deviceAdSweepCodeService;

    @GetMapping(value={"/add.shtml"})
    @Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
    public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
        JSONObject jsonObject = new JSONObject();
        DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
        ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
        response.sendRedirect(reqData.getRedirect());
    }

    static /* synthetic */ DeviceAdSweepCodeService access$000(DeviceAdSweepCodeController x0) {
        return x0.deviceAdSweepCodeService;
    }

    static /* synthetic */ Logger access$100() {
        return log;
    }
}

3) Specifying methods when decompiling

jad com.esell.*.DeviceAdSweepCodeController sweep

output

$ jad com.esell.*.DeviceAdSweepCodeController sweep

ClassLoader:                                                                                                                                                                                                  
+-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                             
  +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                                 
    +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                               

Location:                                                                                                                                                                                                     
file:/home/admin/app/c4237202-afae-4d8b-9dad-e788cb42d7fb/es-yxfbp-main-1.0.0.jar!/BOOT-INF/lib/es-yxfbp-gw-1.0.0-SNAPSHOT.jar!/                                                                              

@GetMapping(value={"/add.shtml"})
@Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
    JSONObject jsonObject = new JSONObject();
    DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
    ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
    response.sendRedirect(reqData.getRedirect());
}

Affect(row-cnt:1) cost in 354 ms.

4) Specify classloader when decompiling

When multiple classloaders have loaded this class, the jad command will output the hashcode corresponding to the ClassLoader instance, and then you only need to execute the jad command again, and use the parameter - c to decompile the class loaded by the specified ClassLoader; as follows

$ jad *DeviceAdSweepCodeController

 Found more than one class for: *DeviceAdSweepCodeController, Please use jad -c <hashcode> *DeviceAdSweepCodeController                                                                                                                                                                
 HASHCODE  CLASSLOADER                                                                                                                                                                                        
 7c75222b  +-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                  
             +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                      
               +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                    
 7c75222b  +-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                  
             +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                      
               +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                    

Affect(row-cnt:0) cost in 24 ms.

Use - c to enter the corresponding source code view

jad -c 7c75222b *DeviceAdSweepCodeController

5) Decompiled output to specified directory

Need to use -- source only

jad --source-only com.esell.gw.yxfbp.rew.adv.controller.AdvController > /usr/local/arthas/file/AdvController.java

3. Use Arthas for online hot update

redefine

Parameter description

Parameter name	Parameter description
[c:]	hashcode of ClassLoader
[p:]	Full path of external. class file, supporting multiple

1) Hot deployment class file

First, compile the java file that needs to be hot updated into a class file locally, upload it to the server, and execute the following command in the arthas process

redefine /usr/local/arthas/file/AdvController.class

The output of the following statement is a successful hot update

To determine whether the changes have been deployed to the server, use the decompile command to obtain the source file to view

jad --source-only com.esell.gw.yxfbp.rew.adv.controller.AdvController > /usr/local/arthas/file/AdvController.java

After downloading, view through vi AdvController.java, use / string to view the corresponding content in command mode, press lowercase n, down search, capital n, up search

Key reminder

Limitations of redefine

• New field/method is not allowed
• The running function cannot take effect without exiting. For example, the following newly added System.out.println will only take effect in the run() function

public class MathGame {
    public static void main(String[] args) throws InterruptedException {
        MathGame game = new MathGame();
        while (true) {
            game.run();
            TimeUnit.SECONDS.sleep(1);
            //This doesn't work because the code has been running in while
            System.out.println("in loop");
        }
    }

    public void run() throws InterruptedException {
        //This takes effect because the run() function can be completed every time
        System.out.println("call run()");
        try {
            int number = random.nextInt();
            List<Integer> primeFactors = primeFactors(number);
            print(number, primeFactors);

        } catch (Exception e) {
            System.out.println(String.format("illegalArgumentCount:%3d, ", illegalArgumentCount) + e.getMessage());
        }
    }

4. Performance monitoring of method calls

Monitor the calling of classes and methods matching class pattern / method pattern.

The monitor command is a non real time return command

The real-time return command is to return immediately after input, rather than to return in real time. It is to wait for the return information of the target Java process until the user enters Ctrl+C.

The server runs the task in the background in the form of task. The embedded code will not be executed with the termination of the task, so after the task is closed, it will not have a great impact on the original performance. In principle, any Arthas command will not change the original business logic.

Dimension description of monitoring

Monitoring item	Explain
timestamp	time stamp
class	Class Java
method	Method (construction method, common method)
total	Number of calls
success	Success times
fail	Failure times
rt	Average RT
fail-rate	Failure rate

Parameter description

Method has a named parameter [c:], which means cycle of output, with an integer parameter value

Parameter name	Parameter description
class-pattern	Class name expression match
method-pattern	Method name expression match
[E]	Turn on regular expression matching, default to wildcard matching
[c:]	Statistics period, default value is 120 seconds

1) Performance monitoring of method calls within a specified period

monitor -c 10 com.esell.v2.device.controller.DeviceBaseController listDevice

output

2) Performance monitoring of calls of multiple methods in a specified period

It should be noted that only full class names can be used instead of wildcards

monitor -c 10 -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search

output

5. Time consumption of each node in the view method

trace

The trace command can actively search the method call path corresponding to class pattern / method pattern (wildcard can be used), render and count all the performance overhead and trace the call link on the whole call link.

Parameter description

Parameter name	Parameter description
class-pattern	Class name expression match
method-pattern	Method name expression match
condition-express	Conditional expression
[E]	Turn on regular expression matching, default to wildcard matching
[n:]	Command execution times
#cost	Method execution time

1) View the time consumption of each node of the method

Use the trace class name method to access this method on the client side

trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd

or

trace *PublishManager updateAd

The output shows the total time of the method and the time of each node

$ trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 279 ms.
`---ts=2019-07-23 10:44:44;thread_name=http-nio-8080-exec-3;id=a1;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[19562.263654ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[0.023008ms] java.lang.Integer:intValue() #76
        +---[7.961462ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.015249ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        +---[42.933313ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
        `---[19508.385811ms] java.util.List:forEach() #81

2) Time consuming to filter out jvm functions

Use trace class name method - j to add - j parameter to filter out jvm function

trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd -j

output

$ trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd -j
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 206 ms.
`---ts=2019-07-23 10:48:38;thread_name=http-nio-8080-exec-20;id=bb;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[16762.507405ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[3.685484ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.013117ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        `---[26.934144ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80

3) Tracking multiple methods of multiple classes

Use trace-E class name | full class name method | method add-E to track multiple methods of multiple classes. Note that wildcards cannot be used here

trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice

output

$ trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 511 ms.
`---ts=2019-07-23 11:45:21;thread_name=http-nio-8080-exec-54;id=dd;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[15607.698171ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[0.020851ms] java.lang.Integer:intValue() #76
        +---[3.550901ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.014086ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        +---[16.370718ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
        `---[15586.764431ms] java.util.List:forEach() #81

`---ts=2019-07-23 11:45:40;thread_name=http-nio-8080-exec-56;id=df;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[249.902613ms] com.esell.v2.device.controller.DeviceBaseController:listDevice()
        +---[3.444852ms] com.esell.yxf.common.util.LoggerMainBuilderUtils:requestLog() #230
        +---[0.011863ms] com.esell.message.SimpleApiRequest:getPayload() #234
        +---[0.054789ms] com.alibaba.fastjson.JSONObject:toJavaObject() #234
        +---[0.064045ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:copyNew() #234
        +---[0.00505ms] com.esell.message.SimpleApiRequest:getString() #235
        +---[0.036919ms] java.lang.String:replaceAll() #236
        +---[0.002666ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:setSortField() #237
        +---[1.288203ms] com.esell.util.SessionUtils:findUser() #240
        +---[0.007632ms] com.esell.api.account.bean.AccountBean:getCrmCode() #241
        +---[0.0048ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:setCrmCode() #241
        +---[0.0156ms] com.esell.api.account.bean.type.AccountUtils:remitCheckPermission() #244
        +---[0.003174ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:getNotBind() #253
        +---[200.227842ms] com.esell.v2.device.service.DeviceBaseService:search() #265
        +---[0.021341ms] com.esell.spring.boot.starter.mybatis.plugin.pagination.PaginationBean:getData() #267
        +---[0.011263ms] com.esell.message.SimpleApiRequest:getArray() #270
        +---[0.006812ms] java.util.ArrayList:<init>() #271
        +---[0.004011ms] com.esell.util.SessionUtils:current() #272
        +---[0.008421ms] com.esell.session.Session:getLanguage() #272
        +---[0.030655ms] java.util.Optional:ofNullable() #273
        +---[0.032682ms] java.util.Collections:emptyList() #273
        +---[0.007926ms] java.util.Optional:orElse() #273
        +---[0.052993ms] java.util.List:forEach() #273
        +---[42.130235ms] java.util.List:forEach() #295
        +---[0.018547ms] com.esell.spring.boot.starter.mybatis.plugin.pagination.PaginationBean:toPagination() #311
        +---[0.017203ms] com.esell.gw.yxfbp.common.PaginationApiResponse:<init>() #311
        `---[0.961965ms] com.esell.yxf.common.util.LoggerMainBuilderUtils:responseLog() #313

4) Filter specified time consuming methods

In many cases, we only want to see the trace result after the rt of a method is greater than a certain time. Now, Arthas can filter according to the execution time of the method. For example, trace * stringutils isblank 'ා cost > 100' means that when the execution time is greater than 100ms, the trace result will be output.

trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice '#cost > 15607'

output

$ trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice '#cost > 15607'
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 1179 ms.
`---ts=2019-07-23 11:47:21;thread_name=http-nio-8080-exec-60;id=e5;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[19575.706387ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[0.00811ms] java.lang.Integer:intValue() #76
        +---[2.816689ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.035768ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        +---[29.068075ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
        `---[19542.923598ms] java.util.List:forEach() #81

Key reminder

trace can help you locate and find performance problems caused by high RT, but it can only track the call link of one level method at a time.

The trace command will only trace the child calls in the function to which it matches, and will not trace down more than one level. Because trace is expensive, multi-layer trace may lead to many classes and functions that ultimately require trace

6. Observation of method execution data

watch

It is convenient for you to observe the call of the specified method. The observable ranges are: return value, throw exception, enter parameter

Parameter description

watch has many parameters, mainly because it can observe objects in four different scenes

Parameter name	Parameter description
class-pattern	Class name expression match
method-pattern	Method name expression match
express	Watch expression
condition-express	Conditional expression
[b]	Observe before method call
[e]	Observe after method exception
[s]	Observe after method return
[f]	Observe after the end of the method (normal return and abnormal return)
[E]	Turn on regular expression matching, default to wildcard matching
[x:]	Specifies the attribute traversal depth of the output result, which is 1 by default

For observation expressions, you can write "params" in this way, and "{params,returnObj,throwExp}" in multiple expressions. As long as it is a legal ognl expression, it can be supported normally. For more expression variables, refer to Expression core variable Description of the node in.

At the same time, for more special examples of ognl expression in Arthas, please refer to Some special usage documents of Arthas

Special note:

• The watch command defines four observation event points, that is, before - b method call, - e method exception, - s method return, - f method end
• Four observation event points - b, - e, - s are turned off by default, - f is turned on by default. When the specified observation point is turned on, the observation expression will be evaluated and output at the corresponding event point
• Note the difference between method in parameter and method out parameter, which may be modified in the middle and lead to inconsistency. Except - b event point params represents method in parameter, other events represent method out parameter
• When - b is used, the return value or exception does not exist because the observation event point is before the method call
• -x is the traversal depth, which can be adjusted to print specific parameters and results. The default value is 1

1) View the request and return parameters of the method

-The value of the x parameter can be set according to the traversal depth of the actual parameter. If you need to view the specific value of resultObj, you can adjust the value of - x

watch *DeviceBaseController listDevice "{params,returnObj}" -x 2

Output. You can see that there are two results in the result. The first is the request parameter and the second is the return parameter

$ watch *DeviceBaseController listDevice "{params,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 833 ms.
ts=2019-07-24 11:56:39; [cost=311.854619ms] result=@ArrayList[
    @Object[][
        @SimpleApiRequest[{"sign":"b3d98718d6ceff8c1668c43592019cf2","appid":"Jvddh8LKdLwmZ3cw","version":"1.3","sequence":1563940597279,"timestamp":1563940597279,"payload":"{\"page\":1,\"size\":10,\"uuid\":\"\",\"group-id\":\"\",\"gatherId\":\"\",\"name\":\"\",\"open\":\"\",\"district-code\":\"\",\"status\":\"\",\"phone-number\":\"\"}"}],
        @RequestFacade[org.apache.catalina.connector.RequestFacade@68db1322],
    ],
    @PaginationApiResponse[
        serialVersionUID=@Long[4126749321937797939],
    ],
]

2) View the specified properties of the method's parameters

View the uuid value of the request

watch *DeviceBaseController listDevice "{params[0].payload.uuid,returnObj}" -x 2

Output, you can see that uuid is 519073369656

$ watch *DeviceBaseController listDevice "{params[0].payload.uuid,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 757 ms.
ts=2019-07-24 12:01:08; [cost=147.622644ms] result=@ArrayList[
    @String[     519073369656],
    @PaginationApiResponse[
        serialVersionUID=@Long[4126749321937797939],
    ],
]

3) Filter according to conditions

Output when uuid of request parameter is 519073369656

watch *DeviceBaseController listDevice "{params[0],returnObj}" "params[0].payload.uuid=='519073369656'" -x 2

output

$ watch *DeviceBaseController listDevice "{params[0],returnObj}" "params[0].payload.uuid=='519073369656'" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 794 ms.
ts=2019-07-24 12:04:27; [cost=79.459047ms] result=@ArrayList[
    @SimpleApiRequest[
        serialVersionUID=@Long[7777957270454431721],
    ],
    @PaginationApiResponse[
        serialVersionUID=@Long[4126749321937797939],
    ],
]

4) View abnormal output

watch *TemplateV2ServiceImpl addTemplate "throwExp" -e  -x 2

output

$ watch *TemplateV2ServiceImpl addTemplate "throwExp" -e  -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 439 ms.
ts=2019-07-24 12:45:12; [cost=64.79821ms] result=@ArrayList[
    com.esell.exception.EsellException: Interactive button jump is not set, please exit and edit again [DEBUG: Interactive button jump is not set, please exit and edit again]
.............................

5) Filter specified time consuming methods

It takes longer than 10ms to be output

watch *TemplateV2ServiceImpl addTemplate "params" -x 2 '#cost>10'

Output time: 103.519568ms

shell $ watch *TemplateV2ServiceImpl addTemplate "params" -x 2 '#cost>10' Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:2) cost in 313 ms. ts=2019-07-24 12:49:49; [cost=103.519568ms] result=@Object[][ @TemplateV2SearchDto[ templateId=null, name=@String[1111jjjj], accountId=@Integer[86], crmCode=@String : 11379, "zindex": 1}], "Id": 1001}]], groupguid = null, s caleRatio=@String[1], tempCover=@ArrayList[isEmpty=false;size=1], components=@ArrayList[isEmpty=false;size=1], ], ]

6) View the parameters of multiple methods of multiple classes

Note that wildcards cannot be used here

watch -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search 'params[0].payload' -x 3

output

$ watch -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search 'params[0].payload' -x 3
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 577 ms.
ts=2019-07-24 15:20:39; [cost=11.840307ms] result=@JSONObject[
    @String[size]:@Integer[8],
    @String[name]:@String[],
    @String[page]:@Integer[1],
]
ts=2019-07-24 15:20:41; [cost=344.565606ms] result=@JSONObject[
    @String[phone-number]:@String[],
    @String[size]:@Integer[10],
    @String[group-id]:@String[],
    @String[gatherId]:@String[],
    @String[name]:@String[],
    @String[page]:@Integer[1],
    @String[district-code]:@String[],
    @String[uuid]:@String[],
    @String[open]:@String[],
    @String[status]:@String[],
]

7. Obtain records of different time and method execution

Although watch is very convenient and flexible, we need to think clearly and observe the spelling of expressions in advance, which is too demanding for troubleshooting, because many times we don't know where the problem comes from, we can only guess by clues.

At this time, it is very helpful to think and judge the whole problem if you can record all the input and return values and thrown exceptions of the method call at that time.

So the time tunnel command was born.

• Command parameter resolution

• -t

  The tt command has many main arguments, - t is one of them. This parameter indicates that you want to record every execution of the print method of the * Test class.

• -n 3

  When you execute a method with low call volume, you may have enough time to interrupt the tt command recording process with CTRL+C, but if you encounter a method with large call volume, your JVM memory will burst in an instant.

  At this time, you can specify the number of times you need to record through the - n parameter. When the number of times is reached, Arthas will actively interrupt the recording process of tt command to avoid the situation that manual operation cannot stop.

• Table field description

Table field	Field interpretation
INDEX	Time segment record number. Each number represents a call. Many subsequent tt commands specify record operations based on this number, which is very important.
TIMESTAMP	Method, recording the local time of this time segment
COST(ms)	Method execution time
IS-RET	Whether the method ends in the form of normal return
IS-EXP	Whether the method ends with throwing exception
OBJECT	Execute the hashCode() of the object. Note that someone once mistakenly thought it was the memory address of the object in the JVM, but unfortunately it was not. But it can help you simply mark the class entity of the currently executing method
CLASS	Executed class name
METHOD	Executed method name

• Conditional expression

  I don't know if you have the following confusion in the use process

• Arthas seems to have a hard time distinguishing between overloads

• I only need to observe certain parameters, but tt has all recorded them for me

  The conditional expression is also written in OGNL, and the core judgment object is still the Advice object. In addition to the tt command, the watch, trace, and stack commands also support conditional expressions.

• Solution overload

  tt -t *Test print params.length==1

  Solve different signature methods by setting the number of parameters. If the number of parameters is the same, you can also write like this

  tt -t *Test print 'params[1] instanceof Integer'

• Resolve specified parameters

  tt -t *Test print params[0].mobile=="13989838402"

• Advice objects that make up conditional expressions

  You can see that params[0] is used in many conditional expressions. For an introduction to this variable, please refer to Expression core variable

1) Get the call record of the method

tt -t *.DeviceBaseController listDevice

output

2) Filter according to conditions

The conditional expression is also written with OGNL, and the core judgment object is still the Advice object. In addition to the tt command, the watch, trace, and stack commands also support conditional expressions.

tt -t *.DeviceBaseController listDevice 'params[0].payload.uuid==519'

output

3) Get previous call record

tt -l

output

4) Filter from call records based on criteria

You need a - s parameter. Similarly, the core object of the search expression is still the Advice object.

tt -s 'method.name == "listDevice"'

output

5) View specific call information of method

For the information of a specific time slice, you can view its details through the - i parameter followed by the corresponding INDEX number. You can view the deeper and detailed parameter output through - x

tt -i 1002

output

6) Call method again

After you make some adjustments, you may need the front-end system to trigger your call again. At this time, you need to ask the students who need front-end coordination to call again. In some scenarios, this call is not triggered so well.

tt command saves all the field information called at that time, so we can initiatively launch a call for an INDEX numbered time slice by ourselves, so as to free your communication cost. At this point you need the - p parameter. Use -- replay times to specify the number of calls, and use -- replay interval to specify the multiple call interval (unit: ms, default: 1000ms)

tt -i 1002 -p

output

You will find that the result is the same, but the call path has changed, and the original program has become the call initiated by the internal thread of Arthas.

Be careful

1. ThreadLocal information lost

   Many frameworks secretly plug some environment variable information into the ThreadLocal of the calling thread. Because the calling thread has changed, the ThreadLocal thread information cannot be saved through Arthas, so the information will be lost.

   Some common cases, such as TraceId of eagle eye, etc.

2. Referenced objects

   It should be emphasized that the tt command is to save the object references of the current environment, but only one reference can be saved. If the input parameter of the method is changed internally, or the returned object is processed later, the most accurate value at that time will not be seen when tt is viewed. That's why the watch command exists.

Welcome to pay attention to the public number, follow up articles update notice, and discuss technical problems together.