# Something like sql\_tracker for Crystal

**URL:** <https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030>\
**Category:** Community\
**Created:** [September 27, 2023, 9:22pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030 "2023-09-27T21:22:21Z")\
**Posts on this page:** 12\
**Page:** 1

<div class="post-metadata">

**Author:** ![hugopl](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/hugopl/32/970_2.png) [@hugopl](https://forum.crystal-lang.org/u/hugopl)\
**Post date:** [September 27, 2023, 9:22pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/1 "2023-09-27T21:22:21Z")

</div>

Hi,

The problem:

- I want to enable a “query counter” and a query threshold, so I can enable this on CI using an environment variable and the test just explodes if we pass the threshold.

This is good to avoid N+1 issues (and others) that pass unnoticed by code review or just to try to keep the number of SQL queries issued under a safe limit.

Do you guys know any solution for Crystal? Or do I need to write my own shard?

---

<div class="post-metadata">

**Author:** ![mdwagner](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/mdwagner/32/1077_2.png) [@mdwagner](https://forum.crystal-lang.org/u/mdwagner)\
**Post date:** [September 28, 2023, 11:57am UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/2 "2023-09-28T11:57:50Z")

</div>

I used this gem extensively in the past in my Rails projects: [GitHub - civiccc/db-query-matchers: RSpec matchers for database queries](https://github.com/civiccc/db-query-matchers). I haven’t seen one in Crystal though. But I’d think it should be relatively easy with crystal-db interface, right?

---

<div class="post-metadata">

**Author:** ![bcardiff](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/bcardiff/32/3_2.png) [@bcardiff](https://forum.crystal-lang.org/u/bcardiff)\
**Post date:** [September 28, 2023, 12:47pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/3 "2023-09-28T12:47:15Z")

</div>

I’m not aware of any matchers. But they should be able to be built on top of [Add logging for executing queries by bcardiff · Pull Request #134 · crystal-lang/crystal-db · GitHub](https://github.com/crystal-lang/crystal-db/pull/134) probably

---

<div class="post-metadata">

**Author:** ![hugopl](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/hugopl/32/970_2.png) [@hugopl](https://forum.crystal-lang.org/u/hugopl)\
**Post date:** [September 28, 2023, 5:33pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/4 "2023-09-28T17:33:09Z")

</div>

The project uses Avram as ORM, so initially I though about attach it to avram query log, but I was thinking more about something that attaches to crystal-db itself, so I can de-couple it from the ORM and the database driver at the same time… this PR on crystal-db will make everything possible. Thanks!

---

<div class="post-metadata">

**Author:** ![hugopl](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/hugopl/32/970_2.png) [@hugopl](https://forum.crystal-lang.org/u/hugopl)\
**Post date:** [January 16, 2024, 10:32pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/5 "2024-01-16T22:32:39Z")

</div>

Known from what line of code the log was triggered is easy by monkey pacthing the Log class, but this is useless because I would like to known not where the Log entry was created, but where’s the code that triggered the query, and this depends on the ORM being used.

Anyway, this Log monkey patch can be useful for someone.

```auto
require "log"

class Log
  {% for method in %w(trace debug info notice warn error fatal) %}
    {% severity = method.id.camelcase %}
    def {{method.id}}(*, exception : Exception? = nil, file = __FILE__ , line = __LINE__ )
      severity = Severity::{{severity}}
      return unless level <= severity
      return unless backend = @backend

      dsl = Emitter.new(@source, severity, exception)
      result = yield dsl

      case result
      when Entry
        new_context = result.context.extend({file: file, line: line})
        new_entry = Entry.new(result.source, result.severity, result.message, new_context, result.exception, timestamp: result.timestamp)
        backend.dispatch new_entry
      when Nil
        # emit nothing
      else
        backend.dispatch dsl.emit(result.to_s, file: file, line: line)
      end
    end
  {% end %}
end

class Foo
  Log = ::Log.for("Foo")

  def initialize
    Log.info { "ctor" }
    Log.info &.emit("with emit", emit_var: "working")
  end
end

Log.info { "Top namespace" }
Foo.new

```

Prints:

```auto
2024-01-16T22:26:37.932473Z INFO - Top namespace -- file: "/usr/lib/crystal/log/main.cr", line: 38
2024-01-16T22:26:37.932476Z INFO - Foo: ctor -- file: "/home/hugo/src/tmp/log_location.cr", line: 32
2024-01-16T22:26:37.932476Z INFO - Foo: with emit -- file: "/home/hugo/src/tmp/log_location.cr", line: 33

```

I.e., it’s useful if you ignore that it get the wrong location for top level calls and eats the emit args used 😅

---

<div class="post-metadata">

**Author:** ![jgaskins](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/jgaskins/32/2449_2.png) [@jgaskins](https://forum.crystal-lang.org/u/jgaskins)\
**Post date:** [January 17, 2024, 3:10am UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/6 "2024-01-17T03:10:34Z")

</div>

I’m a bit late to this thread, but this is something I do in a few apps, too. For example, I have a file that patches `Fiber` and `DB::Statement` to collect all of the queries and stick them onto a property of the current fiber:

```crystal
require "db/statement"

class Fiber
  getter query_counts : Hash(String, Int32) do
    Hash(String, Int32).new do |h, k|
      h[k] = 0
    end
  end
end

class DB::Statement
  def_around_query_or_exec do |asdf|
    yield
  ensure
    Fiber.current.query_counts[command] += 1
  end
end

```

Then I have an `HTTP::Handler` class that collects this over the course of a request and logs them out. I control how much it logs via an env var because logging can get expensive.

```crystal
require "http"
require "log"

class DB::QueryCounter
  include HTTP::Handler

  LOG_PERCENTAGE = ENV.fetch("LOG_QUERY_COUNT_PERCENTAGE", "0").to_f
  Log = ::Log.for(self.class)

  def call(context)
    if rand < LOG_PERCENTAGE
      call_with_logging context
    else
      call_without_logging context
    end
  end

  def call_with_logging(context)
    Fiber.current.query_counts.clear

    begin
      call_without_logging context
    ensure
      Log.info &.emit "Queries",
        total: Fiber.current.query_counts.sum { |_, count| count },
        counts: Fiber.current.query_counts,
        method: context.request.method,
        path: context.request.path
    end
  end

  def call_without_logging(context)
    call_next context
  end
end

```

So each HTTP request outputs something like this (some parts redacted), which I can use GCP log search for and alert if `jsonPayload.data.total` exceeds some threshold for some endpoints:

```json
{
  "timestamp": "2024-01-17T02:08:45.351099000Z",
  "severity": "info",
  "source": "query_counter",
  "message": "Queries",
  "data": {
    "total": 5,
    "counts": {
      "SELECT accounts.id, accounts.avatar_url, accounts.github_login, accounts.created_at, accounts.updated_at FROM accounts WHERE id = $1 LIMIT $2": 1,
      "SELECT oauth_user_tokens.id, oauth_user_tokens.account_id, oauth_user_tokens.value, oauth_user_tokens.expires_at, oauth_user_tokens.refresh_token, oauth_user_tokens.scope, oauth_user_tokens.created_at, oauth_user_tokens.updated_at FROM oauth_user_tokens WHERE id = $1 LIMIT $2": 1,
      "SELECT [columns] FROM [table] WHERE [column] = $1 LIMIT $2": 1,
      "INSERT INTO github_repositories (\"name\", \"full_name\", \"github_id\", \"node_id\") VALUES ($1, $2, $3, $4) ON CONFLICT (github_id) DO UPDATE SET name = $5, full_name = $6, github_id = $7, node_id = $8 RETURNING github_repositories.id, github_repositories.name, github_repositories.full_name, github_repositories.node_id, github_repositories.github_id, github_repositories.created_at, github_repositories.updated_at": 1,
      "SELECT [columns] FROM [table1] INNER JOIN [table2] AS [rel2] ON [table1].[fk]_id = rel2.id INNER JOIN [table3] AS [rel3] ON [rel2].author_id = [rel3].id INNER JOIN accounts AS enqueued_by ON [rel3].enqueued_by_id = enqueued_by.id WHERE [rel2].[fk]_id = $1": 1
    },
    "method": "GET",
    "path": "/the/path/goes/here"
  }
}

```

This way I can filter my logs for exactly which endpoints are running so many queries and see which ones they’re running so many of since it includes the count of each query executed. I also have a similar middleware object that does the same for background jobs.

---

<div class="post-metadata">

**Author:** ![jwoertink](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/jwoertink/32/50_2.png) [@jwoertink](https://forum.crystal-lang.org/u/jwoertink)\
**Post date:** [January 17, 2024, 5:49pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/7 "2024-01-17T17:49:01Z")

</div>

We can also add some patches to Avram if that would help.

Also, in case you didn’t know, you can subscribe to `Avram::Events::QueryEvent` to get the queries as well as subscribe to `Avram::Events::FailedQueryEvent` for the failed queries.

```crystal
Avram::Events::QueryEvent.subscribe do |event, duration|
  puts event.query
  puts event.args
end

```

You can store that separately to do some custom tracking if you needed.

---

<div class="post-metadata">

**Author:** ![hugopl](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/hugopl/32/970_2.png) [@hugopl](https://forum.crystal-lang.org/u/hugopl)\
**Post date:** [January 18, 2024, 1:04pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/8 "2024-01-18T13:04:26Z")

</div>

All the solutions proposed are nice to discover what queries fired during a request, however I was looking for more information, the location in user code that fired the query, that is what SQLTracker ruby gem does. It may be possible to do the same in Crystal by querying the stack trace, probably slow as hell, but for a development tool it may work.

---

<div class="post-metadata">

**Author:** ![jgaskins](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/jgaskins/32/2449_2.png) [@jgaskins](https://forum.crystal-lang.org/u/jgaskins)\
**Post date:** [January 18, 2024, 11:02pm UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/9 "2024-01-18T23:02:06Z")

</div>

> [@hugopl](#):
>
> I was looking for more information, the location in user code that fired the query,

Ahh, sorry, I misunderstood. Still quite doable with very little code with the same `DB::Statement.def_around_query_or_exec` trick as above:

```crystal
class DB::Statement
  def_around_query_or_exec do |asdf|
    yield
  ensure
    # `caller` is expensive, so we only want to do this with a
    # verbose logging setting that we likely wouldn't have enabled
    # in production
    if Log.level <= ::Log::Severity::Debug
     # Filter out this stack frame
      caller.each within: 1.. do |location|
        # Only show application code, no library code
        if location.starts_with?("src/")
          Log.debug &.emit "called from", location: location
        end
      end
    end
  end
end

```

Result:

```plaintext
2024-01-18T22:54:57.503170Z DEBUG - db: Executing query -- query: "SELECT [columns] FROM [table] WHERE [column] = $1 LIMIT $2", args: ["5509c6f9-e265-48b0-8d03-39b7ec6c8d7e", 1]
2024-01-18T22:54:57.536851Z DEBUG - db: called from -- location: "src/routes/organizations.cr:48:26 in 'call'"
2024-01-18T22:54:57.540394Z DEBUG - db: called from -- location: "src/routes/web.cr:32:32 in 'call'"
2024-01-18T22:54:57.582668Z DEBUG - db: called from -- location: "src/web.cr:44:7 in 'call'"

```

---

<div class="post-metadata">

**Author:** ![Blacksmoke16](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/blacksmoke16/32/1241_2.png) [@Blacksmoke16](https://forum.crystal-lang.org/u/Blacksmoke16)\
**Post date:** [January 19, 2024, 1:06am UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/10 "2024-01-19T01:06:39Z")

</div>

I don’t like that the location info is added as separate log messages. I think you’d be better off maybe doing something slightly different. Maybe wrap the `yield` in a `Log.with_context`, do your logic to parse the frames and set them on the `Log.context`? This way they’ll be a part of the `Log::Entry` the `DB` shard emits with the query/args.

Related: [Improve Exception backtrace API · Issue #10681 · crystal-lang/crystal · GitHub](https://github.com/crystal-lang/crystal/issues/10681)

---

<div class="post-metadata">

**Author:** ![jgaskins](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/jgaskins/32/2449_2.png) [@jgaskins](https://forum.crystal-lang.org/u/jgaskins)\
**Post date:** [January 19, 2024, 2:11am UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/11 "2024-01-19T02:11:36Z")

</div>

It depends the log formatter being used and how you consume your logs. With a JSONFormatter and a log reader that renders that well, that’s probably preferable.

But with the default formatter when you’re only using this in development reading it in the terminal output, putting the callstack in the same log entry is not as useful.

 ![image](https://canada1.discourse-cdn.com/flex036/uploads/crystal_lang/original/2X/3/3590592f8aed9308dab3fb765b359ac373cea0ba.png)

> [@Blacksmoke16](#):
>
> Maybe wrap the `yield` in a `Log.with_context`

This doesn’t set the context before logging. The default implementation [logs before yielding](https://github.com/crystal-lang/crystal-db/blob/3eaac85a5d4b7bee565b55dcb584e84e29fc5567/src/db/statement.cr#L147-L150). In order to output what I had above, I had to override `DB::Statement#emit_log`.

---

<div class="post-metadata">

**Author:** ![Blacksmoke16](https://yyz2.discourse-cdn.com/flex036/user_avatar/forum.crystal-lang.org/blacksmoke16/32/1241_2.png) [@Blacksmoke16](https://forum.crystal-lang.org/u/Blacksmoke16)\
**Post date:** [January 19, 2024, 2:18am UTC](https://forum.crystal-lang.org/t/something-like-sql-tracker-for-crystal/6030/12 "2024-01-19T02:18:23Z")

</div>

Ahh gotcha, in that case wonder if you could call `previous_def` within a `Log.with_context` block? 🤔.

I have thought about having like `file = __FILE__ ` and `line = __LINE__ ` defaults on the log methods and pass those through. But that still wouldn’t help as they’d be where the log was emitted, not where the query was made from 😕. Guess you could do something similar on some sort of repo method, with the actual query being in a `Log.context` block, but a bit less than ideal yea :/.