1，打开日志debug模式

1）配置文件中打开debug模式
<logger name="org.springframework" level="debug" />
<logger name="org.hibernate" level="debug" />
2）创建DAO相关的bean
DefaultListableBeanFactory:221 - Creating shared instance of singleton bean 'userDAOImpl'
DefaultListableBeanFactory:449 - Creating instance of bean 'userDAOImpl'
InjectionMetadata:72 - Registered injected element on class [com.hzq.dao.impl.UserDAOImpl]: ResourceElement for private org.hibernate.SessionFactory com.hzq.dao.AbsHibernateGenericDAO.sessionFactory（@Resource(name = "sessionFactory") private SessionFactory sessionFactory;）
3）创建service相关的bean。
DefaultListableBeanFactory:221 - Creating shared instance of singleton bean 'userServiceImpl'
DefaultListableBeanFactory:449 - Creating instance of bean 'userServiceImpl'
InjectionMetadata:72 - Registered injected element on class [com.hzq.service.UserServiceImpl]: ResourceElement for private com.hzq.dao.UserDAO com.hzq.dao.impl.UserServiceImpl.userDAO//注入dao
InjectionMetadata:72 - Registered injected element on class [com.hzq.service.UserServiceImpl]: AutowiredFieldElement for private com.hzq.service.common.CommonService com.hzq.service.common.CommonServiceImpl.commomService//注入其他service
InjectionMetadata:72 - Registered injected element on class [.com.hzq.service.UserServiceImpl]: AutowiredFieldElement for private java.lang.String com.hzq.service.UserServiceImpl.helloStr//注入元数据
....
Finished creating instance of bean 'xxxService'//完成service的创建。//完成创建之后，会把bean缓存起来，用于其他bean的依赖注入
DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'UserServiceImpl'// 注入已经缓存的service bean
4）创建controller相关的bean。
DefaultListableBeanFactory:221 - Creating shared instance of singleton bean 'userController'//创建controller bean
DefaultListableBeanFactory:449 - Creating instance of bean 'userController'
InjectionMetadata:72 - Registered injected element on class [com.hzq.controller.UserController]: AutowiredFieldElement for private com.hzq.service.UserService com.hzq.controller。UserController.apiMerchantService// 注入service bean
DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'commonServiceImpl'
AutowiredAnnotationBeanPostProcessor:535 - Autowiring by type from bean name 'userController' to bean named 'commonServiceImpl'//注入已经缓存好的bean
DefaultListableBeanFactory:485 - Finished creating instance of bean 'apiMerchantController'
5）RequestMappingHandlerMapping匹配。
Looking for request mappings in application context: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Mon Nov 13 14:41:45 CST 2017]; parent: Root WebApplicationContext//寻找应用的上下文
1 request handler methods found on class com.hzq.controller.UserController: {public java.util.Map com.hzq.controller.UserController.index(com.hzq.controller.UserBean,java.lang.String)={[/test/url],methods=[POST]}}//发现handler methods
RequestMappingHandlerMapping:543 - Mapped "{[/test/url],methods=[GET]}" onto public java.util.Map<java.lang.String, java.lang.Object> com.hzq.controller.UserController.index(xxxBean,java.lang.String)
@RequestMapping("/test/url") @ResponseBody public Map<String, Object> index(@RequestBody UserBean userBean, @RequestParam String key)

2，一些细节处理

1）寻找元数据@Value("${send.key}")
o.springframework.jndi.JndiTemplate:150 - Looking up JNDI object with name[java:comp/env/send.key]
Converted JNDI name [java:comp/env/send.key] not found//在env中寻找key
PropertySourcesPropertyResolver:151 - Found key 'send.key' in [class path resource [properties/application-local.properties]] with type [String]//通过配置文件寻找key
2）解析HQL
QueryTranslatorImpl:272 - parse() - HQL: from com.hzq.domain.AppInfo where partner = ?HQL
SQL: select appinfo0_.id as id2_, appinfo0_.appkey as appkey2_, appinfo0_.createTime as createTime2_, appinfo0_.enable as enable2_, appinfo0_.merchantId as merchantId2_, appinfo0_.partner as partner2_ from app_info appinfo0_ where appinfo0_.partner=?parse之后的sql
3）处理事务
DEBUG o.h.transaction.JDBCTransaction:78 - begin开启
DEBUG o.h.transaction.JDBCTransaction:86 - disabling autocommit禁用auto commit
.....执行sql
DEBUG o.s.o.h.HibernateTransactionManager:759 - Initiating transaction commit
o.s.o.h.HibernateTransactionManager:659 - Committing Hibernate transaction on Session在session上提交事务
DEBUG o.h.transaction.JDBCTransaction:130 - commit提交
DEBUG o.h.transaction.JDBCTransaction:223 - re-enabling autocommit重新开启自动提交
DEBUG o.h.transaction.JDBCTransaction:143 - committed JDBC Connection提交jdbc连接
DEBUG org.hibernate.jdbc.ConnectionManager:464 - releasing JDBC connection 释放jdbc连接
ConnectionManager:325 - transaction completed on session with on_close connection release mode关闭session，释放资源

3，处理一个请求的过程。

1）通过filter绑定当前线程的session。
OpenSessionInViewFilter:273 - Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'sessionFactory'
SessionImpl:265 - opened session at timestamp: 15113383701
2）为请求的uri寻找handler method。
DispatcherServlet:865 - DispatcherServlet with name 'dispatcher' processing GET request for [/api/v3/room/enter]
RequestMappingHandlerMapping:310 - Looking up handler method for path /api/v3/room/enter
RequestMappingHandlerMapping:317 - Returning handler method [public java.lang.String com.hzq.ApiAdminRoomController.index(com.hzq.EnterBean,org.springframework.ui.Model,javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse,javax.servlet.http.HttpSession)]
3）找到匹配的controller实例
AuthorizeInterceptor:43 - request aa query string: /api/v3/room/enter//先进入interceptor处理
DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'roomController'//找到匹配的controller singleton instance

4，HqlSqlBaseWalker解析hqlHibernate Query Language to SQL Tree Transform.以及事务处理

1）事务方法相关(使用非事务模式运行，不会创建事务)
AnnotationTransactionAttributeSource:116 - Adding transactional method 'com.hzq.MyService.findByPartner' with attribute: PROPAGATION_SUPPORTS,ISOLATION_DEFAULT; ''//发现事务方法
HibernateTransactionManager:443 - Found thread-bound Session [org.hibernate.impl.SessionImpl@78aac804] for Hibernate transaction//给线程绑定session
2）解析hql过程
QueryTranslatorImpl:272 - parse() - HQL: from com.hzq.domain.AppInfo where partner = ?//HQL
AST:291 - --- HQL AST ---HQL AST信息
HqlSqlBaseWalker begin-->FromClause-->Resolved-->Derived SELECT clause created.-->end//处理流程
AST:258 - --- SQL AST --- SQL AST信息
3）sql处理
ConnectionManager:444 - opening JDBC connection//打开jdbc连接-->执行sql
AbstractBatcher:426 - about to open ResultSet//返回的结果集
ConnectionManager:325 - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!//完成session
SessionImpl:551 - disconnecting session//断开session
ConnectionManager:464 - releasing JDBC connection//释放jdbc连接
4）使用Propagation.REQUIRED和Propagation.REQUIRES_NEW的传播行为。
AnnotationTransactionAttributeSource:116 - Adding transactional method 'com.hzq.MyServiceImpl.geEnterInfo' with attribute: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''//发现@transactional注解类或者方法上
HibernateTransactionManager:443 - Found thread-bound Session [org.hibernate.impl.SessionImpl@78aac804] for Hibernate transaction//发现线程绑定的session
Creating new transaction with name [com.hzq.MyServiceImpl.getEnteInfo]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''//创建一个新事务
HibernateTransactionManager:510 - Preparing JDBC Connection of Hibernate Session//给session准备jdbc连接。
JDBCTransaction:78 - begin//开启事务
org.hibernate.jdbc.ConnectionManager:444 - opening JDBC connection//打开jdbc连接。
DBCTransaction:83 - current autocommit status: true;JDBCTransaction:86 - disabling autocommit//禁用autocommit模式
HibernateTransactionManager:575 - Exposing Hibernate transaction as JDBC transaction [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@459eeb09]//通过代理，将hibernate事务暴露成jdbc事务。
//......进行HQL的解析，以及sql的执行，返回结果AbstractBatcher:426 - about to open ResultSet -->映射城对象-->关闭ResultSet
HibernateTransactionManager:759 - Initiating transaction commit
HibernateTransactionManager:659 - Committing Hibernate transaction on Session//事务提交
JDBCTransaction:130 - commit
JDBCTransaction:223 - re-enabling autocommit//重新启用autocommit
JDBCTransaction:143 - committed JDBC Connection//提交jdbc链接
//完成事务，释放Session和jdbc connection资源。

5，视图解析。

1）解析request的媒体类型。
ContentNegotiatingViewResolver:263 - Requested media types are [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] based on Accept header types and producible media types [*/*])
2）返回解析到的视图。
ContentNegotiatingViewResolver:338 - Returning [org.springframework.web.servlet.view.JstlView: name 'hzq/index'; URL [/WEB-INF/jsp/hzq/index.jsp]] based on requested media type 'text/html'
3）渲染视图。
DispatcherServlet:1276 - Rendering view [org.springframework.web.servlet.view.JstlView: name 'hzq/index'; URL [/WEB-INF/jsp/hzq/index.jsp]] in DispatcherServlet with name 'dispatcher'
4）给视图绑定model对象
JstlView:432 - Added model object 'info' of type [com.hzq.ResultInfo] to request in view with name 'hzq/index'
JstlView:166 - Forwarding to resource [/WEB-INF/jsp/hzq/index.jsp] in InternalResourceView 'hzq/index'
5）成功处理请求
DispatcherServlet:1000 - Successfully completed request

6，mybatis事务

Mybatis 事务回滚。

Creating a new SqlSession
Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@38faa406]
JDBC Connection [ProxyConnection[PooledConnection[com.mysql.jdbc.JDBC4Connection@6743a09e]]] will be managed by Spring
ooo Using Connection [ProxyConnection[PooledConnection[com.mysql.jdbc.JDBC4Connection@6743a09e]]]
==> Preparing: insert into tb_system_log (seq_no, operater, content) values (?, ?, ?)
==> Parameters: 2a6a58f3-e8e2-4dd8-8dd4-789f3773d559(String), null, 2018-06-22 14:28:35(String)
Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@38faa406]
Transaction synchronization rolling back SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@38faa406]
Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@38faa406]

Mybatis 事务提交。

2018-06-22 14:42:43,789 | INFO | Sedis2 RefreshConfigThread ns=request_manage_beta | c.q.r.s.Sedis2 | [Sedis2 ns=request_manage_beta, info:初始化ConfigServer OK, host=10.86.37.202, port=3307]
2018-06-22 14:42:43,793 | INFO | Sedis2 RefreshConfigThread ns=request_manage_beta | c.q.r.s.Sedis2 | [Sedis2 ns=request_manage_beta, info:redis config 没有变化，不需要更新.]
Creating a new SqlSession
Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@3453a509]
JDBC Connection [ProxyConnection[PooledConnection[com.mysql.jdbc.JDBC4Connection@7331eb6b]]] will be managed by Spring
ooo Using Connection [ProxyConnection[PooledConnection[com.mysql.jdbc.JDBC4Connection@7331eb6b]]]
==> Preparing: insert into tb_system_log (seq_no, operater, content) values (?, ?, ?)
==> Parameters: e068015c-8ed3-484e-905e-2021d2e12d6d(String), system(String), 2018-06-22 14:42:44(String)
<== Updates: 1
Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@3453a509]
Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@3453a509]
Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@3453a509]