Horrible response time with NHibernate and Oracle11g

Question

My problem is at the same time simple and complex :

I'm working with NHibernate 3.3 and Oracle 11g with ODP drivers.

This piece of code works like a charm:

var query = Session.CreateSQLQuery("SELECT * FROM wip_event_log WHERE track_id='" + trackId + "'");
query.AddEntity("l", typeof(MotIdenWipEventLog));
var results = query.List<MotIdenWipEventLog>();  

in a couple of milliseconds I get the result set. (only 5 records from a table with 11.000.000 of records)

In the other hand, this piece of code :

var results = Session.Query<MotIdenWipEventLog>().Where(m => m.TRACK_ID == trackId).ToList();

takes about 4 seconds to get 5 the records!.

I read about an problem with the AnsiString columns in Oracle databases (http://bit.ly/1bbSlB7) and added a custom convention for work with strings on my fluent configuration:

Fluently
    .Configure(new Configuration().Configure())
    .Database(OracleClientConfiguration
    .Oracle10
    .ConnectionString(c => c.Is("User ID=XXXX;Password=XXXX;Data Source=(DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = TCP)(HOST = 1.1.1.1)(PORT = 1521)))(CONNECT_DATA = (SID = iden01)))"))
)
.Mappings(
    cfg => cfg.FluentMappings.LocalAddFromAssemblyOf<MotIdenPackSalesModelsHeaderMap>().Conventions.Add<OracleStringPropertyConvention>()
).BuildConfiguration();

and the custom convention MotIdenPackSalesModelsHeaderMap is:

public class OracleStringPropertyConvention : IPropertyConvention
{
    public void Apply(IPropertyInstance instance)
    {
        if (instance.Property.PropertyType == typeof(string)) instance.CustomType("AnsiString");
    }
}

The entity MotIdenWipEventLog is defined below:

[Serializable]
public class MotIdenWipEventLog
{
    public virtual String   TRACK_ID        { get; set; } // VARCHAR2(16 BYTE)  No
    public virtual String   ASSY_PART_NUM   { get; set; } // VARCHAR2(20 BYTE)  Yes
    public virtual String   ASSY_VER_CODE   { get; set; } // VARCHAR2(4 BYTE)   Yes
    public virtual int      PROC_ID         { get; set; } // NUMBER(9,0)        Yes
    public virtual String   WIP_EVENT_CODE  { get; set; } // VARCHAR2(4 BYTE)   Yes
    public virtual DateTime EVENT_DATETIME  { get; set; } // DATE               No
    public virtual int      EVENT_CLKSEQ    { get; set; } // NUMBER(12,0)       Yes
    public virtual String   AREA_ID         { get; set; } // VARCHAR2(8 BYTE)   Yes
    public virtual String   PERSONNEL_ID    { get; set; } // VARCHAR2(11 BYTE)  Yes
    public virtual String   STN_ID          { get; set; } // VARCHAR2(20 BYTE)  Yes
    public virtual int      WIP_COUNT       { get; set; } // NUMBER(3,0)        Yes
    public virtual String   STN_GROUP       { get; set; } // VARCHAR2(8 BYTE)   Yes
}

Mapped through the class MotIdenWipEventLogMap:

public class MotIdenWipEventLogMap : ClassMap<MotIdenWipEventLog>
{
    public MotIdenWipEventLogMap()
    {
        Table("WIP_EVENT_LOG");

        Id(m => m.TRACK_ID, "TRACK_ID").GeneratedBy.Assigned();

        #region Fields

            Map(m => m.TRACK_ID).Not.Nullable()
                .Length(16).Index("WIP_EVENT_LOG_IDX1");    //  VARCHAR2(16 BYTE)   No

            Map(m=>m.ASSY_PART_NUM).Nullable().Length(20);  //  VARCHAR2(20 BYTE)   Yes
            Map(m=>m.ASSY_VER_CODE).Nullable().Length(4);   //  VARCHAR2(4 BYTE)    Yes
            Map(m=>m.PROC_ID).Nullable();                   //  NUMBER(9,0)         Yes
            Map(m=>m.WIP_EVENT_CODE).Nullable().Length(4);  //  VARCHAR2(4 BYTE)    Yes
            Map(m=>m.EVENT_DATETIME).Not.Nullable();        //  DATE                No
            Map(m=>m.EVENT_CLKSEQ).Nullable();              //  NUMBER(12,0)        Yes
            Map(m=>m.AREA_ID).Nullable().Length(8);         //  VARCHAR2(8 BYTE)    Yes
            Map(m=>m.PERSONNEL_ID).Nullable().Length(11);   //  VARCHAR2(11 BYTE)   Yes
            Map(m=>m.STN_ID).Nullable().Length(20);         //  VARCHAR2(20 BYTE)   Yes
            Map(m=>m.WIP_COUNT).Nullable();                 //  NUMBER(3,0)         Yes
            Map(m=>m.STN_GROUP).Nullable().Length(8);       //  VARCHAR2(8 BYTE)    Yes
        #endregion
    }
}

Looking my log file for NHibernate in Debug level of Log4Net:

(...)   
2013-11-06 14:24:22,375 DEBUG - Opened IDataReader, open IDataReaders: 1
2013-11-06 14:24:22,376 DEBUG - processing result set
2013-11-06 14:24:26,956 DEBUG - result set row: 0
2013-11-06 14:24:26,959 DEBUG - returning 'F7012B200ZMH' as column: TRACK1_6_
(...)

and seeing in the NHibernate source code of class Loader.cs :

(...)
try
{
    HandleEmptyCollections(queryParameters.CollectionKeys, rs, session);
    EntityKey[] keys = new EntityKey[entitySpan]; // we can reuse it each time
    if (Log.IsDebugEnabled)
    {
        Log.Debug("processing result set");
    }
    int count;
    for (count = 0; count < maxRows && rs.Read(); count++)
    {
        if (Log.IsDebugEnabled)
        {
            Log.Debug("result set row: " + count);
        }
        object result = GetRowFromResultSet(rs, session, queryParameters, lockModeArray, optionalObjectKey, hydratedObjects, keys, returnProxies);
        results.Add(result);            
(...)

I cant find where the problem is...

What I doing wrong?

Any idea?

Answer 1

Rather a patch than a solution, but you could create a function-based index to match the type your application is requesting.

E.g.,

create index patch_index on your_table(cast(your_column as nvarchar2(16)));

Illustrating this on Oracle 11g using EXPLAIN PLAN.

Using

create table t(x varchar2(10));
create index idx on t(x);
insert into t values ('a');

The query

select * from t where x = 'a';

gives you the following plan

| Id | Operation         | Name | Rows | Bytes  | Cost (%CPU) | Time     |
--------------------------------------------------------------------------
| 0  | SELECT STATEMENT  |      | 1     | 7     | 3 (0)       | 00:00:01 |
|* 1 | TABLE ACCESS FULL | T    | 1     | 7     | 3 (0)       | 00:00:01 |
--------------------------------------------------------------------------

After adding the following index

create index t2 on t(cast(x as nvarchar2(10)))

The same query now gives you the following plan

------------------------------------------------------------------------------------
| Id | Operation                  | Name | Rows | Bytes | Cost (%CPU)| Time        |
------------------------------------------------------------------------------------
| 0  | SELECT STATEMENT           |      |  1   | 19    | 2 (0)      | 00:00:01    |
| 1  | TABLE ACCESS BY INDEX ROWID| T    |  1   | 19    | 2 (0)      | 00:00:01    |
|* 2 | INDEX RANGE SCAN           | T2   |  1   |       | 1 (0)      | 00:00:01    |
------------------------------------------------------------------------------------

You can apply this technique if you cannot fix the problem on the application side.