Pyranid | 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.withDataSource(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();

Database database = Database.withDataSource(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

Use Query::id(Object) to tag statements.

This is useful for tagging queries that should be handled specially. Why might you do this?

To mark a query as "hot" so we don't pollute logs with it
To mark a query as "known to be slow" so we don't flag slow query alerts for it
Your InstanceProvider might key on it to provide custom instances (e.g. during resultset mapping)

For example:

// This query fires every 3 seconds - 
// let's give it a special identifier so we know not to log it.
Executors.newScheduledThreadPool(1).scheduleAtFixedRate(() -> {
  // Safely "claim" some messages off the queue
  List<Message> messages = database.transaction(() ->
      Optional.of(database.query("""
        UPDATE message_queue
        SET message_status_id = :processing
        WHERE id IN (
          SELECT id
          FROM message_queue
          WHERE message_status_id = :unprocessed
          ORDER BY created_at
          LIMIT :limit
          FOR UPDATE
          SKIP LOCKED
        )
        RETURNING *
        """)
        .id("message-queue-claim")
        .bind("unprocessed", MessageStatusId.UNPROCESSED)
        .bind("processing", MessageStatusId.PROCESSING)
        .bind("limit", BATCH_SIZE)
        .fetchList(Message.class)))
      .orElseThrow();

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

// This query fires every 3 seconds - 
// let's give it a special identifier so we know not to log it.
Executors.newScheduledThreadPool(1).scheduleAtFixedRate(() -> {
  // Safely "claim" some messages off the queue
  List<Message> messages = database.transaction(() ->
      Optional.of(database.query("""
        UPDATE message_queue
        SET message_status_id = :processing
        WHERE id IN (
          SELECT id
          FROM message_queue
          WHERE message_status_id = :unprocessed
          ORDER BY created_at
          LIMIT :limit
          FOR UPDATE
          SKIP LOCKED
        )
        RETURNING *
        """)
        .id("message-queue-claim")
        .bind("unprocessed", MessageStatusId.UNPROCESSED)
        .bind("processing", MessageStatusId.PROCESSING)
        .bind("limit", BATCH_SIZE)
        .fetchList(Message.class)))
      .orElseThrow();

  // 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.withDataSource(dataSource)
  .statementLogger(new StatementLogger() {
    @Override
    public void log(@NonNull StatementLog statementLog) {
      // Log everything except "message-queue-claim"
      Statement statement = statementLog.getStatementContext().getStatement();
      if(!statement.getId().equals("message-queue-claim"))
        out.println(statementLog);
    }
  }).build();

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

References:

Database Metadata

The JDBC standard defines a DatabaseMetaData type, which provides comprehensive vendor-specific information about a database as a whole.

Pyranid exposes a Database::readDatabaseMetaData(DatabaseMetaDataReader) method which acquires a transient DatabaseMetaData instance on its own newly-borrowed JDBC Connection (managed by Pyranid internally).

The Connection does not participate in the active transaction, if one exists.

The Connection is automatically closed as soon as the closure completes.

Database database = Database.withDataSource(...).build();

database.readDatabaseMetaData(databaseMetaData -> {
  // e.g. "PostgreSQL"
  out.println(databaseMetaData.getDatabaseProductName());
});

Database database = Database.withDataSource(...).build();

database.readDatabaseMetaData(databaseMetaData -> {
  // e.g. "PostgreSQL"
  out.println(databaseMetaData.getDatabaseProductName());
});

Caution!

Your code should not retain a reference to the DatabaseMetaData instance outside the scope of the closure.