Show Blogger Panel Hide Blogger Panel
Alex Yakunin

October 15, 2009

DataObjects.Net v4.1: easy logging and uber-batching in action

Initially I planned to talk about future queries here, but since almost all space here takes produced log, I decided to mention it as well.

Note: If you're viewing this post in RSS/Atom reader, open its origin to see it with syntax highlighting.

Let's start right from code. If you're interested in conclusions, go to the tail of this post.

Program.cs:
using System;
using System.Linq;
using Xtensive.Storage;
using Xtensive.Storage.Configuration;
using Batching.Model;

namespace Batching.Model
{
  [HierarchyRoot]
  public class MyEntity : Entity
  {
    [Field, Key]
    public int Id { get; private set; }

    [Field(Length = 100)]
    public string Text { get; set; }
  }
}

namespace Batching
{
  class Program
  {
    static void Main(string[] args)
    {
      var config = DomainConfiguration.Load("Default");
      var domain = Domain.Build(config);

      using (Session.Open(domain)) {
        using (var transactionScope = Transaction.Open()) {
          var entity1 = new MyEntity {
            Text = "Entity 1"
          }; // Nothing is sent to server yet
          
          var entity2 = new MyEntity {
            Text = "Entity 2"
          }; // Nothing is sent to server yet

          var futureCount = Query.ExecuteFutureScalar(
            () => Query<MyEntity>.All.Count());

          foreach (var e in Query<MyEntity>.All) // Batch is sent
            Console.WriteLine("Entity.Text: {0}", e.Text); 
          Console.WriteLine("Count: {0}", futureCount.Value);

          // Committing transaction
          transactionScope.Complete();
        }
      }
      Console.ReadLine();
    }
  }
}
App.config:
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="Xtensive.Storage" 
             type="Xtensive.Storage.Configuration.Elements.ConfigurationSection, Xtensive.Storage" />
    <section name="Xtensive.Core.Diagnostics" 
             type="Xtensive.Core.Diagnostics.Configuration.ConfigurationSection, Xtensive.Core" />
  </configSections>
  <Xtensive.Core.Diagnostics>
    <logs>
      <log name=""        provider="Null" />
      <log name="Storage" provider="File" formatString="{5}"/>
    </logs>
  </Xtensive.Core.Diagnostics>
  <Xtensive.Storage>
    <domains>
      <domain name="Default" upgradeMode="Recreate" connectionUrl="sqlserver://localhost/DO40-Tests" >
        <types>
          <add assembly="Batching" />
        </types>
      </domain>
    </domains>
  </Xtensive.Storage>
</configuration>
Output:
Entity.Text: Entity 1
Entity.Text: Entity 2
Count: 2
And finally, its log - Batching.exe.log:
Building Domain: started.
Creating Domain: started.
Creating Domain: completed.
Creating HandlerFactory: started.
Creating HandlerFactory: completed.
Creating DomainHandler: started.
Creating DomainHandler: completed.
Creating NameBuilder: started.
Creating NameBuilder: completed.
Creating DomainHandler: started.
Creating DomainHandler: completed.
Building Model: started.
Building Model Definition: started.
Defining 'Types': started.
Defining 'Xtensive.Storage.IEntity': started.
Defining 'Xtensive.Storage.IEntity': completed.
Defining 'Xtensive.Storage.Entity': started.
Field: 'TypeId'
Defining 'Xtensive.Storage.Entity': completed.
Defining 'Xtensive.Storage.Metadata.MetadataBase': started.
Defining 'Xtensive.Storage.Metadata.MetadataBase': completed.
Defining 'Xtensive.Storage.Metadata.Type': started.
Field: 'Id'
Field: 'Name'
Field: 'TypeId'
Index: 'IX_Name'
Hierarchy: 'Type'
Defining 'Xtensive.Storage.Metadata.Type': completed.
Defining 'Xtensive.Storage.Metadata.Extension': started.
Field: 'Name'
Field: 'Text'
Field: 'Data'
Field: 'TypeId'
Hierarchy: 'Extension'
Defining 'Xtensive.Storage.Metadata.Extension': completed.
Defining 'Xtensive.Storage.Structure': started.
Defining 'Xtensive.Storage.Structure': completed.
Defining 'Xtensive.Storage.Metadata.Assembly': started.
Field: 'Name'
Field: 'Version'
Field: 'TypeId'
Hierarchy: 'Assembly'
Defining 'Xtensive.Storage.Metadata.Assembly': completed.
Defining 'Batching.Model.MyEntity': started.
Field: 'Id'
Field: 'Text'
Field: 'TypeId'
Hierarchy: 'MyEntity'
Defining 'Batching.Model.MyEntity': completed.
Defining 'Types': completed.
Building Model Definition: completed.
Building Custom Definitions: started.
Building Custom Definitions: completed.
Inspecting model definition: started.
Inspecting hierarchy 'Type'
Inspecting hierarchy 'Extension'
Inspecting hierarchy 'Assembly'
Inspecting hierarchy 'MyEntity'
Inspecting type 'Entity'
Inspecting type 'MetadataBase'
Inspecting type 'Type'
Inspecting type 'Extension'
Inspecting type 'Structure'
Inspecting type 'Assembly'
Inspecting type 'MyEntity'
Inspecting model definition: completed.
Processing fixup actions: started.
Executing action: 'Mark 'Type.TypeId' field as system.'
Executing action: 'Reorder fields in 'Type' type.'
Executing action: 'Add primary index to 'Type''
Executing action: 'Mark 'Extension.TypeId' field as system.'
Executing action: 'Reorder fields in 'Extension' type.'
Executing action: 'Mark 'Extension.Name' field as not nullable.'
Executing action: 'Add primary index to 'Extension''
Executing action: 'Mark 'Assembly.TypeId' field as system.'
Executing action: 'Reorder fields in 'Assembly' type.'
Executing action: 'Mark 'Assembly.Name' field as not nullable.'
Executing action: 'Add primary index to 'Assembly''
Executing action: 'Mark 'MyEntity.TypeId' field as system.'
Executing action: 'Reorder fields in 'MyEntity' type.'
Executing action: 'Add primary index to 'MyEntity''
Executing action: 'Remove 'Entity' type.'
Executing action: 'Remove 'MetadataBase' type.'
Processing fixup actions: completed.
Building Actual Model: started.
Building Types: started.
Building Type: started.
Building declared field 'Type.Id'
Building Extension: started.
Building declared field 'Extension.Name'
Building Assembly: started.
Building declared field 'Assembly.Name'
Building MyEntity: started.
Building declared field 'MyEntity.Id'
Building Types: completed.
Building Fields: started.
Building declared field 'Type.TypeId'
Building declared field 'Type.Name'
Building declared field 'Extension.TypeId'
Building declared field 'Extension.Text'
Building declared field 'Extension.Data'
Building declared field 'Assembly.TypeId'
Building declared field 'Assembly.Version'
Building declared field 'MyEntity.TypeId'
Building declared field 'MyEntity.Text'
Building Fields: completed.
Building Associations: started.
Building Associations: completed.
Building Indexes: started.
Building index 'IX_Name'
Building index 'PK_Type'
Building index 'PK_Extension'
Building index 'PK_Assembly'
Building index 'PK_MyEntity'
Building Indexes: completed.
Building Actual Model: completed.
Building Model: completed.
Opening session 'Name = System, Options = Default, CacheType = LruWeak, CacheSize = 16384, DefaultIsolationLevel = ReadCommitted'.
Session 'System, #1'. Creating connection 'sqlserver://localhost/DO40-Tests'.
Session 'System, #1'. Opening connection 'sqlserver://localhost/DO40-Tests'.
Session 'System, #1'. Beginning transaction @ ReadCommitted.
Synchronizing schema in Recreate mode: started.
Target schema:
Extracted schema:
Clearing comparison result:
Status: TargetIsSubset, Can't upgrade safely
Hints:
  
Difference:
  "./" != "./" (NodeDifference): 0
    +Tables: "./Tables (4)" != "./Tables (0)" (NodeCollectionDifference): 4 change(s)
      "./Tables/Metadata.Type" != "" (NodeDifference): Removed
        +Columns: "./Tables/Metadata.Type/Columns (3)" != "" (NodeCollectionDifference): 3 change(s)
          "./Tables/Metadata.Type/Columns/Id" != "" (NodeDifference): Removed
            +Type: "Type: Int32, Length: null" != "" (ValueDifference): values differ
          "./Tables/Metadata.Type/Columns/TypeId" != "" (NodeDifference): Removed
            +Type: "Type: Int32, Length: null" != "" (ValueDifference): values differ
          "./Tables/Metadata.Type/Columns/Name" != "" (NodeDifference): Removed
            +Type: "Type: String?, Length: 1000" != "" (ValueDifference): values differ
        +PrimaryIndex: "./Tables/Metadata.Type/PrimaryIndex (PK_Type)" != "" (NodeDifference): Removed
          +IsUnique: "True" != "False" (ValueDifference): values differ
          +KeyColumns: "./Tables/Metadata.Type/PrimaryIndex/KeyColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
            "./Tables/Metadata.Type/PrimaryIndex/KeyColumns/0" != "" (NodeDifference): Removed
              +Direction: "Positive" != "None" (ValueDifference): values differ
              +Value: "./Tables/Metadata.Type/Columns/Id" != "" (ValueDifference): values differ
        +SecondaryIndexes: "./Tables/Metadata.Type/SecondaryIndexes (1)" != "" (NodeCollectionDifference): 1 change(s)
          "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name" != "" (NodeDifference): Removed
            +IsUnique: "True" != "False" (ValueDifference): values differ
            +KeyColumns: "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/KeyColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
              "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/KeyColumns/0" != "" (NodeDifference): Removed
                +Direction: "Positive" != "None" (ValueDifference): values differ
                +Value: "./Tables/Metadata.Type/Columns/Name" != "" (ValueDifference): values differ
            +PrimaryKeyColumns: "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/PrimaryKeyColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
              "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/PrimaryKeyColumns/0" != "" (NodeDifference): Removed
                +Direction: "Positive" != "None" (ValueDifference): values differ
                +Value: "./Tables/Metadata.Type/Columns/Id" != "" (ValueDifference): values differ
            +IncludedColumns: "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/ValueColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
              "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/IncludedColumns/0" != "" (NodeDifference): Removed
                +Value: "./Tables/Metadata.Type/Columns/TypeId" != "" (ValueDifference): values differ
      "./Tables/Metadata.Extension" != "" (NodeDifference): Removed
        +Columns: "./Tables/Metadata.Extension/Columns (4)" != "" (NodeCollectionDifference): 4 change(s)
          "./Tables/Metadata.Extension/Columns/Name" != "" (NodeDifference): Removed
            +Type: "Type: String, Length: 1024" != "" (ValueDifference): values differ
          "./Tables/Metadata.Extension/Columns/TypeId" != "" (NodeDifference): Removed
            +Type: "Type: Int32, Length: null" != "" (ValueDifference): values differ
          "./Tables/Metadata.Extension/Columns/Text" != "" (NodeDifference): Removed
            +Type: "Type: String?, Length: null" != "" (ValueDifference): values differ
          "./Tables/Metadata.Extension/Columns/Data" != "" (NodeDifference): Removed
            +Type: "Type: Byte[]?, Length: null" != "" (ValueDifference): values differ
        +PrimaryIndex: "./Tables/Metadata.Extension/PrimaryIndex (PK_Extension)" != "" (NodeDifference): Removed
          +IsUnique: "True" != "False" (ValueDifference): values differ
          +KeyColumns: "./Tables/Metadata.Extension/PrimaryIndex/KeyColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
            "./Tables/Metadata.Extension/PrimaryIndex/KeyColumns/0" != "" (NodeDifference): Removed
              +Direction: "Positive" != "None" (ValueDifference): values differ
              +Value: "./Tables/Metadata.Extension/Columns/Name" != "" (ValueDifference): values differ
      "./Tables/Metadata.Assembly" != "" (NodeDifference): Removed
        +Columns: "./Tables/Metadata.Assembly/Columns (3)" != "" (NodeCollectionDifference): 3 change(s)
          "./Tables/Metadata.Assembly/Columns/Name" != "" (NodeDifference): Removed
            +Type: "Type: String, Length: 1024" != "" (ValueDifference): values differ
          "./Tables/Metadata.Assembly/Columns/TypeId" != "" (NodeDifference): Removed
            +Type: "Type: Int32, Length: null" != "" (ValueDifference): values differ
          "./Tables/Metadata.Assembly/Columns/Version" != "" (NodeDifference): Removed
            +Type: "Type: String?, Length: 64" != "" (ValueDifference): values differ
        +PrimaryIndex: "./Tables/Metadata.Assembly/PrimaryIndex (PK_Assembly)" != "" (NodeDifference): Removed
          +IsUnique: "True" != "False" (ValueDifference): values differ
          +KeyColumns: "./Tables/Metadata.Assembly/PrimaryIndex/KeyColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
            "./Tables/Metadata.Assembly/PrimaryIndex/KeyColumns/0" != "" (NodeDifference): Removed
              +Direction: "Positive" != "None" (ValueDifference): values differ
              +Value: "./Tables/Metadata.Assembly/Columns/Name" != "" (ValueDifference): values differ
      "./Tables/MyEntity" != "" (NodeDifference): Removed
        +Columns: "./Tables/MyEntity/Columns (3)" != "" (NodeCollectionDifference): 3 change(s)
          "./Tables/MyEntity/Columns/Id" != "" (NodeDifference): Removed
            +Type: "Type: Int32, Length: null" != "" (ValueDifference): values differ
          "./Tables/MyEntity/Columns/TypeId" != "" (NodeDifference): Removed
            +Type: "Type: Int32, Length: null" != "" (ValueDifference): values differ
          "./Tables/MyEntity/Columns/Text" != "" (NodeDifference): Removed
            +Type: "Type: String?, Length: 100" != "" (ValueDifference): values differ
        +PrimaryIndex: "./Tables/MyEntity/PrimaryIndex (PK_MyEntity)" != "" (NodeDifference): Removed
          +IsUnique: "True" != "False" (ValueDifference): values differ
          +KeyColumns: "./Tables/MyEntity/PrimaryIndex/KeyColumns (1)" != "" (NodeCollectionDifference): 1 change(s)
            "./Tables/MyEntity/PrimaryIndex/KeyColumns/0" != "" (NodeDifference): Removed
              +Direction: "Positive" != "None" (ValueDifference): values differ
              +Value: "./Tables/MyEntity/Columns/Id" != "" (ValueDifference): values differ
    +Sequences: "./Sequences (1)" != "./Sequences (0)" (NodeCollectionDifference): 1 change(s)
      "./Sequences/Int32-Generator" != "" (NodeDifference): Removed
        +Increment: "128" != "0" (ValueDifference): values differ
Actions:
  GroupingNode, Comment=Prepare
    GroupingNode, Comment=.
      GroupingNode, Comment=Sequences[]
        GroupingNode, Comment=Int32-Generator
          RemoveNode, Path=Sequences/Int32-Generator
      GroupingNode, Comment=Tables[]
        GroupingNode, Comment=Metadata.Type
          RemoveNode, Path=Tables/Metadata.Type
        GroupingNode, Comment=Metadata.Extension
          RemoveNode, Path=Tables/Metadata.Extension
        GroupingNode, Comment=Metadata.Assembly
          RemoveNode, Path=Tables/Metadata.Assembly
        GroupingNode, Comment=MyEntity
          RemoveNode, Path=Tables/MyEntity
  GroupingNode, Comment=TemporaryRename
  
Session 'System, #1'. Schema upgrade script:
DROP TABLE [dbo].[Int32-Generator];
DROP TABLE [dbo].[Metadata.Type];
DROP TABLE [dbo].[Metadata.Extension];
DROP TABLE [dbo].[Metadata.Assembly];
DROP TABLE [dbo].[MyEntity];
Session 'n/a'. SQL batch: 
DROP TABLE [dbo].[Int32-Generator];
DROP TABLE [dbo].[Metadata.Type];
DROP TABLE [dbo].[Metadata.Extension];
DROP TABLE [dbo].[Metadata.Assembly];
DROP TABLE [dbo].[MyEntity];
Comparison result:
Status: TargetIsSuperset, Can upgrade safely
Hints:
  
Difference:
  "./" != "./" (NodeDifference): 0
    +Tables: "./Tables (0)" != "./Tables (4)" (NodeCollectionDifference): 4 change(s)
      "" != "./Tables/Metadata.Type" (NodeDifference): Created
        +Columns: "" != "./Tables/Metadata.Type/Columns (3)" (NodeCollectionDifference): 3 change(s)
          "" != "./Tables/Metadata.Type/Columns/Id" (NodeDifference): Created
            +Type: "" != "Type: Int32, Length: null" (ValueDifference): values differ
          "" != "./Tables/Metadata.Type/Columns/TypeId" (NodeDifference): Created
            +Type: "" != "Type: Int32, Length: null" (ValueDifference): values differ
          "" != "./Tables/Metadata.Type/Columns/Name" (NodeDifference): Created
            +Type: "" != "Type: String?, Length: 1000" (ValueDifference): values differ
        +PrimaryIndex: "" != "./Tables/Metadata.Type/PrimaryIndex (PK_Type)" (NodeDifference): Created
          +IsUnique: "False" != "True" (ValueDifference): values differ
          +KeyColumns: "" != "./Tables/Metadata.Type/PrimaryIndex/KeyColumns (1)" (NodeCollectionDifference): 1 change(s)
            "" != "./Tables/Metadata.Type/PrimaryIndex/KeyColumns/0" (NodeDifference): Created
              +Direction: "None" != "Positive" (ValueDifference): values differ
              +Value: "" != "./Tables/Metadata.Type/Columns/Id" (ValueDifference): values differ
        +SecondaryIndexes: "" != "./Tables/Metadata.Type/SecondaryIndexes (1)" (NodeCollectionDifference): 1 change(s)
          "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name" (NodeDifference): Created
            +IsUnique: "False" != "True" (ValueDifference): values differ
            +KeyColumns: "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/KeyColumns (1)" (NodeCollectionDifference): 1 change(s)
              "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/KeyColumns/0" (NodeDifference): Created
                +Direction: "None" != "Positive" (ValueDifference): values differ
                +Value: "" != "./Tables/Metadata.Type/Columns/Name" (ValueDifference): values differ
            +PrimaryKeyColumns: "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/PrimaryKeyColumns (1)" (NodeCollectionDifference): 1 change(s)
              "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/PrimaryKeyColumns/0" (NodeDifference): Created
                +Direction: "None" != "Positive" (ValueDifference): values differ
                +Value: "" != "./Tables/Metadata.Type/Columns/Id" (ValueDifference): values differ
            +IncludedColumns: "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/ValueColumns (1)" (NodeCollectionDifference): 1 change(s)
              "" != "./Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/IncludedColumns/0" (NodeDifference): Created
                +Value: "" != "./Tables/Metadata.Type/Columns/TypeId" (ValueDifference): values differ
      "" != "./Tables/Metadata.Extension" (NodeDifference): Created
        +Columns: "" != "./Tables/Metadata.Extension/Columns (4)" (NodeCollectionDifference): 4 change(s)
          "" != "./Tables/Metadata.Extension/Columns/Name" (NodeDifference): Created
            +Type: "" != "Type: String, Length: 1024" (ValueDifference): values differ
          "" != "./Tables/Metadata.Extension/Columns/TypeId" (NodeDifference): Created
            +Type: "" != "Type: Int32, Length: null" (ValueDifference): values differ
          "" != "./Tables/Metadata.Extension/Columns/Text" (NodeDifference): Created
            +Type: "" != "Type: String?, Length: null" (ValueDifference): values differ
          "" != "./Tables/Metadata.Extension/Columns/Data" (NodeDifference): Created
            +Type: "" != "Type: Byte[]?, Length: null" (ValueDifference): values differ
        +PrimaryIndex: "" != "./Tables/Metadata.Extension/PrimaryIndex (PK_Extension)" (NodeDifference): Created
          +IsUnique: "False" != "True" (ValueDifference): values differ
          +KeyColumns: "" != "./Tables/Metadata.Extension/PrimaryIndex/KeyColumns (1)" (NodeCollectionDifference): 1 change(s)
            "" != "./Tables/Metadata.Extension/PrimaryIndex/KeyColumns/0" (NodeDifference): Created
              +Direction: "None" != "Positive" (ValueDifference): values differ
              +Value: "" != "./Tables/Metadata.Extension/Columns/Name" (ValueDifference): values differ
      "" != "./Tables/Metadata.Assembly" (NodeDifference): Created
        +Columns: "" != "./Tables/Metadata.Assembly/Columns (3)" (NodeCollectionDifference): 3 change(s)
          "" != "./Tables/Metadata.Assembly/Columns/Name" (NodeDifference): Created
            +Type: "" != "Type: String, Length: 1024" (ValueDifference): values differ
          "" != "./Tables/Metadata.Assembly/Columns/TypeId" (NodeDifference): Created
            +Type: "" != "Type: Int32, Length: null" (ValueDifference): values differ
          "" != "./Tables/Metadata.Assembly/Columns/Version" (NodeDifference): Created
            +Type: "" != "Type: String?, Length: 64" (ValueDifference): values differ
        +PrimaryIndex: "" != "./Tables/Metadata.Assembly/PrimaryIndex (PK_Assembly)" (NodeDifference): Created
          +IsUnique: "False" != "True" (ValueDifference): values differ
          +KeyColumns: "" != "./Tables/Metadata.Assembly/PrimaryIndex/KeyColumns (1)" (NodeCollectionDifference): 1 change(s)
            "" != "./Tables/Metadata.Assembly/PrimaryIndex/KeyColumns/0" (NodeDifference): Created
              +Direction: "None" != "Positive" (ValueDifference): values differ
              +Value: "" != "./Tables/Metadata.Assembly/Columns/Name" (ValueDifference): values differ
      "" != "./Tables/MyEntity" (NodeDifference): Created
        +Columns: "" != "./Tables/MyEntity/Columns (3)" (NodeCollectionDifference): 3 change(s)
          "" != "./Tables/MyEntity/Columns/Id" (NodeDifference): Created
            +Type: "" != "Type: Int32, Length: null" (ValueDifference): values differ
          "" != "./Tables/MyEntity/Columns/TypeId" (NodeDifference): Created
            +Type: "" != "Type: Int32, Length: null" (ValueDifference): values differ
          "" != "./Tables/MyEntity/Columns/Text" (NodeDifference): Created
            +Type: "" != "Type: String?, Length: 100" (ValueDifference): values differ
        +PrimaryIndex: "" != "./Tables/MyEntity/PrimaryIndex (PK_MyEntity)" (NodeDifference): Created
          +IsUnique: "False" != "True" (ValueDifference): values differ
          +KeyColumns: "" != "./Tables/MyEntity/PrimaryIndex/KeyColumns (1)" (NodeCollectionDifference): 1 change(s)
            "" != "./Tables/MyEntity/PrimaryIndex/KeyColumns/0" (NodeDifference): Created
              +Direction: "None" != "Positive" (ValueDifference): values differ
              +Value: "" != "./Tables/MyEntity/Columns/Id" (ValueDifference): values differ
    +Sequences: "./Sequences (0)" != "./Sequences (1)" (NodeCollectionDifference): 1 change(s)
      "" != "./Sequences/Int32-Generator" (NodeDifference): Created
        +Increment: "0" != "128" (ValueDifference): values differ
Actions:
  GroupingNode, Comment=Prepare
  GroupingNode, Comment=TemporaryRename
  GroupingNode, Comment=Upgrade
    GroupingNode, Comment=.
      GroupingNode, Comment=Tables[]
        GroupingNode, Comment=Metadata.Type
          CreateNode, Path=, Type=TableInfo, Name=Metadata.Type, Index=0
          GroupingNode, Comment=Columns[]
            GroupingNode, Comment=Id
              CreateNode, Path=Tables/Metadata.Type, Type=ColumnInfo, Name=Id, Index=0
              PropertyChange, Path=Tables/Metadata.Type/Columns/Id, Type=Type: Int32, Length: null
            GroupingNode, Comment=TypeId
              CreateNode, Path=Tables/Metadata.Type, Type=ColumnInfo, Name=TypeId, Index=1
              PropertyChange, Path=Tables/Metadata.Type/Columns/TypeId, Type=Type: Int32, Length: null
            GroupingNode, Comment=Name
              CreateNode, Path=Tables/Metadata.Type, Type=ColumnInfo, Name=Name, Index=2
              PropertyChange, Path=Tables/Metadata.Type/Columns/Name, Type=Type: String?, Length: 1000
          GroupingNode, Comment=PK_Type
            CreateNode, Path=Tables/Metadata.Type, Type=PrimaryIndexInfo, Name=PK_Type
            PropertyChange, Path=Tables/Metadata.Type/PrimaryIndex, IsUnique=True
            GroupingNode, Comment=KeyColumns[]
              GroupingNode, Comment=0
                CreateNode, Path=Tables/Metadata.Type/PrimaryIndex, Type=KeyColumnRef, Name=0, Index=0
                PropertyChange, Path=Tables/Metadata.Type/PrimaryIndex/KeyColumns/0, Value=Tables/Metadata.Type/Columns/Id, Direction=Positive
          GroupingNode, Comment=SecondaryIndexes[]
            GroupingNode, Comment=Type.IX_Name
              CreateNode, Path=Tables/Metadata.Type, Type=SecondaryIndexInfo, Name=Type.IX_Name, Index=0
              PropertyChange, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name, IsUnique=True
              GroupingNode, Comment=KeyColumns[]
                GroupingNode, Comment=0
                  CreateNode, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name, Type=KeyColumnRef, Name=0, Index=0
                  PropertyChange, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/KeyColumns/0, Value=Tables/Metadata.Type/Columns/Name, Direction=Positive
              GroupingNode, Comment=PrimaryKeyColumns[]
                GroupingNode, Comment=0
                  CreateNode, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name, Type=PrimaryKeyColumnRef, Name=0, Index=0
                  PropertyChange, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/PrimaryKeyColumns/0, Value=Tables/Metadata.Type/Columns/Id, Direction=Positive
              GroupingNode, Comment=IncludedColumns[]
                GroupingNode, Comment=0
                  CreateNode, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name, Type=IncludedColumnRef, Name=0, Index=0
                  PropertyChange, Path=Tables/Metadata.Type/SecondaryIndexes/Type.IX_Name/IncludedColumns/0, Value=Tables/Metadata.Type/Columns/TypeId
        GroupingNode, Comment=Metadata.Extension
          CreateNode, Path=, Type=TableInfo, Name=Metadata.Extension, Index=1
          GroupingNode, Comment=Columns[]
            GroupingNode, Comment=Name
              CreateNode, Path=Tables/Metadata.Extension, Type=ColumnInfo, Name=Name, Index=0
              PropertyChange, Path=Tables/Metadata.Extension/Columns/Name, Type=Type: String, Length: 1024
            GroupingNode, Comment=TypeId
              CreateNode, Path=Tables/Metadata.Extension, Type=ColumnInfo, Name=TypeId, Index=1
              PropertyChange, Path=Tables/Metadata.Extension/Columns/TypeId, Type=Type: Int32, Length: null
            GroupingNode, Comment=Text
              CreateNode, Path=Tables/Metadata.Extension, Type=ColumnInfo, Name=Text, Index=2
              PropertyChange, Path=Tables/Metadata.Extension/Columns/Text, Type=Type: String?, Length: null
            GroupingNode, Comment=Data
              CreateNode, Path=Tables/Metadata.Extension, Type=ColumnInfo, Name=Data, Index=3
              PropertyChange, Path=Tables/Metadata.Extension/Columns/Data, Type=Type: Byte[]?, Length: null
          GroupingNode, Comment=PK_Extension
            CreateNode, Path=Tables/Metadata.Extension, Type=PrimaryIndexInfo, Name=PK_Extension
            PropertyChange, Path=Tables/Metadata.Extension/PrimaryIndex, IsUnique=True
            GroupingNode, Comment=KeyColumns[]
              GroupingNode, Comment=0
                CreateNode, Path=Tables/Metadata.Extension/PrimaryIndex, Type=KeyColumnRef, Name=0, Index=0
                PropertyChange, Path=Tables/Metadata.Extension/PrimaryIndex/KeyColumns/0, Value=Tables/Metadata.Extension/Columns/Name, Direction=Positive
        GroupingNode, Comment=Metadata.Assembly
          CreateNode, Path=, Type=TableInfo, Name=Metadata.Assembly, Index=2
          GroupingNode, Comment=Columns[]
            GroupingNode, Comment=Name
              CreateNode, Path=Tables/Metadata.Assembly, Type=ColumnInfo, Name=Name, Index=0
              PropertyChange, Path=Tables/Metadata.Assembly/Columns/Name, Type=Type: String, Length: 1024
            GroupingNode, Comment=TypeId
              CreateNode, Path=Tables/Metadata.Assembly, Type=ColumnInfo, Name=TypeId, Index=1
              PropertyChange, Path=Tables/Metadata.Assembly/Columns/TypeId, Type=Type: Int32, Length: null
            GroupingNode, Comment=Version
              CreateNode, Path=Tables/Metadata.Assembly, Type=ColumnInfo, Name=Version, Index=2
              PropertyChange, Path=Tables/Metadata.Assembly/Columns/Version, Type=Type: String?, Length: 64
          GroupingNode, Comment=PK_Assembly
            CreateNode, Path=Tables/Metadata.Assembly, Type=PrimaryIndexInfo, Name=PK_Assembly
            PropertyChange, Path=Tables/Metadata.Assembly/PrimaryIndex, IsUnique=True
            GroupingNode, Comment=KeyColumns[]
              GroupingNode, Comment=0
                CreateNode, Path=Tables/Metadata.Assembly/PrimaryIndex, Type=KeyColumnRef, Name=0, Index=0
                PropertyChange, Path=Tables/Metadata.Assembly/PrimaryIndex/KeyColumns/0, Value=Tables/Metadata.Assembly/Columns/Name, Direction=Positive
        GroupingNode, Comment=MyEntity
          CreateNode, Path=, Type=TableInfo, Name=MyEntity, Index=3
          GroupingNode, Comment=Columns[]
            GroupingNode, Comment=Id
              CreateNode, Path=Tables/MyEntity, Type=ColumnInfo, Name=Id, Index=0
              PropertyChange, Path=Tables/MyEntity/Columns/Id, Type=Type: Int32, Length: null
            GroupingNode, Comment=TypeId
              CreateNode, Path=Tables/MyEntity, Type=ColumnInfo, Name=TypeId, Index=1
              PropertyChange, Path=Tables/MyEntity/Columns/TypeId, Type=Type: Int32, Length: null
            GroupingNode, Comment=Text
              CreateNode, Path=Tables/MyEntity, Type=ColumnInfo, Name=Text, Index=2
              PropertyChange, Path=Tables/MyEntity/Columns/Text, Type=Type: String?, Length: 100
          GroupingNode, Comment=PK_MyEntity
            CreateNode, Path=Tables/MyEntity, Type=PrimaryIndexInfo, Name=PK_MyEntity
            PropertyChange, Path=Tables/MyEntity/PrimaryIndex, IsUnique=True
            GroupingNode, Comment=KeyColumns[]
              GroupingNode, Comment=0
                CreateNode, Path=Tables/MyEntity/PrimaryIndex, Type=KeyColumnRef, Name=0, Index=0
                PropertyChange, Path=Tables/MyEntity/PrimaryIndex/KeyColumns/0, Value=Tables/MyEntity/Columns/Id, Direction=Positive
      GroupingNode, Comment=Sequences[]
        GroupingNode, Comment=Int32-Generator
          CreateNode, Path=, Type=SequenceInfo, Name=Int32-Generator, Index=0
          PropertyChange, Path=Sequences/Int32-Generator, Increment=128
  GroupingNode, Comment=DataManipulate
  GroupingNode, Comment=Cleanup
  
Session 'System, #1'. Schema upgrade script:
CREATE TABLE [dbo].[Metadata.Type] ([Id] integer NOT NULL,
[TypeId] integer NOT NULL,
[Name] nvarchar(1000) DEFAULT NULL,
CONSTRAINT [PK_Type] PRIMARY KEY ([Id]));
CREATE UNIQUE INDEX [Type.IX_Name] ON [dbo].[Metadata.Type] ([Name] ASC)  INCLUDE ([TypeId]);
CREATE TABLE [dbo].[Metadata.Extension] ([Name] nvarchar(1024) NOT NULL,
[TypeId] integer NOT NULL,
[Text] nvarchar(max) DEFAULT NULL,
[Data] varbinary(max) DEFAULT NULL,
CONSTRAINT [PK_Extension] PRIMARY KEY ([Name]));
CREATE TABLE [dbo].[Metadata.Assembly] ([Name] nvarchar(1024) NOT NULL,
[TypeId] integer NOT NULL,
[Version] nvarchar(64) DEFAULT NULL,
CONSTRAINT [PK_Assembly] PRIMARY KEY ([Name]));
CREATE TABLE [dbo].[MyEntity] ([Id] integer NOT NULL,
[TypeId] integer NOT NULL,
[Text] nvarchar(100) DEFAULT NULL,
CONSTRAINT [PK_MyEntity] PRIMARY KEY ([Id]));
CREATE TABLE [dbo].[Int32-Generator] ([ID] integer IDENTITY (128, 128) NOT NULL);
Session 'n/a'. SQL batch: 
CREATE TABLE [dbo].[Metadata.Type] ([Id] integer NOT NULL,
[TypeId] integer NOT NULL,
[Name] nvarchar(1000) DEFAULT NULL,
CONSTRAINT [PK_Type] PRIMARY KEY ([Id]));
CREATE UNIQUE INDEX [Type.IX_Name] ON [dbo].[Metadata.Type] ([Name] ASC)  INCLUDE ([TypeId]);
CREATE TABLE [dbo].[Metadata.Extension] ([Name] nvarchar(1024) NOT NULL,
[TypeId] integer NOT NULL,
[Text] nvarchar(max) DEFAULT NULL,
[Data] varbinary(max) DEFAULT NULL,
CONSTRAINT [PK_Extension] PRIMARY KEY ([Name]));
CREATE TABLE [dbo].[Metadata.Assembly] ([Name] nvarchar(1024) NOT NULL,
[TypeId] integer NOT NULL,
[Version] nvarchar(64) DEFAULT NULL,
CONSTRAINT [PK_Assembly] PRIMARY KEY ([Name]));
CREATE TABLE [dbo].[MyEntity] ([Id] integer NOT NULL,
[TypeId] integer NOT NULL,
[Text] nvarchar(100) DEFAULT NULL,
CONSTRAINT [PK_MyEntity] PRIMARY KEY ([Id]));
CREATE TABLE [dbo].[Int32-Generator] ([ID] integer IDENTITY (128, 128) NOT NULL);
Synchronizing schema in Recreate mode: completed.
Creating Generators: started.
Creating Generators: completed.
Session 'System, #1'. SQL batch: 
SELECT [a].[Name], [a].[TypeId], [a].[Version] FROM [dbo].[Metadata.Assembly] [a];
Session 'System, #1'. Caching: Key = 'Assembly, (Xtensive.Storage)', Tuple = (Xtensive.Storage, 2, null), State = New.
Session 'System, #1'. Materializing Assembly: Key = 'Assembly, (Xtensive.Storage)'.
Session 'System, #1'. Setting value: Key = 'Assembly, (Xtensive.Storage)', Field = 'Version (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Assembly, (Xtensive.Storage)', Field = 'Version (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Assembly, (Xtensive.Storage)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Assembly, (Xtensive.Storage)', Field = 'Version (FieldInfo)'.
Metadata.Assembly created: 'Xtensive.Storage (Version=1.0.0.0)'.
Session 'System, #1'. Caching: Key = 'Assembly, (Batching)', Tuple = (Batching, 2, null), State = New.
Session 'System, #1'. Materializing Assembly: Key = 'Assembly, (Batching)'.
Session 'System, #1'. Setting value: Key = 'Assembly, (Batching)', Field = 'Version (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Assembly, (Batching)', Field = 'Version (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Assembly, (Batching)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Assembly, (Batching)', Field = 'Version (FieldInfo)'.
Metadata.Assembly created: 'Batching (Version=1.0.0.0)'.
Session 'System, #1'. Persisting (partial)...
Session 'System, #1'. Persist completed.
Session 'System, #1'. SQL batch: 
INSERT INTO [dbo].[Metadata.Assembly] ([Name], [TypeId], [Version]) VALUES (@p0_0, @p0_1, @p0_2);
INSERT INTO [dbo].[Metadata.Assembly] ([Name], [TypeId], [Version]) VALUES (@p1_0, @p1_1, @p1_2);
SELECT [a].[Id], [a].[TypeId], [a].[Name] FROM [dbo].[Metadata.Type] [a];
Session 'System, #1'. Caching: Key = 'Type, (1)', Tuple = (1, 1, null), State = New.
Session 'System, #1'. Materializing Type: Key = 'Type, (1)'.
Session 'System, #1'. Setting value: Key = 'Type, (1)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Type, (1)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Caching: Key = 'Type, (3)', Tuple = (3, 1, null), State = New.
Session 'System, #1'. Materializing Type: Key = 'Type, (3)'.
Session 'System, #1'. Setting value: Key = 'Type, (3)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Type, (3)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Caching: Key = 'Type, (2)', Tuple = (2, 1, null), State = New.
Session 'System, #1'. Materializing Type: Key = 'Type, (2)'.
Session 'System, #1'. Setting value: Key = 'Type, (2)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Type, (2)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Caching: Key = 'Type, (101)', Tuple = (101, 1, null), State = New.
Session 'System, #1'. Materializing Type: Key = 'Type, (101)'.
Session 'System, #1'. Setting value: Key = 'Type, (101)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Type, (101)', Field = 'Name (FieldInfo)'.
Session 'System, #1'. Persisting (partial)...
Session 'System, #1'. Persist completed.
Session 'System, #1'. SQL batch: 
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p0_0, @p0_1, @p0_2);
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p1_0, @p1_1, @p1_2);
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p2_0, @p2_1, @p2_2);
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p3_0, @p3_1, @p3_2);
SELECT TOP 2 [a].[Name], [a].[TypeId], [a].[Text], [a].[Data] FROM [dbo].[Metadata.Extension] [a] WHERE ([a].[Name] = 'Xtensive.Storage.Model') ORDER BY [a].[Name] ASC;
Session 'System, #1'. Caching: Key = 'Extension, (Xtensive.Storage.Model)', Tuple = (Xtensive.Storage.Model, 3, null, null), State = New.
Session 'System, #1'. Materializing Extension: Key = 'Extension, (Xtensive.Storage.Model)'.
Session 'System, #1'. Setting value: Key = 'Extension, (Xtensive.Storage.Model)', Field = 'Text (FieldInfo)'.
Session 'System, #1'. Getting value: Key = 'Extension, (Xtensive.Storage.Model)', Field = 'Text (FieldInfo)'.
Session 'System, #1'. Persisting (full)...
Session 'System, #1'. SQL batch: 
INSERT INTO [dbo].[Metadata.Extension] ([Name], [TypeId], [Text], [Data]) VALUES (@p0_0, @p0_1, @p0_2, @p0_3);
Session 'System, #1'. Persist completed.
Session 'System, #1'. Commit transaction.
Session 'System, #1'. Disposing.
Session 'System, #1'. Closing connection 'sqlserver://localhost/DO40-Tests'.
Building Domain: completed.
Opening session 'Name = Default, Options = Default, CacheType = LruWeak, CacheSize = 16384, DefaultIsolationLevel = ReadCommitted'.
Session 'Default, #2'. Creating connection 'sqlserver://localhost/DO40-Tests'.
Session 'Default, #2'. Opening connection 'sqlserver://localhost/DO40-Tests'.
Session 'Default, #2'. Beginning transaction @ ReadCommitted.
Opening session 'Name = KeyGenerator, Options = Default, CacheType = LruWeak, CacheSize = 16384, DefaultIsolationLevel = ReadCommitted'.
Session 'KeyGenerator, #3'. Creating connection 'sqlserver://localhost/DO40-Tests'.
Session 'KeyGenerator, #3'. Opening connection 'sqlserver://localhost/DO40-Tests'.
Session 'KeyGenerator, #3'. Beginning transaction @ ReadCommitted.
Session 'KeyGenerator, #3'. SQL batch: 
INSERT INTO [dbo].[Int32-Generator] DEFAULT VALUES;
SELECT SCOPE_IDENTITY();
Session 'KeyGenerator, #3'. Commit transaction.
Session 'KeyGenerator, #3'. Disposing.
Session 'KeyGenerator, #3'. Closing connection 'sqlserver://localhost/DO40-Tests'.
Session 'Default, #2'. Caching: Key = 'MyEntity, (1)', Tuple = (1, 101, null), State = New.
Session 'Default, #2'. Materializing MyEntity: Key = 'MyEntity, (1)'.
Session 'Default, #2'. Setting value: Key = 'MyEntity, (1)', Field = 'Text (FieldInfo)'.
Session 'Default, #2'. Getting value: Key = 'MyEntity, (1)', Field = 'Text (FieldInfo)'.
Session 'Default, #2'. Caching: Key = 'MyEntity, (2)', Tuple = (2, 101, null), State = New.
Session 'Default, #2'. Materializing MyEntity: Key = 'MyEntity, (2)'.
Session 'Default, #2'. Setting value: Key = 'MyEntity, (2)', Field = 'Text (FieldInfo)'.
Session 'Default, #2'. Getting value: Key = 'MyEntity, (2)', Field = 'Text (FieldInfo)'.
Session 'Default, #2'. Persisting (partial)...
Session 'Default, #2'. Persist completed.
Session 'Default, #2'. SQL batch: 
INSERT INTO [dbo].[MyEntity] ([Id], [TypeId], [Text]) VALUES (@p0_0, @p0_1, @p0_2);
INSERT INTO [dbo].[MyEntity] ([Id], [TypeId], [Text]) VALUES (@p1_0, @p1_1, @p1_2);
SELECT COUNT_BIG(*) AS [column] FROM [dbo].[MyEntity] [a];
SELECT [a].[Id], [a].[TypeId], [a].[Text] FROM [dbo].[MyEntity] [a];
Session 'Default, #2'. Updating cache: Key = 'MyEntity, (1)', Tuple = (1, 101, Entity 1), State = Synchronized.
Session 'Default, #2'. Getting value: Key = 'MyEntity, (1)', Field = 'Text (FieldInfo)'.
Session 'Default, #2'. Updating cache: Key = 'MyEntity, (2)', Tuple = (2, 101, Entity 2), State = Synchronized.
Session 'Default, #2'. Getting value: Key = 'MyEntity, (2)', Field = 'Text (FieldInfo)'.
Session 'Default, #2'. Commit transaction.
Session 'Default, #2'. Disposing.
Session 'Default, #2'. Closing connection 'sqlserver://localhost/DO40-Tests'.
Really long, but there are lots of interesting things. But for now I'd like to pay your attention to just a single aspect. This log perfectly shows how our uber-batching and future queries work.

First part to pay attention to this batch:
-- Session 'System, #1'. SQL batch: 
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p0_0, @p0_1, @p0_2);
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p1_0, @p1_1, @p1_2);
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p2_0, @p2_1, @p2_2);
INSERT INTO [dbo].[Metadata.Type] ([Id], [TypeId], [Name]) VALUES (@p3_0, @p3_1, @p3_2);
SELECT TOP 2 [a].[Name], [a].[TypeId], [a].[Text], [a].[Data] FROM [dbo].[Metadata.Extension] [a] WHERE ([a].[Name] = 'Xtensive.Storage.Model') ORDER BY [a].[Name] ASC;
You may find this batch is produced by the following code from our SystemUpgradeHandler class:
domainModel.Types
  .Where(type => type.TypeId!=TypeInfo.NoTypeId)
  .Apply(type => new M.Type(type.TypeId, type.UnderlyingType.GetFullName()));

...

var modelHolder = Query<Extension>.All.SingleOrDefault(
  extension => extension.Name==WellKnown.DomainModelExtensionName);
So in fact, it executes 5 different commands. So 5 separate roundtrips is nearly what you would get with EF and many other ORM tools. AFAIK, you would see 2 roundtrips in the best case (if CUD sequence batching is implemented). In our case there is just a single roundtrip!

Note how gracefully we handle SingleOrDefault(): our query translator has added TOP 2 (think why 2 :) ) and ORDER BY to make TOP work.

The second batch is formed by code inside using block of Main method of Program class:
-- Session 'Default, #2'. SQL batch: 
INSERT INTO [dbo].[MyEntity] ([Id], [TypeId], [Text]) VALUES (@p0_0, @p0_1, @p0_2);
INSERT INTO [dbo].[MyEntity] ([Id], [TypeId], [Text]) VALUES (@p1_0, @p1_1, @p1_2);
SELECT COUNT_BIG(*) AS [column] FROM [dbo].[MyEntity] [a];
SELECT [a].[Id], [a].[TypeId], [a].[Text] FROM [dbo].[MyEntity] [a];
Isn't this beautiful? You make a set of CUD commands and queries, but DO4 runs all of them in a single roundtrip! Normally you shouldn't touch your code at all to get this!

So DO4 reduces chattiness between application server and RDBMS to nearly minimal possible level.

You may find that there are 2 more batches.
  • First one updates [Metadata.Extension] table: actually it persists serialized storage model there
  • Second one allocates next bulk of keys from integer key generator (128 at once by default).
Now let's talk a bit about logging. With today's nightly build it is possible to use it without any third-party logger, such as Log4Net. By default it writes everything to Debug output, if debugger is attached to the current process. Note that default log format is more comprehensive - if you completely remove <logs> section (or e.g. remove formatString attribute), you should see nearly the following output:
  0,09s/T1      Info Storage.Building         Building Domain: started.
  0,09s/T1      Info Storage.Building         Creating Domain: started.
  0,12s/T1      Info Storage.Building         Creating Domain: completed.
...
  2,57s/T1     Debug Storage.Providers.Sql    Session 'KeyGenerator, #3'. Beginning transaction @ ReadCommitted.
  2,57s/T1     Debug Storage.Providers.Sql    Session 'KeyGenerator, #3'. SQL batch: 
                                              INSERT INTO [dbo].[Int32-Generator] DEFAULT VALUES;
                                              SELECT SCOPE_IDENTITY();
  2,57s/T1     Debug Storage.Providers.Sql    Session 'KeyGenerator, #3'. Commit transaction.
...
So even integrated log providers are very flexible. You can choose:
  • Which logs (by namespaces they're located in; "Xtensive." prefix is cut out) must be directed to which providers (provider attribute value can be Null, Console, Error, Debug, File; fileName attribute allows to specify file name)
  • Which event types must be shown there (events attribute allows to do this).
  • Pre-defined format: format attribute value can be Simple or Comprehensive.
  • Custom format string: use formatString attribute to set it. Comprehensive format string is "{0,6:F2}s/T{1,-5} {2,5} {3,-24} {5}".
Here is more comprehensive example of logs section:
<!-- Log nothing by default -->
<log name=""
     provider="Null" />
<!-- But use these settings for Xtensive.Core.* logs -->
<log name="Core"
     provider="Console" events="Warning,Error,FatalError" format="Simple" />
<!-- This overrides settings for Core.Diagnistics.* logs -->
<log name="Core.Diagnistics" 
     provider="Console" format="{4}{5}" />
<!-- Use these settings for Xtensive.Storage.* logs -->
<log name="Storage" 
     provider="File" fileName="Storage.log" />
Note: you need today's nightly build to make new logging stuff work. We added such integrated log providers just today.

P.S. Try to study the log - this might explain lots of aspects of our framework.