improve dashboard/thread cpu time sample (#1501)

* dashboard command support native thread, delta time
* thread command support --all option
This commit is contained in:
gongdewei
2020-09-22 22:18:51 +08:00
committed by GitHub
parent 4d06126b76
commit 503e0de6b4
24 changed files with 1193 additions and 609 deletions
@@ -0,0 +1,163 @@
package com.taobao.arthas.core.command.model;
import java.lang.management.LockInfo;
import java.lang.management.MonitorInfo;
import java.lang.management.ThreadInfo;
/**
* Busy thread info, include ThreadInfo fields
*
* @author gongdewei 2020/4/26
*/
public class BusyThreadInfo extends ThreadVO {
private long blockedTime;
private long blockedCount;
private long waitedTime;
private long waitedCount;
private LockInfo lockInfo;
private String lockName;
private long lockOwnerId;
private String lockOwnerName;
private boolean inNative;
private boolean suspended;
private StackTraceElement[] stackTrace;
private MonitorInfo[] lockedMonitors;
private LockInfo[] lockedSynchronizers;
public BusyThreadInfo(ThreadVO thread, ThreadInfo threadInfo) {
this.setId(thread.getId());
this.setName(thread.getName());
this.setDaemon(thread.isDaemon());
this.setInterrupted(thread.isInterrupted());
this.setPriority(thread.getPriority());
this.setGroup(thread.getGroup());
this.setState(thread.getState());
this.setCpu(thread.getCpu());
this.setDeltaTime(thread.getDeltaTime());
this.setTime(thread.getTime());
//thread info
if (threadInfo != null) {
this.setLockInfo(threadInfo.getLockInfo());
this.setLockedMonitors(threadInfo.getLockedMonitors());
this.setLockedSynchronizers(threadInfo.getLockedSynchronizers());
this.setLockName(threadInfo.getLockName());
this.setLockOwnerId(threadInfo.getLockOwnerId());
this.setLockOwnerName(threadInfo.getLockOwnerName());
this.setStackTrace(threadInfo.getStackTrace());
this.setBlockedCount(threadInfo.getBlockedCount());
this.setBlockedTime(threadInfo.getBlockedTime());
this.setInNative(threadInfo.isInNative());
this.setSuspended(threadInfo.isSuspended());
this.setWaitedCount(threadInfo.getWaitedCount());
this.setWaitedTime(threadInfo.getWaitedTime());
}
}
public long getBlockedTime() {
return blockedTime;
}
public void setBlockedTime(long blockedTime) {
this.blockedTime = blockedTime;
}
public long getBlockedCount() {
return blockedCount;
}
public void setBlockedCount(long blockedCount) {
this.blockedCount = blockedCount;
}
public long getWaitedTime() {
return waitedTime;
}
public void setWaitedTime(long waitedTime) {
this.waitedTime = waitedTime;
}
public long getWaitedCount() {
return waitedCount;
}
public void setWaitedCount(long waitedCount) {
this.waitedCount = waitedCount;
}
public LockInfo getLockInfo() {
return lockInfo;
}
public void setLockInfo(LockInfo lockInfo) {
this.lockInfo = lockInfo;
}
public String getLockName() {
return lockName;
}
public void setLockName(String lockName) {
this.lockName = lockName;
}
public long getLockOwnerId() {
return lockOwnerId;
}
public void setLockOwnerId(long lockOwnerId) {
this.lockOwnerId = lockOwnerId;
}
public String getLockOwnerName() {
return lockOwnerName;
}
public void setLockOwnerName(String lockOwnerName) {
this.lockOwnerName = lockOwnerName;
}
public boolean isInNative() {
return inNative;
}
public void setInNative(boolean inNative) {
this.inNative = inNative;
}
public boolean isSuspended() {
return suspended;
}
public void setSuspended(boolean suspended) {
this.suspended = suspended;
}
public StackTraceElement[] getStackTrace() {
return stackTrace;
}
public void setStackTrace(StackTraceElement[] stackTrace) {
this.stackTrace = stackTrace;
}
public MonitorInfo[] getLockedMonitors() {
return lockedMonitors;
}
public void setLockedMonitors(MonitorInfo[] lockedMonitors) {
this.lockedMonitors = lockedMonitors;
}
public LockInfo[] getLockedSynchronizers() {
return lockedSynchronizers;
}
public void setLockedSynchronizers(LockInfo[] lockedSynchronizers) {
this.lockedSynchronizers = lockedSynchronizers;
}
}
@@ -1,36 +0,0 @@
package com.taobao.arthas.core.command.model;
import java.lang.management.ThreadInfo;
/**
* ThreadInfo with cpuUsage
*
* @author gongdewei 2020/4/26
*/
public class ThreadCpuInfo {
private ThreadInfo threadInfo;
private long cpuUsage;
public ThreadCpuInfo(ThreadInfo threadInfo, long cpuUsage) {
this.threadInfo = threadInfo;
this.cpuUsage = cpuUsage;
}
public long getCpuUsage() {
return cpuUsage;
}
public void setCpuUsage(long cpuUsage) {
this.cpuUsage = cpuUsage;
}
public ThreadInfo threadInfo() {
return threadInfo;
}
public void setThreadInfo(ThreadInfo threadInfo) {
this.threadInfo = threadInfo;
}
}
@@ -18,11 +18,12 @@ public class ThreadModel extends ResultModel {
private BlockingLockInfo blockingLockInfo;
//thread -n 5
private ThreadCpuInfo[] busyThreads;
private List<BusyThreadInfo> busyThreads;
//thread stats
private List<ThreadVO> threadStats;
private Map<Thread.State, Integer> threadStateCount;
private boolean all;
public ThreadModel() {
}
@@ -35,13 +36,14 @@ public class ThreadModel extends ResultModel {
this.blockingLockInfo = blockingLockInfo;
}
public ThreadModel(ThreadCpuInfo[] busyThreads) {
public ThreadModel(List<BusyThreadInfo> busyThreads) {
this.busyThreads = busyThreads;
}
public ThreadModel(List<ThreadVO> threadStats, Map<Thread.State, Integer> threadStateCount) {
public ThreadModel(List<ThreadVO> threadStats, Map<Thread.State, Integer> threadStateCount, boolean all) {
this.threadStats = threadStats;
this.threadStateCount = threadStateCount;
this.all = all;
}
@Override
@@ -65,11 +67,11 @@ public class ThreadModel extends ResultModel {
this.blockingLockInfo = blockingLockInfo;
}
public ThreadCpuInfo[] getBusyThreads() {
public List<BusyThreadInfo> getBusyThreads() {
return busyThreads;
}
public void setBusyThreads(ThreadCpuInfo[] busyThreads) {
public void setBusyThreads(List<BusyThreadInfo> busyThreads) {
this.busyThreads = busyThreads;
}
@@ -88,4 +90,12 @@ public class ThreadModel extends ResultModel {
public void setThreadStateCount(Map<Thread.State, Integer> threadStateCount) {
this.threadStateCount = threadStateCount;
}
public boolean isAll() {
return all;
}
public void setAll(boolean all) {
this.all = all;
}
}
@@ -13,7 +13,8 @@ public class ThreadVO {
private String group;
private int priority;
private State state;
private long cpu;
private double cpu;
private long deltaTime;
private long time;
private boolean interrupted;
private boolean daemon;
@@ -61,14 +62,22 @@ public class ThreadVO {
this.state = state;
}
public long getCpu() {
public double getCpu() {
return cpu;
}
public void setCpu(long cpu) {
public void setCpu(double cpu) {
this.cpu = cpu;
}
public long getDeltaTime() {
return deltaTime;
}
public void setDeltaTime(long deltaTime) {
this.deltaTime = deltaTime;
}
public long getTime() {
return time;
}
@@ -92,4 +101,22 @@ public class ThreadVO {
public void setDaemon(boolean daemon) {
this.daemon = daemon;
}
@Override
public boolean equals(Object o) {
if (this == o) return true;
if (o == null || getClass() != o.getClass()) return false;
ThreadVO threadVO = (ThreadVO) o;
if (id != threadVO.id) return false;
return name != null ? name.equals(threadVO.name) : threadVO.name == null;
}
@Override
public int hashCode() {
int result = (int) (id ^ (id >>> 32));
result = 31 * result + (name != null ? name.hashCode() : 0);
return result;
}
}
@@ -9,6 +9,7 @@ import com.taobao.arthas.core.command.model.DashboardModel;
import com.taobao.arthas.core.command.model.GcInfoVO;
import com.taobao.arthas.core.command.model.MemoryEntryVO;
import com.taobao.arthas.core.command.model.RuntimeInfoVO;
import com.taobao.arthas.core.command.model.ThreadVO;
import com.taobao.arthas.core.command.model.TomcatInfoVO;
import com.taobao.arthas.core.shell.command.AnnotatedCommand;
import com.taobao.arthas.core.shell.command.CommandProcess;
@@ -305,7 +306,7 @@ public class DashboardCommand extends AnnotatedCommand {
DashboardModel dashboardModel = new DashboardModel();
//thread sample
Map<String, Thread> threads = ThreadUtil.getThreads();
Map<String, ThreadVO> threads = ThreadUtil.getThreads();
dashboardModel.setThreads(threadSampler.sample(threads.values()));
//memory
@@ -2,7 +2,7 @@ package com.taobao.arthas.core.command.monitor200;
import com.taobao.arthas.core.command.Constants;
import com.taobao.arthas.core.command.model.BlockingLockInfo;
import com.taobao.arthas.core.command.model.ThreadCpuInfo;
import com.taobao.arthas.core.command.model.BusyThreadInfo;
import com.taobao.arthas.core.command.model.ThreadModel;
import com.taobao.arthas.core.command.model.ThreadVO;
import com.taobao.arthas.core.shell.command.AnnotatedCommand;
@@ -51,11 +51,12 @@ public class ThreadCommand extends AnnotatedCommand {
private long id = -1;
private Integer topNBusy = null;
private boolean findMostBlockingThread = false;
private int sampleInterval = 100;
private int sampleInterval = 200;
private String state;
private boolean lockedMonitors = false;
private boolean lockedSynchronizers = false;
private boolean all = false;
static {
states = new HashSet<String>(State.values().length);
@@ -70,6 +71,12 @@ public class ThreadCommand extends AnnotatedCommand {
this.id = id;
}
@Option(longName = "all", flag = true)
@Description("Display all thread results instead of the first page")
public void setAll(boolean all) {
this.all = all;
}
@Option(shortName = "n", longName = "top-n-threads")
@Description("The number of thread(s) to show, ordered by cpu utilization, -1 to show all.")
public void setTopNBusy(Integer topNBusy) {
@@ -122,7 +129,7 @@ public class ThreadCommand extends AnnotatedCommand {
}
private ExitStatus processAllThreads(CommandProcess process) {
Map<String, Thread> threads = ThreadUtil.getThreads();
Map<String, ThreadVO> threads = ThreadUtil.getThreads();
// 统计各种线程状态
Map<State, Integer> stateCountMap = new LinkedHashMap<State, Integer>();
@@ -130,18 +137,20 @@ public class ThreadCommand extends AnnotatedCommand {
stateCountMap.put(s, 0);
}
for (Thread thread : threads.values()) {
for (ThreadVO thread : threads.values()) {
State threadState = thread.getState();
Integer count = stateCountMap.get(threadState);
stateCountMap.put(threadState, count + 1);
}
Collection<Thread> resultThreads = new ArrayList<Thread>();
boolean includeInternalThreads = true;
Collection<ThreadVO> resultThreads = new ArrayList<ThreadVO>();
if (!StringUtils.isEmpty(this.state)) {
this.state = this.state.toUpperCase();
if (states.contains(this.state)) {
for (Thread thread : threads.values()) {
if (state.equals(thread.getState().name())) {
includeInternalThreads = false;
for (ThreadVO thread : threads.values()) {
if (thread.getState() != null && state.equals(thread.getState().name())) {
resultThreads.add(thread);
}
}
@@ -154,10 +163,12 @@ public class ThreadCommand extends AnnotatedCommand {
//thread stats
ThreadSampler threadSampler = new ThreadSampler();
threadSampler.setSampleInterval(sampleInterval);
threadSampler.setIncludeInternalThreads(includeInternalThreads);
threadSampler.sample(resultThreads);
threadSampler.pause(sampleInterval);
List<ThreadVO> threadStats = threadSampler.sample(resultThreads);
process.appendResult(new ThreadModel(threadStats, stateCountMap));
process.appendResult(new ThreadModel(threadStats, stateCountMap, all));
return ExitStatus.success();
}
@@ -171,21 +182,44 @@ public class ThreadCommand extends AnnotatedCommand {
}
private ExitStatus processTopBusyThreads(CommandProcess process) {
Map<Long, Long> topNThreads = ThreadUtil.getTopNThreads(sampleInterval, topNBusy);
Long[] tids = topNThreads.keySet().toArray(new Long[0]);
ThreadInfo[] threadInfos = threadMXBean.getThreadInfo(ArrayUtils.toPrimitive(tids), lockedMonitors, lockedSynchronizers);
if (threadInfos == null) {
ThreadSampler threadSampler = new ThreadSampler();
threadSampler.sample(ThreadUtil.getThreads().values());
threadSampler.pause(sampleInterval);
List<ThreadVO> threadStats = threadSampler.sample(ThreadUtil.getThreads().values());
int limit = Math.min(threadStats.size(), topNBusy);
List<ThreadVO> topNThreads = threadStats.subList(0, limit);
List<Long> tids = new ArrayList<Long>(topNThreads.size());
for (ThreadVO thread : topNThreads) {
if (thread.getId() > 0) {
tids.add(thread.getId());
}
}
ThreadInfo[] threadInfos = threadMXBean.getThreadInfo(ArrayUtils.toPrimitive(tids.toArray(new Long[0])), lockedMonitors, lockedSynchronizers);
if (tids.size()> 0 && threadInfos == null) {
return ExitStatus.failure(1, "get top busy threads failed");
}
//threadInfo with cpuUsage
ThreadCpuInfo[] threadCpuInfos = new ThreadCpuInfo[threadInfos.length];
List<BusyThreadInfo> busyThreadInfos = new ArrayList<BusyThreadInfo>(topNThreads.size());
for (ThreadVO thread : topNThreads) {
ThreadInfo threadInfo = findThreadInfoById(threadInfos, thread.getId());
BusyThreadInfo busyThread = new BusyThreadInfo(thread, threadInfo);
busyThreadInfos.add(busyThread);
}
process.appendResult(new ThreadModel(busyThreadInfos));
return ExitStatus.success();
}
private ThreadInfo findThreadInfoById(ThreadInfo[] threadInfos, long id) {
for (int i = 0; i < threadInfos.length; i++) {
ThreadInfo threadInfo = threadInfos[i];
threadCpuInfos[i] = new ThreadCpuInfo(threadInfo, topNThreads.get(threadInfo.getThreadId()));
if ( threadInfo.getThreadId() == id) {
return threadInfo;
}
}
process.appendResult(new ThreadModel(threadCpuInfos));
return ExitStatus.success();
return null;
}
private ExitStatus processThread(CommandProcess process) {
@@ -1,10 +1,18 @@
package com.taobao.arthas.core.command.monitor200;
import com.taobao.arthas.core.command.model.ThreadVO;
import sun.management.HotspotThreadMBean;
import sun.management.ManagementFactoryHelper;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;
import java.util.*;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
import java.util.Comparator;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
/**
* Thread cpu sampler
@@ -13,61 +21,112 @@ import java.util.*;
*/
public class ThreadSampler {
private long sampleInterval = 100;
private static ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
private static HotspotThreadMBean hotspotThreadMBean;
private static boolean hotspotThreadMBeanEnable = true;
public List<ThreadVO> sample(Collection<Thread> originThreads) {
private Map<ThreadVO, Long> lastCpuTimes = new HashMap<ThreadVO, Long>();
List<Thread> threads = new ArrayList<Thread>(originThreads);
ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
private long lastSampleTimeNanos;
private boolean includeInternalThreads = true;
public List<ThreadVO> sample(Collection<ThreadVO> originThreads) {
List<ThreadVO> threads = new ArrayList<ThreadVO>(originThreads);
// Sample CPU
Map<Long, Long> times1 = new HashMap<Long, Long>();
for (Thread thread : threads) {
long cpu = threadMXBean.getThreadCpuTime(thread.getId());
times1.put(thread.getId(), cpu);
}
if (lastCpuTimes.isEmpty()) {
lastSampleTimeNanos = System.nanoTime();
for (ThreadVO thread : threads) {
if (thread.getId() > 0) {
long cpu = threadMXBean.getThreadCpuTime(thread.getId());
lastCpuTimes.put(thread, cpu);
thread.setTime(cpu / 1000000);
}
}
try {
Thread.sleep(sampleInterval);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
// add internal threads
Map<String, Long> internalThreadCpuTimes = getInternalThreadCpuTimes();
if (internalThreadCpuTimes != null) {
for (Map.Entry<String, Long> entry : internalThreadCpuTimes.entrySet()) {
String key = entry.getKey();
ThreadVO thread = createThreadVO(key);
thread.setTime(entry.getValue() / 1000000);
threads.add(thread);
lastCpuTimes.put(thread, entry.getValue());
}
}
//sort by time
Collections.sort(threads, new Comparator<ThreadVO>() {
@Override
public int compare(ThreadVO o1, ThreadVO o2) {
long l1 = o1.getTime();
long l2 = o2.getTime();
if (l1 < l2) {
return 1;
} else if (l1 > l2) {
return -1;
} else {
return 0;
}
}
});
return threads;
}
// Resample
Map<Long, Long> times2 = new HashMap<Long, Long>(threads.size());
for (Thread thread : threads) {
long cpu = threadMXBean.getThreadCpuTime(thread.getId());
times2.put(thread.getId(), cpu);
long newSampleTimeNanos = System.nanoTime();
Map<ThreadVO, Long> newCpuTimes = new HashMap<ThreadVO, Long>(threads.size());
for (ThreadVO thread : threads) {
if (thread.getId() > 0) {
long cpu = threadMXBean.getThreadCpuTime(thread.getId());
newCpuTimes.put(thread, cpu);
}
}
// internal threads
Map<String, Long> newInternalThreadCpuTimes = getInternalThreadCpuTimes();
if (newInternalThreadCpuTimes != null) {
for (Map.Entry<String, Long> entry : newInternalThreadCpuTimes.entrySet()) {
ThreadVO threadVO = createThreadVO(entry.getKey());
threads.add(threadVO);
newCpuTimes.put(threadVO, entry.getValue());
}
}
// Compute delta map and total time
long total = 0;
Map<Long, Long> deltas = new HashMap<Long, Long>(threads.size());
for (Long id : times2.keySet()) {
long time1 = times2.get(id);
long time2 = times1.get(id);
// Compute delta time
final Map<ThreadVO, Long> deltas = new HashMap<ThreadVO, Long>(threads.size());
for (ThreadVO thread : newCpuTimes.keySet()) {
Long t = lastCpuTimes.get(thread);
if (t == null) {
t = 0L;
}
long time1 = t;
long time2 = newCpuTimes.get(thread);
if (time1 == -1) {
time1 = time2;
} else if (time2 == -1) {
time2 = time1;
}
long delta = time2 - time1;
deltas.put(id, delta);
total += delta;
deltas.put(thread, delta);
}
// Compute cpu
final HashMap<Thread, Long> cpus = new HashMap<Thread, Long>(threads.size());
for (Thread thread : threads) {
long cpu = total == 0 ? 0 : Math.round((deltas.get(thread.getId()) * 100) / total);
cpus.put(thread, cpu);
long sampleIntervalNanos = newSampleTimeNanos - lastSampleTimeNanos;
// Compute cpu usage
final HashMap<ThreadVO, Double> cpuUsages = new HashMap<ThreadVO, Double>(threads.size());
for (ThreadVO thread : threads) {
double cpu = sampleIntervalNanos == 0 ? 0 : (deltas.get(thread) * 10000 / sampleIntervalNanos / 100.0);
cpuUsages.put(thread, cpu);
}
// Sort by CPU time : should be a rendering hint...
Collections.sort(threads, new Comparator<Thread>() {
public int compare(Thread o1, Thread o2) {
long l1 = cpus.get(o1);
long l2 = cpus.get(o2);
Collections.sort(threads, new Comparator<ThreadVO>() {
public int compare(ThreadVO o1, ThreadVO o2) {
long l1 = deltas.get(o1);
long l2 = deltas.get(o2);
if (l1 < l2) {
return 1;
} else if (l1 > l2) {
@@ -78,34 +137,61 @@ public class ThreadSampler {
}
});
List<ThreadVO> threadVOList = new ArrayList<ThreadVO>(threads.size());
for (Thread thread : threads) {
ThreadGroup group = thread.getThreadGroup();
long seconds = times2.get(thread.getId()) / 1000000000;
//long min = seconds / 60;
//String time = min + ":" + (seconds % 60);
long cpu = cpus.get(thread);
for (ThreadVO thread : threads) {
//nanos to mills
long timeMills = newCpuTimes.get(thread) / 1000000;
long deltaTime = deltas.get(thread) / 1000000;
double cpu = cpuUsages.get(thread);
ThreadVO threadVO = new ThreadVO();
threadVO.setId(thread.getId());
threadVO.setName(thread.getName());
threadVO.setGroup(group == null ? "" : group.getName());
threadVO.setPriority(thread.getPriority());
threadVO.setState(thread.getState());
threadVO.setCpu(cpu);
threadVO.setTime(seconds);
threadVO.setInterrupted(thread.isInterrupted());
threadVO.setDaemon(thread.isDaemon());
threadVOList.add(threadVO);
thread.setCpu(cpu);
thread.setTime(timeMills);
thread.setDeltaTime(deltaTime);
}
return threadVOList;
lastCpuTimes = newCpuTimes;
lastSampleTimeNanos = newSampleTimeNanos;
return threads;
}
public long getSampleInterval() {
return sampleInterval;
private Map<String, Long> getInternalThreadCpuTimes() {
if (hotspotThreadMBeanEnable && includeInternalThreads) {
try {
if (hotspotThreadMBean == null) {
hotspotThreadMBean = ManagementFactoryHelper.getHotspotThreadMBean();
}
return hotspotThreadMBean.getInternalThreadCpuTimes();
} catch (Throwable e) {
//ignore ex
hotspotThreadMBeanEnable = false;
}
}
return null;
}
public void setSampleInterval(long sampleInterval) {
this.sampleInterval = sampleInterval;
private ThreadVO createThreadVO(String name) {
ThreadVO threadVO = new ThreadVO();
threadVO.setId(-1);
threadVO.setName(name);
threadVO.setPriority(-1);
threadVO.setDaemon(true);
threadVO.setInterrupted(false);
return threadVO;
}
public void pause(long mills) {
try {
Thread.sleep(mills);
} catch (InterruptedException e) {
// ignore
}
}
public boolean isIncludeInternalThreads() {
return includeInternalThreads;
}
public void setIncludeInternalThreads(boolean includeInternalThreads) {
this.includeInternalThreads = includeInternalThreads;
}
}
@@ -28,37 +28,61 @@ public class DashboardView extends ResultView<DashboardModel> {
// 上半部分放thread top。下半部分再切分为田字格,其中上面两格放memory, gc的信息。下面两格放tomcat,
// runtime的信息
int totalHeight = height - 1;
int threadTopHeight = totalHeight / 2;
int threadTopHeight;
if (totalHeight <= 24) {
//总高度较小时取1/2
threadTopHeight = totalHeight / 2;
} else {
//总高度较大时取1/3,但不少于上面的值(24/2=12)
threadTopHeight = totalHeight / 3;
if (threadTopHeight < 12) {
threadTopHeight = 12;
}
}
int lowerHalf = totalHeight - threadTopHeight;
int runtimeInfoHeight = lowerHalf / 2;
int heapInfoHeight = lowerHalf - runtimeInfoHeight;
//Memory至少保留8行, 显示metaspace信息
int memoryInfoHeight = lowerHalf / 2;
if (memoryInfoHeight < 8) {
memoryInfoHeight = Math.min(8, lowerHalf);
}
//runtime
TableElement runtimeInfoTable = drawRuntimeInfo(result.getRuntimeInfo());
//tomcat
TableElement tomcatInfoTable = drawTomcatInfo(result.getTomcatInfo());
int runtimeInfoHeight = Math.max(runtimeInfoTable.getRows().size(), tomcatInfoTable == null ? 0 : tomcatInfoTable.getRows().size());
if (runtimeInfoHeight < lowerHalf - memoryInfoHeight) {
//如果runtimeInfo高度有剩余,则增大MemoryInfo的高度
memoryInfoHeight = lowerHalf - runtimeInfoHeight;
} else {
runtimeInfoHeight = lowerHalf - memoryInfoHeight;
}
//如果MemoryInfo高度有剩余,则增大ThreadHeight
int maxMemoryInfoHeight = getMemoryInfoHeight(result.getMemoryInfo());
memoryInfoHeight = Math.min(memoryInfoHeight, maxMemoryInfoHeight);
threadTopHeight = totalHeight - memoryInfoHeight - runtimeInfoHeight;
String threadInfo = ViewRenderUtil.drawThreadInfo(result.getThreads(), width, threadTopHeight);
String memoryAndGc = drawMemoryInfoAndGcInfo(result.getMemoryInfo(), result.getGcInfos(), width, runtimeInfoHeight);
String runTimeAndTomcat = drawRuntimeInfoAndTomcatInfo(result.getRuntimeInfo(), result.getTomcatInfo(), width, heapInfoHeight);
String memoryAndGc = drawMemoryInfoAndGcInfo(result.getMemoryInfo(), result.getGcInfos(), width, memoryInfoHeight);
String runTimeAndTomcat = drawRuntimeInfoAndTomcatInfo(runtimeInfoTable, tomcatInfoTable, width, runtimeInfoHeight);
process.write(threadInfo + memoryAndGc + runTimeAndTomcat);
}
static String drawMemoryInfoAndGcInfo(Map<String, List<MemoryEntryVO>> memoryInfo, List<GcInfoVO> gcInfos, int width, int height) {
TableElement table = new TableElement(1, 1);
TableElement memoryInfoTable = new TableElement(3, 1, 1, 1, 1).rightCellPadding(1);
memoryInfoTable.add(new RowElement().style(Decoration.bold.fg(Color.black).bg(Color.white)).add("Memory",
"used", "total", "max", "usage"));
drawMemoryInfo(memoryInfoTable, memoryInfo);
TableElement gcInfoTable = new TableElement(1, 1).rightCellPadding(1);
gcInfoTable.add(new RowElement().style(Decoration.bold.fg(Color.black).bg(Color.white)).add("GC", ""));
drawGcInfo(gcInfoTable, gcInfos);
TableElement memoryInfoTable = drawMemoryInfo(memoryInfo);
TableElement gcInfoTable = drawGcInfo(gcInfos);
table.row(memoryInfoTable, gcInfoTable);
return RenderUtil.render(table, width, height);
}
private static void drawMemoryInfo(TableElement table, Map<String, List<MemoryEntryVO>> memoryInfo) {
private static TableElement drawMemoryInfo(Map<String, List<MemoryEntryVO>> memoryInfo) {
TableElement table = new TableElement(3, 1, 1, 1, 1).rightCellPadding(1);
table.add(new RowElement().style(Decoration.bold.fg(Color.black).bg(Color.white)).add("Memory",
"used", "total", "max", "usage"));
List<MemoryEntryVO> heapMemoryEntries = memoryInfo.get(MemoryEntryVO.TYPE_HEAP);
//heap memory
for (MemoryEntryVO memoryEntryVO : heapMemoryEntries) {
@@ -81,26 +105,38 @@ public class DashboardView extends ResultView<DashboardModel> {
//buffer-pool
List<MemoryEntryVO> bufferPoolMemoryEntries = memoryInfo.get(MemoryEntryVO.TYPE_BUFFER_POOL);
for (MemoryEntryVO memoryEntryVO : bufferPoolMemoryEntries) {
new MemoryEntry(memoryEntryVO).addTableRow(table);
if (bufferPoolMemoryEntries != null) {
for (MemoryEntryVO memoryEntryVO : bufferPoolMemoryEntries) {
new MemoryEntry(memoryEntryVO).addTableRow(table);
}
}
return table;
}
private static void drawGcInfo(TableElement table, List<GcInfoVO> gcInfos) {
private static int getMemoryInfoHeight(Map<String, List<MemoryEntryVO>> memoryInfo) {
int height = 1;
for (List<MemoryEntryVO> memoryEntryVOS : memoryInfo.values()) {
height += memoryEntryVOS.size();
}
return height;
}
private static TableElement drawGcInfo(List<GcInfoVO> gcInfos) {
TableElement table = new TableElement(1, 1).rightCellPadding(1);
table.add(new RowElement().style(Decoration.bold.fg(Color.black).bg(Color.white)).add("GC", ""));
for (GcInfoVO gcInfo : gcInfos) {
table.add(new RowElement().style(Decoration.bold.bold()).add("gc." + gcInfo.getName() + ".count",
"" + gcInfo.getCollectionCount()));
table.row("gc." + gcInfo.getName() + ".time(ms)", "" + gcInfo.getCollectionTime());
}
return table;
}
String drawRuntimeInfoAndTomcatInfo(RuntimeInfoVO runtimeInfo, TomcatInfoVO tomcatInfo, int width, int height) {
String drawRuntimeInfoAndTomcatInfo(TableElement runtimeInfoTable, TableElement tomcatInfoTable, int width, int height) {
if (height <= 0) {
return "";
}
TableElement resultTable = new TableElement(1, 1);
//runtime
TableElement runtimeInfoTable = drawRuntimeInfo(runtimeInfo);
//tomcat
TableElement tomcatInfoTable = drawTomcatInfo(tomcatInfo);
if (tomcatInfoTable != null) {
resultTable.row(runtimeInfoTable, tomcatInfoTable);
} else {
@@ -211,13 +247,17 @@ public class DashboardView extends ResultView<DashboardModel> {
public void addTableRow(TableElement table) {
double usage = used / (double) (max == -1 || max == Long.MIN_VALUE ? total : max) * 100;
if (Double.isNaN(usage) || Double.isInfinite(usage)) {
usage = 0;
}
table.row(name, format(used), format(total), format(max), String.format("%.2f%%", usage));
}
public void addTableRow(TableElement table, Style.Composite style) {
double usage = used / (double) (max == -1 || max == Long.MIN_VALUE ? total : max) * 100;
if (Double.isNaN(usage) || Double.isInfinite(usage)) {
usage = 0;
}
table.add(new RowElement().style(style).add(name, format(used), format(total), format(max),
String.format("%.2f%%", usage)));
}
@@ -1,6 +1,6 @@
package com.taobao.arthas.core.command.view;
import com.taobao.arthas.core.command.model.ThreadCpuInfo;
import com.taobao.arthas.core.command.model.BusyThreadInfo;
import com.taobao.arthas.core.command.model.ThreadModel;
import com.taobao.arthas.core.command.model.ThreadVO;
import com.taobao.arthas.core.shell.command.CommandProcess;
@@ -23,12 +23,12 @@ public class ThreadView extends ResultView<ThreadModel> {
public void draw(CommandProcess process, ThreadModel result) {
if (result.getThreadInfo() != null) {
// no cpu usage info
String content = ThreadUtil.getFullStacktrace(result.getThreadInfo(), -1);
String content = ThreadUtil.getFullStacktrace(result.getThreadInfo());
process.write(content);
} else if (result.getBusyThreads() != null) {
ThreadCpuInfo[] threadInfos = result.getBusyThreads();
for (ThreadCpuInfo info : threadInfos) {
String stacktrace = ThreadUtil.getFullStacktrace(info.threadInfo(), info.getCpuUsage());
List<BusyThreadInfo> threadInfos = result.getBusyThreads();
for (BusyThreadInfo info : threadInfos) {
String stacktrace = ThreadUtil.getFullStacktrace(info, -1, -1);
process.write(stacktrace).write("\n");
}
} else if (result.getBlockingLockInfo() != null) {
@@ -44,6 +44,15 @@ public class ThreadView extends ResultView<ThreadModel> {
for (Integer value : threadStateCount.values()) {
total += value;
}
int internalThreadCount = 0;
for (ThreadVO thread : threadStats) {
if (thread.getId() <= 0) {
internalThreadCount += 1;
}
}
total += internalThreadCount;
StringBuilder threadStat = new StringBuilder();
threadStat.append("Threads Total: ").append(total);
@@ -51,12 +60,20 @@ public class ThreadView extends ResultView<ThreadModel> {
Integer count = threadStateCount.get(s);
threadStat.append(", ").append(s.name()).append(": ").append(count);
}
if (internalThreadCount > 0) {
threadStat.append(", Internal threads: ").append(internalThreadCount);
}
String stat = RenderUtil.render(new LabelElement(threadStat), process.width());
//thread stats
int height = Math.max(5, process.height() - 2);
//remove blank lines
height = Math.min(height, threadStats.size() + 2);
int height;
if (result.isAll()) {
height = threadStats.size() + 1;
} else {
height = Math.max(5, process.height() - 2);
//remove blank lines
height = Math.min(height, threadStats.size() + 2);
}
String content = ViewRenderUtil.drawThreadInfo(threadStats, process.width(), height);
process.write(stat + content);
}
@@ -105,7 +105,7 @@ public class ViewRenderUtil {
}
public static String drawThreadInfo(List<ThreadVO> threads, int width, int height) {
TableElement table = new TableElement(1, 3, 2, 1, 1, 1, 1, 1, 1).overflow(Overflow.HIDDEN).rightCellPadding(1);
TableElement table = new TableElement(1, 6, 3, 2, 2, 2, 2, 2, 2, 2).overflow(Overflow.HIDDEN).rightCellPadding(1);
// Header
table.add(
@@ -116,6 +116,7 @@ public class ViewRenderUtil {
"PRIORITY",
"STATE",
"%CPU",
"DELTA_TIME",
"TIME",
"INTERRUPTED",
"DAEMON"
@@ -124,22 +125,28 @@ public class ViewRenderUtil {
for (ThreadVO thread : threads) {
Color color = colorMapping.get(thread.getState());
long seconds = thread.getTime();
long min = seconds / 60;
String time = min + ":" + (seconds % 60);
long cpu = thread.getCpu();
String time = formatTimeMills(thread.getTime());
String deltaTime = formatTimeMillsToSeconds(thread.getDeltaTime());
double cpu = thread.getCpu();
LabelElement daemonLabel = new LabelElement(thread.isDaemon());
if (!thread.isDaemon()) {
daemonLabel.setStyle(Style.style(Color.magenta));
}
LabelElement stateElement;
if (thread.getState() != null) {
stateElement = new LabelElement(thread.getState()).style(color.fg());
} else {
stateElement = new LabelElement("-");
}
table.row(
new LabelElement(thread.getId()),
new LabelElement(thread.getName()),
new LabelElement(thread.getGroup()),
new LabelElement(thread.getGroup() != null ? thread.getGroup() : "-"),
new LabelElement(thread.getPriority()),
new LabelElement(thread.getState()).style(color.fg()),
stateElement,
new LabelElement(cpu),
new LabelElement(deltaTime),
new LabelElement(time),
new LabelElement(thread.isInterrupted()),
daemonLabel
@@ -147,4 +154,18 @@ public class ViewRenderUtil {
}
return RenderUtil.render(table, width, height);
}
private static String formatTimeMills(long timeMills) {
long seconds = timeMills / 1000;
long mills = timeMills % 1000;
long min = seconds / 60;
//return min + ":" + (seconds % 60);
return String.format("%d:%d.%03d", min, seconds, mills);
}
private static String formatTimeMillsToSeconds(long timeMills) {
long seconds = timeMills / 1000;
long mills = timeMills % 1000;
return String.format("%d.%03d", seconds, mills);
}
}
@@ -1,8 +1,10 @@
package com.taobao.arthas.core.util;
import com.taobao.arthas.core.command.model.BlockingLockInfo;
import com.taobao.arthas.core.command.model.BusyThreadInfo;
import com.taobao.arthas.core.command.model.StackModel;
import com.taobao.arthas.core.command.model.ThreadNode;
import com.taobao.arthas.core.command.model.ThreadVO;
import com.taobao.arthas.core.view.Ansi;
import java.arthas.SpyAPI;
@@ -38,13 +40,13 @@ abstract public class ThreadUtil {
*
* @return
*/
public static Map<String, Thread> getThreads() {
public static Map<String, ThreadVO> getThreads() {
ThreadGroup root = getRoot();
Thread[] threads = new Thread[root.activeCount()];
while (root.enumerate(threads, true) == threads.length) {
threads = new Thread[threads.length * 2];
}
SortedMap<String, Thread> map = new TreeMap<String, Thread>(new Comparator<String>() {
SortedMap<String, ThreadVO> map = new TreeMap<String, ThreadVO>(new Comparator<String>() {
@Override
public int compare(String o1, String o2) {
return o1.compareTo(o2);
@@ -52,12 +54,26 @@ abstract public class ThreadUtil {
});
for (Thread thread : threads) {
if (thread != null) {
map.put(thread.getName() + "-" + thread.getId(), thread);
ThreadVO threadVO = createThreadVO(thread);
map.put(thread.getName() + "-" + thread.getId(), threadVO);
}
}
return map;
}
private static ThreadVO createThreadVO(Thread thread) {
ThreadGroup group = thread.getThreadGroup();
ThreadVO threadVO = new ThreadVO();
threadVO.setId(thread.getId());
threadVO.setName(thread.getName());
threadVO.setGroup(group == null ? "" : group.getName());
threadVO.setPriority(thread.getPriority());
threadVO.setState(thread.getState());
threadVO.setInterrupted(thread.isInterrupted());
threadVO.setDaemon(thread.isDaemon());
return threadVO;
}
/**
* 获取所有线程List
*
@@ -78,89 +94,6 @@ abstract public class ThreadUtil {
return result;
}
/**
* get the top N busy thread
* @param sampleInterval the interval between two samples
* @param topN the number of thread
* @return a Map representing <ThreadID, cpuUsage>
*/
public static Map<Long, Long> getTopNThreads(int sampleInterval, int topN) {
List<Thread> threads = getThreadList();
// Sample CPU
Map<Long, Long> times1 = new HashMap<Long, Long>();
for (Thread thread : threads) {
long cpu = threadMXBean.getThreadCpuTime(thread.getId());
times1.put(thread.getId(), cpu);
}
try {
// Sleep for some time
Thread.sleep(sampleInterval);
}
catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
// Resample
Map<Long, Long> times2 = new HashMap<Long, Long>(threads.size());
for (Thread thread : threads) {
long cpu = threadMXBean.getThreadCpuTime(thread.getId());
times2.put(thread.getId(), cpu);
}
// Compute delta map and total time
long total = 0;
Map<Long, Long> deltas = new HashMap<Long, Long>(threads.size());
for (Long id : times2.keySet()) {
long time1 = times2.get(id);
long time2 = times1.get(id);
if (time1 == -1) {
time1 = time2;
} else if (time2 == -1) {
time2 = time1;
}
long delta = time2 - time1;
deltas.put(id, delta);
total += delta;
}
// Compute cpu
final HashMap<Thread, Long> cpus = new HashMap<Thread, Long>(threads.size());
for (Thread thread : threads) {
long cpu = total == 0 ? 0 : Math.round((deltas.get(thread.getId()) * 100) / total);
cpus.put(thread, cpu);
}
// Sort by CPU time : should be a rendering hint...
Collections.sort(threads, new Comparator<Thread>() {
public int compare(Thread o1, Thread o2) {
long l1 = cpus.get(o1);
long l2 = cpus.get(o2);
if (l1 < l2) {
return 1;
} else if (l1 > l2) {
return -1;
} else {
return 0;
}
}
});
// use LinkedHashMap to preserve insert order
Map<Long, Long> topNThreads = new LinkedHashMap<Long, Long>();
List<Thread> topThreads = topN > 0 && topN <= threads.size()
? threads.subList(0, topN) : threads;
for (Thread thread: topThreads) {
// Compute cpu usage
topNThreads.put(thread.getId(), cpus.get(thread));
}
return topNThreads;
}
/**
* Find the thread and lock that is blocking the most other threads.
@@ -233,13 +166,12 @@ abstract public class ThreadUtil {
}
public static String getFullStacktrace(ThreadInfo threadInfo, long cpuUsage) {
return getFullStacktrace(threadInfo, cpuUsage, 0, 0);
public static String getFullStacktrace(ThreadInfo threadInfo) {
return getFullStacktrace(threadInfo, -1, -1, -1, 0, 0);
}
public static String getFullStacktrace(BlockingLockInfo blockingLockInfo) {
return getFullStacktrace(blockingLockInfo.getThreadInfo(), -1, blockingLockInfo.getLockIdentityHashCode(),
return getFullStacktrace(blockingLockInfo.getThreadInfo(), -1, -1, -1, blockingLockInfo.getLockIdentityHashCode(),
blockingLockInfo.getBlockingThreadCount());
}
@@ -252,7 +184,7 @@ abstract public class ThreadUtil {
* @param blockingThreadCount 阻塞了其他线程的数量
* @return the string representation of the thread stack
*/
public static String getFullStacktrace(ThreadInfo threadInfo, long cpuUsage, int lockIdentityHashCode,
public static String getFullStacktrace(ThreadInfo threadInfo, double cpuUsage, long deltaTime, long time, int lockIdentityHashCode,
int blockingThreadCount) {
StringBuilder sb = new StringBuilder("\"" + threadInfo.getThreadName() + "\"" + " Id="
+ threadInfo.getThreadId());
@@ -260,6 +192,12 @@ abstract public class ThreadUtil {
if (cpuUsage >= 0 && cpuUsage <= 100) {
sb.append(" cpuUsage=").append(cpuUsage).append("%");
}
if (deltaTime >= 0 ) {
sb.append(" deltaTime=").append(deltaTime).append("ms");
}
if (time >= 0 ) {
sb.append(" time=").append(time).append("ms");
}
sb.append(" ").append(threadInfo.getThreadState());
@@ -334,6 +272,102 @@ abstract public class ThreadUtil {
return sb.toString().replace("\t", " ");
}
public static String getFullStacktrace(BusyThreadInfo threadInfo, int lockIdentityHashCode, int blockingThreadCount) {
StringBuilder sb = new StringBuilder("\"" + threadInfo.getName() + "\"");
if (threadInfo.getId() > 0) {
sb.append(" Id=").append(threadInfo.getId());
} else {
sb.append(" [Internal]");
}
double cpuUsage = threadInfo.getCpu();
if (cpuUsage >= 0 && cpuUsage <= 100) {
sb.append(" cpuUsage=").append(cpuUsage).append("%");
}
if (threadInfo.getDeltaTime() >= 0 ) {
sb.append(" deltaTime=").append(threadInfo.getDeltaTime()).append("ms");
}
if (threadInfo.getTime() >= 0 ) {
sb.append(" time=").append(threadInfo.getTime()).append("ms");
}
if (threadInfo.getState() == null) {
sb.append("\n\n");
return sb.toString();
}
sb.append(" ").append(threadInfo.getState());
if (threadInfo.getLockName() != null) {
sb.append(" on ").append(threadInfo.getLockName());
}
if (threadInfo.getLockOwnerName() != null) {
sb.append(" owned by \"").append(threadInfo.getLockOwnerName()).append("\" Id=").append(threadInfo.getLockOwnerId());
}
if (threadInfo.isSuspended()) {
sb.append(" (suspended)");
}
if (threadInfo.isInNative()) {
sb.append(" (in native)");
}
sb.append('\n');
int i = 0;
for (; i < threadInfo.getStackTrace().length; i++) {
StackTraceElement ste = threadInfo.getStackTrace()[i];
sb.append("\tat ").append(ste.toString());
sb.append('\n');
if (i == 0 && threadInfo.getLockInfo() != null) {
Thread.State ts = threadInfo.getState();
switch (ts) {
case BLOCKED:
sb.append("\t- blocked on ").append(threadInfo.getLockInfo());
sb.append('\n');
break;
case WAITING:
sb.append("\t- waiting on ").append(threadInfo.getLockInfo());
sb.append('\n');
break;
case TIMED_WAITING:
sb.append("\t- waiting on ").append(threadInfo.getLockInfo());
sb.append('\n');
break;
default:
}
}
for (MonitorInfo mi : threadInfo.getLockedMonitors()) {
if (mi.getLockedStackDepth() == i) {
sb.append("\t- locked ").append(mi);
if (mi.getIdentityHashCode() == lockIdentityHashCode) {
Ansi highlighted = Ansi.ansi().fg(Ansi.Color.RED);
highlighted.a(" <---- but blocks ").a(blockingThreadCount).a(" other threads!");
sb.append(highlighted.reset().toString());
}
sb.append('\n');
}
}
}
if (i < threadInfo.getStackTrace().length) {
sb.append("\t...");
sb.append('\n');
}
LockInfo[] locks = threadInfo.getLockedSynchronizers();
if (locks.length > 0) {
sb.append("\n\tNumber of locked synchronizers = ").append(locks.length);
sb.append('\n');
for (LockInfo li : locks) {
sb.append("\t- ").append(li);
if (li.getIdentityHashCode() == lockIdentityHashCode) {
sb.append(" <---- but blocks ").append(blockingThreadCount);
sb.append(" other threads!");
}
sb.append('\n');
}
}
sb.append('\n');
return sb.toString().replace("\t", " ");
}
/**
* </pre>
* java.lang.Thread.getStackTrace(Thread.java:1559),
Binary file not shown.

Before

Width:  |  Height:  |  Size: 976 KiB

After

Width:  |  Height:  |  Size: 791 KiB

+49 -37
View File
@@ -18,53 +18,65 @@ dashboard
```
$ dashboard
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
889 RMI TCP Connection(15)-30.10.166. RMI Runtime 9 RUNNABLE 48 0:5 false true
1077 Timer-for-arthas-dashboard-0 system 9 RUNNABLE 24 0:0 false true
1074 as-selector-daemon system 9 RUNNABLE 12 0:0 false true
284 JMX server connection timeout 284 RMI Runtime 9 TIMED_WAITI 8 0:3 false true
16 Timer-1 main 5 TIMED_WAITI 5 0:9 false true
47 Pandora pandora-qos-reporter Pool main 5 TIMED_WAITI 0 0:0 false true
48 JmonitorClient-CheckThread Pool [ main 5 TIMED_WAITI 0 0:0 false true
49 JmonitorClient-HeartBeat Pool [Th main 5 TIMED_WAITI 0 0:0 false true
50 JmonitorClient-ReaderThread Pool main 5 TIMED_WAITI 0 0:0 false true
957 RMI TCP Connection(16)-30.10.166. RMI Runtime 9 RUNNABLE 0 0:2 false true
51 JmonitorClient-WriterThread Pool main 5 TIMED_WAITI 0 0:0 false true
52 ContainerBackgroundProcessor[Stan main 5 TIMED_WAITI 0 0:0 false true
53 http-bio-8080-Acceptor-0 main 5 RUNNABLE 0 0:2 false true
54 http-bio-8080-AsyncTimeout main 5 TIMED_WAITI 0 0:0 false true
11 GC Daemon system 2 TIMED_WAITI 0 0:0 false true
Memory used total max usage GC
heap 59M 223M 1820M 3.26% gc.ps_scavenge.count 118
ps_eden_space 14M 114M 668M 2.11% gc.ps_scavenge.time(ms) 1890
ps_survivor_space 6M 6M 6M 96.08% gc.ps_marksweep.count 5
ps_old_gen 39M 103M 1365M 2.86% gc.ps_marksweep.time(ms) 1140
nonheap 234M 240M 0M 97.46%
code_cache 46M 47M 240M 19.49%
metaspace 167M 172M 0M 97.36%
Runtime Tomcat
os.name Mac OS X connector http-bio-8080
os.version 10.10.5 QPS 0.00
java.version 1.8.0_60 RT(ms) 1.13
java.home error/s 0.00
received/s 0B
systemload.average 3.44 sent/s 0B
processors 4 threadpool http-bio-8080
uptime 16020s busy 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
-1 C2 CompilerThread0 - -1 - 1.55 0.077 0:8.684 false true
53 Timer-for-arthas-dashboard-07b system 5 RUNNABLE 0.08 0.004 0:0.004 false true
22 scheduling-1 main 5 TIMED_WAI 0.06 0.003 0:0.287 false false
-1 C1 CompilerThread0 - -1 - 0.06 0.003 0:2.171 false true
-1 VM Periodic Task Thread - -1 - 0.03 0.001 0:0.092 false true
49 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.02 0.001 0:0.156 false true
16 Catalina-utility-1 main 1 TIMED_WAI 0.0 0.000 0:0.029 false false
-1 G1 Young RemSet Sampling - -1 - 0.0 0.000 0:0.019 false true
17 Catalina-utility-2 main 1 WAITING 0.0 0.000 0:0.025 false false
34 http-nio-8080-ClientPoller main 5 RUNNABLE 0.0 0.000 0:0.016 false true
23 http-nio-8080-BlockPoller main 5 RUNNABLE 0.0 0.000 0:0.011 false true
-1 VM Thread - -1 - 0.0 0.000 0:0.032 false true
-1 Service Thread - -1 - 0.0 0.000 0:0.006 false true
-1 GC Thread#5 - -1 - 0.0 0.000 0:0.043 false true
Memory used total max usage GC
heap 36M 70M 4096M 0.90% gc.g1_young_generation.count 12
g1_eden_space 6M 18M -1 33.33% 86
g1_old_gen 30M 50M 4096M 0.74% gc.g1_old_generation.count 0
g1_survivor_space 491K 2048K -1 24.01% gc.g1_old_generation.time(ms) 0
nonheap 66M 69M -1 96.56%
codeheap_'non-nmethods' 1M 2M 5M 22.39%
metaspace 46M 47M -1 98.01%
Runtime
os.name Mac OS X
os.version 10.15.4
java.version 15
java.home /Library/Java/JavaVirtualMachines/jdk-15.jdk/Contents/Home
systemload.average 10.68
processors 8
uptime 272s
```
### 数据说明
* ID: Java级别的线程ID,注意这个ID不能跟jstack中的nativeID一一对应
* ID: Java级别的线程ID,注意这个ID不能跟jstack中的nativeID一一对应
* NAME: 线程名
* GROUP: 线程组名
* PRIORITY: 线程优先级, 1~10之间的数字,越大表示优先级越高
* STATE: 线程的状态
* CPU%: 线程消耗的cpu占比,采样100ms,将所有线程在这100ms内的cpu使用量求和,再算出每个线程的cpu使用占比。
* TIME: 线程运行总时间,数据格式为`分:秒`
* CPU%: 线程的cpu使用率。比如采样间隔1000ms,某个线程的增量cpu时间为100ms,则cpu使用率=100/1000=10%
* DELTA_TIME: 上次采样之后线程运行增量CPU时间,数据格式为`秒`
* TIME: 线程运行总CPU时间,数据格式为`分:秒`
* INTERRUPTED: 线程当前的中断位状态
* DAEMON: 是否是daemon线程
#### JVM内部线程
Java 8之后支持获取JVM内部线程CPU时间,这些线程只有名称和CPU时间,没有ID及状态等信息(显示ID为-1)。
通过内部线程可以观测到JVM活动,如GC、JIT编译等占用CPU情况,方便了解JVM整体运行状况。
* 当JVM 堆(heap)/元数据(metaspace)空间不足或OOM时,可以看到GC线程的CPU占用率明显高于其他的线程。
* 当执行`trace/watch/tt/redefine`等命令后,可以看到JIT线程活动变得更频繁。因为JVM热更新class字节码时清除了此class相关的JIT编译结果,需要重新编译。
JVM内部线程包括下面几种:
* JIT编译线程: 如 `C1 CompilerThread0`, `C2 CompilerThread0`
* GC线程: 如`GC Thread0`, `G1 Young RemSet Sampling`
* 其它内部线程: 如`VM Periodic Task Thread`, `VM Thread`, `Service Thread`
### 截图展示
![](_static/dashboard.png "dashboard")
![](_static/dashboard.png "dashboard")
+53 -35
View File
@@ -18,39 +18,37 @@ When running in Apache Tomcat Alibaba edition, the dashboard will also present t
```
$ dashboard
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
889 RMI TCP Connection(15)-30.10.166. RMI Runtime 9 RUNNABLE 48 0:5 false true
1077 Timer-for-arthas-dashboard-0 system 9 RUNNABLE 24 0:0 false true
1074 as-selector-daemon system 9 RUNNABLE 12 0:0 false true
284 JMX server connection timeout 284 RMI Runtime 9 TIMED_WAITI 8 0:3 false true
16 Timer-1 main 5 TIMED_WAITI 5 0:9 false true
47 Pandora pandora-qos-reporter Pool main 5 TIMED_WAITI 0 0:0 false true
48 JmonitorClient-CheckThread Pool [ main 5 TIMED_WAITI 0 0:0 false true
49 JmonitorClient-HeartBeat Pool [Th main 5 TIMED_WAITI 0 0:0 false true
50 JmonitorClient-ReaderThread Pool main 5 TIMED_WAITI 0 0:0 false true
957 RMI TCP Connection(16)-30.10.166. RMI Runtime 9 RUNNABLE 0 0:2 false true
51 JmonitorClient-WriterThread Pool main 5 TIMED_WAITI 0 0:0 false true
52 ContainerBackgroundProcessor[Stan main 5 TIMED_WAITI 0 0:0 false true
53 http-bio-8080-Acceptor-0 main 5 RUNNABLE 0 0:2 false true
54 http-bio-8080-AsyncTimeout main 5 TIMED_WAITI 0 0:0 false true
11 GC Daemon system 2 TIMED_WAITI 0 0:0 false true
Memory used total max usage GC
heap 59M 223M 1820M 3.26% gc.ps_scavenge.count 118
ps_eden_space 14M 114M 668M 2.11% gc.ps_scavenge.time(ms) 1890
ps_survivor_space 6M 6M 6M 96.08% gc.ps_marksweep.count 5
ps_old_gen 39M 103M 1365M 2.86% gc.ps_marksweep.time(ms) 1140
nonheap 234M 240M 0M 97.46%
code_cache 46M 47M 240M 19.49%
metaspace 167M 172M 0M 97.36%
Runtime Tomcat
os.name Mac OS X connector http-bio-8080
os.version 10.10.5 QPS 0.00
java.version 1.8.0_60 RT(ms) 1.13
java.home error/s 0.00
received/s 0B
systemload.average 3.44 sent/s 0B
processors 4 threadpool http-bio-8080
uptime 16020s busy 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
-1 C2 CompilerThread0 - -1 - 1.55 0.077 0:8.684 false true
53 Timer-for-arthas-dashboard-07b system 5 RUNNABLE 0.08 0.004 0:0.004 false true
22 scheduling-1 main 5 TIMED_WAI 0.06 0.003 0:0.287 false false
-1 C1 CompilerThread0 - -1 - 0.06 0.003 0:2.171 false true
-1 VM Periodic Task Thread - -1 - 0.03 0.001 0:0.092 false true
49 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.02 0.001 0:0.156 false true
16 Catalina-utility-1 main 1 TIMED_WAI 0.0 0.000 0:0.029 false false
-1 G1 Young RemSet Sampling - -1 - 0.0 0.000 0:0.019 false true
17 Catalina-utility-2 main 1 WAITING 0.0 0.000 0:0.025 false false
34 http-nio-8080-ClientPoller main 5 RUNNABLE 0.0 0.000 0:0.016 false true
23 http-nio-8080-BlockPoller main 5 RUNNABLE 0.0 0.000 0:0.011 false true
-1 VM Thread - -1 - 0.0 0.000 0:0.032 false true
-1 Service Thread - -1 - 0.0 0.000 0:0.006 false true
-1 GC Thread#5 - -1 - 0.0 0.000 0:0.043 false true
Memory used total max usage GC
heap 36M 70M 4096M 0.90% gc.g1_young_generation.count 12
g1_eden_space 6M 18M -1 33.33% 86
g1_old_gen 30M 50M 4096M 0.74% gc.g1_old_generation.count 0
g1_survivor_space 491K 2048K -1 24.01% gc.g1_old_generation.time(ms) 0
nonheap 66M 69M -1 96.56%
codeheap_'non-nmethods' 1M 2M 5M 22.39%
metaspace 46M 47M -1 98.01%
Runtime
os.name Mac OS X
os.version 10.15.4
java.version 15
java.home /Library/Java/JavaVirtualMachines/jdk-15.jdk/Contents/Home
systemload.average 10.68
processors 8
uptime 272s
```
### Notes on column headers
@@ -60,11 +58,31 @@ uptime 16020s busy
* GROUP: thread group name
* PRIORITY: thread priority, ranged from 1 to 10. The greater number, the higher priority
* STATE: thread state
* CPU%: the ratio of CPU usage for the thread, sampled every 100ms
* TIME: total running time in `minute:second` format
* CPU%: the ratio of CPU usage for the thread. For example, the sampling interval is 1000ms, and the incremental cpu time
of a thread is 100ms, then the cpu usage rate=100/1000=10%
* DELTA_TIME: incremental CPU time of thread running after the last sampling in `second` format
* TIME: total CPU time of the thread in `minute:second` format
* INTERRUPTED: the thread interruption state
* DAEMON: daemon thread or not
#### JVM internal threads
After Java 8, it is supported to obtain the CPU time of JVM internal threads. These threads only have the name and CPU time,
without ID and status information (display ID is -1).
JVM activities can be observed through internal threads, such as GC, JIT compilation, etc., to perceive the overall status of JVM.
* When the JVM heap/metaspace space is insufficient or OOM, it can be seen that the CPU usage of the GC threads is
significantly higher than other threads.
* After executing commands such as `trace/watch/tt/redefine`, you can see that JIT threads activities become more frequent.
Because the JIT compilation data related to this class is cleared when the JVM hot update the class bytecode, it needs to be recompiled.
JVM internal threads include the following:
* JIT compilation thread: such as `C1 CompilerThread0`, `C2 CompilerThread0`
* GC thread: such as `GC Thread0`, `G1 Young RemSet Sampling`
* Other internal threads: such as`VM Periodic Task Thread`, `VM Thread`, `Service Thread`
### Screenshot
![](../_static/dashboard.png "dashboard")
+80 -53
View File
@@ -13,11 +13,23 @@ thread
|`[n:]`|the top n busiest threads with stack traces printed|
|`[b]`|locate the thread blocking the others|
|[i `<value>`]|specify the interval to collect data to compute CPU ratios (ms)|
|[--all]|Show all matching threads|
> How the CPU ratios are calculated? <br/><br/>
> CPU ratio for a given thread is the CPU time it takes divided by the total CPU time within a specified interval period. It is calculated in the following way: sample CPU times for all the thread by calling `java.lang.management.ThreadMXBean#getThreadCpuTime` first, then sleep for a period (the default value is 100ms, which can be specified by `-i`), then sample CPU times again. By this, we can get the time cost for this period for each thread, then come up with the ratio. <br/><br/>
> Note: this operation consumes CPU time too (`getThreadCpuTime` is time-consuming), therefore it is possible to observe Arthas's thread appears in the list. To avoid this, try to increase sample interval, for example: 5000 ms.<br/><br/>
> If you'd like to check the CPU ratios from the very beginning of the Java process, [show-busy-java-threads](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads) can come to help.
### How the CPU ratios are calculated?
The cpu ratios here is similar to the thread `%CPU` of the linux command `top -H -p <pid>`. During a sampling interval,
the ratio of the incremental cpu time of each thread in the current JVM to the sampling interval time.
> Working principle description:
* Do the first sampling, get the CPU time of all threads ( by calling `java.lang.management.ThreadMXBean#getThreadCpuTime()` and
`sun.management.HotspotThreadMBean.getInternalThreadCpuTimes()` )
* Sleep and wait for an interval (the default is 200ms, the interval can be specified by `-i`)
* Do the second sampling, get the CPU time of all threads, compare the two sampling data, and calculate the incremental CPU time of each thread
* `Thread CPU usage ratio` = `Thread increment CPU time` / `Sampling interval time` * 100%
> Note: this operation consumes CPU time too (`getThreadCpuTime` is time-consuming), therefore it is possible to observe Arthas's thread appears in the list. To avoid this, try to increase sample interval, for example: 5000 ms.<br/>
> Another way to view the thread cpu usage of the Java process, [show-busy-java-threads](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads) can come to help.
### Usage
@@ -25,59 +37,72 @@ thread
```shell
$ thread -n 3
"as-command-execute-daemon" Id=29 cpuUsage=75% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
at com.taobao.arthas.core.command.monitor200.ThreadCommand$1.action(ThreadCommand.java:58)
at com.taobao.arthas.core.command.handler.AbstractCommandHandler.execute(AbstractCommandHandler.java:238)
at com.taobao.arthas.core.command.handler.DefaultCommandHandler.handleCommand(DefaultCommandHandler.java:67)
at com.taobao.arthas.core.server.ArthasServer$4.run(ArthasServer.java:276)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@6cd0b6f8
"C1 CompilerThread0" [Internal] cpuUsage=1.63% deltaTime=3ms time=1170ms
"as-session-expire-daemon" Id=25 cpuUsage=24% TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at com.taobao.arthas.core.server.DefaultSessionManager$2.run(DefaultSessionManager.java:85)
"arthas-command-execute" Id=23 cpuUsage=0.11% deltaTime=0ms time=401ms RUNNABLE
at java.management@11.0.7/sun.management.ThreadImpl.dumpThreads0(Native Method)
at java.management@11.0.7/sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:466)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:199)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
at java.base@11.0.7/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base@11.0.7/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base@11.0.7/java.lang.Thread.run(Thread.java:834)
"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
"VM Periodic Task Thread" [Internal] cpuUsage=0.07% deltaTime=0ms time=584ms
```
#### List all threads' info when no options provided
* Without thread ID, including `[Internal]` means JVM internal thread, refer to the introduction of [dashboard](dashboard.md) command.
* `cpuUsage` is the CPU usage of the thread during the sampling interval, consistent with the data of the [dashboard](dashboard.md) command.
* `deltaTime` is the incremental CPU time of the thread during the sampling interval. If it is less than 1ms, it will be rounded and displayed as 0ms.
* `time` The total CPU time of thread.
**Note:** The thread stack is acquired at the end of the second sampling, which does not indicate that the thread is
processing the same task during the sampling interval. It is recommended that the interval time should not be too long.
The larger the interval time, the more inaccurate.
You can try to specify different intervals according to the specific situation and observe the output results.
#### List first page threads' info when no options provided
By default, they are arranged in descending order of CPU increment time, and only the first page of data is displayed.
```shell
$ thread
Threads Total: 16, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
30 as-command-execute-daemon system 9 RUNNABLE 72 0:0 false true
23 as-session-expire-daemon system 9 TIMED_WAIT 27 0:0 false true
22 Attach Listener system 9 RUNNABLE 0 0:0 false true
11 pool-2-thread-1 main 5 TIMED_WAIT 0 0:0 false false
12 Thread-2 main 5 RUNNABLE 0 0:0 false true
13 pool-3-thread-1 main 5 TIMED_WAIT 0 0:0 false false
25 as-selector-daemon system 9 RUNNABLE 0 0:0 false true
14 Thread-3 main 5 TIMED_WAIT 0 0:0 false false
26 pool-5-thread-1 system 5 WAITING 0 0:0 false false
15 Thread-4 main 5 RUNNABLE 0 0:0 false false
1 main main 5 WAITING 0 0:2 false false
2 Reference Handler system 10 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
4 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
20 NonBlockingInputStreamThread main 5 WAITING 0 0:0 false true
21 Thread-8 main 5 RUNNABLE 0 0:0 false true
Threads Total: 33, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0, Internal threads: 17
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON
-1 C2 CompilerThread0 - -1 - 5.06 0.010 0:0.973 false true
-1 C1 CompilerThread0 - -1 - 0.95 0.001 0:0.603 false true
23 arthas-command-execute system 5 RUNNABLE 0.17 0.000 0:0.226 false true
-1 VM Periodic Task Thread - -1 - 0.05 0.000 0:0.094 false true
-1 Sweeper thread - -1 - 0.04 0.000 0:0.011 false true
-1 G1 Young RemSet Sampling - -1 - 0.02 0.000 0:0.025 false true
12 Attach Listener system 9 RUNNABLE 0.0 0.000 0:0.022 false true
11 Common-Cleaner InnocuousThrea 8 TIMED_WAI 0.0 0.000 0:0.000 false true
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
2 Reference Handler system 10 RUNNABLE 0.0 0.000 0:0.000 false true
4 Signal Dispatcher system 9 RUNNABLE 0.0 0.000 0:0.000 false true
15 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.029 false true
22 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.196 false true
24 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.038 false true
16 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
17 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
```
#### thread --all, show all matching threads
Display all matching threads. Sometimes it is necessary to obtain all the thread data of the JVM for analysis.
#### thread id, show the running stack for the target thread
```shell
@@ -140,6 +165,10 @@ $ thread -b
#### thread -i, specify the sampling interval
* `thread -i 1000`: Count the thread cpu time of the last 1000ms.
* `thread -n 3 -i 1000`: List the 3 busiest thread stacks in 1000ms
```bash
$ thread -n 3 -i 1000
"as-command-execute-daemon" Id=4759 cpuUsage=23% RUNNABLE
@@ -165,11 +194,9 @@ $ thread -n 3 -i 1000
```bash
[arthas@28114]$ thread --state WAITING
Threads Total: 15, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 3, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRU DAEMON
198 AsyncAppender-Worker-arth system 9 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
14 RMI Scheduler(0) system 9 WAITING 0 0:0 false true
2 Reference Handler system 10 WAITING 0 0:0 false true
204 pool-8-thread-1 system 5 WAITING 0 0:0 false false
Threads Total: 16, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
20 arthas-UserStat system 9 WAITING 0.0 0.000 0:0.001 false true
14 arthas-timer system 9 WAITING 0.0 0.000 0:0.000 false true
```
+74 -55
View File
@@ -13,16 +13,23 @@ thread
|*id*|线程id|
|[n:]|指定最忙的前N个线程并打印堆栈|
|[b]|找出当前阻塞其他线程的线程|
|[i `<value>`]|指定cpu占比统计的采样间隔,单位为毫秒|
|[i `<value>`]|指定cpu使用率统计的采样间隔,单位为毫秒,默认值为200|
|[--all]|显示所有匹配的线程|
> cpu占比是如何统计出来的?
### cpu使用率是如何统计出来的?
> 这里的cpu统计的是,一段采样间隔内,当前JVM里各个线程所占用的cpu时间占总cpu时间的百分比。其计算方法为:
> 首先进行一次采样,获得所有线程的cpu的使用时间(调用的是`java.lang.management.ThreadMXBean#getThreadCpuTime`这个接口),然后睡眠一段时间,默认100ms,可以通过`-i`参数指定,然后再采样一次,最后得出这段时间内各个线程消耗的cpu时间情况,最后算出百分比。
这里的cpu使用率与linux 命令`top -H -p <pid>` 的线程`%CPU`类似,一段采样间隔时间内,当前JVM里各个线程的增量cpu时间与采样间隔时间的比例。
#### 工作原理说明:
* 首先第一次采样,获取所有线程的CPU时间(调用的是`java.lang.management.ThreadMXBean#getThreadCpuTime()``sun.management.HotspotThreadMBean.getInternalThreadCpuTimes()`接口)
* 然后睡眠等待一个间隔时间(默认为200ms,可以通过`-i`指定间隔时间)
* 再次第二次采样,获取所有线程的CPU时间,对比两次采样数据,计算出每个线程的增量CPU时间
* 线程CPU使用率 = 线程增量CPU时间 / 采样间隔时间 * 100%
> 注意: 这个统计也会产生一定的开销(JDK这个接口本身开销比较大),因此会看到as的线程占用一定的百分比,为了降低统计自身的开销带来的影响,可以把采样间隔拉长一些,比如5000毫秒。
> 如果想看从Java进程启动开始到现在的cpu占比情况:可以使用[show-busy-java-threads](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads)这个脚本
> 另外一种查看Java进程的线程cpu使用率方法:可以使用[show-busy-java-threads](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads)这个脚本
### 使用参考
@@ -30,60 +37,70 @@ thread
```shell
$ thread -n 3
"as-command-execute-daemon" Id=29 cpuUsage=75% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
at com.taobao.arthas.core.command.monitor200.ThreadCommand$1.action(ThreadCommand.java:58)
at com.taobao.arthas.core.command.handler.AbstractCommandHandler.execute(AbstractCommandHandler.java:238)
at com.taobao.arthas.core.command.handler.DefaultCommandHandler.handleCommand(DefaultCommandHandler.java:67)
at com.taobao.arthas.core.server.ArthasServer$4.run(ArthasServer.java:276)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@6cd0b6f8
"C1 CompilerThread0" [Internal] cpuUsage=1.63% deltaTime=3ms time=1170ms
"as-session-expire-daemon" Id=25 cpuUsage=24% TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at com.taobao.arthas.core.server.DefaultSessionManager$2.run(DefaultSessionManager.java:85)
"arthas-command-execute" Id=23 cpuUsage=0.11% deltaTime=0ms time=401ms RUNNABLE
at java.management@11.0.7/sun.management.ThreadImpl.dumpThreads0(Native Method)
at java.management@11.0.7/sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:466)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:199)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
at java.base@11.0.7/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base@11.0.7/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base@11.0.7/java.lang.Thread.run(Thread.java:834)
"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
"VM Periodic Task Thread" [Internal] cpuUsage=0.07% deltaTime=0ms time=584ms
```
#### 当没有参数时,显示所有线程的信息
* 没有线程ID,包含`[Internal]`表示为JVM内部线程,参考[dashboard](dashboard.md)命令的介绍
* `cpuUsage`为采样间隔时间内线程的CPU使用率,与[dashboard](dashboard.md)命令的数据一致。
* `deltaTime`为采样间隔时间内线程的增量CPU时间,小于1ms时被取整显示为0ms。
* `time` 线程运行总CPU时间。
注意:线程栈为第二采样结束时获取,不能表明采样间隔时间内该线程都是在处理相同的任务。建议间隔时间不要太长,可能间隔时间越大越不准确。
可以根据具体情况尝试指定不同的间隔时间,观察输出结果。
#### 当没有参数时,显示第一页线程的信息
默认按照CPU增量时间降序排列,只显示第一页数据。
```shell
$ thread
Threads Total: 16, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
30 as-command-execute-daemon system 9 RUNNABLE 72 0:0 false true
23 as-session-expire-daemon system 9 TIMED_WAIT 27 0:0 false true
22 Attach Listener system 9 RUNNABLE 0 0:0 false true
11 pool-2-thread-1 main 5 TIMED_WAIT 0 0:0 false false
12 Thread-2 main 5 RUNNABLE 0 0:0 false true
13 pool-3-thread-1 main 5 TIMED_WAIT 0 0:0 false false
25 as-selector-daemon system 9 RUNNABLE 0 0:0 false true
14 Thread-3 main 5 TIMED_WAIT 0 0:0 false false
26 pool-5-thread-1 system 5 WAITING 0 0:0 false false
15 Thread-4 main 5 RUNNABLE 0 0:0 false false
1 main main 5 WAITING 0 0:2 false false
2 Reference Handler system 10 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
4 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
20 NonBlockingInputStreamThread main 5 WAITING 0 0:0 false true
21 Thread-8 main 5 RUNNABLE 0 0:0 false true
Threads Total: 33, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0, Internal threads: 17
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON
-1 C2 CompilerThread0 - -1 - 5.06 0.010 0:0.973 false true
-1 C1 CompilerThread0 - -1 - 0.95 0.001 0:0.603 false true
23 arthas-command-execute system 5 RUNNABLE 0.17 0.000 0:0.226 false true
-1 VM Periodic Task Thread - -1 - 0.05 0.000 0:0.094 false true
-1 Sweeper thread - -1 - 0.04 0.000 0:0.011 false true
-1 G1 Young RemSet Sampling - -1 - 0.02 0.000 0:0.025 false true
12 Attach Listener system 9 RUNNABLE 0.0 0.000 0:0.022 false true
11 Common-Cleaner InnocuousThrea 8 TIMED_WAI 0.0 0.000 0:0.000 false true
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
2 Reference Handler system 10 RUNNABLE 0.0 0.000 0:0.000 false true
4 Signal Dispatcher system 9 RUNNABLE 0.0 0.000 0:0.000 false true
15 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.029 false true
22 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.196 false true
24 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.038 false true
16 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
17 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
```
#### thread id 显示指定线程的运行堆栈
#### thread --all, 显示所有匹配的线程
显示所有匹配线程信息,有时需要获取全部JVM的线程数据进行分析。
#### thread id, 显示指定线程的运行堆栈
```shell
$ thread 1
@@ -145,6 +162,10 @@ $ thread -b
#### thread -i, 指定采样时间间隔
* `thread -i 1000` : 统计最近1000ms内的线程CPU时间。
* `thread -n 3 -i 1000` : 列出1000ms内最忙的3个线程栈
```bash
$ thread -n 3 -i 1000
"as-command-execute-daemon" Id=4759 cpuUsage=23% RUNNABLE
@@ -170,11 +191,9 @@ $ thread -n 3 -i 1000
```bash
[arthas@28114]$ thread --state WAITING
Threads Total: 15, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 3, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRU DAEMON
198 AsyncAppender-Worker-arth system 9 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
14 RMI Scheduler(0) system 9 WAITING 0 0:0 false true
2 Reference Handler system 10 WAITING 0 0:0 false true
204 pool-8-thread-1 system 5 WAITING 0 0:0 false false
Threads Total: 16, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
20 arthas-UserStat system 9 WAITING 0.0 0.000 0:0.001 false true
14 arthas-timer system 9 WAITING 0.0 0.000 0:0.000 false true
```
@@ -4,41 +4,67 @@
当运行在Ali-tomcat时,会显示当前tomcat的实时信息,如HTTP请求的qps, rt, 错误数, 线程池信息等等。
```bash
```
$ dashboard
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
889 RMI TCP Connection(15)-30.10.166. RMI Runtime 9 RUNNABLE 48 0:5 false true
1077 Timer-for-arthas-dashboard-0 system 9 RUNNABLE 24 0:0 false true
1074 as-selector-daemon system 9 RUNNABLE 12 0:0 false true
284 JMX server connection timeout 284 RMI Runtime 9 TIMED_WAITI 8 0:3 false true
16 Timer-1 main 5 TIMED_WAITI 5 0:9 false true
47 Pandora pandora-qos-reporter Pool main 5 TIMED_WAITI 0 0:0 false true
48 JmonitorClient-CheckThread Pool [ main 5 TIMED_WAITI 0 0:0 false true
49 JmonitorClient-HeartBeat Pool [Th main 5 TIMED_WAITI 0 0:0 false true
50 JmonitorClient-ReaderThread Pool main 5 TIMED_WAITI 0 0:0 false true
957 RMI TCP Connection(16)-30.10.166. RMI Runtime 9 RUNNABLE 0 0:2 false true
51 JmonitorClient-WriterThread Pool main 5 TIMED_WAITI 0 0:0 false true
52 ContainerBackgroundProcessor[Stan main 5 TIMED_WAITI 0 0:0 false true
53 http-bio-8080-Acceptor-0 main 5 RUNNABLE 0 0:2 false true
54 http-bio-8080-AsyncTimeout main 5 TIMED_WAITI 0 0:0 false true
11 GC Daemon system 2 TIMED_WAITI 0 0:0 false true
Memory used total max usage GC
heap 59M 223M 1820M 3.26% gc.ps_scavenge.count 118
ps_eden_space 14M 114M 668M 2.11% gc.ps_scavenge.time(ms) 1890
ps_survivor_space 6M 6M 6M 96.08% gc.ps_marksweep.count 5
ps_old_gen 39M 103M 1365M 2.86% gc.ps_marksweep.time(ms) 1140
nonheap 234M 240M 0M 97.46%
code_cache 46M 47M 240M 19.49%
metaspace 167M 172M 0M 97.36%
Runtime Tomcat
os.name Mac OS X connector http-bio-8080
os.version 10.10.5 QPS 0.00
java.version 1.8.0_60 RT(ms) 1.13
java.home error/s 0.00
received/s 0B
systemload.average 3.44 sent/s 0B
processors 4 threadpool http-bio-8080
uptime 16020s busy 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
-1 C2 CompilerThread0 - -1 - 1.55 0.077 0:8.684 false true
53 Timer-for-arthas-dashboard-07b system 5 RUNNABLE 0.08 0.004 0:0.004 false true
22 scheduling-1 main 5 TIMED_WAI 0.06 0.003 0:0.287 false false
-1 C1 CompilerThread0 - -1 - 0.06 0.003 0:2.171 false true
-1 VM Periodic Task Thread - -1 - 0.03 0.001 0:0.092 false true
49 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.02 0.001 0:0.156 false true
16 Catalina-utility-1 main 1 TIMED_WAI 0.0 0.000 0:0.029 false false
-1 G1 Young RemSet Sampling - -1 - 0.0 0.000 0:0.019 false true
17 Catalina-utility-2 main 1 WAITING 0.0 0.000 0:0.025 false false
34 http-nio-8080-ClientPoller main 5 RUNNABLE 0.0 0.000 0:0.016 false true
23 http-nio-8080-BlockPoller main 5 RUNNABLE 0.0 0.000 0:0.011 false true
-1 VM Thread - -1 - 0.0 0.000 0:0.032 false true
-1 Service Thread - -1 - 0.0 0.000 0:0.006 false true
-1 GC Thread#5 - -1 - 0.0 0.000 0:0.043 false true
Memory used total max usage GC
heap 36M 70M 4096M 0.90% gc.g1_young_generation.count 12
g1_eden_space 6M 18M -1 33.33% 86
g1_old_gen 30M 50M 4096M 0.74% gc.g1_old_generation.count 0
g1_survivor_space 491K 2048K -1 24.01% gc.g1_old_generation.time(ms) 0
nonheap 66M 69M -1 96.56%
codeheap_'non-nmethods' 1M 2M 5M 22.39%
metaspace 46M 47M -1 98.01%
Runtime
os.name Mac OS X
os.version 10.15.4
java.version 15
java.home /Library/Java/JavaVirtualMachines/jdk-15.jdk/Contents/Home
systemload.average 10.68
processors 8
uptime 272s
```
输入 `Q`{{execute T2}} 或者 `Ctrl+C` 可以退出dashboard命令。
### 数据说明
* ID: Java级别的线程ID,注意这个ID不能跟jstack中的nativeID一一对应。
* NAME: 线程名
* GROUP: 线程组名
* PRIORITY: 线程优先级, 1~10之间的数字,越大表示优先级越高
* STATE: 线程的状态
* CPU%: 线程的cpu使用率。比如采样间隔1000ms,某个线程的增量cpu时间为100ms,则cpu使用率=100/1000=10%
* DELTA_TIME: 上次采样之后线程运行增量CPU时间,数据格式为`秒`
* TIME: 线程运行总CPU时间,数据格式为`分:秒`
* INTERRUPTED: 线程当前的中断位状态
* DAEMON: 是否是daemon线程
#### JVM内部线程
Java 8之后支持获取JVM内部线程CPU时间,这些线程只有名称和CPU时间,没有ID及状态等信息(显示ID为-1)。
通过内部线程可以观测到JVM活动,如GC、JIT编译等占用CPU情况,方便了解JVM整体运行状况。
* 当JVM 堆(heap)/元数据(metaspace)空间不足或OOM时,可以看到GC线程的CPU占用率明显高于其他的线程。
* 当执行`trace/watch/tt/redefine`等命令后,可以看到JIT线程活动变得更频繁。因为JVM热更新class字节码时清除了此class相关的JIT编译结果,需要重新编译。
JVM内部线程包括下面几种:
* JIT编译线程: 如 `C1 CompilerThread0`, `C2 CompilerThread0`
* GC线程: 如`GC Thread0`, `G1 Young RemSet Sampling`
* 其它内部线程: 如`VM Periodic Task Thread`, `VM Thread`, `Service Thread`
@@ -4,41 +4,71 @@ The `dashboard`{{execute T2}} command allows you to view the real-time data pane
When running in Apache Tomcat Alibaba edition, the dashboard will also present the real time statistics of the tomcat, including [QPS](https://en.wikipedia.org/wiki/Queries_per_second), RT, error counts, and thread pool, etc.
```bash
```
$ dashboard
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
889 RMI TCP Connection(15)-30.10.166. RMI Runtime 9 RUNNABLE 48 0:5 false true
1077 Timer-for-arthas-dashboard-0 system 9 RUNNABLE 24 0:0 false true
1074 as-selector-daemon system 9 RUNNABLE 12 0:0 false true
284 JMX server connection timeout 284 RMI Runtime 9 TIMED_WAITI 8 0:3 false true
16 Timer-1 main 5 TIMED_WAITI 5 0:9 false true
47 Pandora pandora-qos-reporter Pool main 5 TIMED_WAITI 0 0:0 false true
48 JmonitorClient-CheckThread Pool [ main 5 TIMED_WAITI 0 0:0 false true
49 JmonitorClient-HeartBeat Pool [Th main 5 TIMED_WAITI 0 0:0 false true
50 JmonitorClient-ReaderThread Pool main 5 TIMED_WAITI 0 0:0 false true
957 RMI TCP Connection(16)-30.10.166. RMI Runtime 9 RUNNABLE 0 0:2 false true
51 JmonitorClient-WriterThread Pool main 5 TIMED_WAITI 0 0:0 false true
52 ContainerBackgroundProcessor[Stan main 5 TIMED_WAITI 0 0:0 false true
53 http-bio-8080-Acceptor-0 main 5 RUNNABLE 0 0:2 false true
54 http-bio-8080-AsyncTimeout main 5 TIMED_WAITI 0 0:0 false true
11 GC Daemon system 2 TIMED_WAITI 0 0:0 false true
Memory used total max usage GC
heap 59M 223M 1820M 3.26% gc.ps_scavenge.count 118
ps_eden_space 14M 114M 668M 2.11% gc.ps_scavenge.time(ms) 1890
ps_survivor_space 6M 6M 6M 96.08% gc.ps_marksweep.count 5
ps_old_gen 39M 103M 1365M 2.86% gc.ps_marksweep.time(ms) 1140
nonheap 234M 240M 0M 97.46%
code_cache 46M 47M 240M 19.49%
metaspace 167M 172M 0M 97.36%
Runtime Tomcat
os.name Mac OS X connector http-bio-8080
os.version 10.10.5 QPS 0.00
java.version 1.8.0_60 RT(ms) 1.13
java.home error/s 0.00
received/s 0B
systemload.average 3.44 sent/s 0B
processors 4 threadpool http-bio-8080
uptime 16020s busy 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
-1 C2 CompilerThread0 - -1 - 1.55 0.077 0:8.684 false true
53 Timer-for-arthas-dashboard-07b system 5 RUNNABLE 0.08 0.004 0:0.004 false true
22 scheduling-1 main 5 TIMED_WAI 0.06 0.003 0:0.287 false false
-1 C1 CompilerThread0 - -1 - 0.06 0.003 0:2.171 false true
-1 VM Periodic Task Thread - -1 - 0.03 0.001 0:0.092 false true
49 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.02 0.001 0:0.156 false true
16 Catalina-utility-1 main 1 TIMED_WAI 0.0 0.000 0:0.029 false false
-1 G1 Young RemSet Sampling - -1 - 0.0 0.000 0:0.019 false true
17 Catalina-utility-2 main 1 WAITING 0.0 0.000 0:0.025 false false
34 http-nio-8080-ClientPoller main 5 RUNNABLE 0.0 0.000 0:0.016 false true
23 http-nio-8080-BlockPoller main 5 RUNNABLE 0.0 0.000 0:0.011 false true
-1 VM Thread - -1 - 0.0 0.000 0:0.032 false true
-1 Service Thread - -1 - 0.0 0.000 0:0.006 false true
-1 GC Thread#5 - -1 - 0.0 0.000 0:0.043 false true
Memory used total max usage GC
heap 36M 70M 4096M 0.90% gc.g1_young_generation.count 12
g1_eden_space 6M 18M -1 33.33% 86
g1_old_gen 30M 50M 4096M 0.74% gc.g1_old_generation.count 0
g1_survivor_space 491K 2048K -1 24.01% gc.g1_old_generation.time(ms) 0
nonheap 66M 69M -1 96.56%
codeheap_'non-nmethods' 1M 2M 5M 22.39%
metaspace 46M 47M -1 98.01%
Runtime
os.name Mac OS X
os.version 10.15.4
java.version 15
java.home /Library/Java/JavaVirtualMachines/jdk-15.jdk/Contents/Home
systemload.average 10.68
processors 8
uptime 272s
```
Enter `Q`{{execute T2}} or `Ctrl+C` to exit the dashboard command.
### Notes on column headers
* ID: JVM thread ID, pls. note this ID is different from the nativeID in jstack
* NAME: thread name
* GROUP: thread group name
* PRIORITY: thread priority, ranged from 1 to 10. The greater number, the higher priority
* STATE: thread state
* CPU%: the ratio of CPU usage for the thread. For example, the sampling interval is 1000ms, and the incremental cpu time
of a thread is 100ms, then the cpu usage rate=100/1000=10%
* DELTA_TIME: incremental CPU time of thread running after the last sampling in `second` format
* TIME: total CPU time of the thread in `minute:second` format
* INTERRUPTED: the thread interruption state
* DAEMON: daemon thread or not
#### JVM internal threads
After Java 8, it is supported to obtain the CPU time of JVM internal threads. These threads only have the name and CPU time,
without ID and status information (display ID is -1).
JVM activities can be observed through internal threads, such as GC, JIT compilation, etc., to perceive the overall status of JVM.
* When the JVM heap/metaspace space is insufficient or OOM, it can be seen that the CPU usage of the GC threads is
significantly higher than other threads.
* After executing commands such as `trace/watch/tt/redefine`, you can see that JIT threads activities become more frequent.
Because the JIT compilation data related to this class is cleared when the JVM hot update the class bytecode, it needs to be recompiled.
JVM internal threads include the following:
* JIT compilation thread: such as `C1 CompilerThread0`, `C2 CompilerThread0`
* GC thread: such as `GC Thread0`, `G1 Young RemSet Sampling`
* Other internal threads: such as`VM Periodic Task Thread`, `VM Thread`, `Service Thread`
@@ -1,6 +1,15 @@
这里的cpu统计的是,一段采样间隔内,当前JVM里各个线程所占用的cpu时间占总cpu时间的百分比。其计算方法为: 首先进行一次采样,获得所有线程的cpu使用时间(调用的是`java.lang.management.ThreadMXBean#getThreadCpuTime`这个接口),然后睡眠一段时间,默认100ms,可以通过`-i`参数指定,然后再采样一次,最后得出这段时间内各个线程消耗的cpu时间情况,最后算出百分比。
### cpu使用率是如何统计出来的?
注意: 这个统计也会产生一定的开销(JDK这个接口本身开销比较大),因此会看到as的线程占用一定的百分比,为了降低统计自身的开销带来的影响,可以把采样间隔拉长一些,比如5000毫秒
这里的cpu使用率与linux 命令`top -H -p <pid>` 的线程`%CPU`类似,一段采样间隔时间内,当前JVM里各个线程的增量cpu时间与采样间隔时间的比例
如果想看从Java进程启动开始到现在的cpu占比情况:可以使用[`show-busy-java-threads`](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads)这个脚本
> 工作原理说明:
* 首先第一次采样,获取所有线程的CPU时间(调用的是`java.lang.management.ThreadMXBean#getThreadCpuTime()``sun.management.HotspotThreadMBean.getInternalThreadCpuTimes()`接口)
* 然后睡眠等待一个间隔时间(默认为200ms,可以通过`-i`指定间隔时间)
* 再次第二次采样,获取所有线程的CPU时间,对比两次采样数据,计算出每个线程的增量CPU时间
* 线程CPU使用率 = 线程增量CPU时间 / 采样间隔时间 * 100%
> 注意: 这个统计也会产生一定的开销(JDK这个接口本身开销比较大),因此会看到as的线程占用一定的百分比,为了降低统计自身的开销带来的影响,可以把采样间隔拉长一些,比如5000毫秒。
> 另外一种查看Java进程的线程cpu使用率方法:可以使用[show-busy-java-threads](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads)这个脚本
@@ -5,57 +5,72 @@
```bash
$ thread -n 3
"as-command-execute-daemon" Id=29 cpuUsage=75% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
at com.taobao.arthas.core.command.monitor200.ThreadCommand$1.action(ThreadCommand.java:58)
at com.taobao.arthas.core.command.handler.AbstractCommandHandler.execute(AbstractCommandHandler.java:238)
at com.taobao.arthas.core.command.handler.DefaultCommandHandler.handleCommand(DefaultCommandHandler.java:67)
at com.taobao.arthas.core.server.ArthasServer$4.run(ArthasServer.java:276)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@6cd0b6f8
"as-session-expire-daemon" Id=25 cpuUsage=24% TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at com.taobao.arthas.core.server.DefaultSessionManager$2.run(DefaultSessionManager.java:85)
"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
"C1 CompilerThread0" [Internal] cpuUsage=1.63% deltaTime=3ms time=1170ms
"arthas-command-execute" Id=23 cpuUsage=0.11% deltaTime=0ms time=401ms RUNNABLE
at java.management@11.0.7/sun.management.ThreadImpl.dumpThreads0(Native Method)
at java.management@11.0.7/sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:466)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:199)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
at java.base@11.0.7/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base@11.0.7/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base@11.0.7/java.lang.Thread.run(Thread.java:834)
"VM Periodic Task Thread" [Internal] cpuUsage=0.07% deltaTime=0ms time=584ms
```
### 当没有参数时,显示所有线程的信息
* 没有线程ID,包含`[Internal]`表示为JVM内部线程,参考`dashboard`命令的介绍
* `cpuUsage`为采样间隔时间内线程的CPU使用率,与`dashboard`命令的数据一致。
* `deltaTime`为采样间隔时间内线程的增量CPU时间,小于1ms时被取整显示为0ms。
* `time` 线程运行总CPU时间。
注意:线程栈为第二采样结束时获取,不能表明采样间隔时间内该线程都是在处理相同的任务。建议间隔时间不要太长,可能间隔时间越大越不准确。
可以根据具体情况尝试指定不同的间隔时间,观察输出结果。
### 当没有参数时,显示第一页线程信息
默认按照CPU增量时间降序排列,只显示第一页数据,避免滚屏。
`thread`{{execute T2}}
```bash
$ thread
Threads Total: 16, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
30 as-command-execute-daemon system 9 RUNNABLE 72 0:0 false true
23 as-session-expire-daemon system 9 TIMED_WAIT 27 0:0 false true
22 Attach Listener system 9 RUNNABLE 0 0:0 false true
11 pool-2-thread-1 main 5 TIMED_WAIT 0 0:0 false false
12 Thread-2 main 5 RUNNABLE 0 0:0 false true
13 pool-3-thread-1 main 5 TIMED_WAIT 0 0:0 false false
25 as-selector-daemon system 9 RUNNABLE 0 0:0 false true
14 Thread-3 main 5 TIMED_WAIT 0 0:0 false false
26 pool-5-thread-1 system 5 WAITING 0 0:0 false false
15 Thread-4 main 5 RUNNABLE 0 0:0 false false
1 main main 5 WAITING 0 0:2 false false
2 Reference Handler system 10 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
4 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
20 NonBlockingInputStreamThread main 5 WAITING 0 0:0 false true
21 Thread-8 main 5 RUNNABLE 0 0:0 false true
Threads Total: 33, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0, Internal threads: 17
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON
-1 C2 CompilerThread0 - -1 - 5.06 0.010 0:0.973 false true
-1 C1 CompilerThread0 - -1 - 0.95 0.001 0:0.603 false true
23 arthas-command-execute system 5 RUNNABLE 0.17 0.000 0:0.226 false true
-1 VM Periodic Task Thread - -1 - 0.05 0.000 0:0.094 false true
-1 Sweeper thread - -1 - 0.04 0.000 0:0.011 false true
-1 G1 Young RemSet Sampling - -1 - 0.02 0.000 0:0.025 false true
12 Attach Listener system 9 RUNNABLE 0.0 0.000 0:0.022 false true
11 Common-Cleaner InnocuousThrea 8 TIMED_WAI 0.0 0.000 0:0.000 false true
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
2 Reference Handler system 10 RUNNABLE 0.0 0.000 0:0.000 false true
4 Signal Dispatcher system 9 RUNNABLE 0.0 0.000 0:0.000 false true
15 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.029 false true
22 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.196 false true
24 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.038 false true
16 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
17 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
```
### thread --all, 显示所有匹配的线程
显示所有匹配线程信息,有时需要获取全部JVM的线程数据进行分析。
`thread --all`{{execute T2}}
### thread id, 显示指定线程的运行堆栈
查看线程ID 16的栈:
@@ -122,8 +137,13 @@ $ thread -b
**注意** 目前只支持找出synchronized关键字阻塞住的线程, 如果是`java.util.concurrent.Lock` 目前还不支持。
### thread -i, 指定采样时间间隔
* `thread -i 1000` : 统计最近1000ms内的线程CPU时间。
`thread -i 1000`{{execute T2}}
`thread -n 3 -i 5000`{{execute T2}}
* `thread -n 3 -i 1000` : 列出1000ms内最忙的3个线程栈
`thread -n 3 -i 1000`{{execute T2}}
```bash
$ thread -n 3 -i 1000
@@ -152,11 +172,9 @@ $ thread -n 3 -i 1000
```bash
[arthas@28114]$ thread --state WAITING
Threads Total: 15, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 3, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRU DAEMON
198 AsyncAppender-Worker-arth system 9 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
14 RMI Scheduler(0) system 9 WAITING 0 0:0 false true
2 Reference Handler system 10 WAITING 0 0:0 false true
204 pool-8-thread-1 system 5 WAITING 0 0:0 false false
Threads Total: 16, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
20 arthas-UserStat system 9 WAITING 0.0 0.000 0:0.001 false true
14 arthas-timer system 9 WAITING 0.0 0.000 0:0.000 false true
```
@@ -9,3 +9,4 @@
| [n:] | 指定最忙的前N个线程并打印堆栈 |
| [b] | 找出当前阻塞其他线程的线程 |
| [i <value>] | 指定cpu占比统计的采样间隔,单位为毫秒 |
|[--all]|显示所有匹配的线程|
@@ -1,6 +1,15 @@
### How the CPU ratios are calculated?
CPU ratio for a given thread is the CPU time it takes divided by the total CPU time within a specified interval period. It is calculated in the following way: sample CPU times for all the thread by calling `java.lang.management.ThreadMXBean#getThreadCpuTime` first, then sleep for a period (the default value is 100ms, which can be specified by `-i`), then sample CPU times again. By this, we can get the time cost for this period for each thread, then come up with the ratio.
The cpu ratios here is similar to the thread `%CPU` of the linux command `top -H -p <pid>`. During a sampling interval,
the ratio of the incremental cpu time of each thread in the current JVM to the sampling interval time.
**Note**: this operation consumes CPU time too (getThreadCpuTime is time-consuming), therefore it is possible to observe Arthass thread appears in the list. To avoid this, try to increase sample interval, for example: 5000 ms.
> Working principle description:
* Do the first sampling, get the CPU time of all threads ( by calling `java.lang.management.ThreadMXBean#getThreadCpuTime()` and
`sun.management.HotspotThreadMBean.getInternalThreadCpuTimes()` )
* Sleep and wait for an interval (the default is 200ms, the interval can be specified by `-i`)
* Do the second sampling, get the CPU time of all threads, compare the two sampling data, and calculate the incremental CPU time of each thread
* `Thread CPU usage ratio` = `Thread increment CPU time` / `Sampling interval time` * 100%
If youd like to check the CPU ratios from the very beginning of the Java process, [`show-busy-java-threads`](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads) can come to help.
**Note:** this operation consumes CPU time too (`getThreadCpuTime` is time-consuming), therefore it is possible to observe Arthas's thread appears in the list. To avoid this, try to increase sample interval, for example: 5000 ms.<br/>
> Another way to view the thread cpu usage of the Java process, [show-busy-java-threads](https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads) can come to help.
@@ -5,55 +5,68 @@
```bash
$ thread -n 3
"as-command-execute-daemon" Id=29 cpuUsage=75% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
at com.taobao.arthas.core.command.monitor200.ThreadCommand$1.action(ThreadCommand.java:58)
at com.taobao.arthas.core.command.handler.AbstractCommandHandler.execute(AbstractCommandHandler.java:238)
at com.taobao.arthas.core.command.handler.DefaultCommandHandler.handleCommand(DefaultCommandHandler.java:67)
at com.taobao.arthas.core.server.ArthasServer$4.run(ArthasServer.java:276)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@6cd0b6f8
"as-session-expire-daemon" Id=25 cpuUsage=24% TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at com.taobao.arthas.core.server.DefaultSessionManager$2.run(DefaultSessionManager.java:85)
"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
"C1 CompilerThread0" [Internal] cpuUsage=1.63% deltaTime=3ms time=1170ms
"arthas-command-execute" Id=23 cpuUsage=0.11% deltaTime=0ms time=401ms RUNNABLE
at java.management@11.0.7/sun.management.ThreadImpl.dumpThreads0(Native Method)
at java.management@11.0.7/sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:466)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:199)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
at java.base@11.0.7/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base@11.0.7/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base@11.0.7/java.lang.Thread.run(Thread.java:834)
"VM Periodic Task Thread" [Internal] cpuUsage=0.07% deltaTime=0ms time=584ms
```
### List all threads info when no options provided
* Without thread ID, including `[Internal]` means JVM internal thread, refer to the introduction of `dashboard` command.
* `cpuUsage` is the CPU usage of the thread during the sampling interval, consistent with the data of the `dashboard` command.
* `deltaTime` is the incremental CPU time of the thread during the sampling interval. If it is less than 1ms, it will be rounded and displayed as 0ms.
* `time` The total CPU time of thread.
**Note:** The thread stack is acquired at the end of the second sampling, which does not indicate that the thread is
processing the same task during the sampling interval. It is recommended that the interval time should not be too long.
The larger the interval time, the more inaccurate.
You can try to specify different intervals according to the specific situation and observe the output results.
#### List first page threads' info when no options provided
By default, they are arranged in descending order of CPU increment time, and only the first page of data is displayed.
`thread`{{execute T2}}
```bash
$ thread
Threads Total: 16, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
30 as-command-execute-daemon system 9 RUNNABLE 72 0:0 false true
23 as-session-expire-daemon system 9 TIMED_WAIT 27 0:0 false true
22 Attach Listener system 9 RUNNABLE 0 0:0 false true
11 pool-2-thread-1 main 5 TIMED_WAIT 0 0:0 false false
12 Thread-2 main 5 RUNNABLE 0 0:0 false true
13 pool-3-thread-1 main 5 TIMED_WAIT 0 0:0 false false
25 as-selector-daemon system 9 RUNNABLE 0 0:0 false true
14 Thread-3 main 5 TIMED_WAIT 0 0:0 false false
26 pool-5-thread-1 system 5 WAITING 0 0:0 false false
15 Thread-4 main 5 RUNNABLE 0 0:0 false false
1 main main 5 WAITING 0 0:2 false false
2 Reference Handler system 10 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
4 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
20 NonBlockingInputStreamThread main 5 WAITING 0 0:0 false true
21 Thread-8 main 5 RUNNABLE 0 0:0 false true
Threads Total: 33, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0, Internal threads: 17
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON
-1 C2 CompilerThread0 - -1 - 5.06 0.010 0:0.973 false true
-1 C1 CompilerThread0 - -1 - 0.95 0.001 0:0.603 false true
23 arthas-command-execute system 5 RUNNABLE 0.17 0.000 0:0.226 false true
-1 VM Periodic Task Thread - -1 - 0.05 0.000 0:0.094 false true
-1 Sweeper thread - -1 - 0.04 0.000 0:0.011 false true
-1 G1 Young RemSet Sampling - -1 - 0.02 0.000 0:0.025 false true
12 Attach Listener system 9 RUNNABLE 0.0 0.000 0:0.022 false true
11 Common-Cleaner InnocuousThrea 8 TIMED_WAI 0.0 0.000 0:0.000 false true
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
2 Reference Handler system 10 RUNNABLE 0.0 0.000 0:0.000 false true
4 Signal Dispatcher system 9 RUNNABLE 0.0 0.000 0:0.000 false true
15 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.029 false true
22 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.196 false true
24 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.038 false true
16 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
17 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
```
### thread id, show the running stack for the target thread
@@ -123,7 +136,13 @@ $ thread -b
### thread -i, specify the sampling interval
`thread -n 3 -i 5000`{{execute T2}}
* `thread -i 1000`: Count the thread cpu time of the last 1000ms.
`thread -i 1000`{{execute T2}}
* `thread -n 3 -i 1000`: List the 3 busiest thread stacks in 1000ms.
`thread -n 3 -i 1000`{{execute T2}}
```bash
$ thread -n 3 -i 1000
@@ -152,11 +171,9 @@ $ thread -n 3 -i 1000
```bash
[arthas@28114]$ thread --state WAITING
Threads Total: 15, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 3, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRU DAEMON
198 AsyncAppender-Worker-arth system 9 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
14 RMI Scheduler(0) system 9 WAITING 0 0:0 false true
2 Reference Handler system 10 WAITING 0 0:0 false true
204 pool-8-thread-1 system 5 WAITING 0 0:0 false false
```
Threads Total: 16, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
20 arthas-UserStat system 9 WAITING 0.0 0.000 0:0.001 false true
14 arthas-timer system 9 WAITING 0.0 0.000 0:0.000 false true
```
@@ -12,3 +12,4 @@ Check the basic info and stack trace of the target thread.
| [n:] | the top n busiest threads with stack traces printed |
| [b] | locate the thread blocking the others |
| [i <value>] | specify the interval to collect data to compute CPU ratios (ms) |
|[--all]|Show all matching threads|