CDF Traces: Analyzing Process Launch Sequence
Monday, March 31st, 2008Citrix 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 -