logo头像

不忘初心 方得始终

自定义StopWatch

引言

在平时的开发调试工作或线上中,有时会遇到程序执行效率非常慢,通过一般的经验只能判断出部分逻辑有问题,但判断并不直观且效率较低,不知道方法中哪个阶段比较耗时。目前spring-framework提供了一个StopWatch类可以做类似任务执行时间控制,于是利用此思想重新实现了一套自己的逻辑。

Spring中StopWatch

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
@Slf4j
public class TestStopWatch {

private void test() throws InterruptedException {
StopWatch sw = new StopWatch();

sw.start("起床");
Thread.sleep(1000);
sw.stop();

sw.start("洗漱");
Thread.sleep(2000);
sw.stop();

sw.start("锁门");
Thread.sleep(500);
sw.stop();

log.warn("prettyPrint = {}", sw.prettyPrint());
log.info("totalTimeMillis = {}", sw.getTotalTimeMillis());
log.warn("lastTaskName = {}", sw.getLastTaskName());
log.info("lastTaskInfo = {}", sw.getLastTaskInfo());
log.warn("taskCount = {}", sw.getTaskCount());
}


public static void main(String[] args) throws InterruptedException {
TestStopWatch testStopWatch = new TestStopWatch();
testStopWatch.test();
}
}

输出:

1
2
3
4
5
6
7
8
9
10
11
12
12-22 21:43:49.468 WARN  c.f.o.d.TestStopWatch - prettyPrint = StopWatch '': running time (millis) = 3505
-----------------------------------------
ms % Task name
-----------------------------------------
01004 029% 起床
02001 057% 洗漱
00500 014% 锁门

12-22 21:43:49.476 INFO c.f.o.d.TestStopWatch - totalTimeMillis = 3505
12-22 21:43:49.476 WARN c.f.o.d.TestStopWatch - lastTaskName = 锁门
12-22 21:43:49.477 INFO c.f.o.d.TestStopWatch - lastTaskInfo = org.springframework.util.StopWatch$TaskInfo@5bd03f44
12-22 21:43:49.477 WARN c.f.o.d.TestStopWatch - taskCount = 3

可以看到,Spring中的StopWatch可以方便的排查程序执行效率,但是结果并不直观且代码侵入性太大。

自定义StopWatch

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
@Slf4j
public class StopWatch {
private long startTime;

private long lapStartTime;

private String tagName;

private List<String> steps = new ArrayList<>();

private StopWatch(String tagName) {
this.tagName = tagName;

long start = System.nanoTime();

this.startTime = start;
this.lapStartTime = start;
}

public static StopWatch create(String tagName) {

return new StopWatch(tagName);
}

public void lap(String stepName) {

long elapsedTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - lapStartTime);
int index = steps.size() + 1;
String step = String.format("T%d(%s)/%d", index, stepName, elapsedTime);
steps.add(step);

//reset
this.lapStartTime = System.nanoTime();
}

public void log() {
StringBuilder stringBuilder = createLog();

log.warn(stringBuilder.toString());
}

public void logSlow(long slow) {

long totalElapsedTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime);
if (totalElapsedTime > slow) {
StringBuilder stringBuilder = createLog();
log.warn(stringBuilder.toString());
}
}

private StringBuilder createLog() {
long totalElapsedTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime);

StringBuilder stringBuilder = new StringBuilder(tagName);
stringBuilder.append(' ');
stringBuilder.append(" Total/");
stringBuilder.append(totalElapsedTime);
stringBuilder.append(' ');

for (String step : steps) {
stringBuilder.append(step);
stringBuilder.append(' ');
}
return stringBuilder;
}
}

测试:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
@Slf4j
public class TestStopWatch {

private void test() throws InterruptedException {
StopWatch stopWatch = StopWatch.create("test");

Thread.sleep(1000);
stopWatch.lap("起床");

Thread.sleep(2000);
stopWatch.lap("洗漱");

Thread.sleep(500);
stopWatch.lap("锁门");

stopWatch.log();
}

public static void main(String[] args) throws InterruptedException {
TestStopWatch testStopWatch = new TestStopWatch();
testStopWatch.test();
}
}

结果:

1
12-22 21:53:32.696 WARN  c.f.o.r.c.StopWatch - test  Total/3509 T1(起床)/1001 T2(洗漱)/2005 T3(锁门)/500

通过对比,可以发现自实现的StopWatch类更为简洁,同时也包含了必要的信息,但是功能不如Spring自带的强大。可针对不同的场景使用。

微信打赏

赞赏是不耍流氓的鼓励