Add logging for executing queries

[bcardiff]

See #134 (comment) for the final state of the PR

--

This PR adds a debug "Executing query" message to the db log source. The query and the arguments are passed as local metadata query and `args.

The arguments are translated to Log::Metadata::Value via DB::Statement#arg_to_log method.

For example in crystal-pg the following code would allow customizing how the Geo::Point argument is translated.

class DB::Statement
  private def arg_to_log(arg : PG::Geo::Point)
    Log::Metadata::Value.new("(#{arg.x}, #{arg.y})::point")
  end
end

By default, arg.to_s is used for all the values that are not directly supported by Log::Metadata::Value.

DB::Statement#before_query_or_exec & after_query_or_exec protected methods can be used to hook around the statement execution.

The DB::Statement has now a command : String property that is specified during initialization. This the breaking-change part of this PR.

Fixes #62
Closes #64

[asterite]

This is great! But extending the way logging works by adding overloads to undocumented, private methods might be a bit confusing or obscure.

How about introducing an "interface" (a module) that provides a way to turn an argument into a DB log argument, make the existing objects implement it, and let the implementation use to_s for objects that don't conform to that interface?

Or some other way to make this a bit less hidden.

[bcardiff]

I didn't want to pollute the Object with this. And is something only drivers will need.

Having a public module to encapsulate that interface is good enough for me. Does that sounds good to you?

[jwoertink]

So this is something where crystal-pg, in this case, would implement any overrides with arg_to_log in the PG::Statement class it has? If ORMs wanted to add in their own, we'd have to create a new sub class or override these existing?

[bcardiff]

@jwoertink overriding the method will do.

[bcardiff]

With the last commit I applied the same pattern as in crystal-lang/crystal#9756 .
It will allow measuring the elapsed time in the query without additional heap memory.

class DB::Statement
  def_around_query_or_exec do |args|
    start = Time.monotonic
    res = yield
    elapsed = Time.monotonic - start
    Log.debug &.emit("Finished", elapsed: "#{elapsed.total_seconds.humanize(precision: 2, significant: false)}s")
    res
  end
end

[bcardiff]

The DB::MetadataValueConverter#arg_to_log is the final location to define how arguments are translated to Log::Metadata::Value

class DB::MetadataValueConverter
  def arg_to_log(arg : PG::Geo::Point)
    Log::Metadata::Value.new("(#{arg.x}, #{arg.y})::point")
  end
end

And the DB::Statement.def_around_query_or_exec macro as explained in #134 (comment) is to be used to hook into the command execution lifecycle.