Becoming An Xperf Xpert: Part 5 Gaps of Time For Explorer.exe

Hey y’all, Mark here with another quick real world WDRAP (Windows Desktop Risk Assessment Program) post. This one also involves a time issue which seems to be a theme around here as of late. Also I’ve already had some customers contact their TAM to get a PFE on site based on these posts which is great that means people are actually reading them. Who knew! Make sure you get yours soon don’t delay! (Queue the car salesman music) Kidding but seriously you really probably should.

We took our initial trace and we were greeted by this monster.

Hi!

What in the world is going on here? As we know from other posts that this is not normal to have a gap like that. Explorer should start right after Winlogon finishes. We have a nice 23 to 25 second about gap here. Did the explorer process get into a DeLorean, do 88 MPH, travel 24 seconds into the future to meet us at this point? Where did this time just disappear to? Well the customer was not buying my DeLorean story. Besides you can’t just go buy plutonium anywhere! So we had to dig in to this.

First we use our clone selection to highlight that section of time. We then use the “Zoom To Selection” to update all our graphs to that time range only. The Services pane was quiet so the next logical spot to check to see if any processes are running for this amount of time. We go to the Processes Pane, right click, select view, to select our entire area and then right click select process summary table. We can tell that we are zoomed in the below picture as the time axis is much more granular than normal.

Now we are back to our familiar view we used in the past but we are only looking at processes that are running during this time frame. They could have started earlier in the boot process or started sometime during this time span. Now don’t forget we can drag all those columns around up top to get the data to what is interesting to you. We will want to drag the Duration column all the way to the left and sort by that. For this example we are looking to see if anything fits our duration of 23 to 25 seconds sure enough we do.

Well we went from not having any clue to what was going on to a list of 4 suspects in a few clicks. That’s pretty good. The suspects are a command prompt, Conhost, slstart and something called wKiX32.exe. This is heavy Doc. Well conhost is normal so it’s probably not that but it could be. I like to check the more obvious stuff first. We can also see that wKiX32.exe parent process is 3,628. This is also the Process ID for one of our suspects, SLstart.exe. Getting warmer I bet. That turns out to be Script Logic. We disabled that service for testing purposes and low and behold our gap was gone! Now the customer had some concrete evidence what was causing the delay and can start to remediate with that vendor in their environment. Until next time….