问题 NHibernate SQL查询速度慢


我正在使用LINQ to NH来获取应用启动时的大量数据。我特意补充道 ToList() 强制立即执行查询:

Group group = GetGroup();
Log.Info("started");
var list = Session.Linq<Data>()
    .Where(p => p.Group.Id == group.Id)
    .OrderByDescending(p => p.Stamp.Counter) /* Stamp is composite mapping */
    .Select(p => new
    {
        Counter = p.Stamp.Counter,
        Status = p.Status,
    })
    .Take(4000)
    .ToList();
Log.Info("done");

检查DEBUG日志 NHibernate.SQL logger按预期提供以下SQL(当我开始监视时,在SQL事件探查器中弹出相同的查询):

SELECT top 4000 this_.Counter as y0_, this_.Status as y1_
FROM [Data] this_ 
LEFT OUTER JOIN [Group] group1_ ON this_.Group_id=group1_.Id
WHERE group1_.Id = @p0 
ORDER BY this_.Counter desc; @p0 = 1

问题是,从我的应用程序调用时,此查询需要2分钟才能完成,而在SSMS中执行则需要0.5秒!实际上,当应用程序正在等待查询完成时,我可以在SSMS中执行它并立即获得结果。

你认为这种差异来自哪里?


10695
2017-07-28 13:33


起源

不知道答案,但这是一个非常有趣的发现。 - Davide Piras
GetGroup()是否有可能变慢? - AlfeG
@AlfeG,不,查询字符串在“已启动”消息后立即写入日志,然后挂起几分钟。 - Groo
你可以试试这个:直接执行sql查询,看看需要多少时间.. Session.CreateSqlQuery()并更新问题 - Baz1nga
@ user350374:好主意(但必须等到周一):) - Groo


答案:


由于没有太多关于您的应用程序的信息,我只能猜测。

NH的性能问题通常是由刷新缓存引起的。在每次查询之前刷新缓存。当会话中有很多实体时,可能需要花费很多时间。请尝试以下方法:

Log.Info("Flushing");
Session.Flush();
Session.FlushMode = FlushMode.Never;

Log.Info("Query");
var list = Session.Linq<Data>()
    //...
Log.Info("Done");
// for production code, this belongs into a finally block
Session.FlushMode = FlushMode.Auto; 

如果是的话  如果出现刷新问题,您需要在事务中的某些点上手动刷新。关闭自动冲洗时要小心。它可能会导致丑陋的副作用。这是非常具体的交易,我不能说你如何以正确的方式实现它。你也可以使用 StatelessSession,但对我来说它从来没有奏效(它有一些限制)。您也可以清除会话,这也要求您确切知道自己在做什么。

如果没有冲洗问题,则很难跟踪。使用Profiler查看它是否实际占用SQL Server查询中的时间。它甚至可能是SQL服务器上的缓存问题。在这种情况下,第一次执行查询时需要几分钟,但第二次只需几秒钟。创建正确的索引可能有所帮在这里,我停止猜测......


4
2017-07-29 09:42



谢谢。事实证明,毕竟我需要添加一个索引,这是我怀疑SSMS不是那么快的第一件事(调优顾问并没有告诉我一切都很好)。 SSMS的速度是否可能与您建议的缓存有关?我怀疑这是一个冲洗问题,因为只为此查询创建了一个新会话。 - Groo
如果它是会话中的唯一查询,则不是刷新问题。在Sql Server中缓存可能会导致无法重现的性能问题。另请注意:第一个结果可能会在SSMS中快速显示,而查询仍在运行... - Stefan Steinegger


我的假设是有一些拦截器会减慢物体的物化或急切加载(即N + 1问题)。

我做了一些测试,甚至30 000个对象也无法减慢获取对象列表的速度(从本地机器500ms到获取30000个对象的列表,从远程数据库 - 4秒)。


3
2017-07-29 09:00



没有N + 1问题,它将值加载到匿名类型,没有实体。 - Stefan Steinegger
这看起来像是N + 1问题:) - AlfeG
不,带有“select new ...”子句的查询总是被翻译成一个sql查询。 - Stefan Steinegger


有几个可能的原因:

  • 你将至少4000个对象加载到内存中,给它们加水,NHibernate也必须控制Session和第一级缓存中的每个加载对象
  • 我没有看到你的映射,但很可能在某些时候存在某种急切的加载,它还会垃圾邮件其他查询和加载其他对象等等

这些来自我的头脑,还有我更多。另外检查NHibernate的日志级别是否未设置为DEBUG,它非常详细并且可能消耗大量资源。


2
2017-07-28 13:42



我遇到了同样的问题: stackoverflow.com/questions/5664113/... 正如佩德罗所说 - 这可能是因为你正在加载和保湿这么多物体。 - J. Ed
谢谢。但我不相信加载4000个匿名对象(预计属性是两个 Int64 值)应该是NHibernate的问题(没有什么可以在那里代理)?是的,NHibernate LOG级别 是 设置为DEBUG,但是记录了单个查询行(问题中的那个),所以我也很确定也没有发生过急切加载。由于查询在SSMS中立即返回,所以NHibernate应该做的就是将这些返回的对包装到该匿名类型的实例中。 - Groo
4000 ...你一定是在开玩笑...... - Phill
你可以用无状态会话尝试相同的查询吗? - Sly
我无法想象它与预先加载,第一级缓存,代理和类似的东西有什么关系。它只是加载值并将它们放入匿名类型。缓存中没有关于它的内容,因为它们不是实体。日志级DEBUG实际上可能真的会损害性能,不是查询本身,而是查询结果的处理。 - Stefan Steinegger


今天一个项目的一个不错的观点:

我搜索了大约一周的原因,因为我的nHibernate查询(使用期货加载某些集合的多标准)花了11秒(在MSSQL探查器中持续时间),如果我在SSMS中执行完全相同的组合查询,则大约需要2秒。

解决方案是:我激活了一些日志来运行Ayendes profiler。 NHProf dll丢失了,但是:nHibernate中的一些GetRows方法在水合期间触发日志调用。差异是:9秒!

我刚刚注释掉了log4net配置调用,延迟几乎消失了。

我有大约14.000个实例加上60.000个HasMany集合条目。水合现在需要0.6秒,因为SQL语句需要2秒(这是另一个优化故事)。

并且:我认为水合持续时间和查询执行持续时间一起显示在SQL事件探查器“duration”列中。

2周前的另一个故事是:SQL分析器中的执行计划与在SSMS中执行查询时提供的执行计划不同。原因是,我在nHibernate中使用了OLEDB提供程序。我切换到ADO连接,执行计划是一样的。在查看MS SQL分析器中的某些“协议版本”列时,我发现了这一点。

除了n + 1之外,性能陷阱有很多原因:)

最好的祝愿! 迈克尔


2
2018-04-24 21:02