DevForce 2012: Performance consideration

Performance consideration

Printed From: IdeaBlade
Category: DevForce
Forum Name: DevForce 2012
Forum Discription: For .NET 4.5
URL: http://www.ideablade.com/forum/forum_posts.asp?TID=4359
Printed Date: 06-Sep-2025 at 6:54am

Topic: Performance consideration

Posted By: kdev
Subject: Performance consideration
Date Posted: 25-Sep-2013 at 4:39am

Hi,

I am having very poor performance on querying from a SL Client (using cocktail). I am in a dev environnement.

For instance, trying to retreive one entity + 3 level of navigation property (entity.Nav1.Nav2.Nav3) takes near 500ms (happened to hit 800ms) while the SQL query takes only 11ms on SQL server.

In this exemple Nav1 and Nav3 are a RelatedEntityList and Nav2 is a NavigationProperty. My tables are pretty empty (one or 2 records max)

The repository use QueryStrategy.DataSourceOnly

var entite = await _entiteRepository.FindAsync(p => p.Id == Entite_Id,
                                              cancellationToken,
                                              fetchOptions: options => options.Include(Entite.EntityPropertyNames.LinkEntiteToParam));

1st execution

Elapsed time : 467.0034 ms

2nd execution (same EM, same Entite_Id)

Elapsed time : 203.0475 ms

3rd execution (different EM, different Entite_Id)

Elapsed time : 216.054 ms

Removing the Include give pretty much the same result.

Question 1 : using query inversion OFF why the elapsed time double on the first query ?

question 2 : I find 200ms quite high, more specially when it return 0 entity. Are those time normal at all ?

Note: I tried on Temphire, using the sentence below, to query a non existing entity. It did cost ~150ms each time.

ActiveUnitOfWork.StaffingResources.FindAsync(p => p.Id == Guid.NewGuid(), fetchOptions: opt => opt.Include(p => p.Skills));

Replies:

Posted By: kimj
Date Posted: 25-Sep-2013 at 6:50pm

First, I'm always suspicious of a first execution time. If the EntityManager is not connected and/or logged in, the first query will also wait for the connection to complete and then perform a LoginAsync. If the EntityServer is not already running and started with this first connect, then there's additional overhead while this is done. Also, the first query will cause various other initialization actions on both the client and server, usually the loading of metadata. So, I always "prime" an EntityManager with an initial query before running my "real" test.

In your case, the fact that subsequent execution times were significantly less than the first execution leads me to think that you're seeing this overhead.

Next, 200ms for a query returning no results does seem high, but a) this is Silverlight, b) the query is serialized to your EntityServer, c) the EntityServer asks EF to execute the query, d) EF sends the SQL query to the database server, e) the database runs the query, and e) the results, even if empty, are transmitted back through this pipeline. So, a lot of activity still takes place. I'd also try running in a release configuration in both SL and the web application to see if that helps. You can also try profiling the query, with a 3rd party tool or by adding additional tracing messages, to see if there's a specific problem area.

Posted By: kdev
Date Posted: 27-Sep-2013 at 8:13am

Hi kimj,

I did as you suggested, I ran a "dummy" query first. This query dummy also handle the time (~600ms) induced by the preloader (also named GlobalCache in TempHire).

I did those tests in QueryStrategy.DataSourceOnly to be sure I don't add extra data/time with inversion mode and don't use the cache. Here is what I get :

(EM N°1)
Query dummy : 954.0093 ms
My real query on ID = 1  : 484.0038 ms

then

(EM N°2)
Query dummy : 704.0043 ms
My real query on ID = 2  : 207.0322 ms

then I test again Id == 1

(EM N°3)
Query dummy : 690.028 ms
My real query on ID = 1  : 212.0012 ms

Now I start a new session of my application and I do the same test but in inverted order (to rule out the fact that of the the query might really be faster thant the other one)

(EM N°1)
Query dummy : 950.9732 ms
My real query on ID = 2  : 551.0041 ms

then

(EM N°2)
Query dummy : 695.9999 ms
My real query on ID = 1  : 236.0045 ms

then I test again Id == 2

(EM N°3)
Query dummy : 698.433 ms
My real query on ID = 2  : 209.0148 ms

Note : I did test on a query with many includes. the "normal" time was ~1500ms while the "initial" time was ~3100ms.

This "initial" time seems proportionnal to the "normal" time.

Posted By: kdev
Date Posted: 27-Sep-2013 at 9:04am

I should add that the performance issue hits every different query, not only the first query executed.

as shown in the post above, if you remove the 600ms due to the preloader, you will see that the dummy query has also this problem.

Posted By: kimj
Date Posted: 27-Sep-2013 at 11:03am

Thanks, kdev. We don't see the numbers you're seeing, but the SL query metrics aren't as good as we'd like, and we're investigating further.

Posted By: kdev
Date Posted: 27-Sep-2013 at 11:05am

Ok. Let me know if you want I do some specific test on my side.

Posted By: kimj
Date Posted: 03-Oct-2013 at 7:04am

kdev, is there any chance you can send us the code snippet and Fiddler session archive for this?

Posted By: kdev
Date Posted: 03-Oct-2013 at 10:44am

sent you a pm