天天看點

從啟動日志看Spring IOC的初始化和Bean生命周期

 http://www.cnblogs.com/gnidoc/p/4978074.html

一、Tomcat中啟動IoC容器的日志

啟動Tomcat等容器時,控制台每次都列印出一些日志。

最近剛好在研究Spring源碼,是以換個角度,從啟動日志來簡單的看看Spring的初始化過程!

以下是Tomcat啟動時日志,截取Spring部分。

//-------------------------------------
//從這裡開始Spring的初始化
十一月 10, 2015 8:52:03 上午 org.apache.catalina.core.ApplicationContext log
資訊: Initializing Spring root WebApplicationContext
十一月 10, 2015 8:52:03 上午 org.springframework.web.context.ContextLoader initWebApplicationContext

//ApplicationContext的預處理prepareRefresh
資訊: Root WebApplicationContext: initialization started
十一月 10, 2015 8:52:04 上午 org.springframework.context.support.AbstractApplicationContext prepareRefresh
資訊: Refreshing Root WebApplicationContext: startup date [Tue Nov 10 08:52:04 CST 2015]; root of context hierarchy

//XmlBeanDefinitionReader的loadBeanDefinitions,加載bean
十一月 10, 2015 8:52:04 上午 org.springframework.beans.factory.xml.XmlBeanDefinitionReader loadBeanDefinitions
//<!-- bean定義的配置檔案 -->
//<context-param>
//    <param-name>contextConfigLocation</param-name>
//    <param-value>classpath:applicationContext.xml</param-value>
//</context-param>
資訊: Loading XML bean definitions from class path resource [applicationContext.xml]
//初始化單例的bean
//由于applicationContext.xml中定義了資料源是以有dataSource、jdbcTemplate,定義了事務是以有transactionManager、txAdvice
十一月 10, 2015 8:52:06 上午 org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons
資訊: Pre-instantiating singletons in org.s[email protected]6f1ad0: 
defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,
org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.
context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.
internalCommonAnnotationProcessor,dataSource,jdbcTemplate,transactionManager,
org.springframework.aop.config.internalAutoProxyCreator,serviceMethod,org.springframework.aop.support.
DefaultBeanFactoryPointcutAdvisor#0,txAdvice,org.springframework.context.annotation.ConfigurationClassPostProcessor.importAwareProcessor]; 
root of factory hierarchy

//初始化C3P0資料庫連接配接池
//mchange是C3P0的依賴包
十一月 10, 2015 8:52:06 上午 com.mchange.v2.log.MLog <clinit>
資訊: MLog clients using java 1.4+ standard logging.
十一月 10, 2015 8:52:07 上午 com.mchange.v2.c3p0.C3P0Registry banner
資訊: Initializing c3p0-0.9.1.2 [built 21-May-2007 15:04:56; debug? true; trace: 10]

十一月 10, 2015 8:52:08 上午 org.springframework.web.context.ContextLoader initWebApplicationContext
資訊: Root WebApplicationContext: initialization completed in 4470 ms
//到這裡完成了WebApplicationContext的初始化
//-------------------------------------      

二、大概流程:

1、初始化方法是在 ContextLoader. initWebApplicationContext ()中完成的;

2、首先進行的是預處理操作:AbstractApplicationContext. prepareRefresh ();

3、然後從資源(這裡是applicationContext.xml)中讀取bean的解析、加載bean:XmlBeanDefinitionReader. loadBeanDefinitions ();

4、執行個體化單例的bean,執行個體化scope="singleton"(預設)且無lazy-init="true"的bean:DefaultListableBeanFactory. preInstantiateSingletons ();

5、注冊C3P0資料庫連接配接池:C3P0Registry.banner();

6、到此完成了 WebApplicationContext的初始化!

從上面的步奏可以大概看出Spring初始化的步奏,當然每個方法都隐藏了很多細節,後面再逐個慢慢品味吧!

------------------------------------------------------------------------------------------------------

三、打開Debug日志,進一步觀察:

預設的Spring自帶了log4j,但是需要我們配置。如果不配置,像debug沒有列印出來,下面我們将debug等資訊輸出到控制台,便于我們分析源碼!

在web.xml中聲明log4.properties,在資源檔案中配置:(調到Debug級别)

log4j.rootLogger=DEBUG, R
log4j.appender.R = org.apache.log4j.ConsoleAppender 
log4j.appender.R.Target = System.out 
log4j.appender.R.layout = org.apache.log4j.PatternLayout 
log4j.appender.R.layout.ConversionPattern =[SSH] %p %d{yyyy-MM-dd HH:mm:ss.SSS} %c %m(%L) %n      

然後,我們就可以看到debug日志了!

關鍵日志分析:

可以結合Bean的生命周期一起分析:

為了便于觀察,applicationContext.xml中隻配置最基本的bean

<bean id="book" name="book" class="com.sky.vo.Book" init-method="productBook" destroy-method="destroyBook">
  <property name="title" value="小王子"/>
</bean>
<bean id="myBeanFactoryPostFactory" class="com.sky.processor.MyBeanFactoryPostFactory"/>
<bean id="myBeanPostProcessor" class="com.sky.processor.MyBeanPostProcessor"/>
      

四、下面是日志的分析過程:

搜尋web.xml中的配置資訊

Adding [servletContextInitParams] PropertySource with lowest search precedence(107)
           

XmlWebApplicationContext

XmlWebApplicationContext Refreshing Root WebApplicationContext: startup date [Thu Nov 19 11:18:22 CST 2015]; root of context hierarchy(513)
           

從XML中讀取bean定義資訊

使用到了Reader,從applicationContext.xml中讀到三個bean(book和myBeanPostProcessor,還有BeanFactoryPostFactory)

注:定義了後置處理器,除了實作BeanPostProcessor接口,然後像普通bean一樣在xml中配置即可!

XmlBeanDefinitionReader Loaded 3 bean definitions from location pattern [classpath:applicationContext.xml](216)      

給ApplicationContext配置BeanFactory,中找到<bean id="book">,<bean id="myBeanPostProcessor">的定義

XmlWebApplicationContext Bean factory for Root WebApplicationContext: 
  org.springframework.beans.factory.support.DefaultListableBeanFactory@148d148: 
    defining beans [book,myBeanFactoryPostFactory,myBeanPostProcessor]; root of factory hierarchy(543)
           

首先執行個體化單例的BeanFactoryPostProcessor,Spring容器後置處理器

DefaultListableBeanFactory Creating shared instance of singleton bean 'myBeanFactoryPostFactory'(215)
DefaultListableBeanFactory Creating instance of bean 'myBeanFactoryPostFactory'(432)      

調用了他的構造方法,于是控制台列印了: MyBeanFactoryPostProcessor構造初始化

為了解決bean的循環依賴,也把這個容器後置處理器像普通bean一樣緩存起來了

Eagerly caching bean 'myBeanFactoryPostFactory' to allow for resolving potential circular references(506)      

到這一步時,完成了Spring容器後置處理器的執行個體化

DefaultListableBeanFactory Finished creating instance of bean 'myBeanFactoryPostFactory'(460)      

同時馬上調用了容器後置處理器的方法,列印出了: MyBeanFactoryPostProcessor調用了postProcessBeanFactory

接下來,執行個體化BeanPostProcessor後置處理器

DefaultListableBeanFactory Creating shared instance of singleton bean 'myBeanPostProcessor'(215) 
DefaultListableBeanFactory Creating instance of bean 'myBeanPostProcessor'(432)      

到這裡時,完成了後置處理器的初始化,構造方法被調用了:

控制台輸出了: 這是自定義的BeanPostProcessor 初始化

然後,像普通的bean那樣,緩存下來,以解決潛在的bean循環依賴的問題

DefaultListableBeanFactory Eagerly caching bean 'myBeanPostProcessor' to allow for resolving potential circular references(506)      

繼續執行,完成了BeanPostProcessor這個後置處理器的執行個體化

DefaultListableBeanFactory Finished creating instance of bean 'myBeanPostProcessor'(460)      

給ApplicationContext配置其他,如國際化資源、ApplicationContext事件、主題,這裡暫時不太明白作用

XmlWebApplicationContext Unable to locate MessageSource with name 'messageSource': 
using default [[email protected]1fb4479](810)      
XmlWebApplicationContext Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster':
 using default [org.springframework.context.event[email protected]1c57594](834)      
UiApplicationContextUtils Unable to locate ThemeSource with name 'themeSource': 
using default [o[email protected]1feeacb](85)      

預執行個體化單例bean

DefaultListableBeanFactory Pre-instantiating singletons in 
org.springframework.beans.factory.support.DefaultListableBeanFactory@fe4495: defining beans [book]; root of factory hierarchy(598)
           

建立book的bean

DefaultListableBeanFactory Creating shared instance of singleton bean 'book'(215) 
DefaultListableBeanFactory Creating instance of bean 'book'(432)      

到這裡後,開始調用了構造函數,輸出了我寫的sysout: 控制台:" 調用了Book預設構造函數"

緩存id為book的bean, 解決潛在的循環引用!

DefaultListableBeanFactory Eagerly caching bean 'book' to allow for resolving potential circular references(506)      

到這裡後,調用了setting注入屬性title,控制台輸出了我寫在setTitle方法中語句: set注入了書本标題為:小王子

在setting注入後,随即輸出的是: bean處理器:bean建立前,表示在注入後,調用了BeanPostProcessor的postProcessBeforeInitialization方法(看方法名也很直覺)

調用InitializingBean接口的afterPropertiesSet方法

這時控制台輸出寫在afterPropertiesSet的語句: InitializingBean,相當于init-method

調用生命周期方法init-method,在ApplicationContext.xml中bean中配置:

DefaultListableBeanFactory Invoking init method  'productBook' on bean with name 'book'(1612)
           

這裡輸出了我自定義的init-method為birth方法的語句: 書本初始化init-method

然後這裡調用了Bean後置處理器的postProcessAfterInitialization方法,因為控制台列印了: bean處理器:bean建立後

到這裡完成了bean的執行個體化

DefaultListableBeanFactory Finished creating instance of bean 'book'(460)      

接下來和後置處理器相關,不太明白這裡的傳回是什麼意思?

DefaultListableBeanFactory Returning cached instance of singleton bean 'myBeanFactoryPostFactory'(246)
DefaultListableBeanFactory Returning cached instance of singleton bean 'myBeanPostProcessor'(246)      

沒有找到生命周期處理器,可能是我們沒有定義,是以使用預設的。看不懂,不過看表述是這個意思。

XmlWebApplicationContext Unable to locate LifecycleProcessor with name 'lifecycleProcessor': 
using default [[email protected]7469](861)      

傳回緩存了這個處理器

DefaultListableBeanFactory Returning cached instance of singleton bean 'lifecycleProcessor'(246)      

接下來的日志,更看不懂!總之,大概是JNDI相關的。。。

PropertySourcesPropertyResolver Searching for key 'spring.liveBeansView.mbeanDomain' in [servletConfigInitParams](81) 
PropertySourcesPropertyResolver Searching for key 'spring.liveBeansView.mbeanDomain' in [servletContextInitParams](81) 
PropertySourcesPropertyResolver Searching for key 'spring.liveBeansView.mbeanDomain' in [jndiProperties](81) 
JndiTemplate Looking up JNDI object with name [java:comp/env/spring.liveBeansView.mbeanDomain](150) 
PropertySourcesPropertyResolver Could not find key 'spring.liveBeansView.mbeanDomain' in any property source. Returning [null](103)      

将Spring容器設定到Servlet容器(Web容器)中:

ContextLoader Published root WebApplicationContext 
as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT](326)
           

五、正确的關閉Tomcat,而非kill時:

銷毀單例的bean,從這裡也可以看到,Spring容器對prototype的bean不理會

DefaultListableBeanFactory Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@148d148: defining beans 
[book,myBeanFactoryPostFactory,myBeanPostProcessor]; root of factory hierarchy(444)
           

調用DisposableBean接口的destroy方法

DisposableBeanAdapter Invoking destroy() on bean with name 'book'(226)
           

列印出來: DisposableBean,相當于destroy-method

調用bean的destroy-method

DisposableBeanAdapter Invoking destroy method 'destroyBook' on bean with name 'book'(302)
           

列印: 書本被銷毀destroy-method

六、幾個不小問題

1、如果name="book"的bean設定lazy-init="true",則啟動時不會執行個體化這個bean,日志中隻會列印MyPostBeanProcessor執行個體化;

2、如果name="book"的bean設定scope="prototype",同樣不會在啟動時執行個體化,也不會緩存;什麼時候執行個體化?getBean

而且prototype的bean,IoC容器隻負責反射執行個體化,後續的生命周期不負責,相當于隻new,當然像後置處理器等還是要執行的

3、BeanPostProcessor是IoC的一個擴充點,讓使用者有機會修改bean!而BeanFactoryPostProcessor是讓使用者有機會修改IoC容器的擴充點!

4、Spring的開閉原則:對擴充開放,對修改關閉??不太了解!

5、init-method和InitializingBean.afterPropertiesSet差別?

最終作用都一樣bean構造後執行初始化的方法

由于是接口,命名是限定死的,init-method屬性更靈活

其他同樣作用的方法,一種特殊的BeanPostProcessor,系統自動的CommonAnnotationBeanPostProcessor

-由于用标簽開啟了,<context:annotation-config />,作用類同<bean class="...CommonAnnotationBeanPostProcessor"/>

其中Spring自帶的注解@PostConstruct、@PreDestroy,用來修飾Book的另外兩個方法,這樣同時存在三種初始化方法!

CommonAnnotationBeanPostProcessor Invoking init method on bean 'book      

初始時機:@PreDestroy----->InitializingBean------->init-method

登出時機:@PreDestroy----->DisposableBean----->destroy-method

-------------------------------------------------------------------------------------------------------

七、覆寫Spring的源代碼

按照網上很多部落格,先從GitHub中下載下傳Spring源碼,然後使用Gradle編譯轉換成Eclipse可以導入的工程,但是貌似由于網絡原因,一直失敗,感覺非常麻煩!

後來想了想,要修改源碼,其實還有一個小技巧,就是覆寫jar中文檔案!!!

嘗試1:直接将源碼包下的單個檔案夾spring-web下的org檔案,複制到用來測試的Spring工程下(已經用pom.xml引入了Spring的所有包),引入之後,一大片報錯!缺少很多相關的jar包,總不可能一個個找出來吧!隻有放棄!

嘗試2:如果我隻是修改單個檔案呢,如ContextLoader.java,單獨複制這個檔案會怎樣?

結果是還是報錯:

不過比想象中好很多,隻有一個servlet包找不到。原來是之前釋出的方式是Tomcat提供的,是以這裡pom.xml中顯示引入

<!-- 添加Servlet -->  
<dependency>    
    <groupId>javax.servlet</groupId>    
    <artifactId>servlet-api</artifactId>    
    <version>2.5</version>    
    <scope>provided</scope>    
</dependency>      

重新編譯後,終于不再報錯了!

打開檔案ContextLoader,修改幾行代碼,看看運作時是否執行了!

友善起見,修改幾行日志檔案:

//servletContext.log("Initializing Spring root WebApplicationContext");
        servletContext.log("你正在啟動Spring容器:WebApplicationContext!!!!!");
        if (logger.isInfoEnabled()) {
            //logger.info("Root WebApplicationContext: initialization started");
            logger.info("Spring容器開始初始化:Root WebApplicationContext: initialization started");
        }      

重新啟動Tomcat,列印的日志: