40 second logons. 100 second logons. 200 second logons.
Our users had an average logon time of 8-11 seconds. But some users were hitting 40-200 seconds. Users were frustrated and calling the help desk.
Why?
I did not want to individually examine all of the users whom had a long logon duration. There was dozens of dozens of users, but after sampling 5 of them, the root cause was consistent. Printers were causing long logons.
What I found was users were encountering the long logons on specific workstations. Further investigation revealed these workstations had globally mapped printers. Some workstations had dozens of printers. Some of the printers were long gone, having been moved/re-IP’ed, shutdown, or re-provisioned and the entry in the workstation not updated. Citrix, depending on Receiver version, attempts to do a check to validate the printer’s operation before mapping and this would wait for a network timeout (or a crash of Receiver). When I stopped the print spooler on the local workstation, logons came back down to the proper range.
What I sought to do was create something to make identifying this root cause easier, quicker, and with more specificity - in other words was there a particular printer causing the delay?
Citrix Printing Methods
Citrix has two methods of printing. “Direct connection” and local printing. Direct connection has the potential for larger impact on logon duration as it executes additional steps and actions on the Citrix server.
To enable “Direct Connection”, Citrix has a policy “Direct connection to print servers”. By default, this policy is enabled.
With this policy enabled, it changes the behavior of how Citrix connects printers you have mapped locally as network printers. Citrix has a diagram here:
But I feel this is missing temporal information. I’ve created a video to highlight the steps.
Why is this important?
Citrix has an option that is an absolute requirement for some applications.
“Wait for printers to be created (server desktop)” (Virtual Apps and Desktops 7.x) or “Start this application without waiting for printers to be created. (Unchecked)” (Citrix XenApp 6.5).
This policy needs to be enabled for numerous applications that require a specific printer is present before the application starts. This is usually due to applications that have pre-defined printers like label printers and do a check on app launch. If you have an application like that you probably have this feature enabled.
Citrix has many options for managing printers and they can impact your logon process.
Focusing on Direct Connection being enabled, if “Wait for printers to be created (server desktop)” policy is also enabled, care MUST be taken to minimize logon times.
Direct connection does something that can have a very adverse affect on logon time that is enabled by default. When it connects directly to the print server it will check and install the print driver on the Citrix server. The installation activity is visible via process monitor.
The installation of printer driver, by default, will only occur if the driver is inbox or prestaged on the Citrix server. But the check to see if a print driver needs to be installed occurs every time a session is created. This behavior can be changed by policy.
Why does this impact logon times? Driver installation can take a while, especially if there is communication issues between the Citrix server and print server. Or if the print server is under stress and just simply slow to respond. Or if the driver package that needs to be loaded is especially large, has lots of forms or page formats, multiple trays, etc. This all adds up.
How can I tell what the impact of printers might be on Logon Duration?
I’ve been working on updating a Script-Based Action (SBA) originally posted by Guy Leech on the Citrix blogs. This enhancement to the SBA will output more information breaking down what’s consuming your logon times. Specifically, this tackles how long printers take in the ControlUp column: “Logon Duration - Other”
I’ve created a video showing how to enable the additional logging and how to run the new Script Based Action and what the output looks like:
What’s new in the output?
For the individual printers, direct connection printers now show two lines, the Driver load time and Printer load/connection time.
The driver load time is titled with Driver and then the UNC path to the printer.
The Printer and UNC path shows the the actual connection, printer configuration and establishment time. All Direct Connection printers will be shown with UNC paths.
Citrix Universal Print Driver (UPD) mapped printers using the Citrix Universal Print Driver (print jobs that get sent back to the client for processing) are shown with their “Friendly Name” and do not have a matching “Driver” component as no driver loading is required. In the example output above, ”\printsrv\HP Color LaserJet 5550” is a direct connection printer and “Zebra R110Xi HF (300 dpi)” is a Citrix UPD printer.
Here is an example of the full output:
The “Connect to Printers” is a sub-phase under “Pre-Shell (Userinit)”. Each “Printer:” and “Driver:” is a sub-phase under “Connect to Printers”. In this example screenshot, “Pre-Shell (Userinit)” was consuming 117.6 seconds of a 133.2 second logon duration. Prior to this script that was all that was known. Now we can see that connecting to printers consumes 97.7 of those 117.6 seconds!
Awesome! What’s the catch?
In order to generate this information, some more verbose logging is required on the Citrix server side. I specifically worked to ensure that no 3rd party utilities would be required so we simply need to enable 4 additional features.
Command Line Audit
PrintServer/Operational Logs
Audit Process Creation/Termination
I’ve written a batch script to enable these features:
REM Enable Command Line Auditing
reg add "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\Policies\System\Audit" /v ProcessCreationIncludeCmdLine_Enabled /d 0x1
REM Enable Print Service logging, no retention, size 500MB
wevtutil sl Microsoft-Windows-PrintService/Operational /ms:524288000 /rt:false /ab:false /e
REM Enable Process Termination
Auditpol /set /subcategory:"Process Termination" /success:enable
REM Enable Process Creation
Auditpol /set /subcategory:"Process Creation" /success:enable
Easy!
Wait a minute! Windows Server 2008R2 doesn’t have Command Line Auditing!
Good catch! Windows Server 2008R2 doesn’t have command line auditing so it will miss the driver load information. There is no way around this using native tools, but modification could be done to use a 3rd party tool like sysmon. The output on a 2008R2 system would show the following (with all other features enabled).
Awesome! Let me at this script!
This script is available on the ControlUp site here. If you have ControlUp you can run simply add it via the “Script Based Actions” button and further derive more information on your users logon performance!
Last Gotcha
In some instances the “Connect to Printers phase” may start before “Pre-Shell”. This has been observed and is actually happening! The operating system is attempting to start *some* printer events asynchronously in certain situations and so the connect to Printers may start before userinit, but overall connecting to printers may still be blocking logons while it trys and completes.
Steve Elgan kindly pointed out that it’s important you size your event logs to ensure the data is present for the users whom you want to monitor. If your event logs are sized too small than the data being queried by the script won’t be present. So ensure you have your Security and the Printer event logs sized large enough to capture all of this data! For an idea of scale, you can look at your log size and the oldest entry there. If your log is 1MB in size and your oldest entry is from an hour ago, than sizing your log to 24MB should capture about a day’s worth of information.
Hope this helps you reduce your long logon durations!