N
News Value is a pattern that assigns relative importance to software traces for problem-solving purposes, especially when it is related to a problem description, recent incidents, and timestamps of other supporting artifacts (memory dumps, other traces). For example, in one scenario, an ETW trace was provided with three additional log files:
# Source PID TID Date Time Message
0 Header 1260 1728 12/14/2010 06:48:56.289 ?????
[...]
215301 Unknown 640 808 12/14/2010 07:22:57.508 ????? Unknown( 16): GUID=[...] (No Format Information found).
// LogA
05/11/10 18:28:15.1562 : Service() - entry
[...]
14/12/10 10:31:58.0381 : Notification: sleep
* Start of new log *
14/12/10 10:34:38.4687 : Service() - entry
[...]
14/12/10 11:53:35.2729 : Service.CleanUp complete
* Start of new log *
14/12/10 11:56:11.7031 : Service() - entry
[...]
14/12/10 15:25:23.3004 : Notification: sleep
// LogB
[ 1] 12/14 10:34:29:890 Entry: ctor
[...]
[ 2] 12/14 11:53:30:866 Exit: COMServer.Server.DeleteObject
// LogC
[ 1] 12/14 11:56:03:359 Entry: ctor
[...]
[20] 12/14 15:30:20:110 Exit: Kernel32.Buffer.Release
From the description of the problem, we expected LogB and LogC to be logs from two subsequent process executions where the first launch fails (LogB) and the second launch succeeds (LogC). Looking at their start and end times we see that they make sense from the problem description perspective, but we have to dismiss ETW trace and most of LogA as recorded earlier and having no value for Inter-Correlation analysis of more recent logs. We also see that portions of LogA overlap with LogB and LogC and, for this reason, have analysis value for us.
In the following diagram that illustrates this analysis pattern, in relation to a trace on the left (1st) only the 3rd trace has some value as the other two were recorded either earlier or later:
No Activity is the limit of Discontinuity pattern. The absence of activity can be seen at a thread level or at a process level where it is similar to Missing Component pattern. The difference from the latter pattern is that we know for certain that we selected our process modules for tracing but do not see any trace messages. Consider this example:
# Source PID TID Time Function Message
1 TraceSettings 1480 8692 08:04:20.682 **** Start Trace Session
[... TraceSettings messages 2-11 show that we selected AppA for tracing ...]
12 ModuleB 3124 4816 08:04:37.049 WorkerThread Worker thread running
13 TraceSettings 1480 8692 08:04:41.966 **** Trace Session was stopped
Only modules from AppA process and modules from a coupled process (for example, ModuleB) were selected. However, we only see a reminder message from the coupled process (3124.4816: ModuleB!WorkerThread) and no messages for 21 seconds. Fortunately, AppA process memory dump was saved during the tracing session:
Debug session time: Fri May 21 08:04:31.000 2010 (GMT+0)
We see two threads waiting for a critical section:
0:000> ~*kL
14 Id: 640.8b8 Suspend: 1 Teb: 7ffa7000 Unfrozen
ChildEBP RetAddr
0248f8c0 7c827d29 ntdll!KiFastSystemCallRet
0248f8c4 7c83d266 ntdll!ZwWaitForSingleObject+0xc
0248f900 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
0248f920 0040dea8 ntdll!RtlEnterCriticalSection+0xa8
[...]
0248f9a4 77ce78aa rpcrt4!Invoke+0×30
0248f9c0 77ce7a94 rpcrt4!NdrCallServerManager+0×17
0248fcb8 77ce7b7c rpcrt4!NdrStubCall+0×1d6
0248fcd0 77c7ff7a rpcrt4!NdrServerCall+0×15
0248fd04 77c8042d rpcrt4!DispatchToStubInCNoAvrf+0×38
0248fd58 77c80353 rpcrt4!RPC_INTERFACE::DispatchToStubWorker+0×11f
0248fd7c 77c7e0d4 rpcrt4!RPC_INTERFACE::DispatchToStub+0xa3
0248fdbc 77c7e080 rpcrt4!RPC_INTERFACE::DispatchToStubWithObject+0xc0
0248fdfc 77c812f0 rpcrt4!LRPC_SCALL::DealWithRequestMessage+0×41e
0248fe20 77c88678 rpcrt4!LRPC_ADDRESS::DealWithLRPCRequest+0×127
0248ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430
0248ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd
0248ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0×9d
15 Id: 640.18c0 Suspend: 1 Teb: 7ffdb000 Unfrozen
ChildEBP RetAddr
01b8ff40 7c827d29 ntdll!KiFastSystemCallRet
01b8ff44 7c83d266 ntdll!ZwWaitForSingleObject+0xc
01b8ff80 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
01b8ffa0 0040dba7 ntdll!RtlEnterCriticalSection+0xa8
[...]
01b8ffec 00000000 kernel32!BaseThreadStart+0×34
Unfortunately, it belongs to a missing thread and blocked threads wait forever:
0:000> !cs -l -o -s
-----------------------------------------
DebugInfo = 0x01facdd0
Critical section = 0x01da19c0 (+0x1DA19C0)
LOCKED
LockCount = 0×2
WaiterWoken = No
OwningThread = 0×00001384
RecursionCount = 0×1
LockSemaphore = 0×578
SpinCount = 0×00000000
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled
0:000> ~~[1384]
^ Illegal thread error in ‘~~[1384]’
AppA process was hanging, and it explains why we do not see any activity in the trace.
The following diagram illustrates this analysis pattern:
This pattern is similar to No Component Symbols93 memory analysis pattern:
# Module PID TID Time Message
21372 srcdllA 2968 5476 3:55:10.004 Calling foo()
21373 Unknown 2968 5476 3:55:10.004 ????? Unknown( 27): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21374 Unknown 2968 5476 3:55:10.004 ????? Unknown( 27): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21375 Unknown 2968 5476 3:55:10.004 ????? Unknown( 27): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21376 Unknown 2968 5476 3:55:10.004 ????? Unknown( 28): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21377 Unknown 2968 5476 3:55:10.004 ????? Unknown( 23): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21378 srcdllA 2968 5476 3:55:10.004 Calling bar()
In some cases, when we don’t have TMF files (Trace Meta Files), it is possible to detect broad behavioral patterns such as:
By looking at Thread of Activity, we can sometimes also infer the possible component name based on surrounding trace messages with present TMF files, especially when we have source code access. For example, in the trace shown above, it can be dllA or any other module that foo function calls.