Seeing the SQL in DBIx::Class

There's no question that DBIx::Class is the dominant ORM in Perl. That's because it's fast, it's flexible, and sane. Well, mostly sane, until you need some introspection (if anyone knows a better way to do this, I'm all ears!):

sub _get_json_columns ( $self, $schema_class ) {
    state $json_columns_for = {};
    unless ( exists $json_columns_for->{$schema_class} ) {
        my $columns = $self->schema->resultset($schema_class)
          ->result_source->columns_info;
        $json_columns_for->{$schema_class}
          = [ grep { 'json' eq $columns->{$_}{data_type} } keys %$columns ];
    }
    return $json_columns_for->{$schema_class};
}

But what's terribly frustrating to many devs is getting DBIx::Class to show the queries it's executing, along with the bind parameters (one without the other is often useless).

One thing you can do is use the DBIC_TRACE environment variable:

DBIC_TRACE=1 prove t/path/to/my/test.t

And then immediately regret the extra 873 lines of output to STDERR.

So you learn to direct the trace output to a file:

DBIC_TRACE=1=trace.out prove t/path/to/my/test.t

And then you find yourself staring at those 873 lines and wonder exactly which SELECT statement on the foobar table was wrong.

So you do this, because you're such a clever bugger:

sub available_for ( $self, $character ) {
    my $schema = $self->result_source;

    local $ENV{DBIC_TRACE} = '1=trace.out';

    my $result = $self->search(
        # complicated search arguments
    );
}

And then you wonder why that does nothing and a late night session of frantically googling and hitting stackoverflow finally leads you to the troubleshooting.pod for DBIx::Class.

You can't set DBIC_TRACE at runtime because it's only checked when the storage is built (but it apparently works if you trouble yourself to reconnect to your schema, something which may or may not be an option).

Instead, you can enable debugging on the fly with the storage object. Finally, you get down to this in the resultset class which is giving you trouble:

sub available_for ( $self, $character ) {
    my $storage = $self->result_source->storage;

    $storage->debug(1);    # start debugging
    $storage->debugfh(IO::File->new('trace.out', 'w'));    # write it to a file

    my $result = $self->search(
        # complicated search arguments
    );

    $storage->debug(0);    # end debugging
    return $result;
}

And you still get nothing. You're ready to scream and throw something at the wall.

The above code is correct, but there's one tiny hitch you may have forgotten about (or perhaps never realized).

In DBIx::Class, the query is never executed until you ask for the results of that query. You can think of that as lazy evaluation. This has two benefits. First, if you never use the results, you avoid a database hit. Second, it later lets you chain queries. Here's (a simplification) of code we have for the Tau Station MMORPG.

On every space station, there's work available. It might be a job, or it might be a mission. Here's how you could available work for a character

sub _get_available_work_for_character ( $self, $character ) {
    return $self->available->search( {
        'station_id' => $character->station->station_id,
        'available'  => 1,
    });
}

(Note that missions and jobs share the same table, but there's a boolean flag indicating which is which)

And if you want to find resultsets of missions or jobs:

sub get_jobs ( $self, $character ) {
    return $self->_get_available_work_for_character($character)
      ->search( { is_job => 1 } );   # here's the magic!
}

sub get_missions ( $self, $character ) {
    return $self->_get_available_work_for_character($character)
      ->search( { is_job => 0 } );   # here's the magic!
}

What that does is combine the new search parameters with the old and the resulting SQL is generated once, as needed.

Because of delayed execution and chained resultsets, it's very easy to refactor DBIx::Class applications, but it means our debugging example won't work until we fetch results. Rather than put our $storage->debug(0) far away where we use the results, just call count() on the resultset (or just fetch the results and call reset()) to see the SQL:

sub available_for ( $self, $character ) {
    my $storage = $self->result_source->storage;

    $storage->debug(1);    # start debugging
    $storage->debugfh(IO::File->new('trace.out', 'w'));    # write it to a file

    my $result = $self->search(
        # complicated search arguments
    );

    warn $result->count;      # force SQL to be executed
    $storage->debug(0);       # end debugging
    return $result;
}

I love hacking on DBIx::Class

6 Comments

That's... a rather round-about way to check what a SELECT would look like. Why not simply reify it into SQL right there?

P.S. Currently this works for reads only - there is no equivalent reifier for write operations.

Here's some code directly from one of my util modules that I use to dump resultsets and see the SQL they'll generate (I use it something like warn format_resultset($rs)). It's pretty rough and ready but I find it invaluable:

{

    eval{ use SQL::QueryBuilder::Pretty };
    my $pretty = SQL::QueryBuilder::Pretty->new
        if SQL::QueryBuilder::Pretty->can('new');

    sub format_sql{
        my ($sql, @values) = @_;
        $sql =~ s/\?/_sql_value(shift(@values))/ge;
        return $pretty
            ? $pretty->print($sql)
            : $sql;
    }

    sub _sql_value{
        my $value = shift;

        if (ref $value && ref $value eq 'ARRAY'){
            $value = $value->[1];
        }

        if (!defined $value){
            return 'NULL';
        }
        elsif ($value =~ /^\d+(?:\.\d+)?$/){
            return $value;
        }
        else{
            return "'$value'";
        }
    }

    sub format_resultset{
        my ($rs) = @_;
        my $query = ${ $rs->as_query };
        return format_sql(@{$query});
    }
}

At work I often want to see the SQL that's actually sent to the DB for a particular query (including bind values). As you said, enabling tracing globally makes for very hard to read output.

So I wrote this module instead:

package My::DebugDB;
use strict;
use warnings;

use parent 'Exporter';

our @EXPORT = qw($_tracy);

our $_tracy = sub {
    my ($rs) = @_;
    my $storage = $rs->result_source->storage;
    my $debug_prev = $storage->debug;
    $storage->debug(1);
    bless {
        _rs         => $rs,
        _debug_prev => $debug_prev,
    }, 'My::DebugDB::ResultSet'
};

$ENV{DBIC_TRACE_PROFILE} = 'console';
# see
# - DBIx::Class::Storage
# - DBIx::Class::Storage::Debug::PrettyPrint
# - SQL::Abstract::Tree

{
    package My::DebugDB::ResultSet;

    sub DESTROY {
        my ($self) = @_;
        $self->{_rs}->result_source->storage->debug($self->{_debug_prev});
    }

    sub AUTOLOAD {
        my $self = shift;
        (my $method = our $AUTOLOAD) =~ s{\A .* :: }{}xms;
        return $self->{_rs}->$method(@_);
    }
}

'ok'
__END__

=head1 NAME

My::DebugDB - easy ad-hoc SQL debugging

=head1 SYNOPSIS

  use My::DebugDB;

  # dumps generated SQL to STDERR
  my @results = $some_resultset->$_tracy->search({ foo => 'bar' });

=head1 DESCRIPTION

This module provides an add-on method for L<DBIx::Class> resultsets
to make ad-hoc SQL debugging easier. It works like setting
C<DBIC_TRACE=1> in the environment, but with more fine-grained
control.

=over

=item C<$_tracy>

This variable is exported by C<My::DebugDB>. You can call it as a
method on a resultset. It enables the debug flag of the underlying SQL
storage and returns a wrapper around the resultset (to allow for
method chaining). It also arranges for the original value of the debug
flag to be restored when the resultset wrapper is destroyed.

This means in most cases you can simply insert C<< ->$_tracy >>
before a call to C<< ->all >> or C<< ->search >> to get
the SQL for just that statemement:

    # dumps generated SQL
    my @results = $some_resultset->$_tracy->all;
    # temporary object returned by $_tracy is destroyed here, restoring the
    # previous trace setting

=back

Thanks for the as_query recommendation Peter. I never knew that existed either. Saved me a lot of time today.

I put this aside, because the important my-query-is-slow problem wasn't urgent.

I don't think the ->as_query() comment was there when I did so.

Glad I waited. Thanks, Peter.

Leave a comment

About Ovid

user-pic Freelance Perl/Testing/Agile consultant and trainer. See http://www.allaroundtheworld.fr/ for our services. If you have a problem with Perl, we will solve it for you. And don't forget to buy my book! http://www.amazon.com/Beginning-Perl-Curtis-Poe/dp/1118013840/