Measure user logon times with PowerShell

I recently had a client who was experiencing random slow logons on their Windows 7 systems.  These logons were taking anywhere up to (and sometimes in excess of) ten minutes, so naturally the user base was getting pretty irate.

The problem for the IT department is that these machines were almost exclusively public access machines, and when a user experienced the slow logon, rather than report the issue they tended to kick the machine and walk away.  The end result was that the IT guys really didn’t know where this problem was happening or how widespread it was.  Just to add insult to injury, a machine which exhibited the problem would then be fine afterwards, so they couldn’t reliably replicate the problem.

They had an open ticket with Microsoft, but without an accurate assessment of the extent of the problem, there wasn’t much Microsoft (or anyone else) could do.  I was brought in as a last resort (none taken) but again, without accurate information where do you even start?

The IT department were using WMI monitoring and reporting to pull back information from the entire fleet how long Group Policy was taking to process. This is a good approach, but it’s only part of the logon process – what the user really cares about is how long it takes to get from entering their username and password to when the desktop loads and is responsive.

So my approach is to try and get the most accurate information possible about how long it takes each user to log on – from the time they enter their credentials to the time that the desktop is actually usable.  Once you have accurate information, you can then assess how widespread the problem is, and which are the machines which are exhibiting the most issues.

I have to thank Chris Brown for giving me the idea for this approach, and ThePoSher for the WMI goodness.

Here’s the script I used:

$details1 =
Get-WmiObject Win32_NetworkLoginProfile |
    Sort -Descending LastLogon |
    Select * -First 1 |
    ? {$_.LastLogon -match "(d{14})"} |
 
            New-Object PSObject -Property @{
                Name=$_.Name ;
                LastLogon=[datetime]::ParseExact($matches[0], "yyyyMMddHHmmss", $null)
            }
        }
 
$details2 = Get-Date
 
$time = $details2.TimeOfDay.TotalSeconds - $details1.LastLogon.TimeOfDay.TotalSeconds 
 
$time | Out-File -Append c:templastuser.txt

More on the rationale behind that script in a moment.

I saved this script as userlastlogon.PS1 and saved it to Scripts in the SYSVOL folder of the domain.  I then created a .BAT file (old school, I know) called lastuser.bat which just calls one line:

indirystem32WindowsPowerShellv1.0powershell.exe europa.localSYSVOLeuropa.localscriptsuserlastlogon.ps1 (europa.local is my test domain)

Then I created a GPO which copies the .BAT file into C:ProgramDataMicrosoftWindowsStart MenuProgramsStartup which is basically the Startup folder for All Users:

PowerShell GPO

I also created another GPO which added *.europa.local and file://*.europa.local into the Intranet Zone in IE, to ensure that powershell.exe doesn’t bring up a warning when executing the .PS1 via UNC:

IE Settings

The result is that we now have a script which launches when the user’s desktop is up and running.  This may not be an accurate measure of when a user can be considered to be “logged on”, but from a user’s perspective it’s all they really care about (and what will form the basis of their complaints to the helpdesk).

Now, back to the script.  When the script runs it measures two times – the LastLogon time for the currently-logged-in user, based on the Win32_NetworkLoginProfile WMI class, and the time which the script actually ran which is grabbed via the Get-Date cmdlet.  Both times are then refined using TimeofDay.TotalSeconds, and the higher value is subtracted from the lower.  And you end up with the user’s logon time in seconds (or whatever time metric you choose).

In this example, the result outputs to a text file, but of course you can do pretty much anything – append the values to a CSV on a network share, write the results to the registry and extract them later, or (for a large environment) write the results as they happen out to a SQL database.  The last option is, of course, much more powerful for generating reports and realtime alerts.

Why the .BAT file? That’s simply because it relies on explorer.exe to run, and is going to be one of the last things to load when a user logs on.  The rationale is that if a .BAT file can run from the Startup folder, then the session is sufficiently interactive.

So yes, the script is a basic one, and the hard work was done by someone else (!) but I’m still happy with the result. It also produces a result every time a user logs on, and just keeps running until the IT admins have had enough.

I’d love to hear from any PowerShell or desktop experts who have ideas about how to refine this process to get even more accurate information. 🙂

 

12 comments to Measure user logon times with PowerShell

  • Nice work, James. Going to save this for future reference, no doubt I’ll need it! As I mentioned on Twitter, it would be interesting to see this with some central reporting or something, but I guess that’s a lot of effort to go to versus just grabbing the file from clientAc$temp. Still, a functional approach to a problem way too many of us experience and just avoid fixing!

  • Harvey

    Great write up! I’ve been reading your blogs about SCCM 2012 lately. I’m glad I found your site.

    3 comments or suggestions on this one:

    1) If you are *still* stuck supporting XP workstations, the site to zone mapping GPO setting will grey out and disable the ability to manually add trusted sites. I have also seen this behavior on Vista and Win 7, but not consistently. Anyway, a solution is to use GPO preferences to add trusted sites via the registry instead. There was a nice write up on doing this, but the domain expired 7/24… The reg entries are located at HKEY_CURRENT_USERSOFTWAREMicrosoftWindowsCurrentVersionInternet SettingsZone MapDomains. You’ll need to import the subkeys as well.

    2) You could also run your script as a GPO logon script rather than copy a shortcut to All Users > Startup.

    3) You could redirect the output of your powershell script and append it to a text file on a network share.

    • Chris Brown

      Hi Harvey,

      Some good points. The reason that James copies the shortcut to All Users > Startup is because this is (almost) the *last* thing run at logon, where as GPO scripts are run first. The “logon duration” therefore is calculated as a difference between “LastLogonTime” and the time that the batch file runs. If the script was in a group policy, it would run before the user is even presented with their desktop, thus defeating the purpose of this script.

  • Hey, great post! Thanks so much!

    Could you tell me how I would include the User ID? Sorry, to to PShell, more of a SQL guy.

    Any helpw oudl be greatly appreciated!

    Thanks

    John

  • Robbie

    I am getting spurious times logging some high negative values(-1000’s) and some high positive values(+1000’s)

    Does this work on Win 7 SP1 on 2008R2 domain?

  • Derek Cunniffe

    I get the same issues minus values and 1 second to log in times. I am looking at running a script that measures the time from a 528 user login envent until the GPO finishes writing to the GPO debug file userenv.log, this seems to give a more accurate time.

  • Shahzad

    Hello everyone,

    I was researching this and the other article from James to output to SQL Server. To keep things simple I’ve come up with following revised code, indeed credited to James and his associates with original idea. My modification results in clean output to a text file as following:

    ————————————
    Log on Date:Aug 15 2012
    Log on Workstation:myWorkstation
    Log on User:myWorkstationuseradmin
    Total time to log on:0:01:41

    Here is code for you all who were struggling just like me! 🙂 :

    ===============================================================
    #Get LastLogon details by querying WMI class
    $LoggedOnTime =
    Get-WmiObject Win32_NetworkLoginProfile |
    Sort -Descending LastLogon |
    Select * -First 1 |
    ? {$_.LastLogon -match “(d{14})”} |
    % {
    New-Object PSObject -Property @{
    Name=$_.Name ;
    LastLogon=[datetime]::ParseExact($matches[0], “yyyyMMddHHmmss”, $null)
    }
    }

    #Set Variables for SQL database storage
    $LogonDate = get-date -Format “MMM dd yyyy”
    $WorkstationName = Get-Content env:ComputerName
    $LoggedOnUser = $LoggedOnTime.Name

    #Generate elapsed time
    $CurrentTime = Get-Date
    $elapsedTime = New-TimeSpan $CurrentTime $LoggedOnTime.LastLogon
    $TimeToLogOn = ($elapsedTime -replace ‘.d+$’)

    #Examine if ‘-‘ is found at start of elapsed time, trim it.
    if ($TimeToLogOn.Contains(“-“))
    {
    $TimeToLogOn=$TimeToLogOn.Substring(2)

    }

    #Append details to text file LogOnDetails.txt
    Add-Content LogOnDetails.txt “`n————————————”
    Add-Content LogOnDetails.txt “Log on Date:$LogonDate”
    Add-Content LogOnDetails.txt “`nLog on Workstation:$WorkstationName”
    Add-Content LogOnDetails.txt “`nLog on User:$LoggedOnUser”
    Add-Content LogOnDetails.txt “`nTotal time to log on:$TimeToLogOn”

  • Schalk

    Or you can use the buildin PS feature, Measure-command, to time your script.

  • Sushain Kapoor

    Hi James

    Your script works good. But i am getting inconsistency in WMI last login time stamp. Any idea how i can rectify the same. Means I have restarted the system today but the last login time stamp is of April and even in other systems i checked it is random and not accurate what it should be. I have the same purpose of collecting the network logon time (added Ad upgrade). You have any clue for this ? how to rectify this ? Any alternate means of capturing the network logon time, if there is no remedy to inconsistent last login time stamps in WMI?

    Regards
    Sushain KApoor

  • Giovanni

    Hi James,
    script looks good, but I am getting Cannot index into a null array. when I run
    >> Get-WmiObject Win32_NetworkLoginProfile |
    >> Sort -Descending LastLogon |
    >> Select * -First 1 |
    >> ? {$_.LastLogon -match “(d{14})”} |
    >> New-Object PSObject -Property @{
    >> Name=$_.Name ;
    >> LastLogon=[datetime]::ParseExact($matches[0], “yyyyMMddHHmmss”, $null)
    >> }

    Any clues?
    Thanks

    • James

      Hi Giovanni – that error means that PowerShell is trying to perform an action against an array which has nothing in it. In your example, that’s the $matches array. How is that array being populated?

Leave a Reply to Shahzad Cancel reply

You can use these HTML tags

<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>