New Posts New Posts RSS Feed: Performance consideration
  FAQ FAQ  Forum Search   Calendar   Register Register  Login Login

Performance consideration

 Post Reply Post Reply
Author
kdev View Drop Down
Groupie
Groupie
Avatar

Joined: 03-Jan-2013
Posts: 83
Post Options Post Options   Quote kdev Quote  Post ReplyReply Direct Link To This Post Topic: Performance consideration
    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));

Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391
Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post 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.
Back to Top
kdev View Drop Down
Groupie
Groupie
Avatar

Joined: 03-Jan-2013
Posts: 83
Post Options Post Options   Quote kdev Quote  Post ReplyReply Direct Link To This Post 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.


Back to Top
kdev View Drop Down
Groupie
Groupie
Avatar

Joined: 03-Jan-2013
Posts: 83
Post Options Post Options   Quote kdev Quote  Post ReplyReply Direct Link To This Post 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.
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391
Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post 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.
Back to Top
kdev View Drop Down
Groupie
Groupie
Avatar

Joined: 03-Jan-2013
Posts: 83
Post Options Post Options   Quote kdev Quote  Post ReplyReply Direct Link To This Post Posted: 27-Sep-2013 at 11:05am
Ok. Let me know if you want I do some specific test on my side.
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391
Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post 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? 
Back to Top
kdev View Drop Down
Groupie
Groupie
Avatar

Joined: 03-Jan-2013
Posts: 83
Post Options Post Options   Quote kdev Quote  Post ReplyReply Direct Link To This Post Posted: 03-Oct-2013 at 10:44am
sent you a pm
Back to Top
 Post Reply Post Reply

Forum Jump Forum Permissions View Drop Down