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]