Monitoring Active Directory Import for SharePoint 2013 User Profiles: Part 2

A while back, I wrote a post that covered the basics for monitoring the SharePoint 2013 Active Directory User Profile Import process.  The steps provided in that post provide summary results after a profile import has completed.  But what happens if you need to check the status of a running import?  Unfortunately, the information provided in Central Administration is a simple "synchronizing" status with no actual numbers.  This post will dig into the details that get logged to the ULS logs when a profile import is running.  It is assumed that logging has been configured as described in the previous post.

There are several key events to look for in the ULS logs.  I recommend using a tool like ULS Viewer to make it possible to open multiple logs in a single view and filter the results.

One of the first events you will see in the logs will have a message containing "Name=Timer Job<UPA name>_UserProfileADImportJob", where <UPA name> is the user profile application's name as you would see it in Central Administration.  Filter the logs based on the correlation ID associated with this entry.  Next, search for the entry that has a message containing "UserProfileADImportJob:ImportDC".  This log entry will provide information regarding several key parameters that set boundary controls for the import, namely filter size, batch size, and maximum errors.  If you are interested in the exact LDAP query that is being applied and/or the specific domain controller to which SharePoint has connected, you want to look for the entry containing "ScanDirSyncChanges".  You would use this information in a scenario where you are trying to isolate an issue caused by a specific domain controller (maybe one that is out of sync).

User profiles are queried in batches.  As each batch is queried, you will see an entry containing "SendCurrentBatch: Sending".  This message will be followed by the number of profiles that are included in that batch.  You can use this information to determine how many profiles have been imported and estimate the amount of time the synchronization will take.  In a scenario where you have thousands or millions of profiles, this is extremely helpful.  For example, if I filter my logs so that I see only those messages containing the "SendCurrentBatch: Sending" text, I can quickly determine an average batch size simply by scanning the entries.  Let's say that the average batch size is 1000 profiles.  My next step is to count the number of rows in my filtered view and multiple that by my average batch size.  So, if I have an average batch size of 1000 and my ULS logs contain 25 entries with "SendCurrentBatch: Sending", I can quickly estimate that 25,000 profiles have been processed.  If I know that my expected number of users to be imported is 100,000, I can determine that I am roughly one quarter of the way through the import process.

Another metric that can be gleaned from the ULS logs is an estimate of total synchronization time.  To do this, I look at the timestamps on the entries in my filtered set of results (ie - those containing "SendCurrentBatch: Sending").  I will most likely see a pattern where I am getting "x" number of query batches in an hour.  For sake of example, let's say I am averaging 3 batches an hour and each batch is roughly 1000 profiles.  That means I am processing 3,000 profiles per hour or 72,000 profiles per day.  At that rate, I can estimate that a full synchronization will take 1.4 days.

Hopefully I have provided some ideas on how to gain insight into your user profile synchronization processing.  Until next time, so long!