Slow EF profiling performance

[GoogleCodeExporter]

I tried the profiler with EF and the performance is very slow when the 
profiling context is used. The profiler adds a few hundred ms to each DB call 
using EF.

Please see this link for more info on the issue:

http://stackoverflow.com/questions/6439827/slow-ef-profiling-performance-with-mv
c-mini-profiler

Original issue reported on code.google.com by wvdomin...@gmail.com on 27 Jun 2011 at 7:13

[GoogleCodeExporter]

I've pushed a changeset that should help some and answered your question:

http://stackoverflow.com/questions/6439827/slow-ef-profiling-performance-with-mv
c-mini-profiler/6529371#6529371

Let me know how many queries are being made!

Original comment by jarrod.m.dixon on 30 Jun 2011 at 2:36

• Changed state: Started

[GoogleCodeExporter]

Now it appears that it's only the first query after the profiler context is 
defined that runs slowly. After the first LINQ statement is executed the rest 
go without slowdown. I can see that the stack traces aren't being executed on 
the queries not, but something else appears to be slowing down the initial 
query.

Original comment by wvdomin...@gmail.com on 1 Jul 2011 at 12:16

[GoogleCodeExporter]

can you try current trunk with the latest source and stack traces enabled? do 
you still see the slowdown? 

also is this slowdown for every request or just the initial request the app 
has? 

Original comment by sam.saff...@gmail.com on 7 Jul 2011 at 4:22

[GoogleCodeExporter]

I gave it a try. The slowdown is still there. It appears the first query after 
the context is created is the one that slows down the most. Some of the other 
queries may run a little slower, but the first LINQ query after the context is 
created slows down a great deal.

Excluding the strack trace timings save a little time. Maybe 30ms on the query 
that takes about 330ms using the profiler and about 30ms without.

Original comment by wvdomin...@gmail.com on 7 Jul 2011 at 4:42

[GoogleCodeExporter]

Is there any way you could push a repro solution for us somewhere? Even just 
email it to me as a zip sam.saffron@gmail.com ? 

Original comment by sam.saff...@gmail.com on 7 Jul 2011 at 10:13

[GoogleCodeExporter]

Unfortunately I can't send you what I'm working on right now. I will try to 
make time to create a simple solution to reproduce the issue.

I'm using POCO's for my entities. I'm attaching a sample class file of one of 
my entities. I have lazyloading enabled. My "Entities" class inherits from 
ObjectContext. Is there anything specific I can find out for you?

Original comment by wvdomin...@gmail.com on 8 Jul 2011 at 4:43

Attachments:

• ActionItem.cs

[GoogleCodeExporter]

well if anyone can provide me with a simple repro solution I promise to debug 
through and figure out what is going on.

Original comment by sam.saff...@gmail.com on 9 Jul 2011 at 10:44

[GoogleCodeExporter]

still waiting on a repro ... our sample solution which uses EF does not exhibit 
any of this stuff 

Original comment by sam.saff...@gmail.com on 19 Jul 2011 at 4:19

[GoogleCodeExporter]

Am trying out this profiler for the first time today, and I seem to be seeing 
this issue too. When I use the 'normal' ObjectContext the requests on the page 
I'm testing this on are ~100ms according to the miniprofiler. 

But switching to 
ProfiledDbConnection.Get(connection).CreateObjectContext<MyContext>() the 
reported requests jump up to ~1000ms. This remains constant (it's not just the 
first request), and this is with the ExcludeStackTraceSnippetFromSqlTimings set 
to True.

I'm afraid I don't have a repro project - this is a bit of prototyping on our 
main site I convinced my boss to let me do, and I don't have time to hack our 
site down to a small reproduction. May try and play over the weekend and see 
what I can come up with.

Original comment by randomse...@gmail.com on 22 Jul 2011 at 3:45

[GoogleCodeExporter]

We do not use EF internally ... without a repro project there is not much I can 
do ... I will take time off to fix this once I have a repro. 

Original comment by sam.saff...@gmail.com on 23 Jul 2011 at 11:40

[GoogleCodeExporter]

Ok, here's a sample project that replicates both this issue and the one at 
http://code.google.com/p/mvc-mini-profiler/issues/detail?id=62

I've hacked this together in a couple of hours so some of it is pretty hairy - 
apologies for the overall messiness of it all! 

There's a form that submits a bunch of queries, and a tickbox to turn on/off 
whether or not to use the profiled connection. I was regularly getting 40ms per 
query in the profiler, which jumps up to around 200-300ms with the profiled 
connection turned on.

(interestingly, I then installed Glimpse, and all the times jumped up to around 
200ms, and around 400-500ms for the profiled queries. Didn't realise Glimpse 
was so heavy!)

To set up, create a blank database (I was using SQL Server 2005), run the 
included sql file which will setup a couple of tables and some test data. 
Configure the connection strings as required.

You should see:

1) Reported profile times increase massively with a profiled sql connection vs 
an unprofiled one.

2) Some entries are duplicated in the profiler despite only being sent once 
from the client, as per 
http://code.google.com/p/mvc-mini-profiler/issues/detail?id=62. Debugging this 
the calls to  profiler.Step only happen once per ajax call so I would think 
shouldn't be reported more than once in the profiler.

Hope this helps!

Original comment by randomse...@gmail.com on 24 Jul 2011 at 6:15

Attachments:

• EFTest.zip

[GoogleCodeExporter]

having a look

Original comment by sam.saff...@gmail.com on 25 Jul 2011 at 6:18

[GoogleCodeExporter]

Can you confirm my latest check in fixes this? 

Original comment by sam.saff...@gmail.com on 25 Jul 2011 at 8:19

[GoogleCodeExporter]

Good news - it appears to fix the slow speeds with the profiled connection!

But I'm still getting duplicates. Will bring that up at the other thread as 
this issue appears to be closed.

Original comment by randomse...@gmail.com on 25 Jul 2011 at 8:54

[GoogleCodeExporter]

Ironically you've actually closed the other issue already. Have reported the 
problems over there.

Thanks a lot for looking at this EF issue so quickly, impressive stuff!

Original comment by randomse...@gmail.com on 25 Jul 2011 at 8:58

[GoogleCodeExporter]

wow ... at last we can put this to rest! :)

Original comment by sam.saff...@gmail.com on 25 Jul 2011 at 10:33

• Changed state: Fixed

[GoogleCodeExporter]

This may work for EF 4.1, but now it won't work at all for me. I get this now: 
"Unable to find the requested .Net Framework Data Provider.  It may not be 
installed."

[ArgumentException: Unable to find the requested .Net Framework Data Provider.  
It may not be installed.]
   MvcMiniProfiler.Data.ProfiledDbConnection.get_DbProviderFactory() +286
   System.Data.Common.DbProviderServices.GetProviderFactory(DbConnection connection) +38
   System.Data.Objects.ObjectContextUtils.CreateObjectContext(DbConnection connection) +74

Original comment by wvdomin...@gmail.com on 26 Jul 2011 at 1:06

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

I get the same "Unable to find the requested .Net Framework Data Provider.  It 
may not be installed."

I also get this in the stack trace, not sure if it helps, but it seems to be 
looking at a hard coded path. (my name is not Sam and the path doesn't exist on 
my box).

[ArgumentException: Unable to find the requested .Net Framework Data Provider.  
It may not be installed.]
   MvcMiniProfiler.Data.ProfiledDbConnection.get_DbProviderFactory() in C:\Users\sam\Desktop\mvc-mini-profiler\MvcMiniProfiler\Data\ProfiledDbConnection.cs:75
   System.Data.Common.DbProviderServices.GetProviderFactory(DbConnection connection) +38
   System.Data.Objects.ObjectContextUtils.CreateObjectContext(DbConnection connection) in C:\Users\sam\Desktop\mvc-mini-profiler\MvcMiniProfiler\Data\ContextUtils.cs:33

(* edited to remove some of the stack trace info)

Original comment by bradr...@gmail.com on 27 Jul 2011 at 12:50