为什么这样搞？

公司项目繁杂且各项目连接同一数据库，时常因慢查询问题导致我们PHP组的接口响应超时(也有可能是我们自己程序的问题)。为了排除由哪些SQL执行引起的慢查询问题，我们要隔三差五跟运维部门同事要来慢查询日志进行对比分析。最近一直在想，Laravel中有无办法将Eloquent转换成原生SQL并记录下来？直到看了这个帖子才渐渐有了些思路。因为线上运行的服务都配套做了Error Track(异常捕获)，原理是将每个接口返回的错误码全部记录到日志文件中，把日志文件按半小时分割，每隔半小时Error Track服务就会进行日志分析，若日志里存在错误码，则会发邮件和短信报警。现在有办法在日志文件里记录原生SQL了，接下来就该考虑如何把SQL记录到新的文件里从而不影响异常捕获程序正常运行。

自定义日志文件

最近刚理解了trait，所以这里试着用用，反正也不花钱。
在app目录下新建目录Traits，在Traits里新建文件CustomLogger.php，内容如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
<?php
namespace App\Traits;
use Monolog\Logger;
use Illuminate\Log\Writer;
trait CustomLogger
{
    private static $loggers = array();
    public function getLogger($name, $path = null, $day = 30)
    {
        if (null === $path) {
            $path = storage_path('logs/' . $name . '.log');
        }
        if (!isset(self::$loggers[$name])) {
            self::$loggers[$name] = new Writer(new Logger($name));
            self::$loggers[$name]->useDailyFiles($path, $day);
        }
        $log = self::$loggers[$name];
        return $log;
    }
}

定义这样一个自定义日志性状，支持自定义日志文件名称、日志保存路径及保留时长。哪里需要就可以记哪里了。用法见下文。

监听SQL执行事件

参照文档可知，在AppServiceProvider.php中的boot方法中添加如下代码即可监听。

1
2
3
4
5
DB::listen(function ($query) {
    // $query->sql
    // $query->bindings
    // $query->time
});

现在修改一下匿名方法，把监听到的SQL记录到自定义日志文件里。

1
2
3
4
5
6
7
8
use CustomLogger;    
public function boot()
{
    $log = $this->getLogger('illuminate.query');
    DB::listen(function($query) use ($log) {
        $log->info($query->sql .'['. $query->time .'ms]');
    });
}

stackoverflow上有个帖子说PHP中只有类、接口、方法和常量受命名空间影响，定义trait不需要命名空间，但试了下并不行。所以在AppServiceProvider文件里还需要use App\Traits\CustomLogger;。

补充

项目使用Laravel5.1开发，使用如上步骤报错。以下是5.1版本使用方法：

1
2
3
4
5
6
7
8
9
10
use CustomLogger;    
public function boot()
{
    $log = $this->getLogger('illuminate.query');
    DB::listen(function ($sql, $bindings, $time) use ($log) {
        $tmp = str_replace('?', '"'.'%s'.'"', $sql);
        $sql = vsprintf($tmp, $bindings);
        $log->info($sql .'[execute_time='.$time.'ms]');
    });
}

第二次补充

目前修改后的项目已进入测试阶段，在测试环境查看日志文件里的SQL语句，一坨一坨的。为了以后能精确分析出那些执行时间长的SQL是请求哪些接口出现的，应该在每条SQL语句后标识一下接口名称。非常简单，使用Laravel的Request门面获取到uri即可。修改代码如下：

1
2
3
4
5
6
7
8
9
10
use Illuminate\Support\Facades\Request;
public function boot()
{
    $log = LoggerLib::getLogger('illuminate.query');
    DB::listen(function ($sql, $bindings, $time) use ($log) {
        $tmp = str_replace('?', '"'.'%s'.'"', $sql);
        $sql = vsprintf($tmp, $bindings);
        $log->info($sql .'[execute_time='.$time.'ms][uri='.Request::path().']');
    });
}

可以通过[execute_time=1.24ms][uri=login]这两个标识来过滤日志。比如要查看登录接口执行时间是50毫秒的SQL

1
grep 'execute_time=50.*' | grep 'uri=login' illuminate.query-2017-09-08.log