Pyranid Logo

Core Concepts

Logging and Diagnostics

Pyranid provides tooling for runtime insight into SQL execution.

For many applications, it's important to understand exactly what queries are being run to keep on top of potential performance problems.

Further, it's often useful to mark specific queries for special processing - for example, you might want to log particularly slow or "special" SQL, or you might want to flag a query as needing Custom ResultSet Mapping.

Statement Logging

You may customize your Database with a StatementLogger.

Reasons you might do this include:

  • Writing queries and timing information to your logging system
  • Picking out slow queries for special logging/reporting
  • Collecting a set of queries executed across a unit of work for bulk analysis (e.g. a ThreadLocal<T> or ScopedValue<T> scoped to a single web request)
Database database = Database.forDataSource(dataSource)
  .statementLogger(new StatementLogger() {
    Duration SLOW_QUERY_THRESHOLD = Duration.ofMillis(500);

    @Override
    public void log(@Nonnull StatementLog statementLog) {
      if(statementLog.getTotalDuration().compareTo(SLOW_QUERY_THRESHOLD) > 0)
        out.printf("Slow query: %s\n", statementLog);
    }
  }).build();

StatementLog instances give you access to the following for each SQL statement executed:

  • statementContext
  • connectionAcquisitionDuration (optional)
  • preparationDuration (optional)
  • executionDuration (optional)
  • resultSetMappingDuration (optional)
  • batchSize (optional)
  • exception (optional)

References:

Statement Identifiers

For any data access method that accepts a sql parameter, you may alternatively provide a Statement, which permits you to specify an arbitrary identifier for the SQL.

If you do not explicitly provide a Statement, Pyranid will create one for you and generate its own identifier.

// Regular SQL
database.queryForObject("SELECT * FROM car LIMIT 1", Car.class);

// SQL in a Statement so we can give it an identifier
database.queryForObject(Statement.of(
    "random-car", 
    "SELECT * FROM car LIMIT 1"
  ), Car.class);

This is useful for tagging queries that should be handled specially. Some examples are:

  • Marking a query as "hot" so we don't pollute logs with it
  • Marking a query as "known to be slow" so we don't flag slow query alerts for it
  • Your InstanceProvider might provide custom instances based on resultset data
// Custom tagging system
enum QueryTag {
  HOT_QUERY,
  SLOW_QUERY
};

// This query fires every 3 seconds - 
// let's mark it HOT_QUERY so we know not to log it.
Executors.newScheduledThreadPool(1).scheduleAtFixedRate(() -> {
  database.transaction(() -> {
    List<Message> messages = database.queryForList(
      Statement.of(QueryTag.HOT_QUERY, """
        SELECT *
        FROM message_queue
        WHERE message_status_id=?
        LIMIT ?
        FOR UPDATE
        SKIP LOCKED
    """), Message.class, MessageStatusId.UNPROCESSED, BATCH_SIZE);

    // Implementation not shown
    processMessages(messages);
  });
}, 0, 3, TimeUnit.SECONDS);

A corresponding Database setup:

// Ensure our StatementLogger implementation takes HOT_QUERY into account 
Database database = Database.forDataSource(dataSource)
  .statementLogger(new StatementLogger() {
    @Override
    public void log(@Nonnull StatementLog statementLog) {
      // Log everything except HOT_QUERY
      Statement statement = statementLog.getStatementContext().getStatement();
      if(statement.getId() != HOT_QUERY)
        out.println(statementLog);
    }
  }).build();

References:

Internal Logging

Pyranid uses java.util.Logging internally for diagnostics. This is not normally useful for Pyranid users, but the usual way to hook into this is with SLF4J, which can funnel all the different logging mechanisms in your app through a single one, normally Logback. Your Maven configuration might look like this:

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.4.11</version>
</dependency>

<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>jul-to-slf4j</artifactId>
  <version>2.0.7</version>
</dependency>

You might have code like this which runs at startup:

// Bridge all java.util.logging to SLF4J
java.util.logging.Logger rootLogger = 
  java.util.logging.LogManager.getLogManager().getLogger("");

for (Handler handler : rootLogger.getHandlers())
  rootLogger.removeHandler(handler);

SLF4JBridgeHandler.install();

Don't forget to uninstall the bridge at shutdown time:

// Sometime later
SLF4JBridgeHandler.uninstall();

Note: SLF4JBridgeHandler can impact performance. You can mitigate that with Logback's LevelChangePropagator configuration option as described here.

Previous
Error Handling
Next
Javadoc