ControlUp – Dissecting Logon Times a step further (Printer loading) – Trentent Tye

We have applications that require printers be loaded before the application is started. This is usually because the application will check for a specific printer or default printer and if one is not set (because it hasn’t mapped into the session) then it’ll throw up a dialog or not start entirely.

So we have this value ‘unchecked’ for some applications:

Screen Shot 2016-08-31 at 12.12.08 AM

But how does this impact our logon times?

Well… Our organization just underwent a print server migration/upgrade where some print servers were decommissioned and don’t exist. But some users still have them or references to them on their end points. We do have policies that only map your default printer, but some users are on a policy to map ‘all’ printers they have on their system.

What’s the impact?

Waiting for printers before starting the application…

Without waiting for printers

16 Seconds? How is that so?

Well, it turns out waiting for printers and the subsystem components to support them add a fair amount of time, and then worse is network printers that don’t go anywhere anymore. I’ve seen these logons wait for connection before timing out, all the while the user sits there and waits. The script that comes with ControlUp for analyzing logons is good, but I wanted to know more on why some systems had long logon times and the only clue was Pre-Shell (userinit) taking up all the time. So I dug into the print logs and found a way to measure their impact.

Screen Shot 2016-08-31 at 12.32.05 AM

With my modified script we can clearly see waiting for the printers takes ~15.4s with a few printers over a few seconds and the rest at 0.5 seconds or so. One thing about this process is that mapping printers is synchronous. So when or if 1 stalls, the whole process gets stuck. All my printers were local except for the ‘Generic / Text Only’ which was a network printer where I powered off the server. It hung the longest at 5.9 seconds, but I’ve seen ‘non-existant’ network mapped printers hang for 150 seconds or so…

To facilitate finding the printers we need to pass the clientName to the server and the Print Service Logs need to be enabled.

You can enable the print service logs on server 2008R2 by executing the following:

REG ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Microsoft-Windows-PrintService/Operational" /V "Enabled" /T REG_DWORD /D 1 /F >NUL
REG ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Microsoft-Windows-PrintService/Operational" /V "MaxSize" /T REG_DWORD /D 20971520 /F >NUL
REG ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Microsoft-Windows-PrintService/Operational" /V "MaxSizeUpper" /T REG_DWORD /D 0 /F >NUL
WEVTUTIL SL Microsoft-Windows-PrintService/Operational /E:TRUE

REG ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Microsoft-Windows-PrintService/Operational" /V "Enabled" /T REG_DWORD /D 1 /F >NUL

REG ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Microsoft-Windows-PrintService/Operational" /V "MaxSize" /T REG_DWORD /D 20971520 /F >NUL

REG ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Microsoft-Windows-PrintService/Operational" /V "MaxSizeUpper" /T REG_DWORD /D 0 /F >NUL

WEVTUTIL SL Microsoft-Windows-PrintService/Operational /E:TRUE

The ControlUp arguments need to look like this now:

Screen Shot 2016-08-31 at 12.40.36 AM

Here is my updated script:

function Get-PsEvent {
    
    param (
        [String]$PhaseName,
        [String]$StartProvider,
        [String]$EndProvider,
        [String]$StartXPath,
        [String]$EndXPath,
        [int]$CUAddition
        )

        #$ErrorActionPreference = 'SilentlyContinue'

        try {
            $StartEvent = Get-WinEvent -MaxEvents 1 -ProviderName $StartProvider -FilterXPath $StartXPath -ErrorAction Stop
            if ($StartProvider -eq 'Microsoft-Windows-Security-Auditing' -and $EndProvider -eq 'Microsoft-Windows-Security-Auditing') {
                $EndEvent = Get-WinEvent -MaxEvents 1 -ProviderName $EndProvider -FilterXPath ("{0}{1}" -f $EndXPath,@"

and *[EventData[Data[@Name='ProcessId'] 
and (Data=`'$($StartEvent.Properties[4].Value)`')]] 
"@)

            }
            elseif ($CUAddition) {
                $EndEvent = $StartEvent
                $EndEvent = ($StartEvent.TimeCreated).AddSeconds($CUAddition)

            }

            else {
                $EndEvent = Get-WinEvent -MaxEvents 1 -ProviderName $EndProvider -FilterXPath $EndXPath
            }
       }

        catch {
            if ($PhaseName -ne 'Citrix Profile Mgmt') {
                if ($StartProvider -eq 'Microsoft-Windows-Security-Auditing' -or $EndProvider -eq 'Microsoft-Windows-Security-Auditing' ) {
                    "Could not find $PhaseName events (requires audit process tracking)"
                }
                else {
                    "Could not find $PhaseName events"
                }
                Return
            }
        }
        $EventInfo = @{}

        if ((($EndEvent).GetType()).Name -eq 'DateTime') {
            $Duration = New-TimeSpan -Start $StartEvent.TimeCreated -End $EndEvent
            $EventInfo.EndTime = $EndEvent
        }
        else {
            $Duration = New-TimeSpan -Start $StartEvent.TimeCreated -End $EndEvent.TimeCreated
            $EventInfo.EndTime = $EndEvent.TimeCreated 

        }

        $Script:EventProperties = $StartEvent.Properties

        $EventInfo.PhaseName = $PhaseName
        $EventInfo.StartTime = $StartEvent.TimeCreated

        $EventInfo.Duration = $Duration.TotalSeconds

        $PSObject = New-Object -TypeName PSObject -Property $EventInfo

        if ($EventInfo.Duration) {
            $Script:Output += $PSObject
        }
}

function Get-LogonDurationAnalysis {

param (
    [Parameter(Mandatory=$true)] 
    [String]$Username,
    [Parameter(Mandatory=$true)] 
    [String]$UserDomain,
    [Parameter(Mandatory=$true)] 
    [String]$clientName,
    [int]$CUDesktopLoadTime
    )

$ErrorActionPreference = 'SilentlyContinue'

$Script:Output = @()


try {

$LogonEvent = Get-WinEvent -MaxEvents 1 -ProviderName Microsoft-Windows-Security-Auditing -FilterXPath @"
*[System[(EventID='4624')]] 
and *[EventData[Data[@Name='TargetUserName'] 
and (Data=`"$UserName`")]] 
and *[EventData[Data[@Name='TargetDomainName'] 
and (Data=`"$UserDomain`")]] 
and *[EventData[Data[@Name='LogonType'] 
and (Data=`"2`" or Data=`"10`" or Data=`"11`")]]
and *[EventData[Data[@Name='ProcessName'] 
and (Data=`"C:\Windows\System32\winlogon.exe`")]]
"@ -ErrorAction Stop

}

catch {
Throw 'Could not find EventID 4624 (Successfully logged on event) in the Windows Security log.'
}

$Logon = New-Object -TypeName PSObject

Add-Member -InputObject $Logon -MemberType NoteProperty -Name LogonTime -Value $LogonEvent.TimeCreated
Add-Member -InputObject $Logon -MemberType NoteProperty -Name FormatTime -Value (Get-Date -Date $LogonEvent.TimeCreated -UFormat %r)
Add-Member -InputObject $Logon -MemberType NoteProperty -Name LogonID -Value ($LogonEvent.Properties[7]).Value
Add-Member -InputObject $Logon -MemberType NoteProperty -Name WinlogonPID -Value ($LogonEvent.Properties[16]).Value
Add-Member -InputObject $Logon -MemberType NoteProperty -Name UserSID -Value ($LogonEvent.Properties[4]).Value


$ISO8601Date = Get-Date -Date $Logon.LogonTime
$ISO8601Date = $ISO8601Date.ToUniversalTime()
$ISO8601Date = $ISO8601Date.ToString("s")





#test to see if cmd.exe was launched by Winlogon.exe instead of userinit.exe
if ($KB924034_fix = Get-WinEvent -MaxEvents 1 -ProviderName Microsoft-Windows-Security-Auditing -FilterXPath @"
*[System[(EventID='4688')]]
and *[EventData[Data[@Name='ProcessId'] 
and (Data=`'$($Logon.WinlogonPID)`')]] 
and *[EventData[Data[@Name='NewProcessName'] 
and (Data='C:\Windows\System32\cmd.exe')]] 
"@ -ErrorAction Stop) {
    #write-host "KB924034 tweak found.  Setting ID of this process as the parent of userinit.exe2"
    $UserinitXPath = @"
*[System[(EventID='4688')]]
and *[EventData[Data[@Name='ProcessId'] 
and (Data=`'$($KB924034_fix.Properties[4].Value)`')]] 
and *[EventData[Data[@Name='NewProcessName'] 
and (Data='C:\Windows\System32\userinit.exe')]] 
"@
    } else {
$UserinitXPath = @"
*[System[(EventID='4688')]]
and *[EventData[Data[@Name='ProcessId'] 
and (Data=`'$($Logon.WinlogonPID)`')]] 
and *[EventData[Data[@Name='NewProcessName'] 
and (Data='C:\Windows\System32\userinit.exe')]] 
"@
}






$NPStartXpath = @"
*[System[(EventID='4688')]]
and *[EventData[Data[@Name='ProcessId'] 
and (Data=`'$($Logon.WinlogonPID)`')]] 
and *[EventData[Data[@Name='NewProcessName'] 
and (Data='C:\Windows\System32\mpnotify.exe')]] 
"@

$NPEndXPath = @"
*[System[(EventID='4689')]] 
and *[EventData[Data[@Name='ProcessName'] 
and (Data=`"C:\Windows\System32\mpnotify.exe`")]] 
"@

$ProfStartXpath = @"
*[System[(EventID='10')
and TimeCreated[@SystemTime > '$ISO8601Date']]]
and *[EventData[Data and (Data='$UserName')]]
"@

$ProfEndXpath = @"
*[System[(EventID='1')
and  TimeCreated[@SystemTime&gt;='$ISO8601Date']]]
and *[System[Security[@UserID='$($Logon.UserSID)']]]
"@

$UserProfStartXPath = @"
*[System[(EventID='1')
and  TimeCreated[@SystemTime&gt;='$ISO8601Date']]]
and *[System[Security[@UserID='$($Logon.UserSID)']]]
"@

$UserProfEndXPath = @"
*[System[(EventID='2')
and  TimeCreated[@SystemTime&gt;='$ISO8601Date']]]
and *[System[Security[@UserID='$($Logon.UserSID)']]]
"@

$GPStartXPath = @"
*[System[(EventID='4001')
and  TimeCreated[@SystemTime&gt;='$ISO8601Date']]]
and *[EventData[Data[@Name='PrincipalSamName'] 
and (Data=`"$UserDomain\$UserName`")]] 
"@

$GPEndXPath = @"
*[System[(EventID='8001')]]
and *[EventData[Data[@Name='PrincipalSamName'] 
and (Data=`"$UserDomain\$UserName`")]] 
"@

$GPScriptStartXPath = @"
*[System[(EventID='4018')
and  TimeCreated[@SystemTime&gt;='$ISO8601Date']]]
and *[EventData[Data[@Name='PrincipalSamName'] 
and (Data=`"$UserDomain\$UserName`")]] 
and *[EventData[Data[@Name='ScriptType'] 
and (Data='1')]]
"@

$GPScriptEndXPath = @"
*[System[(EventID='5018')
and  TimeCreated[@SystemTime&gt;='$ISO8601Date']]]
and *[EventData[Data[@Name='PrincipalSamName'] 
and (Data=`"$UserDomain\$UserName`")]] 
and *[EventData[Data[@Name='ScriptType'] 
and (Data='1')]]
"@

$ShellXPath = @"
*[System[(EventID='4688')]] 
and *[EventData[Data[@Name='SubjectLogonId'] 
and (Data=`'$($Logon.LogonID)`')]] 
and *[EventData[Data[@Name='NewProcessName'] 
and (Data=`"C:\Program Files (x86)\Citrix\system32\icast.exe`" or Data=`"C:\Windows\explorer.exe`")]]
"@

$ExplorerXPath = @"
*[System[(EventID='4688')]] 
and *[EventData[Data[@Name='SubjectLogonId'] 
and (Data=`'$($Logon.LogonID)`')]] 
and *[EventData[Data[@Name='NewProcessName'] 
and (Data=`"C:\Windows\explorer.exe`")]]
"@




Get-PsEvent -PhaseName 'Network Providers' -StartProvider 'Microsoft-Windows-Security-Auditing' -EndProvider 'Microsoft-Windows-Security-Auditing' `
-StartXPath $NPStartXpath -EndXPath $NPEndXPath

if (Get-WinEvent -ListProvider 'Citrix Profile management') {

    Get-PsEvent -PhaseName 'Citrix Profile Mgmt' -StartProvider 'Citrix Profile management' -EndProvider 'Microsoft-Windows-User Profiles Service' `
    -StartXPath $ProfStartXpath -EndXPath $ProfEndXpath
}

Get-PsEvent -PhaseName 'User Profile' -StartProvider 'Microsoft-Windows-User Profiles Service' -EndProvider 'Microsoft-Windows-User Profiles Service' `
-StartXPath $UserProfStartXPath -EndXPath $UserProfEndXPath

Get-PsEvent -PhaseName 'Group Policy' -StartProvider 'Microsoft-Windows-GroupPolicy' -EndProvider 'Microsoft-Windows-GroupPolicy' `
-StartXPath $GPStartXPath -EndXPath $GPEndXPath

Get-PsEvent -PhaseName 'GP Scripts' -StartProvider 'Microsoft-Windows-GroupPolicy' -EndProvider 'Microsoft-Windows-GroupPolicy' `
-StartXPath $GPScriptStartXPath -EndXPath $GPScriptEndXPath

if ($Script:EventProperties[3].Value -eq $true) {
    if ($Script:Output[-1].PhaseName -eq 'GP Scripts') {
        $Script:Output[-1].PhaseName = 'GP Scripts (sync)'
    }
}
else {
    if ($Script:Output[-1].PhaseName -eq 'GP Scripts') {
        $Script:Output[-1].PhaseName = 'GP Scripts (async)'
    }
}


Get-PsEvent -PhaseName 'Pre-Shell (Userinit)' -StartProvider 'Microsoft-Windows-Security-Auditing' -EndProvider 'Microsoft-Windows-Security-Auditing' `
-StartXPath $UserinitXPath -EndXPath $ShellXPath


if ($CUDesktopLoadTime) {
Get-PsEvent -PhaseName 'Shell' -StartProvider 'Microsoft-Windows-Security-Auditing' -StartXPath $ExplorerXPath -CUAddition $CUDesktopLoadTime

}

if ($Script:Output[-1].PhaseName -eq 'Shell' -or $Script:Output[-1].PhaseName -eq 'Pre-Shell (Userinit)') {

$TotalDur = "{0:N1}" -f (New-TimeSpan -Start $Logon.LogonTime -End $Script:Output[-1].EndTime | Select-Object -ExpandProperty TotalSeconds) `
+ " seconds"
}

else
{

$TotalDur = 'N/A'

}

#############NEED NEW ARGUMENT: CLIENTNAME
###################### Find how long it took to load printers into the session
###################### This impacts logon when 'wait for printers before starting application' is set
###################### This will not find any printers if the 'wait' is not set because (odds are anyways)
###################### that no printer events will be generated before pre-shell ends.
if (-not($clientName -eq "0")) {
    if (-not(($script:output | where {$_.phaseName -eq "Pre-Shell (Userinit)"}).Duration -eq $null)) {
        $preShellEndTime = (($script:output | where {$_.phaseName -eq "Pre-Shell (Userinit)"}).EndTime)
        #set end search
        $endShellTime = $Logon.LogonTime + [timespan]::FromSeconds($preShellDuration)


        $PrinterSearchISO8601Date = $preShellEndTime
        $PrinterSearchISO8601Date = $PrinterSearchISO8601Date.ToUniversalTime()
        $PrinterSearchISO8601Date = $PrinterSearchISO8601Date.ToString("s")


        $PrinterStartXPath = @"
*[System[TimeCreated[@SystemTime&gt;='$ISO8601Date' 
and @SystemTime&lt;='$PrinterSearchISO8601Date']]]
"@

        $printerEvents = Get-WinEvent -ProviderName "Microsoft-Windows-PrintService" -FilterXPath $PrinterStartXPath | ?{$_.message -like "*$clientName*"} | sort -Property TimeCreated

        #get list of printers:
        $listOfPrinters = @()
        foreach ($printerEvent in $printerEvents) {
            if ($printerEvent.Id -eq "300") {
                $listOfPrinters += ($printerEvent.Message -split "Printer " -split " on " -split "\(from")[1]
            }
        }

        #printer total load time
        $EventInfo = @{}
        $Duration = New-TimeSpan -Start $printerEvents[0].TimeCreated -End $printerEvents[-1].TimeCreated
        $phaseName = "Pre-Shell Printer load time:"
        $EventInfo.PhaseName = $PhaseName
        $EventInfo.Duration = $Duration.TotalSeconds
        $EventInfo.EndTime = $printerEvents[-1].TimeCreated
        $EventInfo.StartTime = $printerEvents[0].TimeCreated

        $PSObject = New-Object -TypeName PSObject -Property $EventInfo

        if ($EventInfo.Duration) {
            $Script:Output += $PSObject
        }

        #get the timespan of each printer creation start event ("Settings for printer X") and end event ("Printer X on Y")
        $EventInfo = @{}
        foreach ($printerEvent in $printerEvents) {
            foreach ($printer in $listOfPrinters) {
            $phaseName = "Printer: $printer"
                if ($printerEvent.message -like "*$printer*" -and $printerEvent.Id -eq "306") {
                    $printerEventStart = $printerEvent.TimeCreated
                }
                if ($printerEvent.message -like "*$printer*" -and $printerEvent.Id -eq "300") {
                    $printerEventEnd = $printerEvent.TimeCreated
                    $Duration = New-TimeSpan -Start $printerEventStart -End $printerEventEnd
                    $EventInfo.PhaseName = $PhaseName
                    $EventInfo.Duration = $Duration.TotalSeconds
                    $EventInfo.EndTime = $printerEventEnd
                    $EventInfo.StartTime = $printerEventStart

                    $PSObject = New-Object -TypeName PSObject -Property $EventInfo

                    if ($EventInfo.Duration) {
                        $Script:Output += $PSObject
                    }
                }


            }
        }
    }
}
###################### Printer scan finished

$Script:Output = $Script:Output | Sort-Object StartTime

for($i=1;$i -le $Script:Output.length-1;$i++) {

    $Deltas = New-TimeSpan -Start $Script:Output[$i-1].EndTime -End $Script:Output[$i].StartTime
    $Script:Output[$i] | Add-Member -MemberType NoteProperty -Name TimeDelta -Value $Deltas -Force



}

$Deltas = New-TimeSpan -Start $Logon.LogonTime -End $Script:Output[0].StartTime
$Script:Output[0] | Add-Member -MemberType NoteProperty -Name TimeDelta -Value $Deltas -Force

Write-Host "User name:`t $UserName `
Logon Time:`t $($Logon.FormatTime) `
Logon Duration:`t $TotalDur"

$Format = @{Expression={$_.PhaseName};Label="Logon Phase"}, `
@{Expression={'{0:N1}' -f $_.Duration};Label="Duration (s)"}, `
@{Expression={'{0:hh:mm:ss.f}' -f $_.StartTime};Label="Start Time"}, `
@{Expression={'{0:hh:mm:ss.f}' -f $_.EndTime};Label="End Time"}, `
@{Expression={'{0:N1}' -f ($_.TimeDelta | Select-Object -ExpandProperty TotalSeconds)};Label="Interim Delay"}
$Script:Output | Format-Table $Format -AutoSize

Write-Host "Only synchronous scripts affect logon duration"


}

$args_fix = ($args[0] -split '\\')
Get-LogonDurationAnalysis -Username $args_fix[1] -UserDomain  $args_fix[0] -clientName $args[1] -CUDesktopLoadTime $args[2]

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

188

189

190

191

192

193

194

195

196

197

198

199

200

201

202

203

204

205

206

207

208

209

210

211

212

213

214

215

216

217

218

219

220

221

222

223

224

225

226

227

228

229

230

231

232

233

234

235

236

237

238

239

240

241

242

243

244

245

246

247

248

249

250

251

252

253

254

255

256

257

258

259

260

261

262

263

264

265

266

267

268

269

270

271

272

273

274

275

276

277

278

279

280

281

282

283

284

285

286

287

288

289

290

291

292

293

294

295

296

297

298

299

300

301

302

303

304

305

306

307

308

309

310

311

312

313

314

315

316

317

318

319

320

321

322

323

324

325

326

327

328

329

330

331

332

333

334

335

336

337

338

339

340

341

342

343

344

345

346

347

348

349

350

351

352

353

354

355

356

357

358

359

360

361

362

363

364

365

366

367

368

369

370

371

372

373

374

375

376

377

378

379

380

381

382

383

384

385

386

387

388

389

390

391

392

393

394

395

396

397

398

399

400

401

402

403

404

405

function Get-PsEvent {

param (

[String]$PhaseName,

[String]$StartProvider,

[String]$EndProvider,

[String]$StartXPath,

[String]$EndXPath,

[int]$CUAddition

)

#$ErrorActionPreference = 'SilentlyContinue'

try {

$StartEvent = Get-WinEvent -MaxEvents 1 -ProviderName $StartProvider -FilterXPath $StartXPath -ErrorAction Stop

if ($StartProvider -eq 'Microsoft-Windows-Security-Auditing' -and $EndProvider -eq 'Microsoft-Windows-Security-Auditing') {

$EndEvent = Get-WinEvent -MaxEvents 1 -ProviderName $EndProvider -FilterXPath ("{0}{1}" -f $EndXPath,@"

and *[EventData[Data[@Name='ProcessId']

and (Data=`'$($StartEvent.Properties[4].Value)`')]]

"@)

}

elseif ($CUAddition) {

$EndEvent = $StartEvent

$EndEvent = ($StartEvent.TimeCreated).AddSeconds($CUAddition)

}

else {

$EndEvent = Get-WinEvent -MaxEvents 1 -ProviderName $EndProvider -FilterXPath $EndXPath

}

catch {

if ($PhaseName -ne 'Citrix Profile Mgmt') {

if ($StartProvider -eq 'Microsoft-Windows-Security-Auditing' -or $EndProvider -eq 'Microsoft-Windows-Security-Auditing' ) {

"Could not find $PhaseName events (requires audit process tracking)"

}

else {

"Could not find $PhaseName events"

}

Return

}

$EventInfo = @{}

if ((($EndEvent).GetType()).Name -eq 'DateTime') {

$Duration = New-TimeSpan -Start $StartEvent.TimeCreated -End $EndEvent

$EventInfo.EndTime = $EndEvent

}

else {

$Duration = New-TimeSpan -Start $StartEvent.TimeCreated -End $EndEvent.TimeCreated

$EventInfo.EndTime = $EndEvent.TimeCreated

}

$Script:EventProperties = $StartEvent.Properties

$EventInfo.PhaseName = $PhaseName

$EventInfo.StartTime = $StartEvent.TimeCreated

$EventInfo.Duration = $Duration.TotalSeconds

$PSObject = New-Object -TypeName PSObject -Property $EventInfo

if ($EventInfo.Duration) {

$Script:Output += $PSObject

}

function Get-LogonDurationAnalysis {

param (

[Parameter(Mandatory=$true)]

[String]$Username,

[Parameter(Mandatory=$true)]

[String]$UserDomain,

[Parameter(Mandatory=$true)]

[String]$clientName,

[int]$CUDesktopLoadTime

)

$ErrorActionPreference = 'SilentlyContinue'

$Script:Output = @()

try {

$LogonEvent = Get-WinEvent -MaxEvents 1 -ProviderName Microsoft-Windows-Security-Auditing -FilterXPath @"

*[System[(EventID='4624')]]

and *[EventData[Data[@Name='TargetUserName']

and (Data=`"$UserName`")]]

and *[EventData[Data[@Name='TargetDomainName']

and (Data=`"$UserDomain`")]]

and *[EventData[Data[@Name='LogonType']

and (Data=`"2`" or Data=`"10`" or Data=`"11`")]]

and *[EventData[Data[@Name='ProcessName']

and (Data=`"C:\Windows\System32\winlogon.exe`")]]

"@ -ErrorAction Stop

}

catch {

Throw 'Could not find EventID 4624 (Successfully logged on event) in the Windows Security log.'

}

$Logon = New-Object -TypeName PSObject

Add-Member -InputObject $Logon -MemberType NoteProperty -Name LogonTime -Value $LogonEvent.TimeCreated

Add-Member -InputObject $Logon -MemberType NoteProperty -Name FormatTime -Value (Get-Date -Date $LogonEvent.TimeCreated -UFormat %r)

Add-Member -InputObject $Logon -MemberType NoteProperty -Name LogonID -Value ($LogonEvent.Properties[7]).Value

Add-Member -InputObject $Logon -MemberType NoteProperty -Name WinlogonPID -Value ($LogonEvent.Properties[16]).Value

Add-Member -InputObject $Logon -MemberType NoteProperty -Name UserSID -Value ($LogonEvent.Properties[4]).Value

$ISO8601Date = Get-Date -Date $Logon.LogonTime

$ISO8601Date = $ISO8601Date.ToUniversalTime()

$ISO8601Date = $ISO8601Date.ToString("s")

#test to see if cmd.exe was launched by Winlogon.exe instead of userinit.exe

if ($KB924034_fix = Get-WinEvent -MaxEvents 1 -ProviderName Microsoft-Windows-Security-Auditing -FilterXPath @"

*[System[(EventID='4688')]]

and *[EventData[Data[@Name='ProcessId']

and (Data=`'$($Logon.WinlogonPID)`')]]

and *[EventData[Data[@Name='NewProcessName']

and (Data='C:\Windows\System32\cmd.exe')]]

"@ -ErrorAction Stop) {

#write-host "KB924034 tweak found. Setting ID of this process as the parent of userinit.exe2"

$UserinitXPath = @"

*[System[(EventID='4688')]]

and *[EventData[Data[@Name='ProcessId']

and (Data=`'$($KB924034_fix.Properties[4].Value)`')]]

and *[EventData[Data[@Name='NewProcessName']

and (Data='C:\Windows\System32\userinit.exe')]]

} else {

$UserinitXPath = @"

*[System[(EventID='4688')]]

and *[EventData[Data[@Name='ProcessId']

and (Data=`'$($Logon.WinlogonPID)`')]]

and *[EventData[Data[@Name='NewProcessName']

and (Data='C:\Windows\System32\userinit.exe')]]

}

$NPStartXpath = @"

*[System[(EventID='4688')]]

and *[EventData[Data[@Name='ProcessId']

and (Data=`'$($Logon.WinlogonPID)`')]]

and *[EventData[Data[@Name='NewProcessName']

and (Data='C:\Windows\System32\mpnotify.exe')]]

$NPEndXPath = @"

*[System[(EventID='4689')]]

and *[EventData[Data[@Name='ProcessName']

and (Data=`"C:\Windows\System32\mpnotify.exe`")]]

$ProfStartXpath = @"

*[System[(EventID='10')

and TimeCreated[@SystemTime > '$ISO8601Date']]]

and *[EventData[Data and (Data='$UserName')]]

$ProfEndXpath = @"

*[System[(EventID='1')

and TimeCreated[@SystemTime>='$ISO8601Date']]]

and *[System[Security[@UserID='$($Logon.UserSID)']]]

$UserProfStartXPath = @"

*[System[(EventID='1')

and TimeCreated[@SystemTime>='$ISO8601Date']]]

and *[System[Security[@UserID='$($Logon.UserSID)']]]

$UserProfEndXPath = @"

*[System[(EventID='2')

and TimeCreated[@SystemTime>='$ISO8601Date']]]

and *[System[Security[@UserID='$($Logon.UserSID)']]]

$GPStartXPath = @"

*[System[(EventID='4001')

and TimeCreated[@SystemTime>='$ISO8601Date']]]

and *[EventData[Data[@Name='PrincipalSamName']

and (Data=`"$UserDomain\$UserName`")]]

$GPEndXPath = @"

*[System[(EventID='8001')]]

and *[EventData[Data[@Name='PrincipalSamName']

and (Data=`"$UserDomain\$UserName`")]]

$GPScriptStartXPath = @"

*[System[(EventID='4018')

and TimeCreated[@SystemTime>='$ISO8601Date']]]

and *[EventData[Data[@Name='PrincipalSamName']

and (Data=`"$UserDomain\$UserName`")]]

and *[EventData[Data[@Name='ScriptType']

and (Data='1')]]

$GPScriptEndXPath = @"

*[System[(EventID='5018')

and TimeCreated[@SystemTime>='$ISO8601Date']]]

and *[EventData[Data[@Name='PrincipalSamName']

and (Data=`"$UserDomain\$UserName`")]]

and *[EventData[Data[@Name='ScriptType']

and (Data='1')]]

$ShellXPath = @"

*[System[(EventID='4688')]]

and *[EventData[Data[@Name='SubjectLogonId']

and (Data=`'$($Logon.LogonID)`')]]

and *[EventData[Data[@Name='NewProcessName']

and (Data=`"C:\Program Files (x86)\Citrix\system32\icast.exe`" or Data=`"C:\Windows\explorer.exe`")]]

$ExplorerXPath = @"

*[System[(EventID='4688')]]

and *[EventData[Data[@Name='SubjectLogonId']

and (Data=`'$($Logon.LogonID)`')]]

and *[EventData[Data[@Name='NewProcessName']

and (Data=`"C:\Windows\explorer.exe`")]]

Get-PsEvent -PhaseName 'Network Providers' -StartProvider 'Microsoft-Windows-Security-Auditing' -EndProvider 'Microsoft-Windows-Security-Auditing' `

-StartXPath $NPStartXpath -EndXPath $NPEndXPath

if (Get-WinEvent -ListProvider 'Citrix Profile management') {

Get-PsEvent -PhaseName 'Citrix Profile Mgmt' -StartProvider 'Citrix Profile management' -EndProvider 'Microsoft-Windows-User Profiles Service' `

-StartXPath $ProfStartXpath -EndXPath $ProfEndXpath

}

Get-PsEvent -PhaseName 'User Profile' -StartProvider 'Microsoft-Windows-User Profiles Service' -EndProvider 'Microsoft-Windows-User Profiles Service' `

-StartXPath $UserProfStartXPath -EndXPath $UserProfEndXPath

Get-PsEvent -PhaseName 'Group Policy' -StartProvider 'Microsoft-Windows-GroupPolicy' -EndProvider 'Microsoft-Windows-GroupPolicy' `

-StartXPath $GPStartXPath -EndXPath $GPEndXPath

Get-PsEvent -PhaseName 'GP Scripts' -StartProvider 'Microsoft-Windows-GroupPolicy' -EndProvider 'Microsoft-Windows-GroupPolicy' `

-StartXPath $GPScriptStartXPath -EndXPath $GPScriptEndXPath

if ($Script:EventProperties[3].Value -eq $true) {

if ($Script:Output[-1].PhaseName -eq 'GP Scripts') {

$Script:Output[-1].PhaseName = 'GP Scripts (sync)'

}

else {

if ($Script:Output[-1].PhaseName -eq 'GP Scripts') {

$Script:Output[-1].PhaseName = 'GP Scripts (async)'

}

Get-PsEvent -PhaseName 'Pre-Shell (Userinit)' -StartProvider 'Microsoft-Windows-Security-Auditing' -EndProvider 'Microsoft-Windows-Security-Auditing' `

-StartXPath $UserinitXPath -EndXPath $ShellXPath

if ($CUDesktopLoadTime) {

Get-PsEvent -PhaseName 'Shell' -StartProvider 'Microsoft-Windows-Security-Auditing' -StartXPath $ExplorerXPath -CUAddition $CUDesktopLoadTime

}

if ($Script:Output[-1].PhaseName -eq 'Shell' -or $Script:Output[-1].PhaseName -eq 'Pre-Shell (Userinit)') {

$TotalDur = "{0:N1}" -f (New-TimeSpan -Start $Logon.LogonTime -End $Script:Output[-1].EndTime | Select-Object -ExpandProperty TotalSeconds) `

+ " seconds"

}

else

{

$TotalDur = 'N/A'

}

#############NEED NEW ARGUMENT: CLIENTNAME

###################### Find how long it took to load printers into the session

###################### This impacts logon when 'wait for printers before starting application' is set

###################### This will not find any printers if the 'wait' is not set because (odds are anyways)

###################### that no printer events will be generated before pre-shell ends.

if (-not($clientName -eq "0")) {

if (-not(($script:output | where {$_.phaseName -eq "Pre-Shell (Userinit)"}).Duration -eq $null)) {

$preShellEndTime = (($script:output | where {$_.phaseName -eq "Pre-Shell (Userinit)"}).EndTime)

#set end search

$endShellTime = $Logon.LogonTime + [timespan]::FromSeconds($preShellDuration)

$PrinterSearchISO8601Date = $preShellEndTime

$PrinterSearchISO8601Date = $PrinterSearchISO8601Date.ToUniversalTime()

$PrinterSearchISO8601Date = $PrinterSearchISO8601Date.ToString("s")

$PrinterStartXPath = @"

*[System[TimeCreated[@SystemTime>='$ISO8601Date'

and @SystemTime<='$PrinterSearchISO8601Date']]]

$printerEvents = Get-WinEvent -ProviderName "Microsoft-Windows-PrintService" -FilterXPath $PrinterStartXPath | ?{$_.message -like "*$clientName*"} | sort -Property TimeCreated

#get list of printers:

$listOfPrinters = @()

foreach ($printerEvent in $printerEvents) {

if ($printerEvent.Id -eq "300") {

$listOfPrinters += ($printerEvent.Message -split "Printer " -split " on " -split "\(from")[1]

}

#printer total load time

$EventInfo = @{}

$Duration = New-TimeSpan -Start $printerEvents[0].TimeCreated -End $printerEvents[-1].TimeCreated

$phaseName = "Pre-Shell Printer load time:"

$EventInfo.PhaseName = $PhaseName

$EventInfo.Duration = $Duration.TotalSeconds

$EventInfo.EndTime = $printerEvents[-1].TimeCreated

$EventInfo.StartTime = $printerEvents[0].TimeCreated

$PSObject = New-Object -TypeName PSObject -Property $EventInfo

if ($EventInfo.Duration) {

$Script:Output += $PSObject

}

#get the timespan of each printer creation start event ("Settings for printer X") and end event ("Printer X on Y")

$EventInfo = @{}

foreach ($printerEvent in $printerEvents) {

foreach ($printer in $listOfPrinters) {

$phaseName = "Printer: $printer"

if ($printerEvent.message -like "*$printer*" -and $printerEvent.Id -eq "306") {

$printerEventStart = $printerEvent.TimeCreated

}

if ($printerEvent.message -like "*$printer*" -and $printerEvent.Id -eq "300") {

$printerEventEnd = $printerEvent.TimeCreated

$Duration = New-TimeSpan -Start $printerEventStart -End $printerEventEnd

$EventInfo.PhaseName = $PhaseName

$EventInfo.Duration = $Duration.TotalSeconds

$EventInfo.EndTime = $printerEventEnd

$EventInfo.StartTime = $printerEventStart

$PSObject = New-Object -TypeName PSObject -Property $EventInfo

if ($EventInfo.Duration) {

$Script:Output += $PSObject

}

###################### Printer scan finished

$Script:Output = $Script:Output | Sort-Object StartTime

for($i=1;$i -le $Script:Output.length-1;$i++) {

$Deltas = New-TimeSpan -Start $Script:Output[$i-1].EndTime -End $Script:Output[$i].StartTime

$Script:Output[$i] | Add-Member -MemberType NoteProperty -Name TimeDelta -Value $Deltas -Force

}

$Deltas = New-TimeSpan -Start $Logon.LogonTime -End $Script:Output[0].StartTime

$Script:Output[0] | Add-Member -MemberType NoteProperty -Name TimeDelta -Value $Deltas -Force

Write-Host "User name:`t $UserName `

Logon Time:`t $($Logon.FormatTime) `

Logon Duration:`t $TotalDur"

$Format = @{Expression={$_.PhaseName};Label="Logon Phase"}, `

@{Expression={'{0:N1}' -f $_.Duration};Label="Duration (s)"}, `

@{Expression={'{0:hh:mm:ss.f}' -f $_.StartTime};Label="Start Time"}, `

@{Expression={'{0:hh:mm:ss.f}' -f $_.EndTime};Label="End Time"}, `

@{Expression={'{0:N1}' -f ($_.TimeDelta | Select-Object -ExpandProperty TotalSeconds)};Label="Interim Delay"}

$Script:Output | Format-Table $Format -AutoSize

Write-Host "Only synchronous scripts affect logon duration"

}

$args_fix = ($args[0] -split '\\')

Get-LogonDurationAnalysis -Username $args_fix[1] -UserDomain $args_fix[0] -clientName $args[1] -CUDesktopLoadTime $args[2]

I hope to dig into other startup components and further drill down into what our user launch process looks like. We wait, and we see 🙂

2 Comments

MIchael 2017-01-04 5:08 am

Hello!

Unfortunately there are no printer listed in my output and I don”t know for what reason:-)

Windows 2008 R2
XenApp 6.5
Published Application: Waiting for Printer
There are entrys with id 300 in the eventlog

Any idea?

MIchael
- trententtye 2017-01-04 9:53 am
  
  Hi Michael,
  
  1) You need to add a variable for the ClientName. If you don’t have that it won’t show any results.
  2) The script looks for two message id’s. 300 and 306. 300 is when it starts mapping printers, 306 is when it completes.
  3) If the sessions finish loading before the printers are finished mapping then they won’t show.

ControlUp – Dissecting Logon Times a step further (Printer loading)

ControlUp – Dissecting Logon Times a step further (Printer loading)

2 Comments

Post a Comment Cancel reply