bigpresh / bigpresh/Catalyst-Plugin-Profile-DBI-Log

Add per-query EXPLAIN links: design notes + DBI::Log findings

Open
#3 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Perl
Stars
0
Forks
0
Avg merge
1h 44m
Merged PRs (30d)
1

Description

## Idea

Add a link against each logged query in the `/dbi/log/show/...` view that runs
`EXPLAIN` for it and displays the plan. The plugin currently never needs a DB
handle of its own — DBI::Log hooks DBI globally, so we passively observe queries
made by handles we don't own. Running EXPLAIN means we'd need to *acquire* a
handle, which is a genuine change in the plugin's relationship to the app.

This ticket records the design discussion and the findings from digging into
DBI::Log to see what's actually feasible.

## Is "`$c->model` → DBIC → `$dbh`" a reasonable approach?

As a *default*, half-reasonable. As the *only* mechanism, no. Two problems:

**1. Bare `$c->model()` is unreliable exactly where it matters.** With no
arguments, Catalyst resolves `$c->config->{default_model}`, else the sole
registered model if there's only one; if there are several and no
`default_model`, it logs `Calling $c->model() will return a random model unless
you specify one of:` and returns an arbitrary one. Apps with a single model are
the apps where this barely matters. Apps with several are where we'd silently
produce a confidently wrong plan.

**2. More importantly — we wouldn't know which handle actually ran the query.**
DBI::Log hooks DBI globally, so a log file can contain queries from *every*
handle in the process, including the raw-DBI legacy paths that are the stated
reason this plugin exists (see the SEE ALSO section in the POD). Explaining a
query against the wrong database gives either an error or — worse — a
syntactically valid plan for a same-named table, which means nothing.

So: use the model as a *default*, but make it overridable and, ideally, checked.

### Proposed shape

```perl
'Plugin::Profile::DBI::Log' => {
explain => 1, # off by default
explain_model => 'DB', # model name, or...
explain_dbh => sub { my $c = shift; ... return $dbh }, # ...total override
},
```

Resolution order: `explain_dbh` coderef → named model → bare `$c->model` →
helpful error naming the models actually registered. The coderef costs about
three lines and is what makes this work for awkward apps rather than only tidy
ones.

Extraction should duck-type rather than assume DBIC:

```perl
$m->can('dbh') ? $m->dbh # Catalyst::Model::DBI
: $m->can('storage') ? $m->storage->dbh # C::M::DBIC::Schema (delegates)
: $m->can('schema') ? $m->schema->storage->dbh
: $m->can('result_source')? $m->result_source->schema->storage->dbh # if a ResultSet was named
: die helpful_message();
```

(That last case matters because `$c->model('DB::Foo')` returns a ResultSet, not
the schema model, and people will configure it that way by mistake.)

### Safety

**Plain `EXPLAIN` only — never `ANALYZE`.** PostgreSQL's `EXPLAIN` does not
execute the statement, even for `UPDATE`/`DELETE`; `EXPLAIN ANALYZE` does, as
does MySQL 8.0.18+. Sticking to plain EXPLAIN means no transaction wrapping is
needed at all, which in turn means we never disturb the app's shared handle or
collide with a DBIC `txn_scope_guard`.

Per-driver syntax: `EXPLAIN` (Pg/mysql), `EXPLAIN QUERY PLAN` (SQLite), bail
with a message otherwise. Knowing the driver requires knowing the handle — see
below.

## Findings: what DBI::Log gives us today

Verified against **DBI::Log 0.12** as released on CPAN (2024-08-09) — downloaded
fresh, not the local working copy. Both bugs below reproduce on the released
version.

### 1. Placeholders ARE inlined — but with two bugs

Confirmed in `pre_query()`: when `replace_placeholders` is on (the default), bind
values are substituted into the SQL via `$dbh->quote()`. So in principle logged
queries are directly EXPLAIN-able without needing to re-bind. Good news for this
feature. However, testing against SQLite turned up two real problems:

**(a) `execute(@args)` loses all bind values — they become `NULL`.**

```
$sth = $dbh->prepare("SELECT * FROM t WHERE a = ? AND b = ?");
$sth->execute(42, "o'brien");
→ logged as: SELECT * FROM t WHERE a = NULL AND b = NULL
```

This is a regression introduced by 0.10 ("Replace params in statements when
given with `$sth->bind_param()`"). 0.09 had no ParamValues handling and simply
consumed `@$args`, which worked.

**Already known and fixed upstream — but not released.** This is
zorgnax/dbilog#23 (open, Oct 2024, from the angle of a DBD::mysql segfault) and
zorgnax/dbilog#24 (closed — an exact duplicate of the symptom above, reported
against PostgreSQL). PR zorgnax/dbilog#25 fixed it, merged 2025-04-22, with
zorgnax/dbilog#26/#27 following up for drivers that index `ParamValues` from 0
rather than 1. Verified against current master: the query above now logs
correctly as `a = '42' AND b = 'o''brien'`.

The catch is that CPAN is still on 0.12 (2024-08-09), which predates all of
that — so anyone installing DBI::Log today still has the bug. See section 3.

Root cause: `pre_query()` runs *before* `$orig_execute`, and at that point
`$sth->{ParamValues}` is already populated with the placeholder keys but `undef`
values:

```
ParamValues BEFORE execute: { '1' => undef, '2' => undef }
ParamValues AFTER execute: { '1' => 42, '2' => 'x' }
```

The ParamValues override loop therefore clobbers the perfectly good `@$args`
with undef, and `quote(undef)` yields `NULL`.

Also, the comment there ("the params can be found in `$sth->{ParamValues}` and
they override arguments sent in to `$sth->execute()`") has it backwards: per the
DBI docs, `execute(@bind_values)` is equivalent to calling `bind_param` for each
beforehand, so the execute args are what win.

The merged fix guards on `grep defined, values %$values`, i.e. only trusts
`ParamValues` when it actually holds defined values, and otherwise falls back to
the execute args.

**Severity note:** DBIC binds via `bind_param()` then calls `$sth->execute()`
with no args (`DBIx::Class::Storage::DBI` lines ~2064 and ~2009), so DBIC
queries take the *working* path even on 0.12. The broken path is raw
`$sth->execute(@args)` — i.e. exactly the hand-rolled legacy DBI code this
plugin was written to catch.

**Worth knowing for the EXPLAIN feature:** the merged fix is not the whole
story. As pointed out in zorgnax/dbilog#23, falling back to execute args can
still misrepresent the value when the driver coerces it — e.g.
`bind_param(1, 3.14159, SQL_INTEGER)` logs `3.14159` though the DB saw `3`.
Getting this exactly right means reading `ParamValues` *after* execution, which
means moving log emission into `post_query()`. The author prefers to keep
logging in `pre_query()` (so hung queries still show up in the log), but has
said he'd accept a `log_post_query => 1` option that defers it; myrrhlin has a
`logging-after` branch that mostly implements this.

That option would suit this plugin well: we only ever read the log after the
request has finished, so we gain nothing from pre-execution logging, and
accurate bind values are exactly what EXPLAIN needs. Worth supporting upstream
and then setting it in our `use DBI::Log` line.

**(b) A literal `?` inside a string literal gets substituted, corrupting the SQL.**

```
$dbh->selectall_arrayref("SELECT * FROM t WHERE b = 'why?' AND a = ?", undef, 5);
→ logged as: SELECT * FROM t WHERE b = 'why'5'' AND a = ?
```

The replacement is a naive regex over `?` with no awareness of quoting, so it
eats the first `?` it finds wherever it is. This also affects PostgreSQL's JSON
operators (`?`, `?|`, `?&`). The result is invalid SQL, which for our purposes
means EXPLAIN will just error.

Properly fixing this needs a quote-aware scan. But a cheap guard gets most of
the value: `$sth->{NUM_OF_PARAMS}` is authoritative, so if it disagrees with a
naive count of `?` in the statement, skip replacement entirely and log the query
with placeholders intact. Better to show an un-substituted query than a
corrupted one.

**This one reproduces on current master and does not appear to be reported
upstream** — the ParamValues discussion in zorgnax/dbilog#23 is a separate
problem, and nothing in the issue list covers quote-awareness. Worth filing
separately.

### 2. Handle details are NOT logged — but the handle is right there

`pre_query()` already receives `$dbh` as an argument (for `execute` it's
`$sth->{Database}`). Everything we need is in scope; it simply isn't recorded.
Adding it to the JSON output looks like a handful of lines:

```perl
$log->{dbh} = {
name => $dbh->{Name}, # DSN tail — db name, host, etc.
driver => $dbh->{Driver}{Name}, # Pg / mysql / SQLite
};
```

That would give us two things this feature needs: the driver (so we pick the
right EXPLAIN syntax) and enough identity to *check* the model's handle matches
the one that ran the query, and refuse rather than guess when it doesn't. Turns
a guess into a checked assumption.

Worth being a little careful about what goes in — `$dbh->{Name}` can contain a
host and database name, and for some drivers a username. That's consistent with
the plugin's existing "dev tool, don't run this in production" stance, but it's
another reason to keep the SECURITY note prominent.

### 3. Upstreaming

All the earlier fork work is merged and released: 0.10 added bind_param
replacement, 0.11 added the JSON output format, 0.12 (2024-08-09) fixed up the
JSON logging. So `format => 'json'` and `replace_placeholders` are both on CPAN
and documented.

The author is currently active (merged a batch of PRs in April 2025), so the
handle-logging change is a straightforward upstream contribution.

**The awkward bit is release lag.** Master has had the `execute(@args)` fix
since 2025-04-22, but there's been no release since 0.12 in August 2024. So:

- Pinning `DBI::Log 0.12` in `dist.ini` gets us `format => 'json'` but *not*
correct bind values for non-DBIC queries.
- There is currently no CPAN version we can pin that has both.

Worth asking zorgnax for a release cutting master — that'd unblock a clean
prereq. Until then, note that `dist.ini` uses `[AutoPrereqs]`, which will have
picked up a bare `DBI::Log` dependency with no minimum version at all; it should
at minimum be pinned to 0.12, with a comment about the bind-value caveat.

## Also spotted while reading the code

`show :Local Args(1)` passes `$profile` straight into
`Path::Tiny::path($dbilog_output_dir, $profile)` with no validation — a
directory traversal. The SECURITY section's "don't run this in production" fairly
covers it, but an EXPLAIN endpoint would take the same parameter plus a line
index, so it's worth pinning both to the known filename pattern while we're in
there.

## Suggested order of work

1. Ask zorgnax for a DBI::Log release cutting master — the `execute(@args)` fix
has been sitting unreleased since April 2025, and without it EXPLAIN is
useless for non-DBIC queries. Nothing to write, just a request; comment on
zorgnax/dbilog#23.
2. File the quote-awareness bug (1b) upstream — appears unreported.
3. Add handle name/driver to the JSON output; contribute upstream.
4. Pin a `DBI::Log` minimum in `dist.ini` (0.12 today; bump to whatever release
includes zorgnax/dbilog#25 once it exists).
5. Then build the EXPLAIN feature on top, with the config chain above.

Steps 1 and 2 gate how useful this is, and neither is much work — but both
depend on someone else cutting a release, so worth kicking off early.

Contributor guide

No contributing guide indexed for this repository

Research direction

Start by reading the `show :Local Args(1)` entry point, `dist.ini`, and DBI::Log's `pre_query()`/`post_query()` handling. Done requires resolving the upstream release and quote-awareness blockers, recording handle details in JSON, pinning the dependency, and only then defining the checked per-query EXPLAIN flow and its configuration.

Written by the indexing model from the issue text.

Assessment

Tech stack
perl, sql
Domain
backend, databases
Issue type
Feature
Difficulty
5/5
Estimated time
Over a week
Activity status
Active
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.