I can not figure out what is happening with my Laravel script. I'm simply selecting an object, and calling a method on it that runs additional queries, but the behavior I'm seeing is very inconsistent. Here's the code:
$product = Product::find(1);
echo $product->numberOfOrders('2014-05-22', '2015-01-27');
Here's the code for the numberOfOrders method:
public function numberOfOrders($startDate = NULL, $endDate = NULL)
{
if(is_null($startDate)) $startDate = '0000-00-00 00:00:00';
if(is_null($endDate)) $endDate = date("Y-m-d");
return Order::whereHas('orderProducts', function($query)
{
$query->where('product_id', $this->id);
})->whereHas('status', function($query)
{
$query->where('sales_data', 1);
})->where('ext_created_at', '>=', $startDate)->where('ext_created_at', '<=', $endDate.' 23:59:59')->distinct()->count();
}
When this code runs, it hangs for about 10 seconds, before returning the integer result. Then, if I run the same code again, it instantly returns the result and continues to do so every time I run it. If I change the $startDate, and run the code again, it hangs for 10 seconds, then returns the result. Then, rerunning the code will again instantly return the result.
Other times, when the code is hanging, instead of returning a result, I get an error message:
PHP Fatal error: Uncaught exception 'PDOException' with message 'SQLSTATE[HY000]: General error: 2027 Malformed packet' in /var/www/html/app/vendor/laravel/framework/src/Illuminate/Database/Connection.php:299
After the error message, if I run the code again, the result is returned instantly.
I am very confused as to what would be causing such inconsistency in my code. I am not doing anything with caching.
I noticed that the whereHas method actually adds subqueries to the query rather than using joins, which I find strange. Writing similar code in CodeIgniter using Datamapper ORM adds joins to the query rather than subqueries, which yields much better performance. Could the subqueries be causing the problem? If so, I still am unsure why things would be behaving so inconsistently.
I've captured some data showing the issue occurring. Here's the output from DB::getQueryLog() the first time:
[3] => Array
(
[query] => select count(*) as aggregate from `orders` where `orders`.`deleted_at` is null and (select count(*) from `order_products` where `order_products`.`order_id` = `orders`.`id` and `product_id` = ? and `order_products`.`deleted_at` is null) >= 1 and (select count(*) from `order_statuses` where `orders`.`order_status_id` = `order_statuses`.`id` and `sales_data` = ? and `order_statuses`.`deleted_at` is null) >= 1 and `ext_created_at` >= ? and `ext_created_at` <= ?
[bindings] => Array
(
[0] => 1
[1] => 1
[2] => 2014-07-29
[3] => 2015-01-27 23:59:59
)
[time] => 22391.73
)
As you can see, it took a very long time to run. After that was done, I ran the same thing again, and here's the output:
[3] => Array
(
[query] => select count(*) as aggregate from `orders` where `orders`.`deleted_at` is null and (select count(*) from `order_products` where `order_products`.`order_id` = `orders`.`id` and `product_id` = ? and `order_products`.`deleted_at` is null) >= 1 and (select count(*) from `order_statuses` where `orders`.`order_status_id` = `order_statuses`.`id` and `sales_data` = ? and `order_statuses`.`deleted_at` is null) >= 1 and `ext_created_at` >= ? and `ext_created_at` <= ?
[bindings] => Array
(
[0] => 1
[1] => 1
[2] => 2014-07-29
[3] => 2015-01-27 23:59:59
)
[time] => 22391.73
)
[4] => Array
(
[query] => select count(*) as aggregate from `orders` where `orders`.`deleted_at` is null and (select count(*) from `order_products` where `order_products`.`order_id` = `orders`.`id` and `product_id` = ? and `order_products`.`deleted_at` is null) >= 1 and (select count(*) from `order_statuses` where `orders`.`order_status_id` = `order_statuses`.`id` and `sales_data` = ? and `order_statuses`.`deleted_at` is null) >= 1 and `ext_created_at` >= ? and `ext_created_at` <= ?
[bindings] => Array
(
[0] => 1
[1] => 1
[2] => 2014-07-29
[3] => 2015-01-27 23:59:59
)
[time] => 1.81
)
As you can see, same exact query, but it's drastically faster. Why would there be such a difference? Are the results being cached somewhere?
In case it helps, I'm running all of this code using php artisan tinker.
EDIT After some more research, I've learned that this is probably the behavior of the mysql query cache.
