Merge pull request #6 from liam-wiltshire/add-logger

Add logger

README.md

@@ -1,6 +1,12 @@
 # liam-wiltshire/laravel-jit-loader
 
-liam-wiltshire/laravel-jit-loader is an extension to the default Laravel Eloquent model to 'very lazy eager load' relationships.
+liam-wiltshire/laravel-jit-loader is an extension to the default Laravel Eloquent model to 'very lazy eager load' relationships with performance comparable with eager loading.
+
+# Installation
+liam-wiltshire/laravel-jit-loader is available as a composer package:
+`composer require liam-wiltshire/laravel-jit-loader`
+
+Once installed, use the `\LiamWiltshire\LaravelJitLoader\Concerns\AutoloadsRelationships` trait in your model, or have your models extend the `\LiamWiltshire\LaravelJitLoader\Model` class instead of the default eloquent model, and JIT loading will be automatically enabled.
 
 # Very Lazy Eager Load?
 In order to avoid [N+1 issues](https://secure.phabricator.com/book/phabcontrib/article/n_plus_one/), you'd normally load your required relationships while building your collection:
@@ -23,7 +29,7 @@ In some situations however, this may not be possible - perhaps front-end develop
 This change will track if your models belong to a collection, and if they do and a relationship is called that hasn't already been loaded, the relationship will be loaded across the whole collection just in time for use.
 
 # Does This Work?
-Yes. At least, it does in our production Laravel app. It's also been tested against a (rather constructed) test, pulling out staff, companies and addresses - while this isn't a 'real life' representation, it should give an idea of what it can do:
+This is used in a number of production applications with no issues. It's also been tested against a (rather constructed) test, pulling out staff, companies and addresses - while this isn't a 'real life' representation, it should give an idea of what it can do:
 
 ```php
     public function handle()
@@ -66,22 +72,45 @@ Yes. At least, it does in our production Laravel app. It's also been tested agai
 
 Running this locally against a database with 200 companies, 1157 addresses and 39685 staff:
 
-## Without JIT loading:
-Queries Run: 10739
-Execution Time: 16.058979034424
-Memory:68MiB
+## Without JIT Loading:
+Queries Run: 10739<br />
+Execution Time: 17.090859889984<br />
+Memory: 70MiB
 
 
-## With JIT loading:
-Queries Run: 6
-Execution Time: 1.6715261936188
-Memory:26MiB
+## With JIT Loading:
+Queries Run: 3<br />
+Execution Time: 1.7261669635773<br />
+Memory: 26MiB
 
-# Installation
-liam-wiltshire/laravel-jit-loader is available as a composer package:
-`composer require liam-wiltshire/laravel-jit-loader`
 
-Once installed, use the `\LiamWiltshire\LaravelJitLoader\Concerns\AutoloadsRelationships` trait in your model, or have your models extend the `\LiamWiltshire\LaravelJitLoader\Model` class instead of the default eloquent model, and JIT loading will be automatically enabled.
+## 'Proper' Eager Loading:
+Queries Run: 3<br />
+Execution Time: 1.659285068512<br />
+Memory: 26MiB
+
+# Logging
+As you can see the different between JIT loading and traditional eager loading is small (c. 0.067 seconds in our above test), so you can likely rely on JIT loader to protect you.
+
+However, if you want to log when the JIT loader is used so that you can do back and correct them later, you can add a `$logChannel` property to your models to ask the trait to log into that channel as configured in Laravel
+
+```php
+class Address extends Model
+{
+    use AutoloadsRelationships;
+    public $timestamps = false;
+
+    /**
+     * @var string
+     */
+    protected $logChannel = 'jit-logger';
+
+    public function company()
+    {
+        return $this->belongsTo(Company::class);
+    }
+}
+```
 
 # Limitations
 This is an early release based on specific use cases. At the moment the autoloading will only be used when the relationship is loaded like a property e.g. `$user->company->name` instead of `$user->company()->first()->name`. I am working on supporting relations loaded in alternate ways, however there is more complexity in that so there isn't a fixed timescale as of yet!

composer.json

@@ -15,7 +15,8 @@
   "require-dev": {
     "phpunit/phpunit": "^7.0.0",
     "squizlabs/php_codesniffer" : "^3.0.0",
-    "phpunit/php-code-coverage": "^6.0.0"
+    "phpunit/php-code-coverage": "^6.0.0",
+    "illuminate/log": "^5.5.0"
   },
   "autoload": {
     "psr-4": {

src/Concerns/AutoloadsRelationships.php

@@ -3,9 +3,11 @@
 namespace LiamWiltshire\LaravelJitLoader\Concerns;
 
 use Illuminate\Database\Eloquent\Model;
+use Illuminate\Log\LogManager;
 use LogicException;
 use Illuminate\Database\Eloquent\Relations\Relation;
 use Illuminate\Database\Eloquent\Collection;
+use Psr\Log\LoggerInterface;
 
 /**
  * Trait AutoloadsRelationships
@@ -24,6 +26,12 @@ trait AutoloadsRelationships
      */
     protected $parentCollection = null;
 
+    /**
+     * @var ?LoggerInterface
+     */
+    protected $logDriver;
+
+
     /**
      * Check to see if we should autoload
      * @return bool
@@ -35,6 +43,57 @@ private function shouldAutoLoad(): bool
             && count($this->parentCollection) <= $this->autoloadThreshold);
     }
 
+    /**
+     * @codeCoverageIgnore
+     */
+    private function getLogDriver()
+    {
+        if (!$this->logDriver) {
+            /**
+             * @var LogManager $logManager
+             */
+            $logManager = app(LogManager::class);
+            $this->logDriver = $logManager->channel($this->logChannel);
+        }
+    }
+
+    /**
+     * @param string $file
+     * @return bool|string
+     * @codeCoverageIgnore
+     */
+    private function getBlade(string $file)
+    {
+        if (strpos($file, "framework/views/") === false) {
+            return false;
+        }
+
+        $blade = file($file)[0];
+        return trim(str_replace(["<?php /* ", " */ ?>"], "", $blade));
+    }
+
+    /**
+     * Log the fact we have used the JIT loader, if required
+     *
+     * @param string $relationship
+     * @param string $file
+     * @param int $lineNo
+     * @return bool
+     */
+    private function logAutoload(string $relationship, string $file, int $lineNo)
+    {
+        if (!isset($this->logChannel)) {
+            return false;
+        }
+
+        $this->getLogDriver();
+
+        $blade = $this->getBlade($file);
+
+        $this->logDriver->info("[LARAVEL-JIT-LOADER] Relationship ". self::class."::{$relationship} was JIT-loaded."
+            ." Called in {$file} on line {$lineNo} " . ($blade ? "view: {$blade})" : ""));
+    }
+
     /**
      * Load the relationship for the given method, and then get a relationship value from a method.
      * @param string $method
@@ -53,7 +112,13 @@ public function getRelationshipFromMethod($method)
         }
 
         if ($this->shouldAutoLoad()) {
-            $this->parentCollection->loadMissing($method);
+            if (!$this->relationLoaded($method)) {
+                $stack = debug_backtrace()[3];
+                $this->logAutoload($method, $stack['file'], $stack['line']);
+                $this->parentCollection->loadMissing($method);
+
+                return current($this->parentCollection->getIterator())->relations[$method];
+            }
         }
 
         return tap($relation->getResults(), function ($results) use ($method) {

tests/Concerns/AutoloadsRelationshipsTest.php

@@ -8,9 +8,11 @@
 
 namespace LiamWiltshire\LaravelJitLoader\Tests\Concerns;
 
-
+use Illuminate\Log\LogManager;
 use LiamWiltshire\LaravelJitLoader\Tests\TestCase;
+use LiamWiltshire\LaravelJitLoader\Tests\TraitlessModel;
 use LiamWiltshire\LaravelJitLoader\Tests\TraitModel;
+use Psr\Log\LoggerInterface;
 
 class AutoloadsRelationshipsTest extends TestCase
 {
@@ -47,4 +49,65 @@ public function testGetRelationshipFromMethodUnderThresholdDoesAutoLoad()
 
         $this->assertTrue($models[1]->relationLoaded('myRelationship'));
     }
+
+    public function testGetRelationshipFromMethodUnderThresholdDoesAutoLoadWithLogging()
+    {
+
+        $driver = $this->getMockBuilder(LoggerInterface::class)->getMock();
+        $driver->expects($this->atLeastOnce())->method('info')->willReturn(true);
+
+        $models = TraitModel::all();
+        $models[0]->setLogging('jitLogger', $driver);
+
+        $related = $models[0]->myRelationship;
+
+        $this->assertTrue($models[1]->relationLoaded('myRelationship'));
+    }
+
+    public function testPerformance()
+    {
+        $startTime = microtime(true);
+        $this->db->getConnection()->flushQueryLog();
+        $models = TraitModel::all();
+
+        foreach ($models as $model) {
+            $model->myRelationship;
+        }
+
+        $traitedCount = count($this->db->getConnection()->getQueryLog());
+        $traitedTime = microtime(true) - $startTime;
+
+        $startTime = microtime(true);
+        $this->db->getConnection()->flushQueryLog();
+
+        $models = TraitlessModel::all();
+
+        foreach ($models as $model) {
+            $model->myRelationship;
+        }
+
+        $traitlessCount = count($this->db->getConnection()->getQueryLog());
+        $traitlessTime = microtime(true) - $startTime;
+
+        $startTime = microtime(true);
+        $this->db->getConnection()->flushQueryLog();
+
+        $models = TraitlessModel::with('myRelationship')->get();
+
+        foreach ($models as $model) {
+            $model->myRelationship;
+        }
+
+        $eagerCount = count($this->db->getConnection()->getQueryLog());
+        $eagerTime = microtime(true) - $startTime;
+
+
+
+        $this->messages[] = "Using Trait: {$traitedCount} queries in {$traitedTime}s";
+        $this->messages[] = "Lazy Loading: {$traitlessCount} queries in {$traitlessTime}s";
+        $this->messages[] = "Eager Loading: {$eagerCount} queries in {$eagerTime}s";
+
+        $this->assertTrue($traitedCount < $traitlessCount);
+        $this->assertTrue($traitedTime < $traitlessTime);
+    }
 }

tests/TestCase.php

@@ -9,10 +9,17 @@
 namespace LiamWiltshire\LaravelJitLoader\Tests;
 
 
+use Illuminate\Contracts\Foundation\Application;
+use Illuminate\Contracts\Http\Kernel;
 use Illuminate\Database\Capsule\Manager;
 
 class TestCase extends \PHPUnit\Framework\TestCase
 {
+
+    public $db;
+
+    public $messages = [];
+
     public function setUp()
     {
         $this->configureDatabase();
@@ -30,6 +37,9 @@ protected function configureDatabase()
         ));
         $db->bootEloquent();
         $db->setAsGlobal();
+
+        $this->db = $db;
+        $this->db->getConnection()->enableQueryLog();
     }
 
     public function migrateIdentitiesTable()
@@ -39,22 +49,46 @@ public function migrateIdentitiesTable()
             $table->integer('dummy_model_id');
             $table->timestamps();
         });
-        DummyModel::create(array('dummy_model_id' => 5));
-        DummyModel::create(array('dummy_model_id' => 4));
-        DummyModel::create(array('dummy_model_id' => 3));
-        DummyModel::create(array('dummy_model_id' => 2));
-        DummyModel::create(array('dummy_model_id' => 1));
+
+        $x = 100;
+        while ($x > 0) {
+            DummyModel::create(array('dummy_model_id' => $x));
+            $x--;
+        }
 
         Manager::schema()->create('trait_models', function($table) {
             $table->increments('id');
             $table->integer('trait_model_id');
             $table->timestamps();
         });
-        TraitModel::create(array('trait_model_id' => 5));
-        TraitModel::create(array('trait_model_id' => 4));
-        TraitModel::create(array('trait_model_id' => 3));
-        TraitModel::create(array('trait_model_id' => 2));
-        TraitModel::create(array('trait_model_id' => 1));
 
+        $x = 100;
+        while ($x > 0) {
+            TraitModel::create(array('trait_model_id' => $x));
+            $x--;
+        }
+
+        Manager::schema()->create('traitless_models', function($table) {
+            $table->increments('id');
+            $table->integer('traitless_model_id');
+            $table->timestamps();
+        });
+
+        $x = 100;
+        while ($x > 0) {
+            TraitlessModel::create(array('traitless_model_id' => $x));
+            $x--;
+        }
+
+    }
+
+    public function __destruct()
+    {
+        if (!empty($this->messages)) {
+            echo "Performance Data:\n";
+            echo implode("\n", $this->messages);
+            echo "\n";
+        }
+        parent::tearDown(); // TODO: Change the autogenerated stub
     }
 }

tests/TraitModel.php

@@ -5,6 +5,7 @@
 
 use Illuminate\Database\Eloquent\Model;
 use LiamWiltshire\LaravelJitLoader\Concerns\AutoloadsRelationships;
+use Psr\Log\LoggerInterface;
 
 class TraitModel extends Model {
 
@@ -26,4 +27,10 @@ public function setAutoloadThreshold(int $autoloadThreshold)
     {
         $this->autoloadThreshold = $autoloadThreshold;
     }
+
+    public function setLogging(string $channel, LoggerInterface $logger)
+    {
+        $this->logChannel = $channel;
+        $this->logDriver = $logger;
+    }
 }