Trace Analysis Patterns (Part 4)
Tuesday, June 16th, 2009Sometimes we see a functional activity in a trace and / or see basic facts. Then we might want to find a correlation between that activity or facts in another part of the trace. If that intra-correlation fits into our problem description we may claim a possible explanation or, if we are lucky, we have just found, an inference to the best explanation, as philosophers of science like to say. Here is an example, but this time using Citrix WindowHistory tracing tool. A third-party application was frequently loosing the focus and the suspicion was on a terminal services client process. It was found that the following WindowHistory trace fragment corresponds to that application:
Handle: 00050586 Class: "Application A Class" Title: ""
Title changed at 15:52:4:3 to "Application A"
Title changed at 15:52:10:212 to "Application A - File1"
[...]
Process ID: 89c
Thread ID: d6c
[...]
Visible: true
Window placement command: SW_SHOWNORMAL
Placement changed at 15:54:57:506 to SW_SHOWMINIMIZED
Placement changed at 15:55:2:139 to SW_SHOWNORMAL
Foreground: false
Foreground changed at 15:52:4:3 to true
Foreground changed at 15:53:4:625 to false
Foreground changed at 15:53:42:564 to true
Foreground changed at 15:53:44:498 to false
Foreground changed at 15:53:44:498 to true
Foreground changed at 15:53:44:592 to false
Foreground changed at 15:53:45:887 to true
Foreground changed at 15:53:47:244 to false
Foreground changed at 15:53:47:244 to true
Foreground changed at 15:53:47:353 to false
Foreground changed at 15:54:26:416 to true
Foreground changed at 15:54:27:55 to false
Foreground changed at 15:54:27:55 to true
Foreground changed at 15:54:27:180 to false
Foreground changed at 15:54:28:428 to true
Foreground changed at 15:54:28:771 to false
Foreground changed at 15:54:28:865 to true
Foreground changed at 15:54:29:99 to false
Foreground changed at 15:54:30:877 to true
Foreground changed at 15:54:57:521 to false
Foreground changed at 15:55:2:76 to true
Foreground changed at 15:57:3:378 to false
Foreground changed at 15:57:11:396 to true
Foreground changed at 15:57:29:601 to false
Foreground changed at 15:57:39:803 to true
Foreground changed at 15:58:54:41 to false
Foreground changed at 15:59:8:96 to true
Foreground changed at 16:1:19:478 to false
Foreground changed at 16:1:27:527 to true
Foreground changed at 16:1:39:914 to false
Foreground changed at 16:2:0:515 to true
Foreground changed at 16:7:14:628 to false
Foreground changed at 16:7:24:246 to true
Foreground changed at 16:9:53:523 to false
Foreground changed at 16:10:15:919 to true
Foreground changed at 16:10:31:426 to false
Foreground changed at 16:11:12:818 to true
Foreground changed at 16:11:59:538 to false
Foreground changed at 16:12:39:456 to true
Foreground changed at 16:13:6:364 to false
Corresponding terminal services client window trace fragment doesn’t have any foreground changes but another application main window has lots of them:
Handle: 000D0540 Class: "Application B Class" Title: "Application B"
[...]
Process ID: 3ac
Thread ID: bd4
[...]
Foreground: false
Foreground changed at 15:50:36:972 to true
Foreground changed at 15:50:53:732 to false
Foreground changed at 15:50:53:732 to true
Foreground changed at 15:50:53:826 to false
Foreground changed at 15:51:51:352 to true
Foreground changed at 15:51:53:941 to false
Foreground changed at 15:53:8:135 to true
Foreground changed at 15:53:8:182 to false
Foreground changed at 15:53:10:178 to true
Foreground changed at 15:53:13:938 to false
Foreground changed at 15:53:30:443 to true
Foreground changed at 15:53:31:20 to false
Foreground changed at 15:53:31:20 to true
Foreground changed at 15:53:31:129 to false
Foreground changed at 15:53:34:78 to true
Foreground changed at 15:53:34:795 to false
Foreground changed at 15:53:34:795 to true
Foreground changed at 15:53:34:873 to false
Foreground changed at 15:53:36:901 to true
Foreground changed at 15:53:42:502 to false
Foreground changed at 15:53:42:502 to true
Foreground changed at 15:53:42:564 to false
Foreground changed at 15:57:3:425 to true
Foreground changed at 15:57:4:595 to false
Foreground changed at 15:57:10:507 to true
Foreground changed at 15:57:11:318 to false
Foreground changed at 15:57:29:632 to true
Foreground changed at 15:57:31:67 to false
Foreground changed at 15:57:32:721 to true
Foreground changed at 15:57:33:844 to false
Foreground changed at 15:58:54:88 to true
Foreground changed at 15:58:56:178 to false
Foreground changed at 15:59:6:505 to true
Foreground changed at 15:59:7:987 to false
Foreground changed at 16:1:19:525 to true
Foreground changed at 16:1:19:961 to false
Foreground changed at 16:1:26:607 to true
Foreground changed at 16:1:27:434 to false
Foreground changed at 16:1:39:914 to true
Foreground changed at 16:1:39:992 to false
Foreground changed at 16:1:49:798 to true
Foreground changed at 16:2:0:437 to false
Foreground changed at 16:7:14:628 to true
Foreground changed at 16:7:14:847 to false
Foreground changed at 16:7:18:76 to true
Foreground changed at 16:7:24:106 to false
Foreground changed at 16:9:58:790 to true
Foreground changed at 16:10:4:16 to false
Foreground changed at 16:10:4:874 to true
Foreground changed at 16:10:4:890 to false
Foreground changed at 16:10:8:634 to true
Foreground changed at 16:10:15:779 to false
Foreground changed at 16:10:56:766 to true
Foreground changed at 16:10:59:402 to false
Foreground changed at 16:10:59:652 to true
Foreground changed at 16:10:59:667 to false
Foreground changed at 16:12:9:397 to true
Foreground changed at 16:12:39:347 to false
Foreground changed at 16:13:18:375 to true
Foreground changed at 16:14:33:656 to false
We can see that most of the time when Application A window looses focus Application B window gets it.
- Dmitry Vostokov @ TraceAnalysis.org -
