快捷導(dǎo)航

spring-boot項(xiàng)目啟動(dòng)遲緩異常排查解決記錄

更新時(shí)間：2022年02月25日 16:16:35 作者：kl

這篇文章主要為大家介紹了spring-boot項(xiàng)目啟動(dòng)遲緩異常排查解決記錄，突然在本地啟動(dòng)不起來了，表象特征就是在本地IDEA上運(yùn)行時(shí)，進(jìn)程卡住也不退出，應(yīng)用啟動(dòng)時(shí)加載相關(guān)組件的日志也不輸出

問題背景

一個(gè)spring boot開發(fā)的項(xiàng)目，spring boot版本是1.5.7，攜帶的spring版本是4.1.3。開發(fā)反饋，突然在本地啟動(dòng)不起來了，表象特征就是在本地IDEA上運(yùn)行時(shí)，進(jìn)程卡住也不退出，應(yīng)用啟動(dòng)時(shí)加載相關(guān)組件的日志也不輸出。癥狀如下圖：

問題分析

因?yàn)闆]有有用的日志信息，所以不能從日志這個(gè)層面上排查問題。但是像這種沒有輸出日志的話，一般情況下，肯定是程序內(nèi)部啟動(dòng)流程卡在什么地方了，只能通過打印下當(dāng)前線程堆棧信息了解下。一般情況下，在服務(wù)器環(huán)境，我們會(huì)使用java工具包中的jstack 工具來查看：如jstack pid（應(yīng)用java進(jìn)程）。

但是，在IDEA本地開發(fā)的話，IDEA內(nèi)置了一個(gè)工具，可以直接查看當(dāng)前應(yīng)用的線程上線文信息，如：

注意下面那個(gè)箭頭指向的像照相機(jī)一樣的圖標(biāo)，故圖思意，就是打印當(dāng)前線程快照的的意思。點(diǎn)擊后，就出現(xiàn)了右邊那些線程上下文信息了，可以看到有很多的線程，我們主要關(guān)注下main線程，線程狀態(tài)確實(shí)是waiting的，接著點(diǎn)擊箭頭所指向的main線程，可以看到如下內(nèi)容：

"main@1" prio=5 tid=0x1 nid=NA waiting
java.lang.Thread.State: WAITING
at sun.misc.Unsafe.park(Unsafe.java:-1)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at org.springframework.boot.autoconfigure.BackgroundPreinitializer.onApplicationEvent(BackgroundPreinitializer.java:63)
at org.springframework.boot.autoconfigure.BackgroundPreinitializer.onApplicationEvent(BackgroundPreinitializer.java:45)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:158)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
at org.springframework.boot.context.event.EventPublishingRunListener.finished(EventPublishingRunListener.java:115)
at org.springframework.boot.SpringApplicationRunListeners.callFinishedListener(SpringApplicationRunListeners.java:79)
at org.springframework.boot.SpringApplicationRunListeners.finished(SpringApplicationRunListeners.java:72)
at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:745)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:134)
- locked(a java.util.concurrent.atomic.AtomicBoolean)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:175)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:98)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:64)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:74)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:325)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:296)
at cn.keking.project.customerManagement.KekingCustomerManagement.main(KekingCustomerManagement.java:36)

可以看到是通過CountDownLatch.await()阻塞了線程，接著看下面那行，所在代碼塊如下：

private static final CountDownLatch preinitializationComplete = new CountDownLatch(1);
@Override
public void onApplicationEvent(SpringApplicationEvent event) {
   if (event instanceof ApplicationEnvironmentPreparedEvent) {
      if (preinitializationStarted.compareAndSet(false, true)) {
         performPreinitialization();
      }
   }
   if (event instanceof ApplicationReadyEvent || event instanceof ApplicationFailedEvent) {
      try {
         preinitializationComplete.await();
      }
      catch (InterruptedException ex) {
         Thread.currentThread().interrupt();
      }
   }
}

這是spring boot中的一個(gè)安全初始化資源的一個(gè)類，代碼所示為監(jiān)聽SpringApplicationEvent事件，可以肯定的是，它的邏輯執(zhí)行到了 preinitializationComplete.await();這里，導(dǎo)致了線程阻塞了。正常情況下，spring會(huì)觸發(fā)ApplicationEnvironmentPreparedEvent事件完成資源的初始化，這里先不深究Spring為什么這么做，主要通過程序邏輯看下為什么卡這里了，在preinitializationComplete.await();所在行打個(gè)斷點(diǎn)，看下event對(duì)象里的信息，如下：

原來event是一個(gè)Spring上下文初始化失敗的異常事件對(duì)象，對(duì)象里包含了具體的異常信息，如箭頭所指，關(guān)鍵異常信息如：

NoSuchMethodError："org.springframework.util.ObjectUtils.

unwrapOptional(Ljava/lang/Object;)Ljava/lang/Object;"

假設(shè)問題

通過上面的分析，基本定位到Spring boot應(yīng)用啟動(dòng)卡住這個(gè)表象背后的真實(shí)原因了，而且也定位到了異常信息。

出現(xiàn)NoSuchMethodError異常，是因?yàn)檎{(diào)用方法的時(shí)候，找不到方法了。一般出現(xiàn)在兩個(gè)有關(guān)聯(lián)的jar包，但是版本對(duì)不上了，也就是常說的jar版本依賴沖突。查看了下，ObjectUtils是spring-core包里的一個(gè)類，當(dāng)前的4.1.3版本確實(shí)沒有這個(gè)unwrapOptional方法，spring-core-5.x的版本才新增了這個(gè)方法。因?yàn)橹暗囊蕾囀菦]有問題，為什么現(xiàn)在spring上下文會(huì)調(diào)用5.x的版本的方法呢？

所以先假設(shè)近期有開發(fā)在pom.xml里添加了新的的依賴，導(dǎo)致了這個(gè)問題。

小心求證

有了找問題的方向就好辦了，因?yàn)榇a都是git管理維護(hù)的，所以查看下pom.xml文件近期的提交記錄即可，查看后，確實(shí)發(fā)現(xiàn)了近期對(duì)pom.xml有改動(dòng)，添加了一個(gè)依賴：

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-context</artifactId>
    <version>5.1.6.RELEASE</version>
</dependency>

這里還涉及到一點(diǎn)Maven依賴優(yōu)先級(jí)的問題，在pom.xml里直接這樣添加的依賴優(yōu)先于其他jar中pom.xml依賴的，也就是說，即使spring boot1.5.7自帶了Spring-context.4.1.3，但是這樣指定后，應(yīng)用最后依賴的還是5.1.6的版本。具體的Maven依賴關(guān)系，可以參考我的博文《關(guān)于Maven的使用，這些你都了解了么？》。結(jié)合之前的分析，八九不離十了就是因?yàn)榧恿诉@個(gè)依賴導(dǎo)致的問題，spring-context.5.1.6配合spring-core.4.1.3肯定得出問題啊。直接移除這個(gè)依賴，然后啟動(dòng)系統(tǒng)一切正常，日志打印了Spring加載上線文的信息。

問題總結(jié)

定位這個(gè)問題的關(guān)鍵在于要了解java中線程堆棧的知識(shí)，在沒有足夠異常日志情況下通過線程快照排查問題。在定位到問題后，如NoSuchMethodError這樣的異常，需要平時(shí)的經(jīng)驗(yàn)積累來假設(shè)問題的真實(shí)原因，然后在追本溯源驗(yàn)明問題所在根本原因。找問題本質(zhì)一定要這種循序漸進(jìn)的思路。舉例，出現(xiàn)這種問題，如果你直接去搜索引擎搜：“Spring boot應(yīng)用啟動(dòng)卡住了”，是搜不出來什么東西的，但是當(dāng)你發(fā)現(xiàn)了是由于jar沖突。去搜索引擎搜索：