DevExpress奮闘記-106 (XPO, log the SQL queries, SQLのロギングの方法あれこれ, TraceListener, DataStoreLogger)

XPOにて、内部で実際に発行されるSQLをロギングするための方法を
いろいろメモメモ。元ネタは、以下のKBです。

• How to log the SQL queries made by XPO
  • http://www.devexpress.com/Support/Center/p/A2572.aspx

まずは、一番手っ取り早い方法です。
アプリケーション構成ファイル (App.config)に以下の設定を記述します。

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.diagnostics>
    <switches>
      <add name="XPO"
           value="3" />
    </switches>
  </system.diagnostics>
</configuration>

上記のようにスイッチを設定することで、VisualStudioの「出力」ウィンドウに
SQLが出力されるようになります。以下、出力例です。

26.06.12 05:56:49.355 Executing sql 'select N0.[OID],N0.[TypeName],N0.[AssemblyName] from [XPObjectType] N0'
26.06.12 05:56:49.407 Result: rowcount = 1, total = 46, N0.{OID,Int32} = 4, N0.{TypeName,String} = 28, N0.{AssemblyName,String} = 14
26.06.12 05:56:49.604 Executing sql 'parameters p0 LONGTEXT,p1 int;insert into [MyData]([Name],[OptimisticLockField],[GCRecord])values(p0,p1,null)' with parameters {hehehe-0},{0}
26.06.12 05:56:49.626 Executing sql 'select @@Identity'
26.06.12 05:56:50.223 Executing sql 'select N0.[OID],N0.[TypeName],N0.[AssemblyName] from [XPObjectType] N0'
・
・
（中略）
・
・
26.06.12 05:56:50.240 Result: rowcount = 1, total = 46, N0.{OID,Int32} = 4, N0.{TypeName,String} = 28, N0.{AssemblyName,String} = 14
26.06.12 05:56:50.274 Executing sql 'select N0.[OID],N0.[Name],N0.[OptimisticLockField],N0.[GCRecord] from [MyData] N0 where N0.[GCRecord] is null'
26.06.12 05:56:50.292 Result: rowcount = 60, total = 1980, N0.{OID,Int32} = 240, N0.{Name,String} = 1260, N0.{OptimisticLockField,Int32} = 240, N0.{GCRecord,Int32} = 240

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using DevExpress.Xpo;
using System.Diagnostics;

namespace XPO04
{
  class Program
  {
    static void Main(string[] args)
    {
      using (UnitOfWork uow = new UnitOfWork())
      {
        for (int i = 0; i < 20; i++)
        {
          new MyData(uow){ Name = string.Format("hehehe-{0}", i) };
        }

        uow.CommitChanges();
      }

      using (UnitOfWork uow = new UnitOfWork())
      {
        foreach (var item in uow.Query<MyData>())
        {
          Console.WriteLine(item.Name);
        }
      }

      Console.ReadLine();
    }
  }

  public class MyData : XPObject
  {
    public MyData(Session session)
      : base(session)
    { }

    // Fields...
    private string _name;

    public string Name
    {
      get
      {
        return _name;
      }
      set
      {
        SetPropertyValue("Name", ref _name, value);
      }
    }
  }
}

次は、先ほどの設定にTraceListenerを設定した版。

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.diagnostics>
    <trace autoflush="true"
           indentsize="2">
      <listeners>
        <add name="LogFileTraceListener"
             type="System.Diagnostics.TextWriterTraceListener"
             initializeData="xpo.log" />
        <remove name="Default" />
      </listeners>
    </trace>
    <switches>
      <add name="XPO"
           value="3" />
    </switches>
  </system.diagnostics>
</configuration>

出力内容は先に挙げた出力と同じですが、こちらはxpo.logファイルにも
内容がロギングされます。

XPOは、ログの出力に.NET標準のロギングメカニズムを利用しているので
自前でカスタムTraceListenerを作成してもロギングさせることが出来ます。
log4netやNLogを利用してログを出力させたい場合などに利用できます。
以下、カスタムTraceListenerを作成してlog4netと組み合わせている例です。

以下、log4netの設定も含めたapp.config。

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>
  <system.diagnostics>
    <switches>
      <add name="XPO"
           value="3"/>
    </switches>
  </system.diagnostics>
  <log4net>
    <appender name="ConsoleLogger"
              type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <param name="ConversionPattern"
               value="%date [%thread] %-5level (%class.%method:%line) - %message%newline" />
      </layout>   
    </appender>
    <appender name="XpoFileApplender"
              type="log4net.Appender.FileAppender">
      <file value="xpo.log" />
      <appendToFile value="true" />
      <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %level - %message%newline" />
      </layout>
    </appender>>
    <root>
      <level value="INFO"/>
      <appender-ref ref="ConsoleLogger"/>
      <appender-ref ref="XpoFileApplender"/>
    </root>
    <logger>
      
    </logger>
  </log4net>
</configuration>

以下、実行部分とカスタムTraceListenerクラスです。

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;

using DevExpress.Xpo;
using log4net;

// AssemblyInfo.csに以下を設定しておきます。
// [assembly: log4net.Config.XmlConfigurator(Watch = true)]

namespace XPO05
{ 
  class Program
  {
    readonly static ILog log = LogManager.GetLogger(typeof(Program));

    static void Main()
    {
      //
      // TraceListenerとlog4netを組み合わせてXPOの内容をロギング.
      //
      log.Info("Program.Main enter...");

      Trace.Listeners.Add(new XpoLog4NetTraceListener(log));

      using (UnitOfWork uow = new UnitOfWork())
      {
        new MyData(uow) { Name = "Hello World" };
        uow.CommitChanges();
      }

      using (UnitOfWork uow = new UnitOfWork())
      {
        var query = from x in uow.Query<MyData>()
                    select x;

        foreach (var item in query)
        {
          Console.WriteLine(item.Name);
        }
      }

      log.Info("Program.Main leave.");
    }
  }

  /// <summary>
  /// サンプル用XPOクラス.
  /// </summary>
  public class MyData : XPObject
  {
    private string _name;
    
    public MyData(Session session) : base(session)
    { 
    }

    public string Name
    {
      get
      {
        return _name;
      }
      set
      {
        SetPropertyValue("Name", ref _name, value);
      }
    }
  }

  /// <summary>
  /// カスタムTraceListener.
  /// </summary>
  class XpoLog4NetTraceListener : TraceListener
  {
    readonly ILog _log;

    public XpoLog4NetTraceListener(ILog log)
    {
      _log = log;
    }

    public override void Write(string message)
    {
      _log.Info(message);
    }

    public override void WriteLine(string message)
    {
       _log.Info(message);
    }
  }
}

実行すると、実行コンソールにログが表示され、アプリ直下にxpo.logファイルが生成されます。

2012-06-26 06:12:27,330 [1] INFO - Program.Main enter...
2012-06-26 06:12:27,840 [1] INFO - 26.06.12 06:12:27.840 Executing sql 'select N0.[OID],N0.[TypeName],N0.[AssemblyName] from [XPObjectType] N0'
2012-06-26 06:12:27,859 [1] INFO - 26.06.12 06:12:27.859 Result: rowcount = 1, total = 46, N0.{OID,Int32} = 4, N0.{TypeName,String} = 28, N0.{AssemblyName,String} = 14
2012-06-26 06:12:27,984 [1] INFO - 26.06.12 06:12:27.984 Executing sql 'parameters p0 LONGTEXT,p1 int;insert into [MyData]([Name],[OptimisticLockField],[GCRecord])values(p0,p1,null)' with parameters {Hello World},{0}
2012-06-26 06:12:27,990 [1] INFO - 26.06.12 06:12:27.990 Executing sql 'select @@Identity'
2012-06-26 06:12:28,104 [1] INFO - 26.06.12 06:12:28.104 Executing sql 'select N0.[OID],N0.[TypeName],N0.[AssemblyName] from [XPObjectType] N0'
2012-06-26 06:12:28,107 [1] INFO - 26.06.12 06:12:28.107 Result: rowcount = 1, total = 46, N0.{OID,Int32} = 4, N0.{TypeName,String} = 28, N0.{AssemblyName,String} = 14
2012-06-26 06:12:28,133 [1] INFO - 26.06.12 06:12:28.133 Executing sql 'select N0.[OID],N0.[Name],N0.[OptimisticLockField],N0.[GCRecord] from [MyData] N0 where N0.[GCRecord] is null'
2012-06-26 06:12:28,137 [1] INFO - 26.06.12 06:12:28.137 Result: rowcount = 14, total = 532, N0.{OID,Int32} = 56, N0.{Name,String} = 364, N0.{OptimisticLockField,Int32} = 56, N0.{GCRecord,Int32} = 56
2012-06-26 06:12:28,193 [1] INFO - Program.Main leave.

上記までは、TraceListenerを利用してロギングを行っていましたが
XPOには、IDataStoreにラップすることによりロギングするやり方もあります。
DataStoreLoggerクラスを利用します。

以下、サンプルです。

using System;
using System.Collections.Generic;
using System.Linq;
using DevExpress.Xpo;
using DevExpress.Xpo.DB;

namespace XPO02
{
  class Program
  {
    static void Main(string[] args)
    {
      //
      // 標準出力にロギングする設定を行う.
      //
      IDataStore trackedDataStore = XpoDefault.GetConnectionProvider(AutoCreateOption.DatabaseAndSchema);
      IDataStore loggingDataStore = new DataStoreLogger(trackedDataStore, Console.Out);
      IDataLayer dataLayer        = new SimpleDataLayer(loggingDataStore);

      using (UnitOfWork uow = new UnitOfWork(dataLayer))
      {
        new XPOSampleData(uow) { Name = "Hello World" };
        uow.CommitChanges();
      }

      using (UnitOfWork uow = new UnitOfWork(dataLayer))
      {
        var query = from x in uow.Query<XPOSampleData>()
                    select x;

        foreach (var item in query)
        {
          Console.WriteLine(item.Name);
        }
      }
    }
  }

  public class XPOSampleData : XPObject
  {
    // Fields...
    private string _name;
    
    public XPOSampleData(Session session) : base(session)
    { 
    }

    public string Name
    {
      get
      {
        return _name;
      }
      set
      {
        SetPropertyValue("Name", ref _name, value);
      }
    }
  }
}

上記サンプルにて

IDataStore loggingDataStore = new DataStoreLogger(trackedDataStore, Console.Out);

の部分が、ロギング用DataStoreを設定している部分です。
一つ目の引数に実DataStoreを、二つ目の引数にTextWriterを設定することが出来ます。
このサンプルでは、Console.Outを設定しています。

サンプルを実行すると、コンソールにログが出力されます。

2012-06-25 21:20:41Z UpdateSchema for tables XPObjectType, opt: True, result: SchemaExists
2012-06-25 21:20:41Z SelectData request with 1 queries:select('N0'.'OID','N0'.'TypeName','N0'.'AssemblyName') from('XPObjectType'.'N0') where() order() group() having() params() constants() ;
result[0] 1 rows: 1      "XPO02.XPOSampleData"   "XPO02"
2012-06-25 21:20:41Z UpdateSchema for tables XPOSampleData, opt: False, result:SchemaExists
2012-06-25 21:20:41Z ModifyData: insert into 'XPOSampleData'('Name','OptimisticLockField','GCRecord') values(?,?,null) params('Hello World','0') constants() result: Ok, identities returned: 3
2012-06-25 21:20:41Z SelectData request with 1 queries:select('N0'.'OID','N0'.'Name','N0'.'OptimisticLockField','N0'.'GCRecord') from('XPOSampleData'.'N0') where(IsNull('N0'.'GCRecord')) order() group() having() params() constants() ;
result[0] 3 rows:
 1      "Hello World"   0       null
 2      "Hello World"   0       null
 3      "Hello World"   0       null

という風にいろいろとログのやり方について記述してきたのですが
最近 (v11以降）は、XPO Profilerという専用のプロファイラーツールが
提供されましたので、そちらを利用するようが、設定も楽で視覚的にも見やすいです。

• XPO Profiler
  • http://documentation.devexpress.com/#XpoProfiler/CustomDocument10646

次回は、XPO Profilerの使い方などについてちょっとメモします。

＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝
過去の記事については、以下のページからご参照下さい。

• いろいろ備忘録日記まとめ
  • http://sites.google.com/site/gsfzero1/