EntityFramework之监听者判断SQL性能指标

Posted 2020-06-23 Jeffcky

前言

当我们利用EF这个ORM框架时，我们可能会利用LINQ或者原生的SQL语句来进行数据操作，此时我们无法确定我们的代码是否会给数据库带来一定的负载，当给数据库带来一定的压力时，由于项目中对数据进行相应的操作实在是太多，我们无法准确的去进行定位，又或者我们不是专业的DBA，无法准确的去分析SQL性能的优劣，此时该怎么办呢？我们完全不需要DBA，我们可以通过相应的操作来判断一段SQL代码的好坏，这就是我们本节需要讲的内容，利用EF中监听者来判断SQL性能，在之前系列中也有提到，可以参考之前系列。我们进入主题。

DbCommandInterceptor

不用讲从字面意思我们就能立马明白大概是【监听命令】，我们看下该类，如下：

我们无需多加细看，看这几个虚方法我们马上就能明白和我们之前猜测的一致，就是进行数据库操作的SQL命令。在这个类中有一个重要的类那就是 DbCommandInterceptionContext ，我们姑且叫做监听SQL命令的上下文吧，我们再看这个类中包含什么。如下：

在这个类中有一个重要的属性 UserState ，哦，意思是用户状态，根据摘要信息得知，我们可以设置我们进行操作的相关信息，同时还是个object类型，看来是利于对象之间的转换而给。

接下来进入主题，我们如何去判断SQL性能指标呢？答案：我们检索出执行SQL时以及执行SQL完成后的消耗时间即可。

SQL性能判断指标

那么问题来了，我们该如何正确这个时间呢？此问题又可以细分为两个步骤。

（1）如何知道SQL命令是正在执行时以及执行完成呢？

（2）知道了之后我们又如何设置以及获取时间呢？

我们一一来划分，首先我建立一个类 SQLProfiler ，而此类肯定是继承于 DbCommandInterceptor ，所以代码就变成了这样。

    public class SQLProfiler : DbCommandInterceptor
    {
        public override void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            Executing(interceptionContext);
            base.ReaderExecuting(command, interceptionContext);
        }

        public override void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            Executed(command, interceptionContext);
            base.ReaderExecuted(command, interceptionContext);
        }

        public override void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            Executing(interceptionContext);
            base.NonQueryExecuting(command, interceptionContext);
        }

        public override void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            Executed(command, interceptionContext);
            base.NonQueryExecuted(command, interceptionContext);
        }

        public override void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            Executing(interceptionContext);
            base.ScalarExecuting(command, interceptionContext);
        }

        public override void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            Executed(command, interceptionContext);
            base.ScalarExecuted(command, interceptionContext);
        }
}

貌似发现了什么，好像方法参数都是什么DbCommand和DbCommandInterCeptionContext，既然这样，我们依样画葫芦诺，为了从执行SQL命令开始，我们此时从这里开始计时，将计时对象给UserState即可，于是就有了下面的代码。

        private void Executing<T>(DbCommandInterceptionContext<T> interceptionContext)
        {
            var timer = new Stopwatch();
            interceptionContext.UserState = timer;
            timer.Start();
        }

此时应该就明朗了，我们在执行完成后来获取该计时对象并利用是否出现异常和我们指定设置的时间来判断其最终所花费的时间。执行完成后代码如下：

        private void Executed<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
        {
            var timer = (Stopwatch)interceptionContext.UserState;
            timer.Stop();

            if (interceptionContext.Exception != null)
            {
                File.AppendAllLines(
                    _logFile,
                    new string[]
                {
                "错误SQL语句",
                interceptionContext.Exception.Message,
                command.CommandText,
                Environment.StackTrace,
                string.Empty,
                string.Empty,
                });
            }
            else if (timer.ElapsedMilliseconds >= _executionTime)
            {
                File.AppendAllLines(
                    _logFile,
                    new string[]
                {
                string.Format("耗时SQL语句({0}ms)",timer.ElapsedMilliseconds),
                command.CommandText,
                Environment.StackTrace,
                string.Empty,
                string.Empty,
                });
            }
        }

上述 _executionTime 是我们在此类构造函数中所设置的时间，构造函数如下：

        private readonly string _logFile;
        private readonly int _executionTime;

        public SQLProfiler(string logFile, int executionTime)
        {
            _logFile = logFile;
            _executionTime = executionTime;
        }

而logFile则是我么所要输出的日志。此时别忘记最重要的一件事，那就是DbConfiguration配置类中进行注册（或者在配置文件中进行注册）。如下：

    public class MyDbConfiguration : DbConfiguration
    {
        public MyDbConfiguration()
        {
            this.AddInterceptor(new SQLProfiler(@"D:\log.txt", 1));
        }
    }

接下来我们来进行检验结果。

检验成果

           using (var ctx = new EntityDbContext())
            {
                SqlParameter[] parameter = { };
                ctx.Database.SqlQuery<Student>("select * from a", parameter).ToList();
                Console.ReadKey();
            }

上述表a实际上是不存在的，我们就是要看看是否能检测到该异常并获取其时间。来，瞧一瞧。

【效果一】

【效果二】

结语

当然，如上述当执行查询时此表不存在肯定是会报错，但是我们的侧重点不在此，这里验证了此表不存在，同时也验证了SQL在执行时和执行完之间的耗时，同时我们可以通过构造函数手动设置当耗时大于我们预期的多少才算需要改善SQL。