ULS, SharePoint Foundation Monitoring High Leaving Monitored Scope (EnsureListItemsData). Execution Time=XXX

Ever wondered what this message meant in ULS?

First of all, there is a public SPMonitoredScope class that allows us to discover  performance bottlenecks.
One of the implementations of this method looks like following:
public SPMonitoredScope(string name, uint maximumExecutionTime, params ISPScopedPerformanceMonitor[] monitors)

If maximumExecutionTime parameter is set to 250, a debug message will be written to ULS when a certain piece of code runs more than 250 milliseconds.


When SPList.GetItems method is executed you don't immediately get data from DataBase because this method is differed until the actual data is requested somewhere. So, when you try to debug performance bottlenecks you might find that this method executes pretty fast. However, when, later you try to request SPListItemCollection the internal EnsureListItemsData method is run. This exact method will ensure that the actual data is retrieved. This is where it might take quite some time to get your List items. Let's see at the internal implementation of the EnsureListItemsData method:

        protected void EnsureListItemsData()
        {      
                using (new SPMonitoredScope("EnsureListItemsData", 250, new ISPScopedPerformanceMonitor[] { new SPSqlQueryCounter(1) }))
                {
                   // Code that fetches data from the Database
                }
        }

As you can see, maximumExecutionTime parameter is set to 250 milliseconds.When the process of getting List data from SPList gets longer that this time you will see this message:

ULS, SharePoint Foundation Monitoring  High Leaving Monitored Scope (EnsureListItemsData). Execution Time=XXX

I hope it sheds some light on this mysterious ULS message.