none
SPListItemCollection: Performance Varies Depending on Account

    Question

  • I have read there is a common problem with performance the first time SPListItemCollection.Count or .GetDataTable() is used. I am consistently experiencing 30 second page load times when calling either of these members for the first time on a SPListItemCollection containing 3500 items.

    I did, however, notice that System Account will load the exact same page in under 1 second. Knowing this, I wrapped the GetDataTable call in elevated permissions which did seem to shave off about 3 seconds but 27 sec page load time is still unusable.

    Any idea why performance is bad for every user account except System?


    Tuesday, May 21, 2013 6:59 PM

All replies

  • ListItem.Count has to collect all the items in the list into memory which is comparatively slow. This will be true of all accounts, i'd assume that it's just cached the data a bit closer for the second time.

    Try running the page with the Developer Dashboard running, that will let you narrow down where the page load time is kicking in.

    Tuesday, May 21, 2013 7:33 PM
  • 05/21/2013 10:39:19.00 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job SchedulingApproval) 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.00 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job SchedulingApproval). Execution Time=2.98138450557264 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.00 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job SchedulingApproval) 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.00 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job SchedulingApproval). Execution Time=1.94521929463102 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.00 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job SchedulingApproval) 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.01 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job SchedulingApproval). Execution Time=2.38466062027436 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.01 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job SchedulingApproval) 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.01 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job SchedulingApproval). Execution Time=1.94466056440134 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.01 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job SchedulingApproval) 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.01 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job SchedulingApproval). Execution Time=2.97859085442424 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.03 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job SchedulingApproval) 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:19.03 OWSTIMER.EXE (0x1D6C) 0x26A4 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job SchedulingApproval). Execution Time=2.73666066497278 309ab010-ea4f-4e34-8160-9c2a4ead0584 05/21/2013 10:39:23.35 w3wp.exe (0x3D04) 0x3584 SharePoint Foundation Topology e5mc Medium WcfSendRequest: RemoteAddress: 'http://pexternalfront:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'Microsoft.SharePoint.Taxonomy.IMetadataWebServiceApplication' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:1a38a7e3-055f-4d58-9ec2-0111d92723e3' 05/21/2013 10:39:23.35 w3wp.exe (0x17D0) 0x1AD8 SharePoint Foundation Topology e5mb Medium WcfReceiveRequest: LocalAddress: 'http://pexternalfront.ngic.cjis.gov:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'System.ServiceModel.Channels.ServiceChannel' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:1a38a7e3-055f-4d58-9ec2-0111d92723e3' 0ee69931-34cd-403c-87e3-2509be7bfcfd 05/21/2013 10:39:23.35 w3wp.exe (0x17D0) 0x1AD8 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (ExecuteWcfServerOperation) 0ee69931-34cd-403c-87e3-2509be7bfcfd 05/21/2013 10:39:23.35 w3wp.exe (0x17D0) 0x1AD8 SharePoint Server Taxonomy fuc5 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' starting. 0ee69931-34cd-403c-87e3-2509be7bfcfd 05/21/2013 10:39:23.35 w3wp.exe (0x17D0) 0x1AD8 SharePoint Server Taxonomy fuc6 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' completed. 0ee69931-34cd-403c-87e3-2509be7bfcfd 05/21/2013 10:39:23.35 w3wp.exe (0x17D0) 0x1AD8 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=2.9922797450514 0ee69931-34cd-403c-87e3-2509be7bfcfd 05/21/2013 10:39:24.87 w3wp.exe (0x3D88) 0x2CC8 SharePoint Foundation Topology e5mc Medium WcfSendRequest: RemoteAddress: 'http://pexternalfront:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'Microsoft.SharePoint.Taxonomy.IMetadataWebServiceApplication' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:f453dcab-43aa-44f5-aa00-1c621cc8db51' 05/21/2013 10:39:24.87 w3wp.exe (0x17D0) 0x1AD8 SharePoint Foundation Topology e5mb Medium WcfReceiveRequest: LocalAddress: 'http://pexternalfront.ngic.cjis.gov:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'System.ServiceModel.Channels.ServiceChannel' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:f453dcab-43aa-44f5-aa00-1c621cc8db51' b1cf6715-77b0-4944-b8b8-6461ebf39cc2 05/21/2013 10:39:24.87 w3wp.exe (0x17D0) 0x1AD8 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (ExecuteWcfServerOperation) b1cf6715-77b0-4944-b8b8-6461ebf39cc2 05/21/2013 10:39:24.87 w3wp.exe (0x17D0) 0x1AD8 SharePoint Server Taxonomy fuc5 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' starting. b1cf6715-77b0-4944-b8b8-6461ebf39cc2 05/21/2013 10:39:24.87 w3wp.exe (0x17D0) 0x1AD8 SharePoint Server Taxonomy fuc6 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' completed. b1cf6715-77b0-4944-b8b8-6461ebf39cc2 05/21/2013 10:39:24.87 w3wp.exe (0x17D0) 0x1AD8 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=1.73988593522361 b1cf6715-77b0-4944-b8b8-6461ebf39cc2 05/21/2013 10:39:30.00 OWSTIMER.EXE (0x1D6C) 0x2480 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job job-diagnostics-blocking-query-provider) 5effa3ac-5806-4e8c-9958-c8183dc154ac 05/21/2013 10:39:30.00 OWSTIMER.EXE (0x1D6C) 0x2050 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job job-diagnostics-sql-memory-provider) c4ce3100-4b9a-4605-b695-02b61cd04967 05/21/2013 10:39:30.01 OWSTIMER.EXE (0x1D6C) 0x2480 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job job-diagnostics-blocking-query-provider). Execution Time=21.1197233167903 5effa3ac-5806-4e8c-9958-c8183dc154ac 05/21/2013 10:39:30.04 OWSTIMER.EXE (0x1D6C) 0x2050 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job job-diagnostics-sql-memory-provider). Execution Time=55.2187498690476 c4ce3100-4b9a-4605-b695-02b61cd04967 05/21/2013 10:39:33.37 w3wp.exe (0x3D04) 0x3584 SharePoint Foundation Topology e5mc Medium WcfSendRequest: RemoteAddress: 'http://pexternalfront:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'Microsoft.SharePoint.Taxonomy.IMetadataWebServiceApplication' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:8d3543c1-7292-4f53-bce9-0b940ac82632' 05/21/2013 10:39:33.37 w3wp.exe (0x17D0) 0x1924 SharePoint Foundation Topology e5mb Medium WcfReceiveRequest: LocalAddress: 'http://pexternalfront.ngic.cjis.gov:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'System.ServiceModel.Channels.ServiceChannel' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:8d3543c1-7292-4f53-bce9-0b940ac82632' a9753760-53f3-47ab-bb7d-ed71a5b09073 05/21/2013 10:39:33.37 w3wp.exe (0x17D0) 0x1924 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (ExecuteWcfServerOperation) a9753760-53f3-47ab-bb7d-ed71a5b09073 05/21/2013 10:39:33.37 w3wp.exe (0x17D0) 0x1924 SharePoint Server Taxonomy fuc5 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' starting. a9753760-53f3-47ab-bb7d-ed71a5b09073 05/21/2013 10:39:33.37 w3wp.exe (0x17D0) 0x1924 SharePoint Server Taxonomy fuc6 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' completed. a9753760-53f3-47ab-bb7d-ed71a5b09073 05/21/2013 10:39:33.37 w3wp.exe (0x17D0) 0x1924 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=2.84449559930103 a9753760-53f3-47ab-bb7d-ed71a5b09073 05/21/2013 10:39:34.00 OWSTIMER.EXE (0x1D6C) 0x2DA8 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job job-application-server-admin-service) 3a1e7c15-5b27-4ac1-bd93-d1a483920fc9 05/21/2013 10:39:34.00 OWSTIMER.EXE (0x1D6C) 0x2DA8 SharePoint Server Search Administration dkd5 High synchronizing search service instance 3a1e7c15-5b27-4ac1-bd93-d1a483920fc9 05/21/2013 10:39:34.00 OWSTIMER.EXE (0x1D6C) 0x2DA8 SharePoint Server Search Administration eff0 High synchronizing search data access service instance 3a1e7c15-5b27-4ac1-bd93-d1a483920fc9 05/21/2013 10:39:35.21 OWSTIMER.EXE (0x1D6C) 0x2DA8 SharePoint Server Search Administration dl2i Medium Search application 'Search Service Application': Provision start addresses in default content source. 3a1e7c15-5b27-4ac1-bd93-d1a483920fc9 05/21/2013 10:39:35.23 OWSTIMER.EXE (0x1D6C) 0x2DA8 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job job-application-server-admin-service). Execution Time=1232.62174382498 3a1e7c15-5b27-4ac1-bd93-d1a483920fc9 05/21/2013 10:39:35.87 w3wp.exe (0x3D88) 0x2CC8 SharePoint Foundation Topology e5mc Medium WcfSendRequest: RemoteAddress: 'http://pexternalfront:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'Microsoft.SharePoint.Taxonomy.IMetadataWebServiceApplication' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:075233bf-010b-4e22-a80a-4147868fd172' 05/21/2013 10:39:35.87 w3wp.exe (0x17D0) 0x1924 SharePoint Foundation Topology e5mb Medium WcfReceiveRequest: LocalAddress: 'http://pexternalfront.ngic.cjis.gov:32843/450ed380d5e64d9982c8f29186b145b1/MetadataWebService.svc' Channel: 'System.ServiceModel.Channels.ServiceChannel' Action: 'http://schemas.microsoft.com/sharepoint/taxonomy/soap/IDataAccessReadOnly/GetChanges' MessageId: 'urn:uuid:075233bf-010b-4e22-a80a-4147868fd172' 9fa3ac7b-b14e-4a82-a093-9af060770951 05/21/2013 10:39:35.87 w3wp.exe (0x17D0) 0x1924 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (ExecuteWcfServerOperation) 9fa3ac7b-b14e-4a82-a093-9af060770951 05/21/2013 10:39:35.87 w3wp.exe (0x17D0) 0x1924 SharePoint Server Taxonomy fuc5 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' starting. 9fa3ac7b-b14e-4a82-a093-9af060770951 05/21/2013 10:39:35.87 w3wp.exe (0x17D0) 0x1924 SharePoint Server Taxonomy fuc6 Medium MetadataWebServiceApplication.GetChanges called on 'Managed Metadata Service' completed. 9fa3ac7b-b14e-4a82-a093-9af060770951 05/21/2013 10:39:35.87 w3wp.exe (0x17D0) 0x1924 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=1.80302245117745 9fa3ac7b-b14e-4a82-a093-9af060770951 05/21/2013 10:39:36.00 OWSTIMER.EXE (0x1D6C) 0x35E0 SharePoint Foundation Monitoring nasq Medium Entering monitored scope (Timer Job job-timer-locks) 8c5f7d7d-5d52-4cea-8f99-c650b2344eb0 05/21/2013 10:39:36.01 OWSTIMER.EXE (0x1D6C) 0x35E0 SharePoint Foundation Monitoring b4ly Medium Leaving Monitored Scope (Timer Job job-timer-locks). Execution Time=19.0309103531315 8c5f7d7d-5d52-4cea-8f99-c650b2344eb0 05/21/2013 10:39:39.34 w3wp.exe (0x3D04) 0x2EC0 SharePoint Foundation Monitoring b4ly High Leaving Monitored Scope (EnsureListItemsData). Execution Time=21025.8222762949 3048525d-5563-4133-96d7-8b2a1a577c94

    I added some logging to see what was happening with users that wasnt with System Account. All of the above is not present when system account loads the page.

    Tuesday, May 21, 2013 8:04 PM
  • Hello,

    Both are having performance issue if list is huge. I would suggest, use CAML query to get data from list and also use rowlimit and view fileds.

    http://dinooptech.blogspot.in/2012/11/retrieving-list-items-with-caml-query.html

    I am sure it will defiantly increase performance.


    Hemendra: "Yesterday is just a memory,Tomorrow we may never see"

    Whenever you see a reply and if you think is helpful, click "Alternate TextVote As Helpful"! And whenever you see a reply being an answer to the question of the thread, click "Alternate TextMark As Answer

    Please feel free to unmark answer if does not resolves your problem.

    Wednesday, May 22, 2013 10:48 AM
  • Both are not having performance issues. System Account is blazing fast even when 8000+ rows are returned.

    I am using CAML query with view fields to get the data. I cannot set a row limit because I need access to the last item, or at the very least the count of all rows, at all times.

    Edit:

    I just tried setting a row limit to see if it would help. Setting the row limit to 600 still took 10 seconds to render the page.

    Wednesday, May 22, 2013 2:41 PM
  • You could have a few issues, around security trimming and object caching (between different caching profiles). Also, what you're doing with the items after retrieving them could be causing issues.

    Have a look at this article (it's SharePoint 2007, but still relevant): http://msdn.microsoft.com/en-us/library/bb687949(v=office.12).aspx

    Have you tried wrapping your code in SPMonitoredScope blocks? This will help you narrow down where your performance issues are. See: http://msdn.microsoft.com/en-us/library/ff512758(v=office.14).aspx


    Regards, Matthew
    MCPD | MCITP
    My Blog
    Please remember to click "Mark As Answer" if a post solves your problem or "Vote As Helpful" if it was useful.

    I just added a webpart to the TechNet Gallery that allows administrative users to upload, crop and format user profile photos. Check it out here: Upload and Crop User Profile Photos

    Wednesday, May 22, 2013 3:21 PM
  • Matt your SPMonitoredScope tip was helpful for me since I didnt know about it, but did not give me any more information about this particular issue.

    I read through the article you linked and checked for any bad coding practices. So far I have found none.

    I just cant understand why System Account executed GetDataTable fast but any other user, even when permissions have been elevated, is extremely slow.

    Wednesday, May 22, 2013 4:37 PM