最近項目中有個定時任務的需求,定時檢查mysql數據與etcd數據的一致性,具體實現細節就不說了,今天要說的就是實現過程中遇到了druid拋出的異常,以及解決的過程 異常 異常詳細信息 五月 05, 2017 4:16:00 下午 com.alibaba.druid.proxy.DruidDrive ...
最近項目中有個定時任務的需求,定時檢查mysql數據與etcd數據的一致性,具體實現細節就不說了,今天要說的就是實現過程中遇到了druid拋出的異常,以及解決的過程
異常
異常詳細信息
五月 05, 2017 4:16:00 下午 com.alibaba.druid.proxy.DruidDriver warn 警告: register druid-driver mbean error javax.management.InstanceAlreadyExistsException: com.alibaba.druid:type=DruidDriver at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324) at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522) at com.alibaba.druid.proxy.DruidDriver.registerDriver(DruidDriver.java:99) at com.alibaba.druid.proxy.DruidDriver$1.run(DruidDriver.java:84) at java.security.AccessController.doPrivileged(Native Method) at com.alibaba.druid.proxy.DruidDriver.<clinit>(DruidDriver.java:81) at com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:579) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:986) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:982) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:102) at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:211) at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:447) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:656) at com.huawei.wgp.task.TaskDbEtcdConsistencyCheck$$EnhancerBySpringCGLIB$$e1d6d636.consistencyCheck(<generated>) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) 五月 05, 2017 4:16:00 下午 com.alibaba.druid.stat.DruidDataSourceStatManager error 嚴重: register mbean error javax.management.InstanceAlreadyExistsException: com.alibaba.druid:type=DruidDataSourceStat at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324) at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522) at com.alibaba.druid.stat.DruidDataSourceStatManager.addDataSource(DruidDataSourceStatManager.java:139) at com.alibaba.druid.pool.DruidDataSource$1.run(DruidDataSource.java:1446) at java.security.AccessController.doPrivileged(Native Method) at com.alibaba.druid.pool.DruidDataSource.registerMbean(DruidDataSource.java:1442) at com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:706) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:986) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:982) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:102) at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:211) at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:447) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:656) at com.huawei.wgp.task.TaskDbEtcdConsistencyCheck$$EnhancerBySpringCGLIB$$e1d6d636.consistencyCheck(<generated>) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)View Code
出現場景
當前開發只是定時任務,那麼工程啟動後一直在等定時任務的啟動,沒有進行其他任何的操作,而一旦定時任務啟動就出現如上異常信息,但是定時任務正常執行完成,並且不影響應用的其他任何服務,就和沒拋異常一樣!
從druid下手分析
程式員多多少少都有強迫症,看不得出現異常。雖說上述的異常不影響應用,但拋出來了就給我一種不爽的感覺,強迫自己解決它。
所有的異常信息都將矛頭指向了druid,那麼我們就從druid下手。很幸運,網上這方面的資料有不少,最後在druid的github上找到了javax.management.InstanceAlreadyExistsException異常的問題和CentOS release 6.5 總是拋InstanceAlreadyExistsException這兩篇issue,一篇說把spring的自動探測關閉掉,一篇說應用容器中同一實例被啟動了兩遍,引起的併發執行了兩個定時任務;同一實例被啟動了兩遍,這個應該不可能,就不去探究了(真不用探究嗎);那麼我們將spring的自動探測關閉掉試試,結果定時任務還是執行了兩遍。按照網上提供的其他方式也沒能解決這個問題,本以為這個問題要求助領導了,可上天還是眷顧我的。
一次偶然的巧合,我在定時任務啟動前,從瀏覽器請求了我的應用,再當定時任務啟動的時候,異常沒有產生,更巧合的是,資料庫中的數據在瀏覽器上顯示重覆了,也就說定時任務產生了兩份相同的數據插入到了資料庫中,定時任務還是執行了兩次! 這麼說來,異常的產生和druid沒關係,很有可能是定時任務的原因。
那麼問題就轉移了,從druid轉移到定時任務了。
從定時任務下手分析
1、不加定時任務
<?xml version="1.0" encoding="UTF-8"?> <beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:context="http://www.springframework.org/schema/context" xmlns:task="http://www.springframework.org/schema/task" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.1.xsd http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.1.xsd http://www.springframework.org/schema/task http://www.springframework.org/schema/task/spring-task-3.1.xsd"> <!-- <bean id="taskDbEtcdConsistencyCheck" class="com.yzb.wgp.task.TaskDbEtcdConsistencyCheck" /> <task:scheduled-tasks scheduler="schedulerDbEtcdConsistencyCheck"> <task:scheduled ref="taskDbEtcdConsistencyCheck" method="consistencyCheck" cron="0 58 23 * * ?" /> </task:scheduled-tasks> <task:scheduler id="schedulerDbEtcdConsistencyCheck" pool-size="2" /> --> </beans>
結果是:啟動之後,不請求應用則dataSource-1不初始化,請求應用,dataSource-1只初始化一次
五月 08, 2017 8:56:12 上午 com.alibaba.druid.pool.DruidDataSource info
信息: {dataSource-1} inited
這個很好理解,連接池採用了懶載入,真正用到的時候才初始化
2、加定時任務
a)、定時任務啟動前,嚮應用SLBAdmin發送請求
結果是:請求的時候初始化dataSource-1一次,接著執行一次定時任務,然後又初始化一次dataSource-1,最後執行一次定時任務
五月 08, 2017 9:21:02 上午 com.alibaba.druid.pool.DruidDataSource info 信息: {dataSource-1} inited 定時任務... 五月 08, 2017 9:22:00 上午 com.alibaba.druid.pool.DruidDataSource info 信息: {dataSource-1} inited 定時任務...
這就有了疑問:
1、定時任務為什麼啟動了2次
2、dataSource-1為什麼會初始化2次,照理說應該只初始化一次,這個兩次是怎麼出現的了,感覺初始化3次都比初始化2次好理解(一次初始化對應所有前端請求,另外2次初始化分別對應兩次定時任務)
3、沒有拋異常:javax.management.InstanceAlreadyExistsException,這又是為什麼了
b)、定時任務啟動前,不嚮應用SLBAdmin發送任何請求
結果是:先出現異常 ,再初始化dataSource-1兩次,最後定時任務執行兩次
異常信息:略,在上面有 五月 08, 2017 9:38:00 上午 com.alibaba.druid.pool.DruidDataSource info 信息: {dataSource-1} inited 五月 08, 2017 9:38:00 上午 com.alibaba.druid.pool.DruidDataSource info 信息: {dataSource-1} inited 定時任務... 定時任務...
這也有了疑問:
1、這裡為什麼出現異常,而且這個異常沒有終止應用程式,應用程式還是能夠正常提供服務
2、為什麼是初始化dataSource-1兩次後調用兩次定時任務,而不是像a)那樣初始化一次dataSource-1,調用一次定時任務,再初始化一次dataSource-1,再調用一次定時任務
3、分析
<bean id="taskDbEtcdConsistencyCheck" class="com.yzb.wgp.task.TaskDbEtcdConsistencyCheck" />
<task:scheduled-tasks>
<task:scheduled ref="taskDbEtcdConsistencyCheck" method="consistencyCheck" cron="0 07 10 * * ?" />
</task:scheduled-tasks>
<task:scheduler id="schedulerConsistencyCheck" pool-size="1"/>
System.out.println("Thread-id=" + Thread.currentThread().getId() + " ThreadName=" + Thread.currentThread().getName() + " : 定時任務...");
將執行定時任務的線程id及線程名列印出來,配置及列印代碼如上,結果和 2、加定時任務 一樣, 只是有我們需要的信息:
Thread-id=17 ThreadName=pool-1-thread-1 : 定時任務...
Thread-id=18 ThreadName=pool-2-thread-1 : 定時任務...
線程id不同,線程池也不同,那麼就說明這是兩個不同的線程(線程名相同只是spring採用了預設的命名規則,如果我們在配置文件中指定線程的名字,那麼線程名也是相同的),這就證明不是同一個線程調用了兩次目標方法,那麼問題又來了:怎麼會產生兩個定時任務的線程了
我們來列舉下可能兩個線程的產生的場景:
i、配置了兩個定時任務,目標類和目標方法是同一個,同時同一時間點執行,像如下配置
<bean id="taskDbEtcdConsistencyCheck" class="com.huawei.wgp.task.TaskDbEtcdConsistencyCheck" />
<task:scheduled-tasks>
<task:scheduled ref="taskDbEtcdConsistencyCheck" method="consistencyCheck" cron="0 07 10 * * ?" />
<task:scheduled ref="taskDbEtcdConsistencyCheck" method="consistencyCheck" cron="0 07 10 * * ?" />
</task:scheduled-tasks>
<task:scheduler id="schedulerConsistencyCheck" pool-size="2"/>
ii、應用中只有一個定時任務,但是應用被tomcat啟動了兩遍
i場景很容易排除,定時任務的配置文件內容很少,很容易排查;但是ii場景是怎麼產生的了,那麼我們去看下tomcat的應用列表
a)、不加定時任務
b)、定時任務啟動前,嚮應用SLBAdmin發送請求
c)、定時任務啟動前,不嚮應用SLBAdmin發送請求
註意上面三張圖片中標紅的地方,理論上來講,每張圖片的第二處標紅的地方是不應該出現的,也就是Path為wgp-Web的那一行應該是不存在的,那麼它是怎麼出現的了? 我們來看下我們的工程
這種不一致是怎麼產生的了,工程名和發佈路徑一開始都是叫wgp-Web,後面發佈路徑改成了SLBAdmin,而工程名沒有改,就導致了這種不一致。那麼我們將工程名也改成SLBAdmin,再看看tomcat應用列表
應用列表正常,而SLBAdmin應用也達到了預料中的正常,既沒有拋出異常,定時任務也只在定點執行了一次。
疑問解答
定時任務啟動前,嚮應用SLBAdmin發送請求
1、定時任務為什麼啟動了2次
解答:應用容器中同一實例被啟動了兩遍,導致併發執行了兩個定時任務。
2、dataSource-1為什麼會初始化2次,照理說應該只初始化一次,這個兩次是怎麼出現的了,感覺初始化3次都比初始化2次好理解(一次初始化對應所有前端請求,另外2次初始化分別對應兩次定時任務)
解答:因為在定時任務啟動前請求了應用SLBAdmin,spring初始化了SLBAdmin的dataSource-1,當SLBAdmin定時任務啟動的時候,就不會再去初始化SLBAdmin的dataSource-1了;但是容器中還存在wgp-Web的定時任務,當到達定點時,SLBAdmin的定時任務和wgp-Web的定時任務會同時併發啟動,由於wgp-Web的dataSource-1還沒有初始化,所以定時任務執行時初始化wgp-Web的dataSource-1。
3、沒有拋異常:javax.management.InstanceAlreadyExistsException,這又是為什麼了
解答:dataSource-1的初始化不是同時併發進行的,SLBAdmin在請求的時候初始化dataSource-1,在定時任務執行前,而wgp-Web是在定時任務啟動的時候初始化的, spring會根據這個時間差來使得兩次連接池的獲取指向同一個連接池。這個答案是我猜想的,真正知道原因的朋友可以留個言!
定時任務啟動前,不嚮應用SLBAdmin發送請求
1、這裡為什麼出現異常,而且這個異常沒有終止應用程式,應用程式還是能夠正常提供服務
解答:dataSource-1的初始化是同時併發進行的,這個更應該說是spring的bug,spring將實現了符合MBean規範的beans註冊到mbeanserver中,但沒處理好異常,所以悲劇了; 也就是說druid是沒有問題的,那麼服務是能正常提供的。
2、為什麼是初始化dataSource-1兩次後調用兩次定時任務,而不是像a)那樣初始化一次dataSource-1,調用一次定時任務,再初始化一次dataSource-1,再調用一次定時任務
解答:兩個定時任務是在同一個定點執行,所以dataSource-1的初始化是同時併發進行的; 而a)中SLBAdmin是在定時任務執行前響應了請求,並初始化了dataSource-1,wgp-Web是在定時任務執行時初始化的dataSource-1。
為什麼之前的版本沒有出現這個問題了:之前的版本沒有定時任務,另外,轉測試版本和上線版本的Path與Display Name是一致的,都是SLBAdmin
總結
問題產生的根本原因還真是:同一實例被啟動了兩遍,Path為/SLBAdmin啟動一次,Path為/wgp-Web啟動一次,
開發過程中最好保證工程名與發佈路徑保證一直,避免不必要的麻煩
參考
https://github.com/alibaba/druid/issues/1200
https://github.com/alibaba/druid/issues/538
http://jingyan.baidu.com/article/48206aeaf9422e216ad6b39b.html
https://my.oschina.net/superkangning/blog/467487