CDF Traces: Analyzing Process Launch Sequence

Citrix CDF traces are based on ETW (Event Tracing for Windows) and therefore Citrix customers, their support personnel and developers can use MS TraceView tool for troubleshooting Citrix terminal service environments:

Viewing Common Diagnostics Facility (CDF) Traces Using TraceView

In cases with slow logon or slow process startup we can analyze process launch sequence to determine delays. In the output trace we can filter tzhook module messages which also contain session id (this is quite handy to differentiate between different sessions), for example: 

PID      TID      TIME          MESSAGE     
21864    21912    06:34:53.598  tzhook: Attach on process - cmd.exe session=51         
21620    20372    06:34:59.754  tzhook: Attach on process - acregl.exe session=51         
18668    21240    06:35:02.704  tzhook: Attach on process - cmstart.exe session=51         
18560    18832    06:35:02.735  tzhook: Attach on process - wfshell.exe session=51         
18204    20060    06:35:06.575  tzhook: Attach on process - icast.exe session=51         
20640    21104    06:35:07.717  tzhook: Attach on process - LOGON.EXE session=51         
21188    21032    06:35:07.938  tzhook: Attach on process - cscript.exe session=51         
21888    19592    06:35:11.157  tzhook: Attach on process - WScript.exe session=51         
20600    20732    06:35:11.780  tzhook: Attach on process - admin.exe session=51         
17976    20456    06:35:18.752  tzhook: Attach on process - winlogon.exe session=53         
21332    13156    06:35:51.625  tzhook: Attach on process - mpnotify.exe session=53         
10988    10732    06:35:57.043  tzhook: Attach on process - rundll32.exe session=53

Here is another process launch sequence for published Notepad application:

PID     TID     TIME            MESSAGE
15828   18720   15:34:02.637    tzhook: Attach on process - winlogon.exe session=2 
5300    18508   15:34:03.043    tzhook: Attach on process - mpnotify.exe session=2 
17948   19300   15:34:03.356    tzhook: Attach on process - userinit.exe session=2 
17956   19316   15:34:03.415    tzhook: Attach on process - cmd.exe session=2 
5384    5324    15:34:03.443    tzhook: Attach on process - cmd.exe session=2 
19432   19264   15:34:03.461    tzhook: Attach on process - SSONSVR.EXE session=2 
12480   7472    15:34:03.466    tzhook: Attach on process - cmd.exe session=2 
19448   19364   15:34:03.474    tzhook: Attach on process - net.exe session=2 
19416   19656   15:34:03.489    tzhook: Attach on process - acregl.exe session=2 
19480   19596   15:34:03.544    tzhook: Attach on process - cmstart.exe session=2 
664     19512   15:34:03.559    tzhook: Attach on process - wfshell.exe session=2 
19904   13140   15:34:03.610    tzhook: Attach on process - net.exe session=2 
6864    20036   15:34:03.746    tzhook: Attach on process - icast.exe session=2 
19540   20016   15:34:03.749    tzhook: Attach on process - ctfmon.exe session=2 
19944   19032   15:34:03.757    tzhook: Attach on process - net.exe session=2 
10232   18356   15:34:03.787    tzhook: Attach on process - notepad.exe session=2

Such sequences are also useful to determine a process upon which the session initialization or startup sequence hangs. In this case a user dump of that process might be useful.

Of course we can do all this with Process Monitor and other similar tools but here we get other Citrix related trace messages as well. All in one.

- Dmitry Vostokov @ DumpAnalysis.org -

3 Responses to “CDF Traces: Analyzing Process Launch Sequence”

  1. Software Generalist » Blog Archive » Reading Notebook: 30-July-09 Says:

    […] winlogon -> userinit -> shell (p. 80) - We can use Citrix CDF traces to learn about process launch sequence in Citrix terminal service environments: http://www.dumpanalysis.org/blog/index.php/2008/03/31/cdf-traces-analyzing-process-launch-sequence/  […]

  2. Crash Dump Analysis » Blog Archive » Trace Analysis Patterns (Part 26) Says:

    […] despite the presence of a process creation trace provider or other components that record the process launch sequence and the trace itself lasts only a few seconds after […]

  3. Crash Dump Analysis » Blog Archive » Trace Analysis Patterns (Part 27) Says:

    […] Some modules may emit messages that tell about their status but from their message text we know the larger computation story like in a process startup sequence example.   […]

Leave a Reply

You must be logged in to post a comment.