排查springboot启动Jar很慢的问题
最近在一台服务器遇到了jar启动很慢的问题。其他机器都是24s，就那台机器需要240s+。这很奇怪 于是写了一个javassist。排查一下启动的时候那些方法运行很慢。
public class PreMainTraceAgent {
public static void premain(String agentArgs, Instrumentation inst) {
inst.addTransformer((loader, className, classBeingRedefined, protectionDomain, classfileBuffer) -> {
String javaClassName = className.replaceAll("/", ".");
try {
CtClass ctClass = BuildClass.methodAddExecuteTime(loader, javaClassName);
if (Objects.isNull(ctClass)) {
return null;
}
return ctClass.toBytecode();
} catch (Throwable e) {
e.printStackTrace();
}
return null;
}, true);
}
static class DefineTransformer implements ClassFileTransformer {
@Override
public byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classfileBuffer) throws IllegalClassFormatException {
System.out.println("premain load Class:" + className);
return classfileBuffer;
}
}
}
public class BuildClass {
public static CtClass methodPrintSql(ClassLoader loader, String className) throws NotFoundException, CannotCompileException {
ClassPool classPool = new ClassPool();
classPool.appendClassPath(new LoaderClassPath(loader));
//热更新替换
//加载系统classpath
classPool.appendSystemPath();
CtClass ctClass = classPool.getOrNull(className);
if (Objects.isNull(ctClass)) {
return null;
}
for (CtMethod method : ctClass.getDeclaredMethods()) {
if (!Modifier.isAbstract(method.getModifiers()) && !Modifier.isInterface(method.getModifiers())
&& !Modifier.isNative(method.getModifiers()) && Objects.nonNull(method)) {
if (method.getName().equals("execute")) {
methodPrintSql(ctClass, method);
}
}
}
return ctClass;
}
public static CtClass methodAddExecuteTime(ClassLoader loader, String className) throws NotFoundException, CannotCompileException {
ClassPool classPool = new ClassPool();
classPool.appendClassPath(new LoaderClassPath(loader));
//热更新替换
//加载系统classpath
classPool.appendSystemPath();
CtClass ctClass = classPool.getOrNull(className);
if (Objects.isNull(ctClass)) {
return null;
}
for (CtMethod method : ctClass.getDeclaredMethods()) {
if (!Modifier.isAbstract(method.getModifiers()) && !Modifier.isInterface(method.getModifiers())
&& !Modifier.isNative(method.getModifiers()) && Objects.nonNull(method)) {
methodAddExecuteTime(ctClass, method);
}
}
return ctClass;
}
public static void methodAddExecuteTime(CtClass ctClass, CtMethod method) throws CannotCompileException, NotFoundException {
method.addLocalVariable("begin", CtClass.longType);
method.addLocalVariable("end", CtClass.longType);
method.insertBefore("{begin = System.currentTimeMillis();}");
method.insertAfter("{end = System.currentTimeMillis();\n" +
" System.out.println("" + ctClass.getName() +"#"+ method.getName() + " method execute time：" + (end - begin) + "ms");}");
}
public static void methodPrintSql(CtClass ctClass, CtMethod method) throws CannotCompileException, NotFoundException {
// method.insertBefore("{System.out.println(this.toString());}");
method.insertBefore("{System.out.println("cfb sql "+this.toString());}");
// method.addLocalVariable("begin", CtClass.longType);
// method.addLocalVariable("end", CtClass.longType);
// method.insertBefore("{begin = System.currentTimeMillis();}");
// method.insertAfter("{end = System.currentTimeMillis();\n" +
// " System.out.println("" + method.getName() + " method execute time：" + (end - begin) + "ms");}");
}
}
打包成jar包。在业务jar包启动的时候加入当前jar包的启动。 接下来会打印出来很多的日志。类似： sun.usagetracker.UsageTrackerClient#getPropertyPrivileged method execute time：0ms sun.usagetracker.UsageTrackerClient#getPropertyPrivileged method execute time：0ms sun.usagetracker.UsageTrackerClient#getOSSpecificConfigFilePath method execute time：1ms
接下来就是写代码聚合：
public class Test2 {
public static void main(String[] args) {
Map<String, Long> map = new HashMap<>();
try (BufferedReader br = Files.newBufferedReader(Paths.get("xxx.log"))) {
String line;
while ((line = br.readLine()) != null) {
try {
String key = line.split(" ")[0];
String number = line.split(" ")[3].replaceAll("time：", "").replaceAll("ms", "").trim();
if (map.containsKey(key)) {
Long data = map.get(key);
map.put(key, data + Long.parseLong(number));
} else {
map.put(key, Long.parseLong(number));
}
}catch (Exception e){
System.out.println(e);
}
}
System.out.println(sortMap(map));
} catch (IOException e) {
throw new RuntimeException(e);
}
}
public static Map<String, Long> sortMap(Map<String, Long> map) {
//利用Map的entrySet方法，转化为list进行排序
List<Map.Entry<String, Long>> entryList = new ArrayList<>(map.entrySet());
//利用Collections的sort方法对list排序
entryList.sort((Comparator<Map.Entry<String, Long>>) (o1, o2) -> {
//正序排列，倒序反过来
return Math.toIntExact(o2.getValue() - o1.getValue());
});
//遍历排序好的list，一定要放进LinkedHashMap，因为只有LinkedHashMap是根据插入顺序进行存储
LinkedHashMap<String, Long> linkedHashMap = new LinkedHashMap<String, Long>();
for (Map.Entry<String,Long> e : entryList
) {
linkedHashMap.put(e.getKey(),e.getValue());
}
return linkedHashMap;
}
}
获取到了一些基本的信息 {org.springframework.boot.loader.archive.JarFileArchive$NestedArchiveIterator#adapt=177710, org.springframework.boot.loader.jar.JarFile#getNestedJarFile=177445,.....} 从这里可以看到是springboot的jar包加载很慢。但是换一台机器就没问题。问题大概率是磁盘吧。 接下来怼磁盘进行性能测试。
本人使用sysbench进行测试。
- sysbench --threads=32 --report-interval=4 --time=60 --test=fileio --file-num=10 --file-total-size=1G --file-test-mode=rndrw prepare
- sysbench --threads=32 --report-interval=4 --time=60 --test=fileio --file-num=10 --file-total-size=1G --file-test-mode=rndrw run
有问题的机器：
File operations: reads/s: 1646.66 writes/s: 1098.01 fsyncs/s: 279.67
Throughput: read, MiB/s: 25.73 written, MiB/s: 17.16
General statistics: total time: 60.1176s total number of events: 181571
Latency (ms): min: 0.00 avg: 10.56 max: 283.46 95th percentile: 44.17 sum: 1917327.68
Threads fairness: events (avg/stddev): 5674.0938/109.15 execution time (avg/stddev): 59.9165/0.04
没问题的机器：
File operations: reads/s: 15729.82 writes/s: 10486.58 fsyncs/s: 2626.94
Throughput: read, MiB/s: 245.76 written, MiB/s: 163.84
General statistics: total time: 60.0193s total number of events: 1730958
Latency (ms): min: 0.00 avg: 1.11 max: 90.98 95th percentile: 5.99 sum: 1917612.56
Threads fairness: events (avg/stddev): 54092.4375/440.21 execution time (avg/stddev): 59.9254/0.00
破案了。辣鸡运维给了辣鸡磁盘。甩锅成功。
