Skip to main content

SQL Log

For ORM, it is important to print generated SQL in logs.

Enable SQL Log

There are two ways to enable SQL logs:

  • When using Spring Boot Starter, there are two ways to configure:

    • Modify application.yml (or application.properties)

      jimmer:
      show-sql: true
    • Configure global Bean

      @Bean
      public Executor executor() {
      return Executor.log();
      }
      info

      If both methods above are used (not recommended), the second method takes precedence.

  • Use underlying API

    JSqlClient sqlClient = JSqlClient
    .newBuilder()
    .setExecutor(Executor.log())
    ...Omit other configurations...
    .build();

The actual printed logs are as follows:

jimmer> sql: select tb_1_.ID, tb_1_.CREATED_TIME, tb_1_.MODIFIED_TIME, tb_1_.NAME, tb_1_.EDITION, tb_1_.PRICE, tb_1_.STORE_ID from BOOK tb_1_  where lower(tb_1_.NAME) like ?  order by tb_1_.NAME asc, tb_1_.EDITION desc limit ?, ?, variables: [%graphql%, 0, 10], purpose: QUERY
caution

If only the SQL log is turned on, the above log will not wrap.

The log has three parts:

  • sql: The SQL statement being executed

  • variables: The JDBC parameters associated with sql, which is an array whose length is the same as the number of "?" characters in sql.

  • purpose: The reason why the SQL is executed, which is an enum with the following values:

    • QUERY: Query directly executed by developers

    • UPDATE: Operations performed by developers via update statements

    • DELETE: Operations performed by developers via delete statements

    • LOAD: Query executed automatically by Jimmer to get the value of associated properties or calculated properties in object fetcher.

    • EXPORT: The user initiates a query to other microservices, and its object fetcher contains remote associations pointing to the current service. Jimmer automatically exposes the data of this service.

    • MUTATE: Operations specified by developers via save commands

    • EVICT: In some cases, the cache that should be cleared cannot be determined solely based on the event information of Jimmer triggers. Jimmer will automatically execute some queries to accurately determine which caches should be cleared.

Pretty SQL

In the previous example, the SQL log is printed in one line, which is poorly readable.

Therefore, the SQL needs to be formatted. There are two implementation methods:

  • When using Spring Boot Starter

    Modify application.yml (or application.properties)

    jimmer:
    show-sql: true
    pretty-sql: true
  • When using underlying API

    JSqlClient sqlClient = JSqlClient
    .newBuilder()
    .setExecutor(Executor.log())
    .setSqlFormatter(SqlFormatter.PRETTY)
    ...Omit other configurations...
    .build();

The log output is as follows:

Execute SQL===>
Purpose: QUERY
SQL: select
tb_1_.ID,
tb_1_.CREATED_TIME,
tb_1_.MODIFIED_TIME,
tb_1_.NAME,
tb_1_.EDITION,
tb_1_.PRICE,
tb_1_.STORE_ID
from BOOK tb_1_
where
lower(tb_1_.NAME) like ? /* %graphql% */ ❶
order by
tb_1_.NAME asc,
tb_1_.EDITION desc
limit ? /* 0 */ ❷, ? /* 10 */ ❸
JDBC response status: success
Time cost: 8ms
<===Execute SQL

In this mode:

  • The SQL statement will be automatically formatted, automatically wrapped, and automatically indented.

  • ❶ ❷ ❸ Unlike the previous example, all JDBC parameters are not printed together, but injected into the original SQL as comments.

  • Other information will be printed, such as whether SQL execution is successful, total execution time of SQL. For insert, update, delete operations, the number of affected rows will also be printed.

Inline SQL Parameters

In the previous examples, the JDBC parameters in the SQL logs were inserted after the JDBC parameter placeholders ? as comment, e.g. ? /* %graphql% */.

Perhaps you want the parameters to be inlined into the SQL statement directly, making it look as if no JDBC parameters were used. This way, the SQL statement in the logs can be copied directly into a SQL IDE to execute.

There are two ways to achieve this

  • Using Spring Boot Starter:

    Modify application.yml (or application.properties):

    jimmer:
    show-sql: true
    pretty-sql: true
    inline-sql-variables: true
  • Using low-level API

    JSqlClient sqlClient = JSqlClient
    .newBuilder()
    .setExecutor(Executor.log())
    .setSqlFormatter(SqlFormatter.INLINE_PRETTY)
    ...other configs omitted...
    .build();

The log output is as follows:

Execute SQL===>
Purpose: QUERY
SQL: select
tb_1_.ID,
tb_1_.CREATED_TIME,
tb_1_.MODIFIED_TIME,
tb_1_.NAME,
tb_1_.EDITION,
tb_1_.PRICE,
tb_1_.STORE_ID
from BOOK tb_1_
where
lower(tb_1_.NAME) like '%graphql%' ❶
order by
tb_1_.NAME asc,
tb_1_.EDITION desc
limit 0 ❷, 10 ❸
JDBC response status: success
Time cost: 8ms
<===Execute SQL

In this mode, we can see the parameters at ❶ ❷ ❸ are directly inlined.

info

This only affects the logs. The actual SQL executed still uses JDBC parameters.

Embed Stack Trace

In addition to coding, developers often need to troubleshoot issues. Whether it is a functional error or a performance issue, the developer needs to investigate it.

If the SQL log only prints JDBC information centered on SQL, the user cannot associate the SQL log with the application code, which is not conducive to users troubleshooting.

Jimmer provides a configuration option that if specified, before executing SQL, it will check the stack trace information of the current thread.

However, these stack traces contain too much information, including infrastructure call frames represented by jdk, jdbc driver, jimmer and spring, while the business-related information that developers care about will be overwhelmed in the ocean of information.

This configuration type is java.util.Collection<String> allowing developers to specify multiple packages or class prefixes. Jimmer will use them to filter the stack trace information. If a call frame can pass the filter, Jimmer will consider it related to user business and include it in the callback parameter before execution.

For SQL log printing, call frames that can pass the filter will appear in the print output to help users troubleshoot issues.

There are two implementation methods:

  • When using Spring Boot Starter

    Modify application.yml (or application.properties)

    jimmer:
    show-sql: true
    pretty-sql: true
    executor-context-prefixes:
    - com.example.business
  • When using underlying API

    JSqlClient sqlClient = JSqlClient
    .newBuilder()
    .setExecutor(Executor.log())
    .setSqlFormatter(SqlFormatter.PRETTY)
    .setExecutorContextPrefixes(
    Collections.singleton(
    "com.example.business"
    )
    )
    ...Omit other configurations...
    .build();

The log output is as follows:

Execute SQL===>
--- Business related stack trace information --- ❶
com.example.business.BookService.findBooks(BookService.java:55) ❷
Purpose: QUERY
SQL: select
tb_1_.ID,
tb_1_.CREATED_TIME,
tb_1_.MODIFIED_TIME,
tb_1_.NAME,
tb_1_.EDITION,
tb_1_.PRICE,
tb_1_.STORE_ID
from BOOK tb_1_
where
lower(tb_1_.NAME) like ? /* %graphql% */
order by
tb_1_.NAME asc,
tb_1_.EDITION desc
limit ? /* 0 */, ? /* 10 */
JDBC response status: success
Time cost: 9ms
<===Execute SQL

At ❶ and ❷, the stack trace information of the thread executing the SQL operation is printed.

tip

However, a large amount of stack trace information is not blindly printed, only what users care about is printed.