Today I had a rather unpleasant experience with my FIM setup. I had to do an update for one specific attribute for approximately 4000 objects in the portal. The FIM Synchronization Service did its magic stuff and was ready to start the exports. When I started the export I saw the fist 100-200 objects being exported rather fast, but then the export was painfully slow. I know the FIM Service MA is the slowest child in the FIM MA family, but past exports (updates to attributes) had been way faster. To be precise, I had now exported 700 updates in approximately 15 minutes.

Again, with my partner in crime Jeroen, we started investigating the SQL side of stuff. Below is how we got to the root cause using SQL Server Profiler:

To start the SQL Server Profiler: Start –> All Programs –> SQL 2008 –> Performance Tools –> SQL Server Profiler
To start a new trace: File –> New Trace
Connect to SQL Server hosting the FIM Service database
The first tab of the trace is less important, however on the second tab we select the following options:

• Show all events
• Check TextData for RPC:Completed
• Check SP:Completed
• Check Showplan XML (below the Performance section)

It should look like this:

And the showplan xml below performance:

Click Run and you’re set to go! If you want you can toggle the live scrolling. Using ctrl-f (find) you can search for a string which is very likely to show up in the actual query. Because we selected textdata in the event selection of the trace, we can actually search the content of the queries! So in my case I searched for “title” as I was updating the “job title” attribute.

Besides the actual query, what’s import here is the duration column. It’s expressed in milliseconds, and I was seeing values of 5000 and going up badly. So basically it took SQL 5 seconds to toggle an attribute from string a to string b. Now that’s a SQL which is really tired or being fed with poor queries. The screenshot shows a value of 999 which means less than 1 second. This is how it was when I fixed the situation. Now that we have the query, we can start examining which part of the query is bullying the SQL service by viewing the showplan above the query (the first showplan you come by above the query). Select it, where the query was displayed seconds ago, we now have a graphical overview which gives an estimation of several steps in the query:

Dixit my colleague, there are steps like tablescan (very bad if the table is big) or sorts, where you can’t do much optimization from our point of view. However the other operations in this query, which cost quit some CPU time according to the estimates, are index seeks. In the above screenshot I highlighted the indexes being accessed. They belong to the objectvalueidentifier table and the objectvaluereference table. Using the SQL management studio you can look them up, the database:

The table with the Indexes below:

To see the actual fragmentation there are some options: you can click the indexes one by one, choose properties and check the fragmentation tab or you can click rebuild all and see the current state for all indexes at once:

This is how it looks after the rebuild. Before the rebuild I had one index which had 16% fragmentation. It’s very likely that this index was slowing the SQL down.

The alternative way of viewing the fragmentation:

And of course real men use a query. Well I don’t have it… yet

After performing a rebuild and continuing the export profile, I got about 1000 updates in 5 minutes. So there was really a big difference there. What did I learn? Oh so cool SQL troubleshooting, again And besides that: database management is really not to be ignored when you are working with FIM. I actually had rebuilt the indexes two days ago, but when you’re changing data frequently, I guess it’s advised to monitor the fragmentation even closer.

Again, thanks Jeroen for sharing your knowledge and providing me a solution for my problem.

Thomas, I’ll bing for that query asap, Vuylsteke