EF6学习笔记二十三:拦截器异常、耗时监控

  • A+
所属分类:腾讯分分彩

要专业系统地学习EF推荐《你必须掌握的Entity Framework 6.x与Core 2.0》。这本书作者(汪鹏,Jeffcky)的博客:https://www.cnblogs.com/CreateMyself/

 上次一直在弄日志,从最开始简单的ctx.Database.Log 然后到自己写一个派生自DatabaseLogFormatter的类,来实现结构化日志输出。里面有很多方法可以供我们重写。

那么DatabaseLogFormater是继承自IDbCommandInterceptor接口,也就是拦截器。可以看到下面这个接口的方法就只有六个,很好理解。NonQuery拦截非查询操作,Reader拦截查询操作,Scalar拦截聚合操作。

那么我们就可使用拦截器来记录异常,在SQL语句执行之前开启计时,在执行完成关闭计时,把耗时的SQL语句记录下来。

其实DatabaseLogFormatter同样提供了以下六个方法,肯定我们只需要继承DatabaseLogFormatter这个类就可以实现异常或耗时情况的记录。

但是我没有去试。第一,因为DatabaseLogFormatter这个类的类名没有“拦截”的意思,那么我们通过继承DatabaseLogFormatter来实现拦截,在语义上就显得有点别扭吧。

第二,通过继承接口,那么我们可以通过接口的强制实现里面的方法,再用VS补全代码的功能,那么就能写很少的代码吧。

EF6学习笔记二十三:拦截器异常、耗时监控

这篇博客,我分成这样几部分来说一下

1、通过拦截实现简单的异常记录(我们先很快的把东西搞出来,能够运行起来)

2、拦截代码里面要格外注意的一个问题

3,、贴出完整的异常和性能监控代码

4、记录我碰到的一个很不解的 问题(很遗憾,这个问题我没有解决)

实现简单的异常拦截

创建Error模型,用来记录异常信息,实现自己的拦截类,然后在EF的配置中进行注册

Error model

EF6学习笔记二十三:拦截器异常、耗时监控

public class Error3
    {
        public int Id { get; set; }
        public string Name { get; set; }
        public DateTime AddTime { get; set; }
    }

View Code

自己的拦截类

EF6学习笔记二十三:拦截器异常、耗时监控

namespace _201901212.NLog
{
    public class DatabaseInterceptorLogger : IDbCommandInterceptor
    {
        static readonly ConcurrentDictionary<DbCommand, DateTime> MStartTime = new ConcurrentDictionary<DbCommand, DateTime>();

        public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            Console.WriteLine("调用NonQueryExecuted");
            Log(command, interceptionContext);
        }

        public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            Console.WriteLine("调用NonQueryExecuting");
            OnStart(command);
        }

        public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            Console.WriteLine("调用ReaderExecuted");
            Log(command, interceptionContext);
        }

        public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            Console.WriteLine("调用ReaderExecuting");
            OnStart(command);
        }

        public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            Console.WriteLine("调用ScalarExecuted");
            Log(command, interceptionContext);
        }

        public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            Console.WriteLine("调用ScalarExecuting");
            OnStart(command);
        }

        private static void Log<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
        {
            Console.WriteLine("拦截结束");
            //  打印SQL语句
            Console.WriteLine(command.CommandText);
            if (interceptionContext.Exception != null)
            {
                using (EFDbContext ctx = new EFDbContext())
                {
                    ctx.Errors3.Add(new Error3 { AddTime = DateTime.Now});
                    ctx.SaveChanges();
                }
            }
        }

        private static void OnStart(DbCommand command)
        {
            //Console.WriteLine("拦截开始");
            MStartTime.TryAdd(command, DateTime.Now);
        }
    }
}

View Code

在EF的配置中注册,这里我没有在上下文的构造函数中注册,而是写一个派生自DbConfiguration的类,独立出来好一点,不用频繁修改上下文类

EF6学习笔记二十三:拦截器异常、耗时监控

public class DBContextConfiguration:DbConfiguration
    {
        public DBContextConfiguration()
        {
            //  添加拦截器
            DbInterception.Add(new DatabaseInterceptorLogger());
        }
    }

View Code

然后我们执行一段会报错的添加操作(时间类型字段的我给个数字+字母的字符串)

EF6学习笔记二十三:拦截器异常、耗时监控

List<SqlParameter> paraList = new List<SqlParameter>
                {
                    new SqlParameter{ ParameterName="@name",SqlDbType = System.Data.SqlDbType.NVarChar,Value = "来到地球"},
                    new SqlParameter{ ParameterName="@pagesize",SqlDbType = System.Data.SqlDbType.Int,Value=329}
                };
                ctx.Database.ExecuteSqlCommand(@"insert into tb_books(id,name,pagesize,addtime)values(newid(),@name,@pagesize,'ewr223')", paraList.ToArray());
                ctx.SaveChanges();

View Code

 EF6学习笔记二十三:拦截器异常、耗时监控

EF6学习笔记二十三:拦截器异常、耗时监控

简单的异常记录就完成了。

这里要注意两个问题。

第一,在操作数据时,EF会对模型做出验证

EF6学习笔记二十三:拦截器异常、耗时监控

 public class Error2
    {
        public string Id { get; set; }
        public string Name { get; set; }
        public DateTime AddTime { get; set; }

    }

View Code

 我添加一个空对象

EF6学习笔记二十三:拦截器异常、耗时监控

 ctx.Errors2.Add(new Error2());
 ctx.SaveChanges();

View Code

 EF6学习笔记二十三:拦截器异常、耗时监控

可以看到,根本就没有执行SQL语句,因为验证没有通过。因为Error2的主键是string类型,而不是int类型,主键一定要给它

那为什么上面我插入错误的时间值,验证用过了,是在执行SQL语句的时候报错了。

EF的验证我没有去研究,现在只能记住,主键不是自增类型的,在添加如果不给主键值,那么就不能通过EF的验证。

第二个要注意的问题

我们在拦截中又构造了上下文对象,而且添加数据,那么会不会触发拦截?肯定的。所以就会出现这样的问题:当我判断Exception是否为null,如果添加error的时候又报错了?那么就会一直循环下去!

我现在改成这样

EF6学习笔记二十三:拦截器异常、耗时监控

private static void Log<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
        {
            Console.WriteLine("拦截结束");
            //  打印SQL语句
            Console.WriteLine(command.CommandText);
            if (interceptionContext.Exception != null)
            {
                using (EFDbContext ctx = new EFDbContext())
                {
                    //  我现在执行一个会报错的添加,datetime类型会报错,因为C#中datetime最小值为0001/1/1 0:00:00,而数据库中是1753/1/1 0:00:00
                    ctx.Errors3.Add(new Error3 ());
                    ctx.SaveChanges();
                }
            }
}

View Code

EF6学习笔记二十三:拦截器异常、耗时监控

 完整的异常以及性能记录

EF6学习笔记二十三:拦截器异常、耗时监控

private static void Log<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
        {
            // timespan表示两个日期差
            DateTime startTime;
            TimeSpan duration;

//ConcurrentDictionary类型 表示可由多个线程同时访问的键、值对的线程安全集合
            MStartTime.TryRemove(command, out startTime);
            if (startTime != default(DateTime))
            {
                duration = DateTime.Now - startTime;
            }
            else
            {
                duration = TimeSpan.Zero;
            }
            const int requestId = -1;
            var parameters = new StringBuilder();
            foreach (DbParameter param in command.Parameters)
            {
                parameters.AppendLine(param.ParameterName + " " + param.DbType + "=" + param.Value);
            }

            var message = interceptionContext.Exception == null
                ? $"Database call took{duration.TotalSeconds.ToString("N3")}" +
                $" sec.RequestId{requestId}\r\n" +
                $"Command:\r\n{parameters + command.CommandText}"
                : $"EF Database call failed after {duration.TotalSeconds.ToString("N3")} " +
                $"sec.RequestId{requestId}\r\n" +
                $"Command:\r\n{parameters.ToString() + command.CommandText}" +
                $"\r\nError:{interceptionContext.Exception}";

            if (duration.TotalSeconds > 1 || message.Contains("EF Database call failed after"))
            {
                using (EFDbContext ctx = new EFDbContext())
                {
                    Error err = new Error
                    {
                        TotalSeconds = (decimal)duration.TotalSeconds,
                        Active = true,
                        CommandType = Convert.ToString(command.CommandType),
                        CreateDate = DateTime.Now,
                        Exception = interceptionContext.Exception == null ? "" : interceptionContext.Exception.ToString(),
                        FileName = "",
                        InnerException = interceptionContext.Exception == null ? "" : Convert.ToString(interceptionContext.Exception.InnerException),
                        Parameters = parameters.ToString(),
                        Query = command.CommandText,
                        RequestId = 0
                    };
                    //  同样的语句造成的异常不必重复记录
                    if (ctx.Errors.Any(a => a.Parameters == err.Parameters && a.Query == err.Query))
                    {
                        return;
                    }
                    ctx.Errors.Add(err);
                    ctx.SaveChanges();
                }
            }
        }

View Code

 现在记录一下,我碰到一个难以理解的问题。

如果是添加操作,那么肯定是调用的NonQueryExecuting 和 NonQueryExecuted 方法

但是如果你的主键是Int类型,并且自增,那么它居然调用的是ReaderExecuting 和 ReaderExecuted方法

Error2 model  主键为string 类型

EF6学习笔记二十三:拦截器异常、耗时监控

 public class Error2
    {
        public string Id { get; set; }
        public string Name { get; set; }
        public DateTime AddTime { get; set; }

    }

View Code

 Error3  model  主键为int类型,EF默认自增

EF6学习笔记二十三:拦截器异常、耗时监控

public class Error3
    {
        public int Id { get; set; }
        public string Name { get; set; }
        public DateTime AddTime { get; set; }
    }

View Code

分别对这两张表进行添加,可以发现生成的SQL语句 是有区别的

 EF6学习笔记二十三:拦截器异常、耗时监控

EF6学习笔记二十三:拦截器异常、耗时监控

可以发现,对主键为自增的表进行添加,多了一条select语句

EF6学习笔记二十三:拦截器异常、耗时监控

SELECT [Id]
FROM [dbo].[tb_Errors3]
WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity()

View Code

首先我们看一下这个scope_identity是什么意思

这个就是取到上一条记录的自增主键的值,除了这个还有@@identity,这两个都是取自增主键的值的,scope_identity()要好用一点,具体哪里好用,还涉及到SQL中作用域的问题。这个我就又没什么研究了。

那我们在数据库中执行看一下,看看scope_indentiy()和@identity

EF6学习笔记二十三:拦截器异常、耗时监控

SET   NOCOUNT   ON;  -- 开启时不返回受影响的行计数
insert   into   tb_Errors(createDate,Active,TotalSeconds,RequestId)   values(getdate(),1,1,1);
select   SCOPE_IDENTITY()   as errorid   from   tb_Errors;
insert   into   tb_Errors(createDate,Active,TotalSeconds,RequestId)   values(getdate(),1,1,1);
select   SCOPE_IDENTITY()   as errorid   from   tb_Errors;
insert   into   tb_Errors(createDate,Active,TotalSeconds,RequestId)   values(getdate(),1,1,1);
select   SCOPE_IDENTITY()   as errorid   from   tb_Errors;
SET   NOCOUNT   OFF;

View Code

EF6学习笔记二十三:拦截器异常、耗时监控

EF6学习笔记二十三:拦截器异常、耗时监控

SET   NOCOUNT   ON;
insert   into   tb_Errors(createDate,Active,TotalSeconds,RequestId)   values(getdate(),0,2,2);
select   @@IDENTITY   as errorid   from   tb_Errors;
insert   into   tb_Errors(createDate,Active,TotalSeconds,RequestId)   values(getdate(),0,2,2);
select   @@IDENTITY   as errorid   from   tb_Errors;
insert   into   tb_Errors(createDate,Active,TotalSeconds,RequestId)   values(getdate(),0,2,2);
select   @@IDENTITY   as errorid   from   tb_Errors;
SET   NOCOUNT   OFF;

View Code

EF6学习笔记二十三:拦截器异常、耗时监控

好像没什么区别

如果主键为自增,那么我们也可以通过SQL语句为主键写入我们自己的值

EF6学习笔记二十三:拦截器异常、耗时监控

--  居然可以这样,手动为自增字段设置值
SET   IDENTITY_INSERT   tb_Errors   ON;
insert   into   tb_Errors(ErrorId,createDate,Active,TotalSeconds,RequestId)   values(1,getdate(),0,2,2);
select   @@IDENTITY   as errorid   from   tb_Errors;
insert   into   tb_Errors(ErrorId,createDate,Active,TotalSeconds,RequestId)   values(2,getdate(),0,2,2);
select   @@IDENTITY   as errorid   from   tb_Errors;
insert   into   tb_Errors(ErrorId,createDate,Active,TotalSeconds,RequestId)   values(3,getdate(),0,2,2);
select   @@IDENTITY   as errorid   from   tb_Errors;
SET   IDENTITY_INSERT tb_Errors   OFF;

View Code

行,我们还是回到上面的那个问题,难道是因为多的那条SELECT语句造成的问题

那么我们执行原始SQL语句来看一下(我们发现原始SQL语句也会被拦截,毕竟就算是执行原始SQL语句,也是调用EF提供的方法)

EF6学习笔记二十三:拦截器异常、耗时监控

ctx.Database.ExecuteSqlCommand(@"INSERT[dbo].[tb_Errors3]([Name], [AddTime])VALUES(NULL,'2020-2-20')
                SELECT[Id] FROM[dbo].[tb_Errors3] WHERE @@ROWCOUNT > 0 AND[Id] = scope_identity()");
                ctx.SaveChanges();

View Code

 EF6学习笔记二十三:拦截器异常、耗时监控

看到了吧,我用执行SQL语句,它是调用的NonQueryExecuting和NonQueryExecuted

这就真的让人搞不懂了!