I am trying to improve performance of a relatively complicated entity framework query. Using the DbContext.Database.Log
action I examined the ouput while executing my main query of interest and I noticed something odd. According to the log, the query itself is taking only ~ 10,000 ms, however there is over a minute between when the query "completes" and when the connection is closed. I have no idea what is happening in this time as the log shows a blank line. Here is the output:
2018-09-07 14:10:34,641 [1] INFO EntityDataRepository [jobInstanceID: 0] - -- Executing at 9/7/2018 2:10:34 PM -07:00
2018-09-07 14:10:46,421 [1] INFO EntityDataRepository [jobInstanceID: 0] - -- Completed in 11776 ms with result: SqlDataReader
2018-09-07 14:10:46,458 [1] INFO EntityDataRepository [jobInstanceID: 0] -
2018-09-07 14:11:48,667 [1] INFO EntityDataRepository [jobInstanceID: 0] - Closed connection at 9/7/2018 2:11:48 PM -07:00
Could someone please educate me on what is going on here? See below for a simplified/generic version of the code:
(from child in entities.SelectMany(e => e.children.Where(childFilter))
join read in childReads on child.ID equals read.childID
join readType in readTypes on read.readTypeID equals readType.ID
where readFilter
select new {child, read, readType}).ToList()