Examining Laravel Database Queries

March 18, 2014

I've been using Laravel lately for most web projects, which I've been finding to be a pleasure to develop with. Laravel is straighforward, has great documentation, and is well thought out to make development tasks fast and pain-free.

Like any full-featured web framework, Laravel provides an ORM implementation, called Eloquent, which translates objects and their relations to an underlying SQL datasource. For example, a database table called users may relate to a model class called User, which can be queried:

$users = User->all();     // find all users
$user = User->find(123);  // find a user with id 123
$users = User->where('account_type', 'PAID')->get();  // find all paying users

More complex queries may also be strung together using the Query Builder interface.

$users = DB::table('users')
  ->join('profiles','users.id','=','profiles.creator_id')
  ->where('users.id',1)
  ->select('users.email','profiles.name')
  ->get();

Sometimes it is helpful to see what is going on behind the scenes and to see the actual SQL that the Query Builder generates and sends to the database. This can easily be achieved by making use of Laravel's Event observers. By observing an event called illuminate.query, we can log all SQL queries going to the database plus their execution time.

Event::listen('illuminate.query', function($sql,$bindings,$time) {
  Log::info(sprintf("%s (%s) : %s",$sql,implode(",",$bindings),$time));
});

This will print all SQL queries plus their bindings and execution time to Laravel's logs. It can be added pretty much anywhere but according to Laravel's documentation, best practice is inside start/global.php.

As one step better, we can look for bindings that may be dates and convert them to strings so that they do not cause an error in the implode function of the statement above.

Event::listen('illuminate.query', function($sql,$bindings,$time) {
  for ($i = 0; $i < sizeof($bindings); $i++) {
    if ($bindings[$i] instanceof DateTime) {
     $bindings[$i]= $bindings[$i]->getTimestamp();
    }
  }
  Log::info(sprintf("%s (%s) : %s",$sql,implode(",",$bindings),$time));
});

Now, any time your application executes a query, it will be logged to app/storage/logs/ and you should see something like this, indicating the query, the bindings (id = 1), and the execution time (0.5ms):

[2014-03-18 18:14:02] local.INFO: select `users`.`email`, `profiles`.`name` from `users` inner join `profiles` on `users`.`id` = `profiles`.`creator_id` where `users`.`id` = ? (1) : 0.5 [] []

This code should either be removed completely from production environments, or simply ignored.

if (app()->env !== 'production') {
  Event::listen('illuminate.query', function($sql,$bindings,$time) {
    for ($i = 0; $i < sizeof($bindings); $i++) {
      if ($bindings[$i] instanceof DateTime) {
       $bindings[$i]= $bindings[$i]->getTimestamp();
      }
    }
    Log::info(sprintf("%s (%s) : %s",$sql,implode(",",$bindings),$time));
  });
}
 

comments powered by Disqus

About This Site

This site was designed by We Are How.

This site is powered by Sculpin static site generator and the source is available here.

Yotta = 10^24, or 1 000 000 000 000 000 000 000 000, the largest metric prefix.


Contact

Get in touch to find out how we can help you refine your vision and implement a dynamite product that will help your business grow. Our agile product development process is thoughtfully designed to give clients ongoing feedback and visibility from project inception to completion.