代码实现
引入了Profiler用于打印日志调用耗时，包括Profiler和ProfilerEntry两个类
package org.apache.james.mailbox.profiler;
/**
* 耗时统计工具
*
* @since 2021-01-20
*/
public class Profiler {
private static final ThreadLocal<ProfilerEntry> entryStack = new ThreadLocal();
public Profiler() {
}
public static void start() {
start(null);
}
public static void start(String message) {
entryStack.set(new ProfilerEntry(message, null, null));
}
public static void enter(String message) {
ProfilerEntry currentEntry = getCurrentEntry();
if (currentEntry != null) {
currentEntry.enterSubEntry(message);
}
}
public static void release() {
ProfilerEntry currentEntry = getCurrentEntry();
if (currentEntry != null) {
currentEntry.release();
}
}
public static String dump() {
return dump("", "");
}
public static String dump(String prefix1, String prefix2) {
ProfilerEntry entry = entryStack.get();
return entry != null ? entry.toString(prefix1, prefix2) : "";
}
private static ProfilerEntry getCurrentEntry() {
ProfilerEntry subEntry = entryStack.get();
ProfilerEntry entry = null;
if (subEntry != null) {
do {
entry = subEntry;
subEntry = subEntry.getUnreleasedEntry();
} while (subEntry != null);
}
return entry;
}
}
package org.apache.james.mailbox.profiler;
import java.text.MessageFormat;
import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;
import org.apache.commons.lang3.StringUtils;
/**
* 耗时统计工具
*
* @since 2021-01-20
*/
public final class ProfilerEntry {
private final List<ProfilerEntry> subEntries = new ArrayList(4);
private final Object message;
private final ProfilerEntry parentEntry;
private final ProfilerEntry firstEntry;
private final long baseTime;
private final long startTime;
private long endTime;
ProfilerEntry(Object message, ProfilerEntry parentEntry, ProfilerEntry firstEntry) {
this.message = message;
this.startTime = System.currentTimeMillis();
this.parentEntry = parentEntry;
this.firstEntry = null != firstEntry ? firstEntry : this;
this.baseTime = firstEntry == null ? 0L : firstEntry.startTime;
}
public String getMessage() {
String messageString = null;
if (this.message instanceof String) {
messageString = (String) this.message;
}
return (String) StringUtils.defaultIfEmpty(messageString, (CharSequence) null);
}
public long getStartTime() {
return this.baseTime > 0L ? this.startTime - this.baseTime : 0L;
}
public long getDuration() {
return this.endTime < this.startTime ? -1L : this.endTime - this.startTime;
}
public long getDurationOfSelf() {
long duration = this.getDuration();
if (duration < 0L) {
return -1L;
} else if (this.subEntries.isEmpty()) {
return duration;
} else {
ProfilerEntry entry;
for (Iterator var3 = this.subEntries.iterator(); var3.hasNext(); duration -= entry.getDuration()) {
entry = (ProfilerEntry) var3.next();
}
return duration < 0L ? -1L : duration;
}
}
public double getPercentage() {
double parentDuration = 0.0D;
double duration = (double) this.getDuration();
if (this.parentEntry != null && this.parentEntry.isReleased()) {
parentDuration = (double) this.parentEntry.getDuration();
}
return duration > 0.0D && parentDuration > 0.0D ? duration / parentDuration : 0.0D;
}
public double getPercentageOfAll() {
double firstDuration = 0.0D;
double duration = (double) this.getDuration();
if (this.firstEntry != null && this.firstEntry.isReleased()) {
firstDuration = (double) this.firstEntry.getDuration();
}
return duration > 0.0D && firstDuration > 0.0D ? duration / firstDuration : 0.0D;
}
public void release() {
this.endTime = System.currentTimeMillis();
}
public boolean isReleased() {
return this.endTime > 0L;
}
public void enterSubEntry(Object message) {
ProfilerEntry subEntry = new ProfilerEntry(message, this, this.firstEntry);
this.subEntries.add(subEntry);
}
public ProfilerEntry getUnreleasedEntry() {
ProfilerEntry subEntry = null;
if (!this.subEntries.isEmpty()) {
subEntry = this.subEntries.get(this.subEntries.size() - 1);
if (subEntry.isReleased()) {
subEntry = null;
}
}
return subEntry;
}
@Override
public String toString() {
return this.toString("", "");
}
public String toString(String prefix1, String prefix2) {
StringBuffer buffer = new StringBuffer();
this.toString(buffer, prefix1, prefix2);
return buffer.toString();
}
private void toString(StringBuffer buffer, String prefix1, String prefix2) {
buffer.append(prefix1);
String message = this.getMessage();
long startTime = this.getStartTime();
long duration = this.getDuration();
long durationOfSelf = this.getDurationOfSelf();
double percent = this.getPercentage();
double percentOfAll = this.getPercentageOfAll();
Object[] params = new Object[] {message, startTime, duration, durationOfSelf, percent, percentOfAll};
StringBuffer pattern = new StringBuffer("{1,number} ");
if (this.isReleased()) {
pattern.append("[{2,number}ms");
if (durationOfSelf > 0L && durationOfSelf != duration) {
pattern.append(" ({3,number}ms)");
}
if (percent > 0.0D) {
pattern.append(", {4,number,##%}");
}
if (percentOfAll > 0.0D) {
pattern.append(", {5,number,##%}");
}
pattern.append("]");
} else {
pattern.append("[UNRELEASED]");
}
if (message != null) {
pattern.append(" - {0}");
}
buffer.append(MessageFormat.format(pattern.toString(), params));
for (int i = 0; i < this.subEntries.size(); ++i) {
ProfilerEntry subEntry = (ProfilerEntry) this.subEntries.get(i);
buffer.append('
');
if (i == this.subEntries.size() - 1) {
subEntry.toString(buffer, prefix2 + "`---", prefix2 + " ");
} else if (i == 0) {
subEntry.toString(buffer, prefix2 + "+---", prefix2 + "| ");
} else {
subEntry.toString(buffer, prefix2 + "+---", prefix2 + "| ");
}
}
}
}
使用方法
样例
package demo;
import lombok.extern.slf4j.Slf4j;
import profiler.Profiler;
@Slf4j
public class ProfilerDemo {
public static void main(String[] args) throws InterruptedException {
Profiler.start("ProfilerDemo");
Profiler.enter("Enter sayHello");
ProfilerDemo.sayHello();
Profiler.release();
Profiler.enter("Enter sayHello2");
ProfilerDemo.sayHello2();
Profiler.release();
Profiler.release();
System.out.println(Profiler.dump());
}
public static void sayHello() throws InterruptedException {
Profiler.enter("Enter sayHello");
Thread.sleep(500);
ProfilerDemo.sayHello2();
Profiler.release();
}
public static void sayHello2() throws InterruptedException {
Profiler.enter("Enter sayHello2");
Thread.sleep(500);
ProfilerDemo.sayHello3();
Profiler.release();
}
public static void sayHello3() throws InterruptedException {
Profiler.enter("Enter sayHello3");
Thread.sleep(500);
Profiler.release();
}
}
结果如下
0 [2,546ms, 100%] - ProfilerDemo
+---0 [1,534ms, 60%, 60%] - Enter sayHello
| `---0 [1,534ms (512ms), 100%, 60%] - Enter sayHello
| `---512 [1,022ms (515ms), 67%, 40%] - Enter sayHello2
| `---1,027 [507ms, 50%, 20%] - Enter sayHello3
`---1,534 [1,012ms, 40%, 40%] - Enter sayHello2
`---1,534 [1,012ms (507ms), 100%, 40%] - Enter sayHello2
`---2,041 [505ms, 50%, 20%] - Enter sayHello3
使用说明
1、通过Profiler.start("ProfilerDemo");开启日志链
2、调用过程中使用，如下组合，成对调用，否则不成链
Profiler.enter("xxx");
Profiler.release();
3、最后通过Profiler.release();结束全部调用
4、通过日志打印，调用Profiler.dump()方法打出调用耗时链
注意点
- 成对使用Profiler.enter("xxx");和Profiler.release();
- 可以嵌套使用
- 需要在同一线程中使用，因为底层使用了ThreadLocal来统计
- 可以在上层方法调用Profiler.enter，在后续的调用类中Profiler.release();