Spring-boot records the total SQL time and count of each request

The target records the HTTP, ES, and mysql time spent in each request. This section discusses mysql

Why explore? Isn’t that easy? But can it satisfy the following points?

It can record parameters such as limit
Can write parameters and SQL together, can be used directly
Able to record time
It can count the total number of SQL executions in a request and the total elapsed time

Spring native capabilities

logging.level.org.hibernate.SQL=debug
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=trace
Copy the code

Use the preceding two configurations.

✔️ can display SQL.
❌ cannot be displayed in a row with parameters
❌ cannot display the limit parameter
❌ Cannot count and record time

2021-02-23 19:35:42.932 DEBUG 97586 --- [  restartedMain] org.hibernate.SQL                        : select admin0_.id as id1_0_, admin0_.create_time as create_t2_0_, admin0_.modify_time as modify_t3_0_, admin0_.email as email4_0_, admin0_.password as password5_0_, admin0_.status as status6_0_, admin0_.username as username7_0_ from admin admin0_ where admin0_.username=?
2021-02-23 19:35:42.949 TRACE 97586 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [root]
Copy the code

The original log + org. Hibernate. EmptyInterceptor

Org. Hibernate. EmptyInterceptor provide hooks, hibernate itself provides the entity of curd hook. Rewrite the EmptyInterceptor method to implement a count. But the onPrepareStatement method is just an event before the SQL is assembled, and it is not a complete SQL.

✔️ can display SQL
❌ cannot be displayed in a row with parameters
❌ cannot display the limit parameter
✔ ️ can count
❌ Cannot record the time

spring.jpa.properties.hibernate.ejb.interceptor=com.vison.itdoc.config.HibernateInterceptor
Copy the code

public class HibernateInterceptor extends EmptyInterceptor {
    
    @Override
    public boolean onLoad(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) {
// Log.info("onload..." , entity)
        return true;
    }
    
    @Override
    public String onPrepareStatement(String string) {
        // count++
        return INSTANCE.onPrepareStatement(string);
    }
    
    @Override
    public void afterTransactionCompletion(Transaction t) {
        INSTANCE.afterTransactionCompletion(t);
        Log.info("after trans complete", t); }}Copy the code

log4jdbc

Log4jdbc can solve the problem of SQL complete display and record time

2021-02-23 19:59:13.709 INFO 97586 -- [NIO-8081-exec-1] JdbC.sqlTiming: select posts0_.id as id1_2_, posts0_.create_time as create_t2_2_, posts0_.modify_time as modify_t3_2_, posts0_.content as content4_2_, posts0_.title as title5_2_ from posts posts0_ where 1=1 order by posts0_.id asc limit 10 ; {executed in 1 msec}Copy the code

It is also possible to define SQL records executed for more than a certain amount of time as type error.

        <dependency>
            <groupId>com.googlecode.log4jdbc</groupId>
            <artifactId>log4jdbc</artifactId>
            <version>1.2</version>
            <scope>runtime</scope>
        </dependency>

Copy the code

spring.datasource.driver-class-name: net.sf.log4jdbc.DriverSpy
Mysql > log4JDBC
spring.datasource.url=jdbc:log4jdbc:mysql://localhost:3306/xxxx? useUnicode=true&characterEncoding=UTF-8
Oracle url with log4JDBC
# spring. The datasource. Url: JDBC: log4jdbc: oracle: thin: @ 127.0.0.1:1521: the former

Copy the code

Note Add spring.datasource. Driver-class-name and change spring.datasource. Url to JDBC: log4JDBC

Log4jdbc.properties can define more configurations

Configure the package or class to match the path that needs to be logged
#log4jdbc.debug.stack.prefix=com.drp
# log4JDBC loaded drivers (driver name)
#log4jdbc.drivers=oracle.jdbc.OracleDriver
log4jdbc.auto.load.popular.drivers=true
Display a WARN warning in the log
log4jdbc.statement.warn=true
SQL statements that take longer to execute than this value will be recorded as a WARN level.
log4jdbc.sqltiming.warn.threshold=2000
SQL statements that take longer than this value will be recorded as error.
log4jdbc.sqltiming.error.threshold=3000
# log Boolean as 'true'/'false' or 1/0. It is set to false by default and disabled for portability.
#log4jdbc.dump.booleanastruefalse=true
The maximum number of characters in a line is 90 by default
#log4jdbc.dump.sql.maxlinelength=90
Dump the entire stack trace by default false if dumped in debug mode
log4jdbc.dump.fulldebugstacktrace=false

# Whether to record certain types of statements. Default is true
log4jdbc.dump.sql.select=true
log4jdbc.dump.sql.insert=true
log4jdbc.dump.sql.delete=true
log4jdbc.dump.sql.update=true
log4jdbc.dump.sql.create=true

Add a semicolon at the end of the output SQL. Default is false
log4jdbc.dump.sql.addsemicolon=true

# Set this to false to not prune recorded SQL
log4jdbc.trim.sql=true
# Set this to false without removing additional empty lines
log4jdbc.trim.sql.extrablanklines=true

#log4jdbc.suppress.generated.keys.exception=false


Copy the code

✔️ can display SQL
✔️ can be displayed with parameters
✔️ displays the limit parameter
✔ ️ can count
✔️ records single SQL time
❌ The total time cannot be collected

The downside is that log4JDBC alone does not suffice. Theoretically log4jdbc + org. Hibernate. EmptyInterceptor can meet the demand

P6Spy

After the test, P6Spy is found to meet the requirements most:

✔️ can display SQL
✔️ cannot be displayed with parameters
✔️ cannot display the limit parameter
✔ ️ can count
✔️ Cannot record the time
✔️ supports hooks before and after curd events. Hook parameters return SQL and execution time and exception information 🚀

        <dependency>
            <groupId>p6spy</groupId>
            <artifactId>p6spy</artifactId>
            <version>3.9.1</version>
        </dependency>

Copy the code

Same as log4JDBC, driver and URL need to be changed

spring.datasource.driver-class-name=com.p6spy.engine.spy.P6SpyDriver
spring.datasource.url=jdbc:p6spy:mysql://localhost:3306/test? useLegacyDatetimeCode=false&serverTimezone=UTC
Copy the code

Psy. Properties can define more configurations

#modulelist=com.p6spy.engine.spy.P6SpyFactory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFact ory
modulelist=com.vison.itdoc.config.CustomeP6Factory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
#moduelist is key, I'm using a custom Factory here, because I need to customize the event
appender=com.p6spy.engine.spy.appender.Slf4JLogger
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=%(executionTime) ms|%(category)|%(sql)
excludecategories=result,resultset,info,debug
Copy the code

The SQL and time consuming information is displayed using the default configuration normally

 4 ms|statement|select admin0_.id as id1_0_, admin0_.create_time as create_t2_0_, admin0_.modify_time as modify_t3_0_, admin0_.email as email4_0_, admin0_.password as password5_0_, admin0_.status as status6_0_, admin0_.username as username7_0_ from admin admin0_ where admin0_.username='root'
Copy the code

You can see the elapsed time information and the actual parameters

Custom events

Modulelist = com. P6spy. Engine. Spy. P6SpyFactory to customize the Factory

Custom Factory

public class CustomeP6Factory implements com.p6spy.engine.spy.P6Factory {

    @Override
    public P6LoadableOptions getOptions(P6OptionsRepository optionsRepository) {
        return new P6SpyOptions(optionsRepository);
    }

    @Override
    public JdbcEventListener getJdbcEventListener(a) {
        return new P6spyListener(); // Use a custom Listener}}Copy the code

Custom events

public class P6spyListener extends JdbcEventListener {

    @Override
    public void onAfterExecuteQuery(PreparedStatementInformation statementInformation, long timeElapsedNanos, SQLException e) {
        App.sqlCount.incrementAndGet();
        Log.info("execute query...", statementInformation.getSqlWithValues());
    }

    @Override
    public void onAfterExecuteUpdate(PreparedStatementInformation statementInformation, long timeElapsedNanos, int rowCount, SQLException e) {
        App.sqlCount.incrementAndGet();
        Log.info("execute update..", statementInformation.getSqlWithValues());
    }

    @Override
    public void onAfterExecute(StatementInformation statementInformation, long timeElapsedNanos, String sql, SQLException e) {
        Log.info("execute..", statementInformation.getSqlWithValues()); }}Copy the code

As you can see, I did the SQL count in the custom event. I can then print the total NUMBER of SQL executions per request at the end of the request.

public class RequestInitInterceptor implements HandlerInterceptor {

    public RequestInitInterceptor(a) {}@Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {
        App._uniq_req_no = UUID.randomUUID().toString();
        App.sqlCount = new AtomicInteger(0);
        Log.setMsgTraceNo(App._uniq_req_no);
        Log.info("request start...", handler);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
            throws Exception {
        Log.info(String.format("Finish request SQL count :%s", App.sqlCount)); }}Copy the code

Because the event parameter also gives timeElapsedNanos, we can finally count the time taken for all SQL executions. This allows us to see exactly what the most time-consuming operations are within a request. Achieve similar effects to the following:

Cooperate with customDispatcherServletIt can record request data, return data, SQL execution data times, and time consuming

The 2021-03-01 11:19:40. 694 | | DEBUG | | C.V.I.C.L oggableDispatcherServlet | | | | GET "/ admin/posts? page=1&rows=10&sort=id&desc=false", The parameters = {masked} 2021-03-01 11:19:40. 698 | | INFO | | C.V.I.C.R.P reHandle: 32 | | 6 ebd23e2 - f58 fc32-4 - a5b8 - fd39d496d0d4 | |  request start... | | 2021-03-01 11:19:40. 716 | | INFO | | C.V.I.C.P.O nAfterExecuteQuery: 23 | | 6 ebd23e2 - f58 fc32-4 - a5b8 - fd39d496d0d4 | | execute SQL | | select count (*) as col_0_0_ from posts posts0_ time-consuming 2 ms 11:19:40 2021-03-01. 734 | | DEBUG | | C.V.I.C.A.P.G et: 44 | | 6 ebd23e2 - f58 fc32-4 - a5b8 - fd39d496d0d4 | | get number 35 11:19:40. 2021-03-01 740 | | DEBUG | | C.V.I.S.P.Q uery: 39 | | 6ebd23e2-fc32-4f58-a5b8-fd39d496d0d4 || Page request [number: 0, size 10, sort: id: ASC] 2021-03-01 11:19:40. 762 | | INFO | | C.V.I.C.P.O nAfterExecuteQuery: 23 | | 6 ebd23e2 - f58 fc32-4 - a5b8 - fd39d496d0d4 | | Execute SQL | | select posts0_. Id as id1_2_, posts0_. Create_time as create_t2_2_, posts0_. Modify_time as modify_t3_2_, posts0_.content as content4_2_, Posts0_. Title as title5_2_ from posts posts0_ WHERE true=1 order by posts0_ 11:19:40. 777 | | INFO | | C.V.I.C.P.O nAfterExecuteQuery: 23 | | 6 ebd23e2 - f58 fc32-4 - a5b8 - fd39d496d0d4 | | execute SQL | | select Count (posts0_. Id) as col_0_0_ from posts posts0_ where true = 1 takes 4 ms 11:19:40 2021-03-01. 809 | | INFO | | c.v.i.c.R.afterCompletion:39 || 6ebd23e2-fc32-4f58-a5b8-fd39d496d0d4 || finish request... | | SQL execution times: 3 SQL total time: 9 ms 11:19:40. 2021-03-01 819 | | INFO | | C.V.I.C.L.D oDispatch: 52 | | 6ebd23e2-fc32-4f58-a5b8-fd39d496d0d4 || {" uri ":"/admin/posts ", "clientIp" : "127.0.0.1", "method" : "GET", "request" : {" page ": /" 1 ", "rows" : [] "10", "sort" : (" id "), "desc" : [ "False"]}, "status" : 200, the "response" : {" code ": 0," MSG ":" success ", "data" : {" docs ": {" content" : [{" id ": 1," createTime ":" the 2021-02-22 T03: 53:02. 039 + 0800 ", "modifyTime" : "the 2021-02-22 T03:53:02. 039 + 0800", "title" : "test", "content" : "# test # test \ n \ n \ n \ n# > test To "}, {" id ": 2," createTime ":" the 2021-02-22 T09:57:32. 837 + 0800 ", "modifyTime" : "the 2021-02-22 T09:57:32. 837 + 0800", "title" : "test2", "co Ntent ":" test2 "}, {" id ": 3," createTime ":" the 2021-02-22 T10:07:37. 769 + 0800 ", "modifyTime" : "the 2021-02-22 T10:07:37. 769 + 0800", "title" : "Test3", "content", "test3"}, {" id ": 4," createTime ":" the 2021-02-22 T10: verily. 691 + 0800 ", "modifyTime" : "the 2021-02-22 T10: verily. 691 + 080 0","title":"test4","content":"## The secondary title "}, {" id ": 5," createTime ":" the 2021-02-22 T10: nothing. 925 + 0800 ", "modifyTime" : "the 2021-02-22 T10: nothing. 925 + 0800", "title" : "test5"," Content ":" test5 "}, {" id ": 6," createTime ":" the 2021-02-22 T18: behold. 530 + 0800 ", "modifyTime" : "the 2021-02-22 T18: behold. 530 + 0800", "the title Test6 ":" ", "content" : "test6"}, {" id ": 7," createTime ":" the 2021-02-22 T19:50:56. 805 + 0800 ", "modifyTime" : "the 2021-02-22 T19:50:56. 805 + 0 800 ", "title" : "test7", "content" : "t12212"}, {" id ": 8," createTime ":" the 2021-02-23 T17: young. 492 + 0800 ", "modifyTime" : "the 2021-02-23 T17 : young. 492 + 0800 ", "title" : "test", "content" : "# # # Secondary title "}, {9, "id" : "createTime" : "the 2021-02-23 T21:02:08. 924 + 0800", "modifyTime" : "the 2021-02-23 T21:02:08. 924 + 0800", "title" : "21", "con Tent ":" 12121 "}, {" id ": 10," createTime ":" the 2021-02-24 T09:53:08. 278 + 0800 ", "modifyTime" : "the 2021-02-24 T09:53:08. 278 + 0800", "title" : "test insert","content":"test insert"}],"pageable":{"sort":{"unsorted":false,"sorted":true,"empty":false},"offset":0,"pageNumber":0,"pageSize":10,"pag ed":true,"unpaged":false},"totalPages":4,"totalElements":35,"last":false,"numberOfElements":10,"first":true,"number":0," sort":{"unsorted":false,"sorted":true,"empty":false},"size":10,"empty":false}},"uniq_req_no":"6ebd23e2-fc32-4f58-a5b8-fd 39 d496d0d4 "}} 2021-03-01 11:19:40. 820 | | DEBUG | | C.V.I.C.L oggableDispatcherServlet | | 6ebd23e2-fc32-4f58-a5b8-fd39d496d0d4 || Completed 200 OKCopy the code

Spring-boot records the total SQL time and count of each request

Spring native capabilities

The original log + org. Hibernate. EmptyInterceptor

log4jdbc

P6Spy

Custom events

Related Posts

Java. Lang. NullPointerException FAQ | Java Debug notes

2.5 Apache Flink EventTime and Windows

The Facebook HVVM engine will move from PHP to Hack