大家可能都用过 Spring 自带的 StopWatch 工具类，可以统计多个任务的耗时，输出每个任务的耗时占比，但是有个不太好用的地方就是必须手动调用 start 和 stop 方法，并且一旦漏掉 stop 下次再调用 start 的时候就会抛异常啦。此外 它不支持嵌套调用，如果我既想了解一个任务在全局中的耗时情况，同时这个任务可能逻辑比较重，里面又拆分了很多小逻辑，我怎么统计这些小逻辑的耗时呢，我新建一个 StopWatch 来统计不就行啦
基于此，我设计了一个支持嵌套调用，能够格式化输出父子任务的耗时的工具。
由于需要记录嵌套任务，所以设计 Task 的时候，必须支持父子结构，记录一下当前任务的层级对最后格式化输出会很有帮助。
每一个 Task 都能记录自己的总耗时，以及累计子任务的耗时，同时为了防止 OOM 的情况，我们必须忽略超出阈值的子任务详情。
要记录父子任务的耗时，需要一个栈来模拟方法栈的执行过程，同时可以采用 ThreadLocal 来简化获取当前 Task。
为了防止我们漏掉调用 stop 方法，可以结合 Lambda 函数在我们的框架里就基于 try finally 来完成这一套操作。
框架本身不应该影响业务异常，我们需要抛出任务自身调用的异常。
最终代码如下：NestedTask.java
import lombok.Getter;
import lombok.Setter;
import java.text.NumberFormat;
import java.util.ArrayList;
import java.util.List;
import java.util.Locale;
import java.util.Objects;
import java.util.concurrent.TimeUnit;
/**
* @author 24x7
*/
@Getter
public class NestedTask {
@Setter
private NestedTask parent;
private final String name;
private final long start;
/**
* 最多记录任务的数量，防止 oom
*/
private final int threshold;
private long duration;
@Setter
private int level;
/**
* 子任务
*/
private List<NestedTask> tasks;
public NestedTask(String name) {
this.name = name;
this.start = System.nanoTime();
this.threshold = 100;
}
public void stop() {
this.duration = System.nanoTime() - this.start;
}
public void addTask(NestedTask task) {
if (Objects.isNull(tasks)) {
tasks = new ArrayList<>();
}
if (tasks.size() < threshold) {
tasks.add(task);
}
}
public long getTimeMillis() {
return TimeUnit.NANOSECONDS.toMillis(this.duration);
}
public double getTotalTime(TimeUnit timeUnit) {
return (double) this.duration / TimeUnit.NANOSECONDS.convert(1, timeUnit);
}
public String detail() {
NumberFormat nf = NumberFormat.getNumberInstance(Locale.ENGLISH);
nf.setMaximumFractionDigits(9);
nf.setGroupingUsed(false);
NumberFormat pf = NumberFormat.getPercentInstance(Locale.ENGLISH);
pf.setMinimumIntegerDigits(2);
pf.setGroupingUsed(false);
StringBuilder sb = new StringBuilder(128);
sb.append("执行耗时分析 '").append(this.name).append("': ");
String total = nf.format(getTimeMillis());
sb.append(total).append(" ms");
int width = Math.max(sb.length(), 40);
sb.append("\n");
double allTaskTotalTime = getTotalTime(TimeUnit.SECONDS);
if (Objects.nonNull(this.tasks) && !this.tasks.isEmpty()) {
String line = "-".repeat(width) + "\n";
String unitName = String.format("%-12s", "ms");
sb.append(line);
sb.append(unitName).append(" % Task name\n");
sb.append(line);
int digits = total.indexOf('.');
if (digits < 0) {
digits = total.length();
}
nf.setMinimumIntegerDigits(digits);
nf.setMaximumFractionDigits(10 - digits);
for (NestedTask task : this.tasks) {
detail0(sb, task, allTaskTotalTime, nf, pf);
}
}
else {
sb.append("No task info kept");
}
return sb.toString();
}
private static void detail0(StringBuilder sb, NestedTask task, double allTaskTotalTime, NumberFormat nf, NumberFormat pf) {
int level = task.getLevel();
sb.append(String.format("%-14s", nf.format(task.getTimeMillis())));
double selfTime = task.getTotalTime(TimeUnit.SECONDS);
// 总的任务中的占比
String p0 = pf.format(selfTime / allTaskTotalTime);
sb.append(String.format("%-12s", p0));
if (level > 1) {
sb.append(" ".repeat(Math.max(0, level - 2)));
sb.append("|__");
// 当前任务中的占比
sb.append(task.getName());
double totalTime = Objects.isNull(task.parent) ? task.getTotalTime(TimeUnit.SECONDS) : task.parent.getTotalTime(TimeUnit.SECONDS);
String p1 = pf.format(selfTime / totalTime);
sb.append(" (").append(p1).append(")");
} else {
sb.append(task.getName());
}
sb.append('\n');
List<NestedTask> subTasks = task.getTasks();
if (Objects.isNull(subTasks) || subTasks.isEmpty()) {
return;
}
for (NestedTask subTask : subTasks) {
detail0(sb, subTask, allTaskTotalTime, nf, pf);
}
}
public String summary() {
return "执行耗时分析 '" + this.name + "': " + getTimeMillis() + " ms";
}
@Override
public String toString() {
return this.name;
}
}
SimpleNestedProfiler.java
import lombok.AccessLevel;
import lombok.NoArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import java.util.LinkedList;
import java.util.concurrent.Callable;
/**
* @author 24x7
*/
@NoArgsConstructor(access = AccessLevel.PRIVATE)
@Slf4j
public final class SimpleNestedProfiler {
/**
* 性能分析器栈
*/
private static final ThreadLocal<LinkedList<NestedTask>> LOCAL_PROFILER_STACK = ThreadLocal.withInitial(LinkedList::new);
/**
* 追踪方法耗时的嵌套最大深度
*/
private static final int MAX_DEPTH = 8;
public static void clean() {
LOCAL_PROFILER_STACK.remove();
}
private static NestedTask start(String name) {
LinkedList<NestedTask> profilers = LOCAL_PROFILER_STACK.get();
NestedTask task = new NestedTask(name);
if (!profilers.isEmpty()) {
NestedTask parent = profilers.getLast();
task.setLevel(parent.getLevel() + 1);
task.setParent(parent);
if (profilers.size() < MAX_DEPTH) {
parent.addTask(task);
}
}
profilers.addLast(task);
return task;
}
private static void stop(NestedTask task) {
task.stop();
LinkedList<NestedTask> profilers = LOCAL_PROFILER_STACK.get();
if (profilers.isEmpty()) {
return;
}
NestedTask removed = profilers.getLast();
if (removed == task) {
profilers.removeLast();
output(task);
}
}
private static void output(NestedTask task) {
if (task.getLevel() != 0) {
return;
}
try {
log.info("{}", task.detail());
} catch (Exception e) {
log.error("打印耗时分析结果出异常啦, task={}", task, e);
}
}
public static <T> T submit(Callable<T> callable, String taskName) {
NestedTask task = start(taskName);
try {
return callable.call();
} catch (Exception e) {
log.error("分析异常, task={}", taskName, e);
if (e instanceof YourBizRuntimeException) {
throw (YourBizRuntimeException) e;
}
throw new YourBizRuntimeException("system error");
} finally {
stop(task);
}
}
public static void execute(Runnable callable, String taskName) {
NestedTask task = start(taskName);
try {
callable.run();
} finally {
stop(task);
}
}
}
SimpleNestedProfilerTest.java
import java.util.concurrent.ThreadLocalRandom;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.LockSupport;
/**
* @author 24x7
*/
public class SimpleNestedProfilerTest {
private static int task1() {
sleep();
return 1;
}
private static void task2() {
sleep();
}
private static void task3() {
sleep();
for (int i = 0; i < 5; i++) {
SimpleNestedProfiler.execute(SimpleNestedProfilerTest::subTask, "子任务 - " + i);
}
}
private static void subTask() {
sleep();
}
private static void sleep() {
int i = ThreadLocalRandom.current().nextInt(10, 100);
LockSupport.parkNanos(TimeUnit.MILLISECONDS.toNanos(i));
}
private static void task() {
int i = SimpleNestedProfiler.submit(SimpleNestedProfilerTest::task1, "任务1"); // NOSONAR
SimpleNestedProfiler.execute(SimpleNestedProfilerTest::task2, "任务2");
SimpleNestedProfiler.execute(SimpleNestedProfilerTest::task3, "任务3");
}
public static void main(String[] args) {
try {
SimpleNestedProfiler.execute(SimpleNestedProfilerTest::task, "总任务");
} finally {
SimpleNestedProfiler.clean();
}
}
}
测试执行结果如下
23:51:31.148 [main] INFO SimpleNestedProfiler -- 执行耗时分析 '总任务': 625 ms
----------------------------------------
ms % Task name
----------------------------------------
077 12% 任务1
063 10% 任务2
483 77% 任务3
060 10% |__子任务 - 0 (12%)
093 15% |__子任务 - 1 (19%)
078 12% |__子任务 - 2 (16%)
091 15% |__子任务 - 3 (19%)
060 10% |__子任务 - 4 (13%)