为什么在 QueryOver SingleOrDefault 中很慢？

Question

我在一个项目中使用 Nhibernate，我正在尝试运行一个简单的查询来验证用户登录。它工作正常但速度很慢，如果我删除 SingleOrDefault() 它会变得非常非常快。

所以我的问题是：为什么 .SingleOrDefault 会使下面的代码变得很慢，我可以用一些东西来代替它以使其更快吗？

var user = Session.QueryOver<Customer>()
                    .Where(c => c.Username == username)
                    .SingleOrDefault();

谢谢

编辑：

这可能有点太多了，但我不太确定如何过滤它。在 SingleOrDefault 步骤中 nhibernate 的整个输出是：

2012-03-07 16:24:09,808 DEBUG NHibernate.Loader.Criteria.CriteriaQueryTranslator - put criteria=Username = Koste alias=this0_
2012-03-07 16:24:09,808 DEBUG NHibernate.Loader.Criteria.CriteriaQueryTranslator - returning alias=this_ for criteria=Username = Koste
2012-03-07 16:24:09,808 DEBUG NHibernate.AdoNet.AbstractBatcher - Opened new IDbCommand, open IDbCommands: 1
2012-03-07 16:24:09,808 DEBUG NHibernate.AdoNet.AbstractBatcher - Building an IDbCommand object for the SqlString: SELECT TOP (?) this_.CustomerID as CustomerID16_0_, this_.FirstName as FirstName16_0_, this_.LastName as LastName16_0_, this_.Username as Username16_0_, this_.Password as Password16_0_, this_.PersonalInformation as Personal6_16_0_, this_.LastLogin as LastLogin16_0_, this_.IsApproved as IsApproved16_0_, this_.IsReceiveRightsBulletins as IsReceiv9_16_0_, this_.CompanyID as CompanyID16_0_, this_.CustomerTypeID as Custome11_16_0_ FROM Customers.Customer this_ WHERE this_.Username = ?
2012-03-07 16:24:09,808 DEBUG NHibernate.Engine.QueryParameters - BindParameters(Positional0:NHibernate.Type.StringType) Koste -> [1]
2012-03-07 16:24:09,808 DEBUG NHibernate.Type.StringType - binding 'Koste' to parameter: 1
2012-03-07 16:24:09,808 INFO NHibernate.Loader.Loader - SELECT TOP (@p0) this_.CustomerID as CustomerID16_0_, this_.FirstName as FirstName16_0_, this_.LastName as LastName16_0_, this_.Username as Username16_0_, this_.Password as Password16_0_, this_.PersonalInformation as Personal6_16_0_, this_.LastLogin as LastLogin16_0_, this_.IsApproved as IsApproved16_0_, this_.IsReceiveRightsBulletins as IsReceiv9_16_0_, this_.CompanyID as CompanyID16_0_, this_.CustomerTypeID as Custome11_16_0_ FROM Customers.Customer this_ WHERE this_.Username = @p1
2012-03-07 16:24:09,808 DEBUG NHibernate.SQL - SELECT TOP (@p0) this_.CustomerID as CustomerID16_0_, this_.FirstName as FirstName16_0_, this_.LastName as LastName16_0_, this_.Username as Username16_0_, this_.Password as Password16_0_, this_.PersonalInformation as Personal6_16_0_, this_.LastLogin as LastLogin16_0_, this_.IsApproved as IsApproved16_0_, this_.IsReceiveRightsBulletins as IsReceiv9_16_0_, this_.CompanyID as CompanyID16_0_, this_.CustomerTypeID as Custome11_16_0_ FROM Customers.Customer this_ WHERE this_.Username = @p1;@p0 = 1 [Type: Int32 (0)], @p1 = 'Koste' [Type: String (250)]
2012-03-07 16:24:09,808 DEBUG NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver
2012-03-07 16:24:09,840 DEBUG NHibernate.AdoNet.AbstractBatcher - ExecuteReader took 14 ms
2012-03-07 16:24:09,840 DEBUG NHibernate.AdoNet.AbstractBatcher - Opened IDataReader, open IDataReaders: 1
2012-03-07 16:24:09,840 DEBUG NHibernate.Loader.Loader - processing result set
2012-03-07 16:24:09,840 DEBUG NHibernate.Loader.Loader - result set row: 0
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.Int32Type - returning '1' as column: CustomerID16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Loader.Loader - result row: EntityKey[IPRBA.Core.Domain.Model.Customers.Customer#1]
2012-03-07 16:24:09,840 DEBUG NHibernate.Loader.Loader - Initializing object from DataReader: [IPRBA.Core.Domain.Model.Customers.Customer#1]
2012-03-07 16:24:09,840 DEBUG NHibernate.Persister.Entity.AbstractEntityPersister - Hydrating entity: [IPRBA.Core.Domain.Model.Customers.Customer#1]
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.StringType - returning 'Koste' as column: FirstName16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.StringType - returning 'Budinoski' as column: LastName16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.StringType - returning 'Koste' as column: Username16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.StringType - returning 'Koste123' as column: Password16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.StringType - returning null as column: Personal6_16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.DateTimeType - returning '1/1/2012 12:00:00 AM' as column: LastLogin16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.BooleanType - returning 'True' as column: IsApproved16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.BooleanType - returning 'False' as column: IsReceiv9_16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.Int32Type - returning null as column: CompanyID16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Type.Int32Type - returning '1' as column: Custome11_16_0_
2012-03-07 16:24:09,840 DEBUG NHibernate.Loader.Loader - done processing result set (1 rows)
2012-03-07 16:24:09,840 DEBUG NHibernate.Driver.NHybridDataReader - running NHybridDataReader.Dispose()
2012-03-07 16:24:09,840 DEBUG NHibernate.AdoNet.AbstractBatcher - Closed IDataReader, open IDataReaders :0
2012-03-07 16:24:09,840 DEBUG NHibernate.AdoNet.AbstractBatcher - DataReader was closed after 15 ms
2012-03-07 16:24:09,840 DEBUG NHibernate.AdoNet.AbstractBatcher - Closed IDbCommand, open IDbCommands: 0
2012-03-07 16:24:09,840 DEBUG NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection
2012-03-07 16:24:09,840 DEBUG NHibernate.Connection.ConnectionProvider - Closing connection
2012-03-07 16:24:09,841 DEBUG NHibernate.Loader.Loader - total objects hydrated: 1
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.TwoPhaseLoad - resolving associations for [IPRBA.Core.Domain.Model.Customers.Customer#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.Loading.LoadContexts - creating collection wrapper:[IPRBA.Core.Domain.Model.Customers.Customer.CustomerBookRights#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.Loading.LoadContexts - creating collection wrapper:[IPRBA.Core.Domain.Model.Customers.Customer.CustomerContactInfos#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.Loading.LoadContexts - creating collection wrapper:[IPRBA.Core.Domain.Model.Customers.Customer.CustomerMembershipTypes#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.Loading.LoadContexts - creating collection wrapper:[IPRBA.Core.Domain.Model.Customers.Customer.CustomerSubscriptionTypes#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Event.Default.DefaultLoadEventListener - loading entity: [IPRBA.Core.Domain.Model.Customers.CustomerType#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Event.Default.DefaultLoadEventListener - creating new proxy for entity
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.TwoPhaseLoad - done materializing entity [IPRBA.Core.Domain.Model.Customers.Customer#1]
2012-03-07 16:24:09,841 DEBUG NHibernate.Engine.StatefulPersistenceContext - initializing non-lazy collections
2012-03-07 16:24:09,841 DEBUG NHibernate.AdoNet.ConnectionManager - after autocommit
2012-03-07 16:24:09,841 DEBUG NHibernate.Impl.SessionImpl - transaction completion
2012-03-07 16:24:09,841 DEBUG NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection

Answer 1

@Phil 指出明显的问题后，我们发现问题出在日志记录中，与提供的信息无关。