Small knowledge, big challenge! This article is participating in the creation activity of “Essential Tips for Programmers”.
This article has participated in the “Digitalstar Project” and won a creative gift package to challenge the creative incentive money.
What is Arthas
Arthas is an open source Java diagnostic tool developed by Alibaba. Arthas can check thread status and JVM information of Java applications and diagnose business problems online, such as checking method call entry and exit parameters, execution process, thrown exceptions, and output method execution time, which greatly improves the efficiency of troubleshooting online problems.
Liverpoolfc.tv: arthas.aliyun.com/zh-cn/
Two, features list
What can Arthas do for you?
Arthas can help you when you are stuck with a problem like:
- From which JAR is this class loaded? Why are all kinds of class-related exceptions reported?
- Why didn’t the code I changed execute? Did I not commit? Got the branch wrong?
- If you encounter a problem, you cannot debug it online. Can you only re-publish it by logging?
- There is a problem with a user’s data processing online, but it cannot be debugged online, and it cannot be reproduced offline!
- Is there a global view of the health of the system?
- Is there any way to monitor the real-time health of the JVM?
- How to quickly locate application hot spots, generate flame map?
- How do I find an instance of a class directly from the JVM?
Arthas supports JDK 6+, Linux/Mac/Windows, command line interaction, and rich Tab auto-completion to further locate and diagnose problems.
Four, quick installation
1. Prerequisites
[root@c41287379b7c /]# yum install telnet
[root@c41287379b7c /]# yum install unzip
Copy the code2. One-click installation
Download the Arthas script using the command:
[root@c41287379b7c /]# curl -L https://alibaba.github.io/arthas/install.sh | sh
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 961 100 961 0 0 743 0 0:00:01 0:00:01- : - : -743
downloading... ./as.sh1598.
Arthas install successed.
Copy the codeDownload the Arthas JAR package using the command:
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
Copy the codeArthas provides a JAR package that is essentially a Java application.
Five, quick use
1. Start the script and connect to the process
Quick start with script:
[root@c41287379b7c /]# ./as.sh
Arthas script version: 3.17.
[INFO] JAVA_HOME: /usr/jdk18.. 0 _111
Found existing java process, please choose one and hit RETURN.
* [1] :1 org.apache.catalina.startup.Bootstrap
1 If there are more than one Java process, a list will appear here. Enter the serial number to connect the process.
updating version 3.17.. Download arthas from: https:/ / repo1.maven.org/maven2/com/taobao/arthas/arthas-packaging/3.1.7/arthas-packaging-3.1.7-bin.zip# # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # #100.0%
Archive: /tmp/temp_31.7 _1673./arthas-3.17.-bin.zip
creating: /tmp/temp_31.7 _1673./async-profiler/
inflating: /tmp/temp_31.7 _1673./arthas-spy.jar
inflating: /tmp/temp_31.7 _1673./arthas-agent.jar
inflating: /tmp/temp_31.7 _1673./arthas-client.jar
inflating: /tmp/temp_31.7 _1673./arthas-boot.jar
inflating: /tmp/temp_31.7 _1673./arthas-demo.jar
inflating: /tmp/temp_31.7 _1673./install-local.sh
inflating: /tmp/temp_31.7 _1673./as.sh
inflating: /tmp/temp_31.7 _1673./as.bat
inflating: /tmp/temp_31.7 _1673./as-service.bat
inflating: /tmp/temp_31.7 _1673./async-profiler/libasyncProfiler-linux-x64.so
inflating: /tmp/temp_31.7 _1673./async-profiler/libasyncProfiler-mac-x64.so
inflating: /tmp/temp_31.7 _1673./arthas-core.jar
update completed.
Arthas home: /root/.arthas/lib/3.17./arthas
Calculating attach execution time...
Attaching to 1 using version /root/.arthas/lib/3.17./arthas... Real 0m2.298s user 0m0.302s SYS 0m0.145s Attach success. current timestamp is1583537651
Trying 127.0. 01.. Connected to127.0. 01..
Escape character is '^]'.
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ' '-.. -'|'--' | / O \ '. -'|. -. | |'--'. '. | | | -. | | - | `. ` - | | | | | | \ \ | | | | | | | | | |. -'| ` --' `--'`--' The '-' `--'` -' `--'`--' `--'` -- -- -- -- --'
wiki https://alibaba.github.io/arthas
tutorials https://alibaba.github.io/arthas/arthas-tutorials
version 3.17.
pid 1
time 2020-03-06 23:34:10
[arthas@1] $Copy the code2. Start the JAR package and connect to the process
The user executing the program needs to have the same permissions as the target process.
For example, execute as admin:
Sudo su admin && Java -jar arthas-boot.jar or sudo -u admin -eh java-jar arthas-boot.jarCopy the codeIf attach does not attach the target process, check the logs under ~/logs/arthas/.
If the download speed is slow, you can use aliyun’s image:
java -jar arthas-boot.jar --repo-mirror aliyun --use-http
Copy the codejava -jar arthas-boot.jar -h Print more parameter information.
Copy the codeSelect apply Java process:
$ $ java -jar arthas-boot.jar
* [1]: 35542
[2]: 71560 math-game.jar
Copy the codeMath-game is the second process, type 2, then enter/Enter. Arthas attaches to the target process and prints a log:
[INFO] Try to attach process 71560
[INFO] Attach process 71560 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ' '-.. -'|'--' | / O \ '. -'|. -. | |'--'. '. | | | -. | | - | `. ` - | | | | | | \ \ | | | | | | | | | |. -'| ` --' `--'`--' The '-' `--'` -' `--'`--' `--'` -- -- -- -- --'Wiki: https://arthas.aliyun.com/doc version: 3.0.5.20181127201536 pid: 71560 time: 19:16:24 $2020-11-28Copy the codeAfter the Arthas Logo appears, it is ready to use.
Six, use examples
1. Dashboard (real-time data panel of current system)
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
1572 http-nio-8080-exec-139 main 5 TIMED_WAITI 18 0:12 false true
1561 http-nio-8080-exec-138 main 5 RUNNABLE 17 0:18 false true
1539 http-nio-8080-exec-131 main 5 TIMED_WAITI 10 1:17 false true
1575 http-nio-8080-exec-141 main 5 TIMED_WAITI 10 0:0 false true
1573 http-nio-8080-exec-140 main 5 TIMED_WAITI 9 0:8 false true
1559 http-nio-8080-exec-136 main 5 TIMED_WAITI 8 0:29 false true
1558 grpc-default-executor-1340 main 5 TIMED_WAITI 4 0:5 false true
28 grpc-default-worker-ELG-1-4 main 5 RUNNABLE 4 6:44 false true
1560 http-nio-8080-exec-137 main 5 RUNNABLE 4 0:23 false true
Memory used total max usage GC
heap 155M 311M 843M 18.47% gc.ps_scavenge.count 6631
ps_eden_space 39M 171M 310M 12.72% gc.ps_scavenge.time(ms) 52792
ps_survivor_space 1M 2M 2M 90.63% gc.ps_marksweep.count 21
ps_old_gen 114M 138M 632M 18.10% gc.ps_marksweep.time(ms) 11572
Runtime
os.name Linux
os.version 3.10. 0-1062.91..el7.x86_64
java.version 1.8. 0 _111
java.home /usr/jdk18.. 0 _111/jre
Copy the code2. Sysprop (View or modify Java properties)
// View all properties
[arthas@1]$ sysprop KEY VALUE ------------------------------------------------------------------------------------------------------------------------ --------------- java.vendor Oracle Corporation sun.java.launcher SUN_STANDARD catalina.base /apache-tomcat-8.59.
sun.management.compiler HotSpot 64-Bit Tiered Compilers
......
java.specification.versio 1.8
n
[arthas@1] $// View specific properties
[arthas@1]$ sysprop java.rmi.server.hostname
java.rmi.server.hostname=106.5417.234.
[arthas@1]$ sysprop file.encoding
file.encoding=ANSI_X34.-1968
[arthas@1] $// Modify attributes
[arthas@1]$ sysprop user.country
user.country=US
[arthas@1]$ sysprop user.country CN
Successfully changed the system property.
user.country=CN
Copy the code3. Mbeans (View mbean information in real time)
The -i 1000 parameter is refreshed once every second.
[arthas@1]$ mbean -i 1000 java.lang:type=Threading *Count
NAME VALUE
--------------------------------
PeakThreadCount 61
DaemonThreadCount 51
ThreadCount 59
TotalStartedThreadCount 1586
Copy the code4. Thread (View thread)
// View all threads
[arthas@1]$ thread
Threads Total: 59, NEW: 0, RUNNABLE: 24, BLOCKED: 0, WAITING: 9, TIMED_WAITING: 26, TERMINATED: 0
ID NAME GROUP PRIORIT STATE %CPU TIME INTERRU DAEMON
1572 http-nio-8080-exec-139 main 5 TIMED_W 17 1:32 false true
1597 http-nio-8080-exec-151 main 5 RUNNABL 15 0:10 false true
1539 http-nio-8080-exec-131 main 5 TIMED_W 11 2:37 false true
1591 http-nio-8080-exec-148 main 5 RUNNABL 11 0:23 false true
1587 http-nio-8080-exec-146 main 5 TIMED_W 9 0:33 false true
1585 grpc-default-executor-1 main 5 TIMED_W 5 0:9 false true. Affect(row-cnt:0) cost in 106 ms.
[arthas@1] $Copy the codeLooking at all the threads above, you can see that 1572 consumes 17% of the CPU (this percentage is calculated on a per-CPU basis). So you need to see what this thread is doing.
// View the thread stack information
[arthas@1]$ thread 1572
"http-nio-8080-exec-139" Id=1572 RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173)
- locked com.mysql.jdbc.util.ReadAheadInputStream@afb14dd
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2954)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3375)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3365)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3805)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
- locked com.mysql.jdbc.JDBC4Connection@21123f41
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
- locked com.mysql.jdbc.JDBC4Connection@21123f41
at com.mysql.jdbc.PreparedStatement.execute$original$vADsw8UZ(PreparedStatement.java:1192)
- locked com.mysql.jdbc.JDBC4Connection@21123f41
at com.mysql.jdbc.PreparedStatement.execute$original$vADsw8UZ$accessor$md9IHdH2(PreparedStatement.java)
......
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@31355af3
Affect(row-cnt:0) cost in 152 ms.
[arthas@1]$
Copy the code5, thread-n (check the thread stack information of the top CPU)
View the stack of the top 3 threads occupying the CPU at 1 second intervals.
[arthas@1]$ thread -n 3 -i 1000
"http-nio-8080-exec-153" Id=1604 cpuUsage=31% RUNNABLE
at java.lang.Throwable.fillInStackTrace(Native Method)
at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
- locked java.lang.NoSuchMethodException@41cb2ff9
at java.lang.Throwable.<init>(Throwable.java:265)
at java.lang.Exception.<init>(Exception.java:66)... Number of locked synchronizers =1
- java.util.concurrent.ThreadPoolExecutor$Worker@35ddf68a
"http-nio-8080-exec-150" Id=1595 cpuUsage=27% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3fb3dff3
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3fb3dff3
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:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
"http-nio-8080-exec-147" Id=1589 cpuUsage=19% RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173)
- locked com.mysql.jdbc.util.ReadAheadInputStream@afb14dd. Number of locked synchronizers =1
- java.util.concurrent.ThreadPoolExecutor$Worker@5a014dec
Affect(row-cnt:0) cost in 1140 ms.
[arthas@1]$
Copy the codeJad (Decompiled Code)
[arthas@1]$ jad com.7dgroup.blog.controller.BackBlogController
ClassLoader:
+-ParallelWebappClassLoader
context: ROOT
delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@22d7b4f8
+-java.net.URLClassLoader@22d7b4f8
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-sun.misc.Launcher$ExtClassLoader@5f4fff0
Location:
/apache-tomcat-8.59./webapps/ROOT/WEB-INF/classes/
/* * Decompiled with CFR. * * Could not load the following classes: * com.7dgroup.blog.common.exception.JsonResponseException ...... * /
package com.7dgroup.blog.controller;
import com.7dgroup.blog.common.exception.JsonResponseException;
import com.7dgroup.blog.common.model.Page;
import com.7dgroup.blog.common.model.Response;
import com.7dgroup.blog.controller.BackBlogController;
import com.7dgroup.blog.model.Blog;
import com.7dgroup.blog.model.User;
import com.7dgroup.blog.service.BlogReadService;
import com.7dgroup.blog.service.BlogWriteService;
import com.7dgroup.blog.service.CategoryService;
import com.7dgroup.blog.vo.BlogQuery;
import java.lang.reflect.Method;
import java.util.Date;
import java.util.List;
import java.util.concurrent.Callable;
import javax.servlet.http.HttpSession;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.ConstructorInter;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.EnhancedInstance;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Controller;
import org.springframework.ui.Model;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.ResponseBody;
@Controller
@RequestMapping(value={"/back/blog"})
public class BackBlogController
implements EnhancedInstance.EnhancedInstance {
@Autowired
BlogReadService blogReadService;
@Autowired
BlogWriteService blogWriteService;
@Autowired
CategoryService categoryService;
private volatile Object _$EnhancedClassField_ws;
public static volatile /* synthetic */ InstMethodsInter delegate$3vsfol1;
public static volatile /* synthetic */ InstMethodsInter delegate$s214mp1;
public static volatile /* synthetic */ ConstructorInter delegate$1726vl1;
private static final /* synthetic */ Method cachedValue$fhzPhYBQ$0j0d661;
private static final /* synthetic */ Method cachedValue$fhzPhYBQ$7jqr912;
private static final /* synthetic */ Method cachedValue$fhzPhYBQ$k1ffbv0;
private static final /* synthetic */ Method cachedValue$fhzPhYBQ$50tnsu0;
public static volatile /* synthetic */ InstMethodsInter delegate$l07kai0;
public static volatile /* synthetic */ InstMethodsInter delegate$b310fa0;
public static volatile /* synthetic */ ConstructorInter delegate$51jjf90;
private static final /* synthetic */ Method cachedValue$CYumwYK8$0j0d661;
private static final /* synthetic */ Method cachedValue$CYumwYK8$7jqr912;
private static final /* synthetic */ Method cachedValue$CYumwYK8$k1ffbv0;
private static final /* synthetic */ Method cachedValue$CYumwYK8$50tnsu0;
public BackBlogController(a) {
this(null);
delegate$51jjf90.intercept(this.new Object[0]);
}
private /* synthetic */ BackBlogController(auxiliary.xIr7AqvV xIr7AqvV2) {
}
@RequestMapping(value={""})
public String page(Model model, Page<Blog> page, BlogQuery blogQuery, HttpSession httpSession) {
return (String)delegate$b310fa0.intercept(this.newObject[]{model, page, blogQuery, httpSession}, (Callable<? >)new auxiliary.ADTaVnew(this, model, page, blogQuery, httpSession), cachedValue$CYumwYK8$7jqr912); }...final /* synthetic */ Object delete$original$PYp487Vn$accessor$CYumwYK8(Long l) {
return this.delete$original$PYp487Vn(l);
}
}
Affect(row-cnt:9) cost in 1594 ms.
[arthas@1] $Copy the code7, sc (check the loaded class)
[arthas@1]$ sc -d com.jt.blog.controller.BackBlogController
class-info com.jt.blog.controller.BackBlogController
code-source /apache-tomcat- 8.5.9 /webapps/ROOT/WEB-INF/classes/
name com.jt.blog.controller.BackBlogController
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name BackBlogController
modifier public.classLoaderHash 15101d33
Affect(row-cnt: 2)cost in 48 ms.arthas@ $1]Copy the code8. Sm (List the methods used to load a class)
[arthas@1]$ sm com.jt.blog.controller.BackBlogController
com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 <init>()V
com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 page(Lorg/springframework/ui/Model; Lcom/jt/blog/common/model/Page; Lcom/jt/blog/vo/BlogQuery; Ljavax/servlet/http/HttpSession;)Ljava/lang/String; . Affect(row-cnt:73) cost in 17 ms.
[arthas@1] $Copy the code9. Trace (Elapsed time of tracing method)
We can use the trace command to find the most time-consuming method by knowing the package name, class name, and method name.
[arthas@1]$ trace com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 page
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt: 1)cost in 235 ms. ` -ts=2020-03-07 00:40:01; thread_name=http-nio-8080-exec-167; id=662; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[91.777786ms] com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41:page()
`---[91.101545ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
`---ts=2020-03-07 00:40:02; thread_name=http-nio-8080-exec-166; id=661; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[58.901494ms] com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41:page()
`---[58.727281ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
`---ts=2020-03-07 00:40:02; thread_name=http-nio-8080-exec-150; id=63b; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[93.064632ms] com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41:page()
`---[92.902346ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0. [arthas@1]$ trace tk.mybatis.mapper.common.Mapper insert
Press Q or Ctrl+C to abort.
Affect(class-cnt:5 , method-cnt5) :cost in 538 ms. ` -ts=2020-03-07 00:59:22; thread_name=http-nio-8080-exec-172; id=671; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[2.938966ms] com.sun.proxy.$Proxy90:insert()
`---ts=2020-03-07 00:59:22; thread_name=http-nio-8080-exec-172; id=671; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[0.895433ms] com.sun.proxy.$Proxy93:insert()
`---ts=2020-03-07 00:59:24; thread_name=http-nio-8080-exec-150; id=63b; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[2.156481ms] com.sun.proxy.$Proxy90:insert()
Copy the code[arthas@1]$ trace com.jt.blog.service.BlogReadServiceImpl page
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt: 1)cost in 371 ms. ` -ts=2020-03-07 01:04:44; thread_name=http-nio-8080-exec-6; id=32; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@3d0c8d44 `---[75.94035ms] com.jt.blog.service.BlogReadServiceImpl:page()
+---[0.034707ms] com.jt.blog.common.model.Response:<init>() #34+ -- -- -0.019337ms] com.jt.blog.common.model.Page:getPageNo() #36+ -- -- -0.01106ms] com.jt.blog.common.model.Page:getPageSize() #36+ -- -- -4.590002ms] com.github.pagehelper.PageHelper:startPage() #36+ -- -- -0.542359ms] tk.mybatis.mapper.entity.Example:<init>() #37+ -- -- -0.070315ms] tk.mybatis.mapper.entity.Example:createCriteria() #38+ -- -- -0.037231ms] com.jt.blog.vo.BlogQuery:getCategoryId() #40+ -- -- -0.007289ms] com.jt.blog.vo.BlogQuery:getBeginTime() #43+ -- -- -0.007167ms] com.jt.blog.vo.BlogQuery:getPersonal() #46+ -- -- -0.006318ms] com.jt.blog.vo.BlogQuery:getPersonal() #47+ -- -- -0.009675ms] tk.mybatis.mapper.entity.Example$Criteria:andEqualTo() #47+ -- -- -30.90447ms] tk.mybatis.mapper.common.Mapper:selectByExample() #50+ -- -- -36.179664ms] com.jt.blog.service.BlogReadServiceImpl:wrapBlogStatistics() #51 [throws Exception]
+---[0.785948ms] com.google.common.base.Throwables:getStackTraceAsString() #58+ -- -- -0.522234ms] org.slf4j.Logger:error() #58
`---[0.030388ms] com.jt.blog.common.model.Response:setError() #59
`---ts=2020-03-07 01:04:44; thread_name=http-nio-8080-exec-10; id=3c; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@3d0c8d44 `---[94.699363ms] com.jt.blog.service.BlogReadServiceImpl:page()
+---[0.009802ms] com.jt.blog.common.model.Response:<init>() #34+ -- -- -0.007825ms] com.jt.blog.common.model.Page:getPageNo() #36.Copy the codeWe can see that the total time of page method is 75.94035 ms:
- SelectByExample call time 30.90447 ms;
- It took 36.179664 ms to call wrapBlogStatistics;
- StartPage Invocation takes 4.590002 ms.
The selectByExample and wrapBlogStatistics methods take a long time, and when you can pinpoint the method-level consumption time, you can find the reason for the slowness.
10. Stack (View the call stack of a method)
[arthas@1]$ stack tk.mybatis.mapper.common.Mapper insert
Press Q or Ctrl+C to abort.
Affect(class-cnt:5 , method-cnt5) :cost in 561 ms.
ts=2020-03-07 01:00:51; thread_name=http-nio-8080-exec-171; id=66f; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33@com.jt.blog.service.BlogWriteServiceImpl.create()
at sun.reflect.GeneratedMethodAccessor255.invoke(null: -1)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)... ts=2020-03-07 01:00:51; thread_name=http-nio-8080-exec-171; id=66f; is_daemon=true; priority=5; TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33@com.jt.blog.service.BlogWriteServiceImpl.create()
at sun.reflect.GeneratedMethodAccessor255.invoke(null: -1)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)... [arthas@1] $Copy the code11. Classloader (view the classLoader inheritance tree, urls, classloading information)
[arthas@1]$ classloader
name numberOfInstances loadedCountTotal
org.apache.catalina.loader.ParallelWebappClassLoader 2 6680
BootstrapClassLoader 1 3836
sun.misc.Launcher$AppClassLoader 1 3029
com.taobao.arthas.agent.ArthasClassloader 1 1194
java.net.URLClassLoader 1 860
org.apache.skywalking.apm.agent.core.plugin.loader.AgentClassLoader 3 306
sun.reflect.DelegatingClassLoader 289 289
sun.misc.Launcher$ExtClassLoader 1 13
javax.management.remote.rmi.NoCallStackClassLoader 2 2
Affect(row-cnt:9) cost in 36 ms.
[arthas@1] $Copy the code12. Monitor (Monitoring method)
[arthas@1]$ monitor -h
USAGE:
monitor [-c <value>] [-h] [-n <value>] [-E <value>] class-pattern method-pattern
SUMMARY:
Monitor method execution statistics.e.g. total/success/failure count.average rt.fail rate.etc.
Examples:
monitor org.apache.commons.lang.StringUtils isBlank
monitor org.apache.commons.lang.StringUtils isBlank -c 5
monitor -E org\.apache\.commons\.lang\.StringUtils isBlank
WIKI:
https: / /alibaba.github.io/arthas/monitor
OPTIONS:
-c, -cycle <value> The monitor interval (in seconds), 60 seconds by default
-h, -help this help
-n, -limits <value> Threshold of execution times
-E, -regex <value> Enable regular expression to match (wildcard matching by default)
<class-pattern> Path and classname of Pattern Matching
<method-pattern> Method of Pattern Matching
[arthas@ $1]Copy the codeExample:
[arthas@1]$ monitor tk.mybatis.mapper.common.Mapper insert
Press Q or Ctrl+C to abort.
Affect(class-cnt:5 , method-cnt5) :cost in 411 ms.
timestamp class method total success fail avg-rt(ms) fail-rat
e-- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- the 2020-03-07 01:11:38com.sun.proxy. $Proxy93 insert 197 197 0 1.67 0.00%
2020-03-07 01:11:38 com.sun.proxy. $Proxy90 insert 197 197 0 3.39 0.00%
Copy the codeSeven,
In this article, I mainly introduced what Arthas is, why it is used, and demonstrated how Arthas commands are used. Examples are typical ways to troubleshoot online problems and demonstrate the power and convenience of Arthas.