locked
WCF Data Service 5.6.x: Paged Content with Expand Takes Long Time RRS feed

  • Question

  • Hello Community,

    We are attempting to download all entities of a particular type within our client entity context to the client application.  This is about 62,000 entities.  We are using the guidance provided here:

    http://msdn.microsoft.com/en-us/library/ee358711(v=vs.110).aspx

    If we do not use any Expands, this works very smoothly, downloading 1000 items at a time (our configured paging limit), and taking around 25-30 seconds:

    Page 0 at 230ms.
    Page 1 at 212ms.
    Page 2 at 222ms.
    Page 3 at 223ms.
    Page 4 at 213ms.
    Page 5 at 220ms.
    Page 6 at 211ms.
    Page 7 at 223ms.
    Page 8 at 203ms.
    Page 9 at 217ms.
    Page 10 at 212ms.
    Page 11 at 203ms.
    Page 12 at 242ms.
    Page 13 at 198ms.
    Page 14 at 230ms.
    Page 15 at 204ms.
    Page 16 at 207ms.
    Page 17 at 248ms.
    Page 18 at 224ms.
    Page 19 at 210ms.
    Page 20 at 206ms.
    Page 21 at 200ms.
    Page 22 at 205ms.
    Page 23 at 225ms.
    Page 24 at 205ms.
    Page 25 at 213ms.
    Page 26 at 210ms.
    Page 27 at 206ms.
    Page 28 at 205ms.
    Page 29 at 256ms.
    Page 30 at 248ms.
    Page 31 at 202ms.
    Page 32 at 200ms.
    Page 33 at 197ms.
    Page 34 at 214ms.
    Page 35 at 208ms.
    Page 36 at 239ms.
    Page 37 at 209ms.
    Page 38 at 211ms.
    Page 39 at 217ms.
    Page 40 at 220ms.
    Page 41 at 206ms.
    Page 42 at 207ms.
    Page 43 at 212ms.
    Page 44 at 201ms.
    Page 45 at 201ms.
    Page 46 at 210ms.
    Page 47 at 222ms.
    Page 48 at 208ms.
    Page 49 at 206ms.
    Page 50 at 209ms.
    Page 51 at 236ms.
    Page 52 at 223ms.
    Page 53 at 208ms.
    Page 54 at 203ms.
    Page 55 at 215ms.
    Page 56 at 217ms.
    Page 57 at 244ms.
    Page 58 at 206ms.
    Page 59 at 204ms.
    Page 60 at 204ms.
    Page 61 at 241ms.
    Page 62 at 123ms.
    All Items = 25356.

    However, when we introduce Expands in this process, we are finding the time increase exponentially with each pass of entity requests.  That is, the more 1000 items it retrieves, the longer each pass takes.  As seen here, it starts out at ~600ms for the first pass, and ends up at ~14 seconds for the last one:

    Page 0 at 629ms.
    Page 1 at 725ms.
    Page 2 at 831ms.
    Page 3 at 823ms.
    Page 4 at 1025ms.
    Page 5 at 1135ms.
    Page 6 at 976ms.
    Page 7 at 1387ms.
    Page 8 at 1420ms.
    Page 9 at 1333ms.
    Page 10 at 1332ms.
    Page 11 at 1421ms.
    Page 12 at 1677ms.
    Page 13 at 1534ms.
    Page 14 at 1189ms.
    Page 15 at 1860ms.
    Page 16 at 1916ms.
    Page 17 at 2169ms.
    Page 18 at 2343ms.
    Page 19 at 2376ms.
    Page 20 at 2510ms.
    Page 21 at 2323ms.
    Page 22 at 2679ms.
    Page 23 at 2523ms.
    Page 24 at 3031ms.
    Page 25 at 2254ms.
    Page 26 at 3238ms.
    Page 27 at 3396ms.
    Page 28 at 4025ms.
    Page 29 at 5231ms.
    Page 30 at 4462ms.
    Page 31 at 5154ms.
    Page 32 at 5408ms.
    Page 33 at 5545ms.
    Page 34 at 6317ms.
    Page 35 at 4635ms.
    Page 36 at 7118ms.
    Page 37 at 6863ms.
    Page 38 at 7270ms.
    Page 39 at 7928ms.
    Page 40 at 8177ms.
    Page 41 at 8371ms.
    Page 42 at 8832ms.
    Page 43 at 9158ms.
    Page 44 at 9986ms.
    Page 45 at 9436ms.
    Page 46 at 10170ms.
    Page 47 at 10637ms.
    Page 48 at 11146ms.
    Page 49 at 10129ms.
    Page 50 at 11380ms.
    Page 51 at 10656ms.
    Page 52 at 11708ms.
    Page 53 at 10413ms.
    Page 54 at 10662ms.
    Page 55 at 12193ms.
    Page 56 at 12812ms.
    Page 57 at 13256ms.
    Page 58 at 13338ms.
    Page 59 at 13441ms.
    Page 60 at 13556ms.
    Page 61 at 13562ms.
    Page 62 at 6656ms.
    All Items = 403356.

    We're scratching our heads here wondering if there is something obvious we are missing.

    If we pause the process, we find that most of the time is being spent in the materialization process of the WCF Data Service Entity Context:

    It would be great to get some assistance/insight on this matter.  We are kind of stumped here.

    Thank you in advance,

    Michael


    Monday, May 12, 2014 7:17 PM

Answers

  • I think I have seen something like this before. The DataServiceContext has build in change tracking. For each entity returned from the server it needs to look in its internal collection to see if it is already tracking the entity. The more entities it is already tracking the longer it takes to process the response from the server. There are some mechanism to turn off the change tracking on the context. If you do not need try to turn it off. If you really care about the best performance you should switch to using the ODataLib's MessageReader directly to avoid in memory stream copying. See http://social.msdn.microsoft.com/Forums/en-US/502c8430-2c05-4ff5-921f-520dcd18d1d7/wcf-data-services-client-large-dataset-performance?forum=adodotnetdataservices And http://social.msdn.microsoft.com/Forums/en-US/549ccb5a-fc97-4dbc-b238-7555242609f9/performancethroughput-issue-in-wcf-ds-client-systemdataservicesclientqueryresultexecutequery?forum=adodotnetdataservices Uffe
    • Edited by Uffe Lauesen Thursday, May 15, 2014 4:44 PM Links added
    • Marked as answer by Mike-E_wins Thursday, May 15, 2014 6:01 PM
    Thursday, May 15, 2014 4:38 PM

All replies

  • Hello,

    It may do something other with the expand condition. It seems that you specify page size from the service side. You can have a try to specify page size from client side as below to check whether it will perform better:

    http://localhost:8322/SchoolDataService.svc/Courses?$skip=10&top=10

    If I this does not work for you, please let me know.

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Tuesday, May 13, 2014 2:18 AM
    Moderator
  • Hi Fred,

    Thank you for your reply.  Isn't what you are suggesting already done automatically by the GetContinuation() link as described by the link in my original post?  Regardless, if I do a for loop with the Skip/Take strategy as you recommend, I still experience the same behavior.  That is, each successive page takes more time than the last.

    var result = new List<TEntity>();
    
    var response = (QueryOperationResponse<TEntity>) query.Execute();
    totalCount.NotNull( x => x( response.TotalCount ) );
    
    var total = response.TotalCount;
    const int pageSize = 500;
    
    var stopwatch = new Stopwatch();
    stopwatch.Start();
    
    for ( var i = 0; i < total / pageSize; i++ )
    {
    	var pager = new Stopwatch();
    	pager.Start();
    
    	var page = query.Skip( i * pageSize ).Take( pageSize );
    	response = page.AsTo<DataServiceQuery<TEntity>, QueryOperationResponse<TEntity>>( x => (QueryOperationResponse<TEntity>)x.Execute() );
    	result.AddRange( response );
    	currentCount.NotNull( x => x( result.LongCount() ) );
    
    	Debug.WriteLine( "Page {0} in {1}ms", i, pager.ElapsedMilliseconds );
    }
    
    Debug.WriteLine( "Complete = {0}", stopwatch.ElapsedMilliseconds );

    Sample paging (please note that I did not wait the entire process):

    Page 0 in 671ms
    Page 1 in 708ms
    Page 2 in 753ms
    Page 3 in 799ms
    Page 4 in 811ms
    Page 5 in 790ms
    Page 6 in 890ms
    Page 7 in 901ms
    Page 8 in 920ms
    Page 9 in 944ms
    Page 10 in 929ms
    Page 11 in 985ms
    Page 12 in 1052ms
    Page 13 in 1087ms
    Page 14 in 1035ms
    Page 15 in 1202ms
    Page 16 in 1246ms
    Page 17 in 1291ms
    Page 18 in 1370ms
    Page 19 in 1447ms
    Page 20 in 1465ms
    Page 21 in 1402ms
    Page 22 in 1553ms
    Page 23 in 1750ms
    Page 24 in 1885ms
    Page 25 in 1824ms
    Page 26 in 1713ms
    Page 27 in 1663ms
    Page 28 in 1674ms
    Page 29 in 1726ms
    Page 30 in 1751ms
    Page 31 in 1918ms
    Page 32 in 1957ms
    Page 33 in 1925ms
    Page 34 in 2159ms
    Page 35 in 2199ms
    Page 36 in 2209ms
    Page 37 in 2226ms
    Page 38 in 2311ms
    Page 39 in 2198ms
    Page 40 in 2439ms
    Page 41 in 2612ms
    Page 42 in 2637ms
    Page 43 in 2621ms
    Page 44 in 2725ms
    Page 45 in 3011ms
    Page 46 in 2789ms
    Page 47 in 2933ms
    Page 48 in 3122ms

    I have done this on a simple query such as context.Entities.IncludeTotalCount(), and I still get the behavior above.

    Thank you for your continued assistance,

    Michael


    Tuesday, May 13, 2014 8:44 PM
  • Hello,

    Okey, I have submitted a feedback to ms team to check whether there is some solution for it:

    https://connect.microsoft.com/VisualStudio/feedback/details/873124/wcf-data-service-5-6-x-paged-content-with-expand-takes-long-time

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Wednesday, May 14, 2014 8:15 AM
    Moderator
  • Great, thank you Fred.
    Wednesday, May 14, 2014 12:44 PM
  • I think I have seen something like this before. The DataServiceContext has build in change tracking. For each entity returned from the server it needs to look in its internal collection to see if it is already tracking the entity. The more entities it is already tracking the longer it takes to process the response from the server. There are some mechanism to turn off the change tracking on the context. If you do not need try to turn it off. If you really care about the best performance you should switch to using the ODataLib's MessageReader directly to avoid in memory stream copying. See http://social.msdn.microsoft.com/Forums/en-US/502c8430-2c05-4ff5-921f-520dcd18d1d7/wcf-data-services-client-large-dataset-performance?forum=adodotnetdataservices And http://social.msdn.microsoft.com/Forums/en-US/549ccb5a-fc97-4dbc-b238-7555242609f9/performancethroughput-issue-in-wcf-ds-client-systemdataservicesclientqueryresultexecutequery?forum=adodotnetdataservices Uffe
    • Edited by Uffe Lauesen Thursday, May 15, 2014 4:44 PM Links added
    • Marked as answer by Mike-E_wins Thursday, May 15, 2014 6:01 PM
    Thursday, May 15, 2014 4:38 PM
  • Thank you Uffe!  That was it.  To be more precise, it's setting this property to NoTracking before performing the query.

    http://msdn.microsoft.com/en-us/library/system.data.services.client.dataservicecontext.mergeoption.aspx

    Much thanks and appreciation!

    Thursday, May 15, 2014 6:02 PM