User Profile Manager - Unavoidable Delays

30 Jun 2018

https://twitter.com/TrententTye/status/1011396648688185344

I’ve been exploring optimizing logon times and noticed “User Profile Service” always showed up for 1-3 seconds. I asked why and began my investigation.

The first thing I needed to do is separate the “User Profile Service” into it’s own process. It’s originally configured to share the same process as other services which makes procmon’ing difficult.

Making this change is easy:

Now that the User Profile Service is running in it’s own process we can use Process Monitor to target that PID.

I logged onto the RDS server with a different account and started my procmon trace. I then logged into server:

One of the beautiful things about a video like this is we can start to go through frame-by-frame if needed to observe the exact events that are occurring. Process Monitor also gives us a good overview of what’s happening with the “Process Activity” view:

9,445 file events, 299,668 registry events. Registry, by far, has the most events occurring on it. And so we investigate:

Setting the initial permissions of the user hive began at 2:14:46.3208182 and finished at 2:14:46.4414112. Spanning a total time of 121 milliseconds. Pretty quick but to minimize logon duration it’s worth examining each key in the Default User hive and ensuring you do not have any unnecessary keys. Each of these keys will have their permissions evaluated and modified.

The user profile server now goes through each “ProfileNotification” and, if it’s applicable, executes whatever action the module is responsible for. In my screenshot we can see the User Profile Service alerts the “WSE”. Each key actually contains the friendly name, giving you a hint about its role:

It also appears we can measure the duration of each module by the “RegOpenKey” and “RegCloseKey” events tied to that module.

In my procmon log, the WSE took 512ms, the next module “WinBio” took 1ms, etc. The big time munchers for my system were:

WSE: 512ms
SyncCenter: 260ms
SHACCT: 14ms
SettingProfileHandler: 4ms
GPSvc: 59ms
GamesUX: 60ms
DefaultAssociationsProfileHandler: 4450ms (!)

However, does this need to be *blocking* the login process? Probably not. This could be an option to be run asynchronously with you, as the admin, gambling that any required associations will be set before the user gets the desktop/app… Or if you have applications that are entirely single purpose that simply read and write to a database somewhere than this is superfluous.

But I’m on the fence if this is a good idea. To disable it, I’ve found deleting the “DefaultAssociationsProfileHandler” does work, associations are skipped and we logon 1-4 seconds faster. However, launching a file directly or shortcut with a url handler will prompt you to choose your default program (as should be expected).

I’m exploring this idea. Deleting the key entirely and using SetUserFTA to set associations.

We have ~400 App-V applications that write/overwrite approximately 800 different registered applications and file extensions into our registry hive (we publish globally - this puts them there). This is the reason why I started this investigation is some of our servers with lots of AppV applications were reporting longer UserProfileService times and tying it all together, this one module in the User Profile Service appears to be the culprit. And with Spectre increasing the duration of registry operations 400% this became noticeable real quick in our testing.

Lastly, time is still being consumed on RDS and server platforms by the infuriating garbage services like GamesUX (“Games Explorer”). It just tweaks a nerve a little bit when I see time being consumed on wasteful processes.