mvc-mini-profiler slows down Entity Framework

Question

I've set up mvc-mini-profiler against my Entity Framework-powered MVC 3 site. Everything is duly configured; Starting profiling in Application_Start, ending it in Application_End and so on. The profiling part works just fine.

However, when I try to swap my data model object generation to providing profilable versions, performance slows to a grind. Not every SQL query, but some queries take about 5x the entire page load. (The very first page load after firing up IIS Express takes a bit longer, but this is sustained.)

Negligible time (~2ms tops) is spent querying, executing and "data reading" the SQL, while this line:

var person = dataContext.People.FirstOrDefault(p => p.PersonID == id);

...when wrapped in using(profiler.Step()) is recorded as taking 300-400 ms. I profiled with dotTrace, which confirmed that the time is actually spent in EF as usual (the profilable components do make very brief appearances), only it is taking much longer.

This leads me to believe that the connection or some of its constituent parts are missing sufficient data, making EF perform far worse.

This is what I'm using to make the context object (my edmx model's class is called DataContext):

var conn = ProfiledDbConnection.Get(
    /* returns an SqlConnection */CreateConnection());
return CreateObjectContext<DataContext>(conn);

I originally used the mvc-mini-profiler provided ObjectContextUtils.CreateObjectContext method. I dove into it and noticed that it set a wildcard metadata workspace path string. Since I have the database layer isolated to one project and several MVC sites as other projects using the code, those paths have changed and I'd rather be more specific. Also, I thought this was the cause of the performance issue. I duplicated the CreateObjectContext functionality into my own project to provide this, as such:

    public static T CreateObjectContext<T>(DbConnection connection) where T : System.Data.Objects.ObjectContext {
        var workspace = new System.Data.Metadata.Edm.MetadataWorkspace(
          GetMetadataPathsString().Split('|'),
          // ^-- returns 
          //  "res://*/Redacted.csdl|res://*/Redacted.ssdl|res://*/Redacted.msl"
          new Assembly[] { typeof(T).Assembly });

        // The remainder of the method is copied straight from the original,
        // and I carried over a duplicate CtorCache too to make this work.
        var factory = DbProviderServices.GetProviderFactory(connection);
        var itemCollection = workspace.GetItemCollection(System.Data.Metadata.Edm.DataSpace.SSpace);
        itemCollection.GetType().GetField("_providerFactory", // <==== big fat ugly hack
            BindingFlags.NonPublic | BindingFlags.Instance).SetValue(itemCollection, factory);
        var ec = new System.Data.EntityClient.EntityConnection(workspace, connection);
        return CtorCache<T, System.Data.EntityClient.EntityConnection>.Ctor(ec);
    }

...but it doesn't seem to make much of a difference. The problem still exists whether I use the above hacked version that's more specific with metadata workspace paths or the mvc-mini-profiler provided version. I just thought I'd mention that I've tried this too.

Having exhausted all this, I'm at my wits' end. Once again: when I just provide my data context as usual, no performance is lost. When I provide a "profilable" data context, performance plummets for certain queries (I don't know what influences this either). What could mvc-mini-profiler do that's wrong? Am I still feeding it the wrong data?

I think this is the same problem as this person ran into.

I'm the one having that same issue at the link you provided. I hope we can find a resolution. — WVDominick, Jun 23 '11 at 15:26
I forwarded this to the EF team ... hopefully we will get some guidance — Sam Saffron, Jun 24 '11 at 02:04
@Jesper also: if anyone can provide me with a simple repro solution I promise to debug through and figure out what is going on. see: http://code.google.com/p/mvc-mini-profiler/issues/detail?id=43 and http://stackoverflow.com/questions/6613180/how-do-i-correctly-profile-entity-framework — Sam Saffron, Jul 09 '11 at 10:46

score 6 · Accepted Answer · answered Jul 25 '11 at 10:36

6

I just resolved this issue today.

see: http://code.google.com/p/mvc-mini-profiler/issues/detail?id=43

It happened cause some of our fancy hacks were not cached well enough. In particular:

var workspace = new System.Data.Metadata.Edm.MetadataWorkspace(
     new string[] { "res://*/" },       
     new Assembly[] { typeof(T).Assembly });

Is a very expensive call, so we need to cache the workspace.

answered Jul 25 '11 at 10:36

Sam Saffron

128,308
78
326
506

Nice. I skimmed through your code previously and I completely missed this. – Ladislav Mrnka Jul 25 '11 at 10:59
That did solve it. Thanks! Now I'm battling session state lock contention adding 500 ms between the profiler starting and MVC getting to work. The fun never ends. – Jesper Aug 01 '11 at 12:17
@Jesper do you have a repro, is this our fault ? – Sam Saffron Aug 02 '11 at 12:51
@Sam: No, I think I'm just overtly triggering ASP.NET's well-known session state reader-writer-lock. [It's basically this issue](http://stackoverflow.com/questions/6172350/mysterious-asp-net-mvc-action-high-latency-issue). I have managed to not trigger this despite being through a number of MVC projects and also some Web Forms projects, but it seems to happen even without the mini-profiler. – Jesper Aug 02 '11 at 14:21

score -2 · Answer 2 · answered Jun 27 '11 at 17:15

-2

Profiling, by definition, will effect performance of the application being profiled. The profiler needs to insert it's own method calls throughout the application, intercept low level system calls, and record all that data someplace (meaning writes to disk). All of those tasks take up precious CPU cycles, memory, and disk access.

answered Jun 27 '11 at 17:15

RyanR

7,728
1
25
39

1

Oh sure, I understand that and I am comfortably at ease with this tradeoff, but this is a dramatic increase in a small spectrum of seemingly trivial operations. It's also not the case that performance decreases equally or roughly equally across the board. Some queries that materialize way more objects are also way faster. This is reproducibly a clear outlier, for seemingly no reason. – Jesper Jun 28 '11 at 07:21
Have you tried any of the generic profiling tools instead, to see if they exhibit the same performance issues? – RyanR Jun 28 '11 at 13:18
Yes; the question states that I used dotTrace to pinpoint the hot path while this profiler was installed. (Execution everywhere slowed to a crawl.) The question is about how this doesn't make sense and how I'm hoping I just didn't set this up right. mvc-mini-profiler isn't really a profiler per the common definition since it doesn't tap into everything in order to instrument the execution, but it serves a need that's hard to meet otherwise (visit its site for a deeper treatise) so I would be very happy if I only had to reach for dotTrace when something calls for the heavy artillery. – Jesper Jun 28 '11 at 16:28
Clarification: I used dotTrace to try to figure out what EF or mvc-mini-profiler was doing to slow down one thing in particular. With mvc-mini-profiler disabled, I don't see this discrepancy, regardless of whether I'm profiling with dotTrace or not. – Jesper Jun 28 '11 at 16:30
Ryan, this was a clear bug - mini profiler is a production safe profiler impact is minimal both when profiling and not. EF is rather strange and hard to intercept – Sam Saffron Jul 25 '11 at 10:37

mvc-mini-profiler slows down Entity Framework

2 Answers2