Module: DatabaseLogger

Defined in:
lib/middleware/database_logger.rb

Overview

Note:

While there were concerns about the performance impact of logging in the redis-rb gem, this middleware is designed to be optional and can be easily enabled or disabled as needed. The performance impact is minimal when logging is disabled, and the benefits during development and debugging often outweigh the slight performance cost when enabled.

DatabaseLogger is Valkey/RedisClient middleware.

This middleware addresses the need for detailed Database command logging, which was removed from the redis-rb gem due to performance concerns. However, in many development and debugging scenarios, the ability to log Database commands can be invaluable.

Examples:

Enable Database command logging

DatabaseLogger.logger = Logger.new(STDOUT)
RedisClient.register(DatabaseLogger)

Capture commands for testing

commands = DatabaseLogger.capture_commands do
  redis.set('key', 'value')
  redis.get('key')
end
puts commands.first[:command]  # => ["SET", "key", "value"]

See Also:

Constant Summary collapse

CommandMessage = 
Data.define(:command, :μs, :timeline)

Class Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Class Attribute Details

.commands ⇒ Array (readonly)

Gets the captured commands for testing purposes.

Returns:

  • (Array) —

    Array of command hashes with :command, :duration, :timeline



49
50
51
 
# File 'lib/middleware/database_logger.rb', line 49

def commands
  @commands
end

.logger ⇒ Logger?

Gets/sets the logger instance used by DatabaseLogger.

Returns:

  • (Logger, nil) —

    The current logger instance or nil if not set.



41
42
43
 
# File 'lib/middleware/database_logger.rb', line 41

def logger
  @logger
end

.max_commands ⇒ Integer

Gets/sets the maximum number of commands to capture.

Returns:

  • (Integer) —

    The maximum number of commands to capture.



45
46
47
 
# File 'lib/middleware/database_logger.rb', line 45

def max_commands
  @max_commands
end

.process_start ⇒ Float (readonly)

Gets the timestamp when DatabaseLogger was loaded.

Returns:

  • (Float) —

    The timestamp when DatabaseLogger was loaded.



53
54
55
 
# File 'lib/middleware/database_logger.rb', line 53

def process_start
  @process_start
end

Class Method Details

.append_command(message) ⇒ Array

Thread-safe append with bounded size

Parameters:

  • message (String) —

    The message to append.

Returns:

  • (Array) —

    The updated array of commands.



85
86
87
88
 
# File 'lib/middleware/database_logger.rb', line 85

def append_command(message)
  @commands.shift if @commands.size >= @max_commands
  @commands << message
end

.capture_commands { ... } ⇒ Array

Captures commands in a block and returns them. This is useful for testing to see what commands were executed.

Examples:

Test what Redis commands your code executes

commands = DatabaseLogger.capture_commands do
  my_library_method()
end
assert_equal "SET", commands.first[:command][0]
assert commands.first[:duration] > 0

Yields:

  • [] The block of code to execute while capturing commands.

Returns:

  • (Array) —

    Array of captured commands with timing information. Each command is a hash with :command, :duration, :timestamp keys.



75
76
77
78
79
 
# File 'lib/middleware/database_logger.rb', line 75

def capture_commands
  clear_commands
  yield
  @commands.to_a
end

.clear_commands ⇒ Array

Clears the captured commands array.

Returns:

  • (Array) —

    Empty array



57
58
59
60
 
# File 'lib/middleware/database_logger.rb', line 57

def clear_commands
  @commands.clear
  nil
end

.now_in_μs ⇒ Integer Also known as: now_in_microseconds

Returns the current time in microseconds. This is used to measure the duration of Database commands.

Alias: now_in_microseconds

Returns:

  • (Integer) —

    The current time in microseconds.



96
97
98
 
# File 'lib/middleware/database_logger.rb', line 96

def now_in_μs
  Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
end

Instance Method Details

#call(command, _config) ⇒ Object

Note:

Commands are always captured with minimal overhead for testing purposes. Logging only occurs when DatabaseLogger.logger is set.

Logs the Database command and its execution time.

This method is called for each Database command when the middleware is active. It always captures commands for testing and logs them if a logger is set.

Parameters:

  • command (Array) —

    The Database command and its arguments.

  • _config (Hash) —

    The configuration options for the Valkey/Redis connection.

Returns:

  • (Object) —

    The result of the Database command execution.



114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
 
# File 'lib/middleware/database_logger.rb', line 114

def call(command, _config)
  block_start = DatabaseLogger.now_in_μs
  result = yield
  block_duration = DatabaseLogger.now_in_μs - block_start
  lifetime_duration = (Time.now.to_f - DatabaseLogger.process_start).round(6)

  # We intentionally use two different codepaths for getting the
  # time, although they will almost always be so similar that the
  # difference is negligible.
  message = CommandMessage.new(command, block_duration, lifetime_duration)
  DatabaseLogger.append_command(message)

  # Log if logger is set
  DatabaseLogger.logger&.debug(Oj.dump(message.to_h, mode: :strict))

  result
end