EF6學習筆記二十三：攔截器異常、耗時監控
要專業系統地學習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補全程式碼的功能，那麼就能寫很少的程式碼吧。
這篇部落格，我分成這樣幾部分來說一下
1、通過攔截實現簡單的異常記錄（我們先很快的把東西搞出來，能夠執行起來）
2、攔截程式碼裡面要格外注意的一個問題
3,、貼出完整的異常和效能監控程式碼
4、記錄我碰到的一個很不解的 問題（很遺憾，這個問題我沒有解決）
實現簡單的異常攔截
建立Error模型，用來記錄異常資訊，實現自己的攔截類，然後在EF的配置中進行註冊
Error model
public class Error3
{
public int Id { get; set; }
public string Name { get; set; }
public DateTime AddTime { get; set; }
}
View Code
自己的攔截類
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的類，獨立出來好一點，不用頻繁修改上下文類
public class DBContextConfiguration:DbConfiguration
{
public DBContextConfiguration()
{
//新增攔截器
DbInterception.Add(new DatabaseInterceptorLogger());
}
}
View Code
然後我們執行一段會報錯的新增操作（時間型別欄位的我給個數字+字母的字串）
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
簡單的異常記錄就完成了。
這裡要注意兩個問題。
第一，在操作資料時，EF會對模型做出驗證
public class Error2
{
public string Id { get; set; }
public string Name { get; set; }
public DateTime AddTime { get; set; }
}
View Code
我新增一個空物件
ctx.Errors2.Add(new Error2()); ctx.SaveChanges(); View Code
可以看到，根本就沒有執行SQL語句，因為驗證沒有通過。因為Error2的主鍵是string型別，而不是int型別，主鍵一定要給它
那為什麼上面我插入錯誤的時間值，驗證用過了，是在執行SQL語句的時候報錯了。
EF的驗證我沒有去研究，現在只能記住，主鍵不是自增型別的，在新增如果不給主鍵值，那麼就不能通過EF的驗證。
第二個要注意的問題
我們在攔截中又構造了上下文物件，而且新增資料，那麼會不會觸發攔截？肯定的。所以就會出現這樣的問題：當我判斷Exception是否為null,如果新增error的時候又報錯了？那麼就會一直迴圈下去！
我現在改成這樣
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
完整的異常以及效能記錄
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 型別
public class Error2
{
public string Id { get; set; }
public string Name { get; set; }
public DateTime AddTime { get; set; }
}
View Code
Error3 model 主鍵為int型別，EF預設自增
public class Error3
{
public int Id { get; set; }
public string Name { get; set; }
public DateTime AddTime { get; set; }
}
View Code
分別對這兩張表進行新增，可以發現生成的SQL語句 是有區別的
可以發現，對主鍵為自增的表進行新增，多了一條select語句
SELECT [Id] FROM [dbo].[tb_Errors3] WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity() View Code
首先我們看一下這個scope_identity是什麼意思
這個就是取到上一條記錄的自增主鍵的值，除了這個還有@@identity,這兩個都是取自增主鍵的值的，scope_identity()要好用一點，具體哪裡好用，還涉及到SQL中作用域的問題。這個我就又沒什麼研究了。
那我們在資料庫中執行看一下，看看scope_indentiy()和@identity
SETNOCOUNTON;-- 開啟時不返回受影響的行計數 insertintotb_Errors(createDate,Active,TotalSeconds,RequestId)values(getdate(),1,1,1); selectSCOPE_IDENTITY()as erroridfromtb_Errors; insertintotb_Errors(createDate,Active,TotalSeconds,RequestId)values(getdate(),1,1,1); selectSCOPE_IDENTITY()as erroridfromtb_Errors; insertintotb_Errors(createDate,Active,TotalSeconds,RequestId)values(getdate(),1,1,1); selectSCOPE_IDENTITY()as erroridfromtb_Errors; SETNOCOUNTOFF; View Code
SETNOCOUNTON; insertintotb_Errors(createDate,Active,TotalSeconds,RequestId)values(getdate(),0,2,2); select@@IDENTITYas erroridfromtb_Errors; insertintotb_Errors(createDate,Active,TotalSeconds,RequestId)values(getdate(),0,2,2); select@@IDENTITYas erroridfromtb_Errors; insertintotb_Errors(createDate,Active,TotalSeconds,RequestId)values(getdate(),0,2,2); select@@IDENTITYas erroridfromtb_Errors; SETNOCOUNTOFF; View Code
好像沒什麼區別
如果主鍵為自增，那麼我們也可以通過SQL語句為主鍵寫入我們自己的值
--居然可以這樣，手動為自增欄位設定值 SETIDENTITY_INSERTtb_ErrorsON; insertintotb_Errors(ErrorId,createDate,Active,TotalSeconds,RequestId)values(1,getdate(),0,2,2); select@@IDENTITYas erroridfromtb_Errors; insertintotb_Errors(ErrorId,createDate,Active,TotalSeconds,RequestId)values(2,getdate(),0,2,2); select@@IDENTITYas erroridfromtb_Errors; insertintotb_Errors(ErrorId,createDate,Active,TotalSeconds,RequestId)values(3,getdate(),0,2,2); select@@IDENTITYas erroridfromtb_Errors; SETIDENTITY_INSERT tb_ErrorsOFF; View Code
行，我們還是回到上面的那個問題，難道是因為多的那條SELECT語句造成的問題
那麼我們執行原始SQL語句來看一下（我們發現原始SQL語句也會被攔截，畢竟就算是執行原始SQL語句，也是呼叫EF提供的方法）
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
看到了吧，我用執行SQL語句，它是呼叫的NonQueryExecuting和NonQueryExecuted
這就真的讓人搞不懂了！