单元测试CPU100%问题排查单元测试CPU100%问题排查

我们代码从dev合到release的时候，会跑单元测试，检查单元测试覆盖率达到了50%才能合到release发布到uat环境
但是最近几个月，单元测试一直需要跑30-50分钟，才能跑完。
之前也有一次单元测试跑的时间过长，然后我删删改改从30分钟到了10分钟；
但是这次我们又有这样的问题了，很浪费时间，很影响工作效率。
我本地跑了一下单元测试，有了一个大发现。
我本地是windows，CPU会飙到100%，电脑也差不多卡死了。

文章图片
image.png
前几天我就发现了这个现象了，也打算找找CPU100%的原因，因为我们单元测试已经写得蛮标准规范的了，把该mock的地方都mock掉了，里面没有啥特殊的代码的，而且跑单元测试的时候，应该是一个单元测试一个单元测试的跑的，根本不会这么消耗CPU。
直接从任务管理器中拿到PID，然后jstack到txt中

文章图片
image.png

2021-05-07 20:40:21 Full thread dump OpenJDK 64-Bit Server VM (25.202-b08 mixed mode):"qconfig-logger" #278 daemon prio=5 os_prio=0 tid=0x0000000028fc5000 nid=0x574 waiting on condition [0x000000004ec4e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for<0x000000073c5bd2f0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492) at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)"FileWatcher-Thread" #277 daemon prio=5 os_prio=0 tid=0x0000000028fc6800 nid=0x65e4 waiting on condition [0x000000004e94e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for<0x0000000740a8e430> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492) at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680) at com.ctrip.framework.foundation.config.local.watchservice.AbstractWatchService.take(AbstractWatchService.java:114) at com.ctrip.framework.foundation.config.local.file.RecursiveWatcher.take(RecursiveWatcher.java:54) at com.ctrip.framework.foundation.config.local.file.FileEventDispatcher.run(FileEventDispatcher.java:32) at java.lang.Thread.run(Thread.java:748)"pool-101-thread-1" #276 prio=5 os_prio=0 tid=0x0000000028fc4800 nid=0x320 runnable [0x000000004e84e000] java.lang.Thread.State: RUNNABLE at java.io.WinNTFileSystem.getBooleanAttributes(Native Method) at java.io.File.exists(File.java:819) at com.ctrip.framework.foundation.config.local.watchservice.PollingWatchService$PollingWatchKey.poll(PollingWatchService.java:366) - locked <0x0000000740f22998> (a com.ctrip.framework.foundation.config.local.watchservice.PollingWatchService$PollingWatchKey) at com.ctrip.framework.foundation.config.local.watchservice.PollingWatchService$PollingWatchKey$1.run(PollingWatchService.java:264) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)"FileWatcher-Thread" #275 daemon prio=5 os_prio=0 tid=0x0000000028fc6000 nid=0x5f20 waiting on condition [0x000000004e74e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for<0x0000000740a8e430> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492) at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680) at com.ctrip.framework.foundation.config.local.watchservice.AbstractWatchService.take(AbstractWatchService.java:114) at com.ctrip.framework.foundation.config.local.file.RecursiveWatcher.take(RecursiveWatcher.java:54) at com.ctrip.framework.foundation.config.local.file.FileEventDispatcher.run(FileEventDispatcher.java:32) at java.lang.Thread.run(Thread.java:748)"pool-100-thread-1" #274 prio=5 os_prio=0 tid=0x0000000028fc7800 nid=0x5d6c runnable [0x000000004e64e000] java.lang.Thread.State: RUNNABLE at sun.nio.fs.WindowsNativeDispatcher.FindFirstFile0(Native Method) at sun.nio.fs.WindowsNativeDispatcher.FindFirstFile(WindowsNativeDispatcher.java:185) at sun.nio.fs.WindowsDirectoryStream.(WindowsDirectoryStream.java:78) at sun.nio.fs.WindowsFileSystemProvider.newDirectoryStream(WindowsFileSystemProvider.java:518) at java.nio.file.Files.newDirectoryStream(Files.java:457) at com.ctrip.framework.foundation.config.local.watchservice.PollingWatchService$PollingWatchKey.poll(PollingWatchService.java:303) - locked <0x0000000740bbb530> (a com.ctrip.framework.foundation.config.local.watchservice.PollingWatchService$PollingWatchKey) at com.ctrip.framework.foundation.config.local.watchservice.PollingWatchService$PollingWatchKey$1.run(PollingWatchService.java:264) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)"qconfig-worker-local-callback#-thread-1" #273 daemon prio=5 os_prio=0 tid=0x000000002adf5000 nid=0x2314 waiting on condition [0x000000004e54e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for<0x000000073e76e578> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)

发现很多线程一直在跑，都在等锁啥的。
我又拿process explorer看了一下，N多的线程。

文章图片
image.png 我就拿着jstack出来的内容找了框架组的同事，果然有问题。
跟框架同事研究了一下，他们说是他们有一个线程，会查看qconfig的文件变更，200微秒就会跑一次这个监听，而且这个逻辑只有在跑单元测试的这个环境会有：(。这个逻辑其实也没什么问题，后来发现了问题根本所在：
就是一个单元测试跑完后，这个监听的线程并没有结束掉，还会继续存在，继续查看文件变更。
这就导致了线程越跑越多，把cpu都卡死了。
用框架同事的话说，就是起了很多个在跑死循环的线程。电脑不卡才怪，单元测试不慢才怪呢。
找到问题了，就等框架同事把这个bug修复掉。
框架同事先把200微秒改成了1个小时，打了个包给我，我再跑了一次，直接起飞，我电脑上只用了4分钟不到，就把单元测试跑完了。
主要问题还是线程没有跟着单元测试结束掉导致的，这个他们还在排查，等下个版本修复了给到正式的包我们。
今天这个感觉很有成就感，我以前都没有真正的用到jstack解决过问题，今天这个jstack+process explorer，真是实战了一把，帮我们发现了一个大bug。虽然还没有用到jstack的高深用法，但是也发现了问题。
【单元测试CPU100%问题排查】不过本来前几天就能发现这个的，当时不知道怎么就没有继续排查下去，做事情要专心，不能被打断。