为ORM生成的SQL语句作日志
原创地址：http://www.cnblogs.com/jfzhu/archive/2012/12/08/2808277.html
转载请注明出处
将ORM为你生成的SQL语句记录日志，会为你在生产环境中的排错解难带来极大的便利。记录ORM生成的SQL语句，涉及到两个方面；一个是如何获得ORM生成的SQL语句，一个是如何记录日志。关于如何作日志，有很多种方法，我推荐使用log4net。在我之前的博客中，已经介绍了如何使用log4net的RollingFileAppender记录日志，这里就不再赘述。我在本文中以三个比较常用的ORM：LINQ to SQL，Entity Framework，NHibernate为例子，来演示如何获得它们生成的SQL语句，并将它们写入日志。
（1）LINQ to SQL
获得LINQ to SQL为你生成的SQL语句，你需要使用到你的DataContext的Log属性。你可以为DataContext的Log属性赋予一个StringWriter对象。请看下面的代码示例：
private void button1_Click(object sender, EventArgs e) { MethodBase methodBase = new StackFrame().GetMethod(); string methodString = this.GetType().Name + "::" + methodBase.Name; var ctx = new NorthwindModelDataContext(); var sw = new StringWriter(); ctx.Log = sw; var customers = from c in ctx.Customers where c.CompanyName.Contains("Restaurant") orderby c.PostalCode select new { c.CustomerID, c.CompanyName, c.PostalCode }; dataGridView1.DataSource = customers; Logger.LogDebug(methodString, sw.GetStringBuilder().ToString()); } private void button2_Click(object sender, EventArgs e) { MethodBase methodBase = new StackFrame().GetMethod(); string methodString = this.GetType().Name + "::" + methodBase.Name; var ctx = new NorthwindModelDataContext(); var sw = new StringWriter(); ctx.Log = sw; var customer = new Customer { CustomerID = "AAPIZ", CompanyName = "Aaron Pizza Restaurant" }; ctx.Customers.InsertOnSubmit(customer); ctx.SubmitChanges(); Logger.LogDebug(methodString, sw.GetStringBuilder().ToString()); }
生成的SQL语句可以用YourDataContext.Log.GetStringBuilder()方法来获得。Logger类的定义如下：
public class Logger { private static ILog logger = LogManager.GetLogger(""); public static void LogDebug(string MethodName, string Message) { logger.Debug(MethodName + "::" + Message); } public static void LogInfo(string MethodName, string Message) { logger.Info(MethodName + "::" + Message); } public static void LogWarning(string MethodName, string Message) { logger.Warn(MethodName + "::" + Message); } public static void LogError(string MethodName, string Message) { logger.Error(MethodName + "::" + Message); } public static void LogFatal(string MethodName, string Message) { logger.Fatal(MethodName + "::" + Message); } }
如果你的项目只有一个Logger，你可以象上面一样，在LogManager.GetLogger(string name)的方法中传递一个空的字符串作为参数。并且在配置文件中，也不需要定义Logger了，可以直接在root下面添加appender-ref
<?xml version="1.0"?> <configuration> <configSections> <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/> </configSections> <connectionStrings> <add name="WindowsFormsApplication2.Properties.Settings.NORTHWINDConnectionString" connectionString="Data Source=nlbesawse23;Initial Catalog=NORTHWIND;Integrated Security=True" providerName="System.Data.SqlClient"/> </connectionStrings> <log4net debug="false"> <root> <level value="DEBUG"/> <appender-ref ref="RollingLogFileAppenderWebform"/> </root> <appender name="RollingLogFileAppenderWebform" type="log4net.Appender.RollingFileAppender"> <file value="c:\\temp\\linq2sql.log.txt"/> <appendToFile value="true"/> <MaxSizeRollBackups value="10"/> <MaximumFileSize value="1MB"/> <RollingStyle value="Size"/> <StaticLogFileName value="true"/> <layout type="log4net.Layout.PatternLayout"> <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/> </layout> </appender> </log4net> <startup><supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/></startup></configuration>
在上面的代码中，分别执行了一个SELECT和一个INSERT，来看一下日志文件中对生成的SQL语句的记录：
2012-12-06 16:40:50,463 [9] DEBUG - Form1::button1_Click::
SELECT [t0].[CustomerID], [t0].[CompanyName], [t0].[PostalCode]
FROM [dbo].[Customers] AS [t0]
WHERE [t0].[CompanyName] LIKE @p0
ORDER BY [t0].[PostalCode]
-- @p0: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [%Restaurant%]
-- Context: SqlProvider(Sql2008) Model: AttributedMetaModel Build: 4.0.30319.1
2012-12-06 16:40:54,151 [9] DEBUG - Form1::button2_Click::
INSERT INTO [dbo].[Customers]([CustomerID], [CompanyName], [ContactName], [ContactTitle], [Address], [City], [Region], [PostalCode], [Country], [Phone], [Fax])
VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10)
-- @p0: Input NChar (Size = 5; Prec = 0; Scale = 0) [AAPIZ]
-- @p1: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Aaron Pizza Restaurant]
-- @p2: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p3: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p4: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p5: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p6: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p7: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p8: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p9: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- @p10: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [Null]
-- Context: SqlProvider(Sql2008) Model: AttributedMetaModel Build: 4.0.30319.1
（2） Entity Framework
对Entity Framework我只能获得它的SELECT语句，也就是说对于UPDATE、INSERT、DELETE语句，我也没有一个好的办法获得它们。当然如果你使用的数据库是SQL Server的话，你可以使用SQL Server Profiler来监控对数据库的操作，也可以购买一些第三方的软件，比如Entity Framework Profiler。我比较习惯使用log4net的方式来作日志，所以如果你有好的办法的话，欢迎你给我留言。下面来看一下如何获得Entity Framework生成的SELECT语句。
public static class ExtensionMethods { public static string ToTraceString<T>(this IQueryable<T> query) { var objQuery = query as ObjectQuery<T>; if (objQuery != null) return objQuery.ToTraceString(); return string.Empty; } } private void button1_Click(object sender, EventArgs e) { MethodBase methodBase = new StackFrame().GetMethod(); string methodString = this.GetType().Name + "::" + methodBase.Name; var db = new NORTHWINDEntities(); var customers = from c in db.Customers where c.CompanyName.Contains("Restaurant") orderby c.PostalCode select new { c.CustomerID, c.CompanyName, c.PostalCode }; dataGridView1.DataSource = customers; Logger.LogDebug(methodString, customers.ToTraceString()); }
为你的query定义一个扩展方法ToTraceString()，获得Entity Framework为该query生成的SQL语句可以直接调用yourQuery.ToTraceString()方法。关于如何定义扩展方法，可以查看我以前的博客。注意在ToTraceString()扩展方法中，需要将IQueryable<T> query cast为 ObjectQuery<T>。对Logger类的定义和LINQ to SQL的例子相同，log4net使用的配置文件如下，
<?xml version="1.0"?> <configuration> <configSections> <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/> </configSections> <connectionStrings> <add name="NORTHWINDEntities" connectionString="metadata=res://*/NorthwindModel.csdl|res://*/NorthwindModel.ssdl|res://*/NorthwindModel.msl;provider=System.Data.SqlClient;provider connection string="data source=nlbesawse23;initial catalog=NORTHWIND;integrated security=True;multipleactiveresultsets=True;App=EntityFramework"" providerName="System.Data.EntityClient"/> </connectionStrings> <log4net debug="false"> <root> <level value="DEBUG"/> <appender-ref ref="RollingLogFileAppenderWebform"/> </root> <appender name="RollingLogFileAppenderWebform" type="log4net.Appender.RollingFileAppender"> <file value="c:\\temp\\entityframwork.log.txt"/> <appendToFile value="true"/> <MaxSizeRollBackups value="10"/> <MaximumFileSize value="1MB"/> <RollingStyle value="Size"/> <StaticLogFileName value="true"/> <layout type="log4net.Layout.PatternLayout"> <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/> </layout> </appender> </log4net> <startup><supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/></startup></configuration>
该SELECT查询在日志中的记录为：
2012-12-06 17:19:43,204 [9] DEBUG - Form1::button1_Click::
SELECT
[Project1].[C1] AS [C1],
[Project1].[CustomerID] AS [CustomerID],
[Project1].[CompanyName] AS [CompanyName],
[Project1].[PostalCode] AS [PostalCode]
FROM ( SELECT
[Extent1].[CustomerID] AS [CustomerID],
[Extent1].[CompanyName] AS [CompanyName],
[Extent1].[PostalCode] AS [PostalCode],
1 AS [C1]
FROM [dbo].[Customers] AS [Extent1]
WHERE [Extent1].[CompanyName] LIKE N'%Restaurant%'
) AS [Project1]
ORDER BY [Project1].[PostalCode] ASC
（3） NHibernate
NHibernate已经使用了log4net来输出日志，所以你只需要在配置文件中配置好log4net，就可以得到NHibernate生成的日志文件。
private void button1_Click(object sender, EventArgs e) { MethodBase methodBase = new StackFrame().GetMethod(); string methodString = this.GetType().Name + "::" + methodBase.Name; Logger.LogDebug(methodString, "button1 is clicked"); var factory = CreateSessionFactory(); using (var session = factory.OpenSession()) { var customers = session.Query<Customers>() .Where(x => x.CompanyName.Contains("Restaurant")) .OrderBy(c => c.CustomerID).Select(x => new {x.CompanyName, x.CustomerID, x.PostalCode}) .ToList(); dataGridView1.DataSource = customers; } } private void button2_Click(object sender, EventArgs e) { MethodBase methodBase = new StackFrame().GetMethod(); string methodString = this.GetType().Name + "::" + methodBase.Name; Logger.LogDebug(methodString, "button2 is clicked"); var factory = CreateSessionFactory(); using (var session = factory.OpenSession()) { var category = new Customers { CustomerID = "AAPIZ", CompanyName = "Aaron Pizza Restaurant" }; session.Save(category); session.Flush(); } }
在上面的代码中，不要忘记在使用NHibernate前，先在日志中写点内容，否则是看不到NHibernate生成的日志内容的 - Logger.LogDebug(methodString, "button1 is clicked");
使用的log4net配置如下：
<?xml version="1.0"?> <configuration> <configSections> <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/> </configSections> <log4net debug="false"> <root> <level value="DEBUG"/> <appender-ref ref="RollingLogFileAppenderWebform"/> </root> <appender name="RollingLogFileAppenderWebform" type="log4net.Appender.RollingFileAppender"> <file value="c:\\temp\\nhibernate.log.txt"/> <appendToFile value="true"/> <MaxSizeRollBackups value="10"/> <MaximumFileSize value="1MB"/> <RollingStyle value="Size"/> <StaticLogFileName value="true"/> <layout type="log4net.Layout.PatternLayout"> <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/> </layout> </appender> <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender"> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/> </layout> </appender> </log4net> <startup> <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/> </startup> </configuration>
使用上面的配置文件，你可以获得NHibernate生成的所有日志，但是NHibernate生成了大量的日志，如果你只关心HNibernate生成的SQL语句，你还需要对log4net的配置做调整。我摘录下来一小部分日志文件的内容
2012-12-07 17:16:46,435 [9] DEBUG NHibernate.Engine.QueryParameters - BindParameters(name_p1:NHibernate.Type.StringType) Restaurant -> [0]
2012-12-07 17:16:46,435 [9] DEBUG NHibernate.Type.StringType - binding 'Restaurant' to parameter: 0
2012-12-07 17:16:46,435 [9] INFO NHibernate.Loader.Loader - select customers0_.CompanyName as col_0_0_, customers0_.CustomerID as col_1_0_, customers0_.PostalCode as col_2_0_ from [Customers] customers0_ where customers0_.CompanyName like ('%'+@p0+'%') order by customers0_.CustomerID asc
2012-12-07 17:16:46,435 [9] DEBUG NHibernate.SQL - select customers0_.CompanyName as col_0_0_, customers0_.CustomerID as col_1_0_, customers0_.PostalCode as col_2_0_ from [Customers] customers0_ where customers0_.CompanyName like ('%'+@p0+'%') order by customers0_.CustomerID asc;@p0 = 'Restaurant' [Type: String (4000)]
2012-12-07 17:16:46,435 [9] DEBUG NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver
2012-12-07 17:16:46,435 [9] DEBUG NHibernate.AdoNet.AbstractBatcher - ExecuteReader took 0 ms
上面的日志片断中，NHibernate.Engine.QueryParameters、NHibernate.Type.StringType、NHibernate.Loader.Loader、NHibernate.SQL、NHibernate.Connection.DriverConnectionProvider、NHibernate.AdoNet.AbstractBatcher 都是NHibernate定义好的Logger。而这其中只有NHibernate.SQL是关于生成的SQL语句的，所以在log4net的配置文件中，我们只需要定义NHibernate.SQL的Logger。
<?xml version="1.0"?> <configuration> <configSections> <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/> </configSections> <log4net debug="false"> <root> <level value="DEBUG"/> </root> <appender name="RollingLogFileAppenderWebform" type="log4net.Appender.RollingFileAppender"> <file value="c:\\temp\\nhibernate.log.txt"/> <appendToFile value="true"/> <MaxSizeRollBackups value="10"/> <MaximumFileSize value="1MB"/> <RollingStyle value="Size"/> <StaticLogFileName value="true"/> <layout type="log4net.Layout.PatternLayout"> <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/> </layout> </appender> <logger name="NHibernate.SQL"> <appender-ref ref="RollingLogFileAppenderWebform" /> </logger> </log4net> <startup><supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/></startup></configuration>
对Logger类的定义要使用LogManager.GetLogger("NHibernate.SQL");
public class Logger { private static ILog logger = LogManager.GetLogger("NHibernate.SQL"); public static void LogDebug(string MethodName, string Message) { logger.Debug(MethodName + "::" + Message); } public static void LogInfo(string MethodName, string Message) { logger.Info(MethodName + "::" + Message); } public static void LogWarning(string MethodName, string Message) { logger.Warn(MethodName + "::" + Message); } public static void LogError(string MethodName, string Message) { logger.Error(MethodName + "::" + Message); } public static void LogFatal(string MethodName, string Message) { logger.Fatal(MethodName + "::" + Message); } }
看一下生成的日志文件，SELECT和INSERT语句都被记录了下来。
2012-12-07 23:18:11,623 [9] DEBUG NHibernate.SQL - Form1::button1_Click::button1 is clicked
2012-12-07 23:18:13,358 [9] DEBUG NHibernate.SQL - select customers0_.CompanyName as col_0_0_, customers0_.CustomerID as col_1_0_, customers0_.PostalCode as col_2_0_ from [Customers] customers0_ where customers0_.CompanyName like ('%'+@p0+'%') order by customers0_.CustomerID asc;@p0 = 'Restaurant' [Type: String (4000)]
2012-12-07 23:18:18,405 [9] DEBUG NHibernate.SQL - Form1::button2_Click::button2 is clicked
2012-12-07 23:18:18,452 [9] DEBUG NHibernate.SQL - INSERT INTO [Customers] (CompanyName, ContactName, ContactTitle, Address, City, Region, PostalCode, Country, Phone, Fax, CustomerID) VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10);@p0 = 'Aaron Pizza Restaurant' [Type: String (4000)], @p1 = NULL [Type: String (4000)], @p2 = NULL [Type: String (4000)], @p3 = NULL [Type: String (4000)], @p4 = NULL [Type: String (4000)], @p5 = NULL [Type: String (4000)], @p6 = NULL [Type: String (4000)], @p7 = NULL [Type: String (4000)], @p8 = NULL [Type: String (4000)], @p9 = NULL [Type: String (4000)], @p10 = 'AAPIZ' [Type: String (4000)]
评论
#1楼 2012-12-08 11:33 猫之良品