http://qs1969.pair.com?node_id=774751

reasonablekeith has asked for the wisdom of the Perl Monks concerning the following question:

I have a Catalyst app that builds some graphs which is occasionally giving screwy results. It will be fine, and then the result set suddenly returns, missing values. I've boiled an example down to the code as follows. 
package myapp::Controller::tests::report;

use strict;
use warnings;
use parent 'Catalyst::Controller';

sub day_simple :Local :Args(2) {
    my ( $self, $c, $test_id, $passed_date) = @_;

    my @passed_date_split = split /\D/, $passed_date;
    my $formatted_passed_date = join '-', @passed_date_split;

    my $tests_rs = $c->model('DB::Tests')->search(
        { 
            name        => { '=',  $test_id },
            date_time   => { '>=', "$formatted_passed_date 00:00:00", 
+'<=', "$formatted_passed_date 23:59:59" },
        },
        {
            order_by    => 'date_time',
        },
    );

    my $output = "";
    while (my $row = $tests_rs->next) {
        $output .= $row->get_column('date_time') . ", " . $row->get_co
+lumn('time_taken') . "<br/>\n";
    }

    $c->response->body( $output );
}

[download]
which when run gives 
2009-06-24 00:03:41, 0.952
2009-06-24 00:14:06, 0.968
2009-06-24 00:24:31, 0.968
2009-06-24 00:34:50, 0.812
2009-06-24 00:45:17, 0.844
2009-06-24 00:55:49, 1.577
, 0.921
2009-06-24 01:16:29, 0.812
2009-06-24 01:26:50, 1.39
2009-06-24 01:37:35, 8.387
2009-06-24 01:48:24, 1.181
, 0.847
2009-06-24 02:09:19, 1.739
2009-06-24 02:19:49, 0.877
etc...

[download]
All those lines are there in the database all with valid date_time value (as implied by the order by date_time directive).

Very wierdly, runing a select over this table from a mysql command shell seems to clear this problem, and the values start returning normally for a while, but the problem always comes back. Bouncing apache has no effect.

I'm running active perl v5.10.0, apache 2.2.11.0, Win Server 2003, DBIx::Class v0.08010, Catalyst 5.71001 and modperl 1.99.

Any help/pointers much appreciated.

Thanks.

Rob

---
my name's not Keith, and I'm not reasonable.

Replies are listed 'Best First'.
Re: DBIC intermittently returning rows missing date_time value
by moritz (Cardinal) on Jun 25, 2009 at 15:59 UTC
    DBI has logging facilities; you could try to set up the log level and see if anything suspicious comes up.

    Update: I really meant DBI's tracing facilities, not the ones from DBIx::Class

    Oh, and I remember something where I similar weird database problems when I had an autoincrementing column in postgres and manually inserted some values into it without telling it rebuild whatever it needs to rebuild.

[reply]
Re: DBIC intermittently returning rows missing date_time value
by reasonablekeith (Deacon) on Jun 26, 2009 at 07:51 UTC
    I put DBIC_TRACE on, but that just gives me the SQL being run, which looks fine.

    I have also tried running the URL through the Catalyst test srcipt ala... 

    myapp_test.pl /tests/report/day_simple/ART_CRV/2009-06-24

    [download]
    this gives the same error, so I guess I can at least rule out apache and modperl. I know this isn't very glamorous guys but I would really appreciate some ideas.

    Thanks

    ---
    my name's not Keith, and I'm not reasonable.
[reply]
[d/l]
      Show us the trace output
[reply]
        As said, looks fine to me. 
        SELECT me.id, me.name, me.date_time, me.status_code, me.time_taken FRO
+M tests me
 WHERE ( ( ( date_time <= ? AND date_time >= ? ) AND name = ? ) ) ORDE
+R BY date_
time: '2009-06-24 23:59:59', '2009-06-24 00:00:00', 'ART_CRV'
Use of uninitialized value $date_time in concatenation (.) or string a
+t D:/upload/Websites/iic2/script/../lib/iic2/Controller/tests/report.
+pm line 26.
__SNIPPED_A_WHOLE_BUNCH_OF_THESE_THAT_ARE_ALL_THE_SAME_AND_RELATE_TO_T
+HE_MISSING_DATE
Use of uninitialized value $date_time in concatenation (.) or string a
+t D:/upload/Websites/iic2/script/../lib/iic2/Controller/tests/report.
+pm line 26.
[info] *** Request 1292 (0.005/s) [6088] [Mon Jun 29 11:54:59 2009] **
+*
[debug] "GET" request for "tests/report/day_simple/ART_CRV/2009-06-24"
+ from "127
.0.0.1"
[debug] Path is "tests/report/day_simple"
[debug] Arguments are "ART_CRV/2009-06-24"
[info] Request took 0.151744s (6.590/s)
.------------------------------------------------------------+--------
+---.
| Action                                                     | Time   
+   |
+------------------------------------------------------------+--------
+---+
| /tests/report/day_simple                                   | 0.12781
+2s |
| /end                                                       | 0.00176
+9s |
'------------------------------------------------------------+--------
+---'

        [download]
[reply]
[d/l]

Back to Seekers of Perl Wisdom