Glimpse HUD 和 SQL 选项卡中的数据库查询计数之间的差异

Question

这个问题涉及 Glimpse.MVC3 和 Glimpse.EF5 包。我正在尝试调试旧 MVC3 站点上的性能问题。 根据 Glimpse 的 HUD，一个特定的 GET 请求总共有 12 个查询，总共 28 毫秒 - 但是当我展开打开主面板并单击 SQL 选项卡时，它说只有 6 个查询，总共 10.41 毫秒。顶部的计数都显示 6，当我计算它列出的查询时，有 6。当我看到编写的代码时，这也是有意义的。（无论哪种方式，我都可以看到太多是延迟加载，需要修复。

Glimpse 没有迹象表明相同的 6 个查询正在执行两次（当我看到 HUD 显示的数字是面板的两倍时，我的大脑就会这样做）。

此外，HUD 显示 0 个 Ajax 请求，但历史记录部分实际上显示 1（这绝对是准确的）。

任何想法为什么会有差异？（请记住，我更关心查询的差异。

编辑 - 根据请求从文件中生成 JSON：

glimpse_sql:
{
  data:
  {
    "SQL Statistics":
    [
      {
        connectionCount: 6
        queryCount: 6
        transactionCount: 0
        queryExecutionTime: 6.91
        connectionOpenTime: 116.08
      }
    ]
    Queries:
    [
      [
        Commands per Connection
        Duration
      ]
hud:
  {
    sql:
    {
      data:
      {
        queryCount: 12
        connectionCount: 12
        transactionCount: 0
        queryExecutionTime: 41.87
        connectionOpenTime: 242.96
      }
      name: sql
    }

编辑 2 - 查询

"Queries":[["Commands per Connection","Duration"],
[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT TOP (2) rn[Extent1].[TrxnID] AS [TrxnID], rn[Extent1].[StartTime] AS [StartTime], rn[Extent1].[Lane] AS [Lane], rn[Extent1].[EmployeeID] AS [EmployeeID], rn[Extent1].[OptionsCompleted] AS [OptionsCompleted], rn[Extent1].[StoreID] AS [StoreID], rn[Extent1].[NoVehicleTireCheck] AS [NoVehicleTireCheck], rnFROM [Activity].[Trxn] AS [Extent1]rnWHERE [Extent1].[TrxnID] = 353 /* @p__linq__0 */",[["Name","Value","Type","Size"],["@p__linq__0",353,"Int32",0]],1,1.12,76.67,false,null,null,""]],5.85],
[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT rn[Extent1].[TrxnID] AS [TrxnID], rn[Extent1].[CustomerID] AS [CustomerID], rn[Extent1].[FirstName] AS [FirstName], rn[Extent1].[LastName] AS [LastName], rn[Extent1].[RewardAccountID] AS [RewardAccountID], rn[Extent1].[CustomerEmail] AS [CustomerEmail], rn[Extent1].[HomePhone] AS [HomePhone]rnFROM [Activity].[Trxn_Customers] AS [Extent1]rnWHERE [Extent1].[TrxnID] = 353 /* @EntityKeyValue1 */",[["Name","Value","Type","Size"],["@EntityKeyValue1",353,"Int32",0]],0,1.18,102.7,false,null,null,""]],21.7],
[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT rn[Extent1].[TrxnID] AS [TrxnID], rn[Extent1].[VehicleID] AS [VehicleID], rn[Extent1].[VehicleVIN] AS [VehicleVIN], rn[Extent1].[VehicleOdometer] AS [VehicleOdometer], rn[Extent1].[VehicleEngineID] AS [VehicleEngineID], rn[Extent1].[VehicleMakeID] AS [VehicleMakeID], rn[Extent1].[ModelYear] AS [ModelYear]rnFROM [Activity].[Trxn_Vehicles] AS [Extent1]rnWHERE [Extent1].[TrxnID] = 353 /* @EntityKeyValue1 */",[["Name","Value","Type","Size"],["@EntityKeyValue1",353,"Int32",0]],0,1.26,2301.56,false,null,null,""]],27.72],
[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT rn[Extent1].[TrxnID] AS [TrxnID], rn[Extent1].[SecondaryVehicleID] AS [SecondaryVehicleID], rn[Extent1].[SecondaryVehicleVIN] AS [SecondaryVehicleVIN], rn[Extent1].[SecondaryVehicleTypeID] AS [SecondaryVehicleTypeID], rn FROM [Activity].[Trxn_SecondaryVehicles] AS [Extent1]rn WHERE [Extent1].[TrxnID] = 353 /* @EntityKeyValue1 */",[["Name","Value","Type","Size"],["@EntityKeyValue1",353,"Int32",0]],0,1.15,2325.95,false,null,null,""]],23.15],
[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT rn[Extent1].[TrxnServiceID] AS [TrxnServiceID], rn[Extent1].[TrxnID] AS [TrxnID], rn[Extent1].[PackageID] AS [PackageID], rn[Extent1].[PartID] AS [PartID], rn[Extent1].[Qty] AS [Qty]rnFROM [Activity].[Trxn_Services] AS [Extent1]rnWHERE [Extent1].[TrxnID] = 353 /* @EntityKeyValue1 */",[["Name","Value","Type","Size"],["@EntityKeyValue1",353,"Int32",0]],0,1.02,2342.92,false,null,null,""]],15.74],
[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT rn[Extent1].[TrxnNoteID] AS [TrxnNoteID], rn[Extent1].[TrxnID] AS [TrxnID], rn[Extent1].[NoteText] AS [NoteText], rn[Extent1].[NoteNumber] AS [NoteNumber], rn[Extent1].[SendToInvoice] AS [SendToInvoice]rnFROM [Activity].[Trxn_Notes] AS [Extent1]rnWHERE [Extent1].[TrxnID] = 353 /* @EntityKeyValue1 */",[["Name","Value","Type","Size"],["@EntityKeyValue1",353,"Int32",0]],0,1.19,4689.34,false,null,null,""]],21.92]
]},"name":"SQL"}

Answer 1

嗯，我想通了。但首先，看一下问题发生所需的确切使用方案。

使用场景
仅当您出现以下情况时，才会出现问题：
一个。为上下文启用延迟加载。b.将 EF 模型直接传递给视图，不要使用视图模型（无论如何，这不是好的做法，但正是此旧代码正在执行的操作）。

我学到了什么
1）事实证明，HUD显示的查询数量较高#是正确的 - SQL Server Profiler揭示了这一点。

2）Glimpse本身似乎正在触发额外的查询。当我将"元数据"选项卡保持打开状态时，它似乎以某种方式访问了导航属性，从而导致延迟加载。如果我关闭 Glimpse，或将 Glimpse 保留为打开状态但禁用"元数据"选项卡，则不会发生额外的查询。

解释
我花了一段时间才弄清楚这一点，因为我搜索了代码并建立了一个测试场景来隔离问题。在其中，我检索了一条记录，之后没有触及任何导航属性。逐步完成它，我确定在我的代码中没有访问导航属性来导致它 - 但应用程序仍然生成所有这些额外的查询，我对它们的来源感到完全困惑。

我最终放弃了弄清楚它，禁用了上下文的延迟加载（这可以防止额外的调用），但随后在其中一个导航属性上抛出了一个NullReferenceException。我急切加载了这个特定的导航属性，所以我对为什么它是空的更加困惑。在该 nav 属性上设置断点，我发现它被命中了两次 - 一次是当我调用它时（此时它不是空），但在我的 View/Razor 代码完成编译后的第二次，它神秘地再次被命中。调用堆栈似乎指向它来自Glimpse。果然，我能够继续处理异常并加载页面（没有错误或缺少数据），但 Glimpse 在引用该属性的元数据选项卡中显示错误。我将两个和两个放在一起，并尝试打开/关闭Glimpse，然后禁用"元数据"选项卡。在任一情况下，额外的查询都会停止，并且在打开 Glimpse 但禁用元数据选项卡的情况下，HUD 和 SQL 选项卡查询计数匹配。问题解决了。

现在要明确的是，我并不是说这是我上述性能问题的原因 - 当性能问题开始时甚至没有安装 Glimpse，据我了解，无论如何，Glimpse 在发布模式下默认处于关闭状态。性能问题是由代码中发生的一些明显的延迟加载引起的。但是，当我修复代码中发生的延迟加载时，HUD 选项卡中的查询计数并没有减少太多，性能也没有提高 - 现在这是有道理的。对于我从代码中删除的每个延迟加载的查询，Glimpse 都会通过访问"元数据"选项卡的导航属性在后台生成一个查询。

底线/TLDR：禁用"一瞥元数据"选项卡可以为我解决问题。在调试模式下减少了查询数量和更好的性能，并且Glimpse的HUD与其SQL选项卡之间的查询计数没有差异。