4,3 billion people living in France

Dieser Post wurde aus meiner alten WordPress-Installation importiert. Sollte es Darstellungsprobleme, falsche Links oder fehlende Bilder geben, bitte einfach hier einen Kommentar hinterlassen. Danke.

 

Look at the title and you're done. No need to add a text to this post if everything is said in the title. Not really? France is too small to hold half of the world's population? No way! My computer told me that 4.294.967.296 people live in France - and computers don't fail, you know?

Actually, a project database stated this value earlier today. And yesterday. And the day before. And perhaps a long time ago. And noone ever noticed! The table is rarely used and no other values are calculated based on this cell's value. No one notices - until I started listening the mySQL warnings today.

 

The background story

The mySQL command line client has a little feature that most of us never notice:

mysql> CREATE TEMPORARY TABLE text(this_day date);Query OK, 0 rows affected (0.05 sec)
mysql> INSERT INTO text(this_day) VALUES(NOW());Query OK, 1 row affected, 1 warning (0.05 sec)

It's reporting the result state (OK or error), the number of rows affected by this query, the time  - and the number of warnings. But why did this query issue a warning? Let's ask the server:

mysql> SHOW WARNINGS;+-------+------+-----------------------------------------------+| Level | Code | Message                                       |+-------+------+-----------------------------------------------+| Note  | 1265 | Data truncated for column 'this_day' at row 1 |+-------+------+-----------------------------------------------+1 row in set (0.04 sec)

The table has a date column and I tried to insert a datetime (or timestamp). The time was ignored and just the date part was used:

 

mysql> SELECT this_day,NOW() FROM text;+------------+---------------------+| this_day   | NOW()               |+------------+---------------------+| 2013-02-07 | 2013-02-07 18:07:51 |+------------+---------------------+1 row in set (0.04 sec)

The table's value has no space for the time but NOW() returns the time. Using CURRENT_DATE() instead of NOW() for the INSERT would right.

But... why?

But why should you care about this - the result doesn't differ between CURRENCT_DATE() and NOW(). A simple sample: You want to save some timestamp (including time) but someone (maybe even you) created the column as "date". You might notice that without using the warnings - but usually after three month of partial timestamps being written.

I didn't want to add warning checks to every single $sth->execute or $dbh->select* call (we have quite a lot of them) and so I used our existing DBI subclassing for the warning checks.

Subclassing DBI

 

There is a pretty good documentation on DBI subclassing on CPAN and I won't rewrite the whole stuff, just show the two required modules:

The first:

package MyProject::DB::db;
use 5.010;use strict;use warnings;
use DBI;
our @ISA = ('DBI::db');
1;

The second:

 

package MyProject::DB::st;
use 5.010;use strict;use warnings;
use DBI;
our @ISA = ('DBI::st');our $VERSION = '0.01';
1;

That's all and it's pretty useless until you add functions :-) Perl is simple, isn't it?

Warnings occur during the execution of a query, so we need to overload the execute() method of the statement handler. I usually want to know the original query and also overloaded the prepare() method to store it in the statement handle.

For MyProject::DB::db

sub prepare { my $self = shift;
 # Use the original prepare function my $sth = $self->SUPER::prepare(@_); # Add a "private_" key - the prefix is required by DBI $sth->{private_query} = $_[0];
 return $sth;}

You might want to override prepare_cached and others the same way but one function should be enough as a sample.

For MyProject::DB::st

 

 

sub execute { my $self = shift;
 # Use the original execute function my $rv = $self->SUPER::execute(@_);
 # Warning occured, fetch using native DBI and issue wh if ($self->{mysql_warning_count}) {  # Loop through all warnings  for my $warning (@{$self->{Database}->selectall_arrayref('SHOW WARNINGS')}) {
   # Report each warning   MyProject::Report::warning(    short            => $warning->[2] . ' (' . $warning->[1] . ") for\n\n" . $self->{private_query},    additional_stuff => {     database => $self->{Database}->{Name},     values => \@_,,    },   );  } }
 return $rv;}

I wrote a reporting system for errors and warnings some time ago which adds the environment, HTTP request data, a stacktrace and some other stuff which might help debugging the problem, but it doesn't use the database! short contains the warning text and number plus the original query while additional_stuff adds more information using Data::Dumper.

Do not report warnings using the database routines which are checking for warnings! You may easily end up in an endless loop if a warning is triggered while reporting a warning which will report the new warning which till trigger another warning... got it?

I tried some different report styles and ended up by reporting each warning (which are grouped by "short" later) instead of all warnings per query in one message - but you should try yourself.

Beware: The prepare and execute functions run very often and usually deep inside other sourcecode. A badly written function may slow down your application a lot. Using other modules should be restricted to an absolute required minimum and you should prefer modules where you really really know what they're doing!

Results

The project which now reports mySQL warnings is very old and grown. It is running on many generations of sourcecode from many different developers. It's heavily used - and I got overrun by more than 100.000 warning reports within two hours - including some useless ones (for this project) like Table already exists from a CREATE TABLE IF NOT EXISTS statement. I started skipping the known-to-be-useless-for-us warning codes using next if $warning->[1] == 1234; lines and got the masses down to a usable amount.

Back to France

One of these was warning number 1264: Out of range value for column 'some_counter' at row 1. The cell being updated contained a user counter for France - and something made it reach the 32 Bit integer limit of 4294967296.

I could imagine two possible reasons: France has 4,3 billion inhabitants (and all of them are registered users on our project) or the table cell has been corrupted. The second one is impossible because computers never fail and the remaining option... just look at the title.