Discrepancy between DB Query count in Glimpse HUD & SQL Tab

Question

This question concerns Glimpse.MVC3 and Glimpse.EF5 packages. I'm trying to debug performance issues on an old MVC3 site. According to Glimpse's HUD, a particular GET request has 12 queries at 28ms total - but when I expand to open up the Main Panel, and click the SQL Tab, it says there are only 6 queries at 10.41ms total. Both the count at the top says 6, and when I count the queries it lists, there are 6. This would also make sense when I see the code written. (Either way I can see too much is being lazy loaded and it needs fixed.)

There are no indicators from Glimpse that the same 6 queries are being executed twice (which is where my brain goes when I see the HUD shows twice the number the panel does).

Additionally, the HUD shows 0 Ajax requests, but the history section actually shows 1 (which is definitely accurate).

Any ideas why there would be a discrepancy? (Keeping in mind I'm more concerned about the discrepancy with the queries.)

EDIT - JSON from file as requested:

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
    }

EDIT 2 - Queries

"Queries":[["Commands per Connection","Duration"],

[[["Transaction Start","Ordinal","Command","Parameters","Records","Duration","Offset","Async","Transaction End","Errors"],[null,"1","SELECT TOP (2) \r\n[Extent1].[TrxnID] AS [TrxnID], \r\n[Extent1].[StartTime] AS [StartTime], \r\n[Extent1].[Lane] AS [Lane], \r\n[Extent1].[EmployeeID] AS [EmployeeID], \r\n[Extent1].[OptionsCompleted] AS [OptionsCompleted], \r\n[Extent1].[StoreID] AS [StoreID], \r\n[Extent1].[NoVehicleTireCheck] AS [NoVehicleTireCheck], \r\nFROM [Activity].[Trxn] AS [Extent1]\r\nWHERE [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 \r\n[Extent1].[TrxnID] AS [TrxnID], \r\n[Extent1].[CustomerID] AS [CustomerID], \r\n[Extent1].[FirstName] AS [FirstName], \r\n[Extent1].[LastName] AS [LastName], \r\n[Extent1].[RewardAccountID] AS [RewardAccountID], \r\n[Extent1].[CustomerEmail] AS [CustomerEmail], \r\n[Extent1].[HomePhone] AS [HomePhone]\r\nFROM [Activity].[Trxn_Customers] AS [Extent1]\r\nWHERE [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 \r\n[Extent1].[TrxnID] AS [TrxnID], \r\n[Extent1].[VehicleID] AS [VehicleID], \r\n[Extent1].[VehicleVIN] AS [VehicleVIN], \r\n[Extent1].[VehicleOdometer] AS [VehicleOdometer], \r\n[Extent1].[VehicleEngineID] AS [VehicleEngineID], \r\n[Extent1].[VehicleMakeID] AS [VehicleMakeID], \r\n[Extent1].[ModelYear] AS [ModelYear]\r\nFROM [Activity].[Trxn_Vehicles] AS [Extent1]\r\nWHERE [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 \r\n[Extent1].[TrxnID] AS [TrxnID], \r\n[Extent1].[SecondaryVehicleID] AS [SecondaryVehicleID], \r\n[Extent1].[SecondaryVehicleVIN] AS [SecondaryVehicleVIN], \r\n[Extent1].[SecondaryVehicleTypeID] AS [SecondaryVehicleTypeID], \r\n FROM [Activity].[Trxn_SecondaryVehicles] AS [Extent1]\r\n 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 \r\n[Extent1].[TrxnServiceID] AS [TrxnServiceID], \r\n[Extent1].[TrxnID] AS [TrxnID], \r\n[Extent1].[PackageID] AS [PackageID], \r\n[Extent1].[PartID] AS [PartID], \r\n[Extent1].[Qty] AS [Qty]\r\nFROM [Activity].[Trxn_Services] AS [Extent1]\r\nWHERE [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 \r\n[Extent1].[TrxnNoteID] AS [TrxnNoteID], \r\n[Extent1].[TrxnID] AS [TrxnID], \r\n[Extent1].[NoteText] AS [NoteText], \r\n[Extent1].[NoteNumber] AS [NoteNumber], \r\n[Extent1].[SendToInvoice] AS [SendToInvoice]\r\nFROM [Activity].[Trxn_Notes] AS [Extent1]\r\nWHERE [Extent1].[TrxnID] = 353 /* @EntityKeyValue1 */",[["Name","Value","Type","Size"],["@EntityKeyValue1",353,"Int32",0]],0,1.19,4689.34,false,null,null,""]],21.92]

]},"name":"SQL"}

Glabella

Can you post the relevant bits of your /Glimpse.axd?n=glimpse_request&requestId={guid}... json file here? If you view source on your page you should see the full URL as the last <script> include. – Zymo

Added some of that file I thought may be relevant. Is this what you were looking for? Do you need any other sections? Btw - I see you're one of the devs - so I will take this opportunity to thank you for making such an awesome tool. :) – Glabella

Thanks EF0! Actually, it looks like you trimmed out the section I was most interested in. Can you add all of glimpse_sql.data.queries? Feel free to sanitize the SQL if it is sensitive. – Zymo

@Zymo - added that section. – Glabella

Answer 1

Well, I figured it out. But first, take a look at the exact usage scenario that would need to be in place for the problem to occur.

Usage Scenario
The problem only occurs if you:
a. Have lazy loading enabled for the context.
b. Pass your EF model to the view directly, and don't use a viewmodel (which isn't good practice anyway, but was what this legacy code was doing).

What I Learned
1) It turns out the higher # of queries the HUD showed was correct - SQL Server Profiler reveals this.

2) Glimpse itself appears to be triggering the extra queries. When I leave the Metadata tab turned on, it appears to somehow access the navigation properties, causing lazy-loading. If I turn Glimpse off, or leave Glimpse on but disable the Metadata tab, no extra queries happen.

Explanation
It took me awhile to figure this out, as I searched through the code and built up a test scenario to isolate the problem. In it, I retrieved a single record, and didn't touch any nav properties afterward. Stepping through it, I knew for sure there were no navigation properties being accessed in my code to cause it - yet there were still all these extra queries being generated by the app, and I was completely baffled as to where they were coming from.

I finally gave up on figuring it out, disabled lazy-loading for the context (which prevents the extra calls), but then a NullReferenceException was being thrown on one of the nav properties. This particular nav property I had eager loaded, so I was even more confused to why it was null. Setting a breakpoint on that nav property, I found it was hit twice - once when I called it (and at that point it wasn't null), but then a 2nd time after my View/Razor code had finished compiling, it mysteriously was hit again. The call stack seemed to point to it coming from Glimpse. Sure enough, I was able to continue through the exception and the page loaded (with no errors or missing data), but Glimpse had an error displayed in the Metadata tab referencing that property. I put two and two together and experimented with turning Glimpse on/off and then disabling the Metadata tab. In either case, the extra queries stopped, and with Glimpse on but the Metadata tab disabled, the HUD and SQL Tab query count matched. Problem solved.

Now just to be clear, I am not saying this was the cause of my aforementioned performance issues - Glimpse was not even installed when the performance issues started, and as I understand it, Glimpse is off by default in Release mode anyway. The performance problem was caused by some obvious lazy-loading happening in code. However, as I fixed the lazy-loading happening in code, the query count in the HUD tab wasn't decreasing much, and performance wasn't increasing - and now that makes sense. For every lazily-loaded query I removed from the code, Glimpse was generating one behind the scenes by accessing navigation properties for the Metadata tab.

Bottom Line/TLDR: Disabling the Glimpse Metadata tab fixes the problem for me. Reduced query count & better performance in Debug mode, and there is no discrepancy in query count between Glimpse's HUD and its SQL Tab.

Glabella

This is a wonderful amount of info on debugging queries with Glimpse. Thank you very much; this should be upvoted a zillion times. – Impasse