spring-boot - spring-boot 在启动期间挂起一段时间

Question

我们使用 camel 的 spring-boot 应用程序之一在启动时会挂起 1 到 5 分钟，但并非始终如一。

应用程序运行的生产环境是树莓派，运行 openJDK。我们无法在开发机器上重现该问题。

然而，即使在 pis 上，这个问题也非常罕见，而且似乎只发生在某些人身上。事实上，我们目前在该领域只有一个这是一个持续存在的问题，但由于它是太阳能供电的，所以它在某种程度上是一个关键问题。这个问题之前在另一个 Pi 上观察到过一次，它不是关键的，也不是 100% 一致的，一段时间后又消失了。不幸的是，我们无法测试 pi 的硬件问题。旅行费用将是巨大的，所以在我们没有其他选择之前，我们无法负担去替换它的可能性，即使这样也无法解决问题。此外，pis 系统日志在挂起发生期间和前后都没有显示任何可疑活动。

这只是为了解释为什么我发布这个问题，即使目前不能 100% 排除硬件问题。我们只需要先排除其他所有内容。

现在来回答实际问题：这是挂起发生时应用程序的完整跟踪 (log.level.root = TRACE)。我可以提供启动的完整跟踪，但不认为垃圾邮件成千上万行日志会有多大帮助。我最感兴趣的是你是否看到任何可疑的东西。我已经查看了这些条目一段时间，并没有看到任何关于挂起原因的提示，但我对 spring-boot 内部生活的经验非常有限。

2019-10-30 08:28:16.090 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Eagerly caching bean 'org.springframework.context.annotation.internalScheduledAnnotationProcessor' to allow for resolving potential circular references
2019-10-30 08:28:16.091 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Getting BeanInfo for class [org.springframework.scheduling.annotation.ScheduledAnnotationBeanPostProcessor]
2019-10-30 08:28:16.106 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Caching PropertyDescriptors for class [org.springframework.scheduling.annotation.ScheduledAnnotationBeanPostProcessor]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'applicationContext' of type [org.springframework.context.ApplicationContext]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanFactory' of type [org.springframework.beans.factory.BeanFactory]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanName' of type [java.lang.String]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'class' of type [java.lang.Class]
2019-10-30 08:28:16.108 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'embeddedValueResolver' of type [org.springframework.util.StringValueResolver]
2019-10-30 08:28:16.109 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'order' of type [int]
2019-10-30 08:28:16.109 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'scheduledTasks' of type [java.util.Set]
2019-10-30 08:28:16.109 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'scheduler' of type [java.lang.Object]
2019-10-30 08:28:16.185 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'org.springframework.context.annotation.internalScheduledAnnotationProcessor'
2019-10-30 08:28:16.186 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'persistenceExceptionTranslationPostProcessor'
2019-10-30 08:28:16.186 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'persistenceExceptionTranslationPostProcessor'
2019-10-30 08:28:16.370 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'environment'
2019-10-30 08:28:16.375 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'persistenceExceptionTranslationPostProcessor' via factory method to bean named 'environment'
2019-10-30 08:28:16.379 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'configurationProperties'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'commandLineArgs'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'systemProperties'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'systemEnvironment'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'random'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'applicationConfig: [file:./application.properties]'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'applicationConfig: [classpath:/application.properties]'
2019-10-30 08:28:16.381 DEBUG 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Could not find key 'spring.aop.proxy-target-class' in any property source
2019-10-30 08:28:16.398 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Eagerly caching bean 'persistenceExceptionTranslationPostProcessor' to allow for resolving potential circular references
2019-10-30 08:28:16.399 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Getting BeanInfo for class [org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Caching PropertyDescriptors for class [org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanClassLoader' of type [java.lang.ClassLoader]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanFactory' of type [org.springframework.beans.factory.BeanFactory]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beforeExistingAdvisors' of type [boolean]
2019-10-30 08:28:16.438 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'class' of type [java.lang.Class]
2019-10-30 08:28:16.438 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'exposeProxy' of type [boolean]
2019-10-30 08:28:16.439 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'frozen' of type [boolean]
2019-10-30 08:28:16.440 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'opaque' of type [boolean]
2019-10-30 08:28:16.440 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'optimize' of type [boolean]
2019-10-30 08:28:16.441 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'order' of type [int]
2019-10-30 08:28:16.441 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'proxyClassLoader' of type [java.lang.ClassLoader]
2019-10-30 08:28:16.441 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'proxyTargetClass' of type [boolean]
2019-10-30 08:28:16.442 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'repositoryAnnotationType' of type [java.lang.Class]
2019-10-30 08:28:16.507 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'persistenceExceptionTranslationPostProcessor'
2019-10-30 08:28:16.507 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'dataSourceInitializerPostProcessor'
2019-10-30 08:28:16.507 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'dataSourceInitializerPostProcessor'
2019-10-30 08:28:16.522 DEBUG 456 --- [main] o.s.b.f.annotation.InjectionMetadata : Registered injected element on class [org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor]: AutowiredFieldElement for private org.springframework.beans.factory.BeanFactory org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor.beanFactory
2019-10-30 08:28:16.522 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Eagerly caching bean 'dataSourceInitializerPostProcessor' to allow for resolving potential circular references
2019-10-30 08:28:16.522 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Getting BeanInfo for class [org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor]
2019-10-30 08:28:16.532 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Caching PropertyDescriptors for class [org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor]
2019-10-30 08:28:16.533 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'class' of type [java.lang.Class]
2019-10-30 08:28:16.533 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'order' of type [int]

// Note the significant time jump!

2019-10-30 08:30:16.087 TRACE 454 --- [main] org.apache.sshd.client.SshClient : addSessionListener(SshClient[f66866])[org.apache.sshd.common.session.helpers.SessionTimeoutListener@b50150] registered
2019-10-30 08:30:16.088 TRACE 454 --- [main] .a.s.c.u.t.ThreadUtils$SshdThreadFactory : newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[f66866]-timer-thread-1] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@1b986cd[State = -1, empty queue]
2019-10-30 08:30:16.161 TRACE 454 --- [main] o.a.sshd.common.io.nio2.Nio2Connector : Creating Nio2Connector
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.camel.component.ssh.SshProducer : Starting producer: Producer[ssh://root:xxxxxx@192.168.1.1]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.camel.component.exec.ExecProducer : Starting producer: Producer[exec://sudo]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.camel.component.exec.ExecProducer : Starting producer: Producer[exec://sudo]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://switch-off-camera]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.camel.component.seda.SedaProducer : Starting producer: Producer[seda://capture-image]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://switch-off-camera]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.camel.component.seda.SedaProducer : Starting producer: Producer[seda://image-queue]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://failed-upload]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://switch-off-camera]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.164 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.164 DEBUG 454 --- [main] o.a.camel.component.seda.SedaProducer : Starting producer: Producer[seda://capture-command]
2019-10-30 08:30:16.164 DEBUG 454 --- [main] o.a.camel.spring.SpringCamelContext : Route: route1 >>> EventDrivenConsumerRoute[seda://start-deepsleep -> Pipeline[[Channel[Log(route1)[Starting deep sleep for ${body} seconds]], Channel[SetBody(Simple: sh -c '(sleep 15; io set out0 1; sleep 2; lpm -i ${body})' </dev/null >/dev/null 2>&1 &)], Channel[Log(route1)[Executing SSH command: ${body}]], C
2019-10-30 08:30:16.165 DEBUG 454 --- [main] o.a.camel.spring.SpringCamelContext : Starting consumer (order: 1000) on route: route1
2019-10-30 08:30:16.165 TRACE 454 --- [main] a.c.m.DefaultManagementLifecycleStrategy : Checking whether to register SedaConsumer[seda://start-deepsleep] from route: EventDrivenConsumerRoute[seda://start-deepsleep -> Pipeline[[Channel[Log(route1)[Starting deep sleep for ${body} seconds]], Channel[SetBody(Simple: sh -c '(sleep 15; io set out0 1; sleep 2; lpm -i ${body})' </dev/null >/dev/null 2>&1
2019-10-30 08:30:16.166 DEBUG 454 --- [main] javax.management.mbeanserver : name = org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18)
2019-10-30 08:30:16.167 DEBUG 454 --- [main] javax.management.mbeanserver : name = org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18)
2019-10-30 08:30:16.167 TRACE 454 --- [main] o.a.c.management.DefaultManagementAgent : Registering MBean with ObjectName: org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18)
2019-10-30 08:30:16.168 TRACE 454 --- [main] o.a.c.m.DefaultManagementMBeanAssembler : Assembling MBeanInfo for: org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18) from @ManagedResource object: org.apache.camel.management.mbean.ManagedConsumer@8572f0
2019-10-30 08:30:16.168 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from class: class org.apache.camel.management.mbean.ManagedConsumer
2019-10-30 08:30:16.174 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.Integer org.apache.camel.management.mbean.ManagedConsumer.getInflightExchanges()
2019-10-30 08:30:16.175 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public org.apache.camel.Consumer org.apache.camel.management.mbean.ManagedConsumer.getConsumer()
2019-10-30 08:30:16.175 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.String org.apache.camel.management.mbean.ManagedConsumer.getEndpointUri()
2019-10-30 08:30:16.175 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from sub class: class org.apache.camel.management.mbean.ManagedService
2019-10-30 08:30:16.176 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from class: class org.apache.camel.management.mbean.ManagedService
2019-10-30 08:30:16.180 TRACE 454 --- [ForkJoinPool.commonPool-worker-2] org.apache.camel.util.LRUCache : onRemoval class org.apache.camel.management.mbean.ManagedService -> null
2019-10-30 08:30:16.180 TRACE 454 --- [ForkJoinPool.commonPool-worker-3] org.apache.camel.util.LRUCache : onRemoval interface org.apache.camel.api.management.mbean.ManagedServiceMBean -> null
2019-10-30 08:30:16.180 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.String org.apache.camel.management.mbean.ManagedService.getServiceType()
2019-10-30 08:30:16.180 TRACE 454 --- [ForkJoinPool.commonPool-worker-2] org.apache.camel.util.LRUCache : onRemoval class org.apache.camel.management.mbean.ManagedProducer -> null
2019-10-30 08:30:16.181 TRACE 454 --- [ForkJoinPool.commonPool-worker-3] org.apache.camel.util.LRUCache : onRemoval interface org.apache.camel.api.management.mbean.ManagedProducerMBean -> null
2019-10-30 08:30:16.181 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public boolean org.apache.camel.management.mbean.ManagedService.isSupportSuspension()
2019-10-30 08:30:16.182 TRACE 454 --- [ForkJoinPool.commonPool-worker-3] org.apache.camel.util.LRUCache : onRemoval interface org.apache.camel.api.management.ManagedInstance -> null
2019-10-30 08:30:16.182 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public boolean org.apache.camel.management.mbean.ManagedService.isStaticService()
2019-10-30 08:30:16.182 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public void org.apache.camel.management.mbean.ManagedService.setRoute(org.apache.camel.Route)
2019-10-30 08:30:16.182 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.String org.apache.camel.management.mbean.ManagedService.getCamelManagementName()

我已经标记了似乎什么都没有发生的时间间隔。现在，我已经删除了其中的一些条目。石英作业存储正在处理 h2 数据库，我们的一项服务的计划任务已经在运行。没有可疑的东西，我们设法在一些测试运行中完全排除了它们，但这表明整个系统并没有停滞不前。Spring-boot 在继续之前似乎只是在等待某些东西。

我希望家里有更多使用 spring-boot 的人可以根据这些日志告诉我 spring-boot 在那段时间正在等待什么。

我们还排除了错误记录时间的可能性（即实际上并不存在挂起，而是时钟跳动），特别是因为这是一个 pi。

在骆驼实例化端点和骆驼开始路由之间发生挂起可能会也可能不会值得注意。通常这些只是第二个 Appart，但我希望在日志中看到一些麻烦，如果有挂断的话。

标签： spring-bootraspberry-piapache-camel

Answer 1

问题是您要部署的 Pi 没有足够的“噪音”让随机数生成器正常启动。Oracle 对此问题有一个解决方案：https ://docs.oracle.com/cd/E13209_01/wlcp/wlss30/configwlss/jvmrand.html