Analyzing Media Foundation traces
As we mentioned in our previous blog post, log files generated by MFTrace quickly become huge, and it can be difficult to sort out interesting traces from background noise. This blog post will share a few tips to help analyze those log files.
TextAnalysisTool.NET
One (free) tool that we often use is TextAnalysilTool.NET. The tool itself is rather minimalist: It just loads log files and lets you enter string patterns to filter out or highlight traces. However, it is very effective at focusing on what matters. Installing TextAnalysisTool.NET is straightforward—just download and uncompress the zip file.
Starting where we left off in the previous post, let’s collect another trace from Windows Media Player. Open an elevated command prompt, add the SDK to your path (see the previous post), and run Windows Media Player under MFTrace:
MFTrace.exe -o mf.log "%PROGRAMFILES%\Windows Media Player\wmplayer.exe" "%PUBLIC%\Videos\Sample Videos\Wildlife.wmv"
Let the video play for a few seconds. Then close Windows Media Player. At this point, you should have a log file named “mf.log” in the current directory. Open this file with TextAnalysisTool.NET as follows:
TextAnalysisTool.NET.exe mf.log
TextAnalysisTool.NET will show two views. The traces appear in the top view. The bottom view contains string patterns that filter or highlight the traces.
To filter out traces, select Add new filter from the Filter menu, or type CTRL+N. In the Add Filter dialog, enter a string pattern and choose a highlight color:
You can also select whether the string is case-sensitive or uses a regular expression. When you click OK, traces that do not match the pattern will appear grayed out. To completely hide those traces, select Show only filtered lines from the View menu, or type CTRL+H.
This should be enough to get you started. For more details on how to use TextAnalysis, see the help file “TextAnalysisTool.NET.txt,” which is contained in the zip file.
Tips and tricks to analyze traces
One of the first filters to use on a trace is the string “fail”. Traces that contain this string are likely to indicate problems. For example, the following trace shows where a codec rejected a proposed media type:
00120 3992,B28 23:14:38.80074 CMFTransformDetours::SetInputType @00672C90 Failed MT: MF_MT_MAJOR_TYPE=MEDIATYPE_Video;MF_MT_SUBTYPE=MFVideoFormat_WMV3;MF_MT_FRAME_SIZE=3092376453600 (720,480);MF_MT_USER_DATA=4f d1 1a 01 ;MF_MT_AVG_BITRATE=1895000;MF_MT_FRAME_RATE=128849018881001 (30000,1001);MF_MT_PIXEL_ASPECT_RATIO=34359738377 (8,9);MF_MT_INTERLACE_MODE=2
Note that some failures may be benign. For example, the following trace just means that the codec needs another sample before it can produce some output:
00489 6072,10E4 16:23:07.47317 CMFTransformDetours::ProcessOutput @0357ED34 failed hr=0xC00D6D72 MF_E_TRANSFORM_NEED_MORE_INPUT
This error code is expected during normal streaming, unless all the calls to ProcessOutput return this error code. For example, this can happen if the H.264 decoder does not find a valid start code within the H.264 bitstream.
The log file can also tell you whether the topology was successfully resolved and how the pipeline components got connected (or not). To figure this out, filter traces that contain the string “TopologyHelpers”:
00248 6072,DC0 16:23:07.21976 CTopologyHelpers::Trace @02F21080 >>>>>>>>>>>>> ready topology
00249 6072,DC0 16:23:07.22002 CTopologyHelpers::TraceNode @ Node 0 @02EFC0D0 ID:17B800000007, 0 inputs, 1 outputs, type 1, {528E8D22-311F-4B88-BCE8-22A2374E8CFC}=1;MF_TOPONODE_SOURCE=@02EDBE48; (…)
00250 6072,DC0 16:23:07.22008 CTopologyHelpers::TraceObject @ Source @02EDBE48 {00000000-0000-0000-0000-000000000000} (C:\Windows\system32\MF.dll), MFMEDIASOURCE_CHARACTERISTICS=0x00000006
00251 6072,DC0 16:23:07.22018 CTopologyHelpers::TraceStream @ Output stream 0, connected to node @02EFC170 stream 0, MT: MF_MT_MAJOR_TYPE=MEDIATYPE_Audio; (…)
00252 6072,DC0 16:23:07.22040 CTopologyHelpers::TraceNode @ Node 1 @02EFC030 ID:17B800000009, 1 inputs, 0 outputs, type 0, (…)
00253 6072,DC0 16:23:07.22044 CTopologyHelpers::TraceObject @ Sink @02F1DF58 {D23E6476-B104-4707-81CB-E1CA19A07016} (C:\Windows\system32\MF.dll), (null)
00254 6072,DC0 16:23:07.22053 CTopologyHelpers::TraceStream @ Input stream 0, connected to node @02F19DA8 stream 0, MT: MF_MT_MAJOR_TYPE=MEDIATYPE_Audio;(…)
(…)
00293 6072,DC0 16:23:07.22528 CTopologyHelpers::Trace @02F21080 MF_TOPOLOGY_RESOLUTION_STATUS = 0
00294 6072,DC0 16:23:07.22529 CTopologyHelpers::Trace @02F21080 <<<<<<<<<<<<< ready topology
If everything went well, as is the case here, the resolution status is zero. The rest of the selected traces give details about each of the components in the topology and how they are connected to one another. Among other things, this information includes the media type of the connection.
Another useful filter is the object address, which allows you to focus on the lifetime of one object in particular. For instance, the following traces were selected by filtering with “0357ED34”. They show the first few calls on a Windows Media Player effect.
00149 6072,DC0 16:23:06.91749 CMFTransformDetours::SetInputType @0357ED34 Succeeded MT: MF_MT_MAJOR_TYPE=MEDIATYPE_Audio;(…)
00151 6072,DC0 16:23:06.91919 CMFTransformDetours::SetOutputType @0357ED34 Succeeded MT: MF_MT_MAJOR_TYPE=MEDIATYPE_Audio; (…)
00194 6072,DC0 16:23:07.18577 CTopologyHelpers::TraceObject @ MFT @0357ED34 {777D0CFF-0375-43B9-8532-FB04A4903593} (C:\Windows\System32\wmpeffects.dll), <NULL>
00230 6072,DC0 16:23:07.19396 CMFTransformDetours::ProcessMessage @0357ED34 Message type=0x10000000 MFT_MESSAGE_NOTIFY_BEGIN_STREAMING, param=00000000
00473 6072,9B0 16:23:07.40790 CMFTransformDetours::ProcessMessage @0357ED34 Message type=0x10000003 MFT_MESSAGE_NOTIFY_START_OF_STREAM, param=00000000
00489 6072,10E4 16:23:07.47317 CMFTransformDetours::ProcessOutput @0357ED34 failed hr=0xC00D6D72 MF_E_TRANSFORM_NEED_MORE_INPUT
00508 6072,10E4 16:23:07.59281 CMFTransformDetours::ProcessInput @0357ED34 Stream ID 0, Sample @083C8720, Time 0ms, Duration 46ms, Buffers 1, Size 16384B, MFSampleExtension_CleanPoint=1;MFSampleExtension_Discontinuity=1;MFSampleExtension_SampleKeyID=1;MFSampleExtension_Token=@00000000
00509 6072,10E4 16:23:07.59628 CMFTransformDetours::ProcessOutput @0357ED34 Stream ID 0, Sample @083C8810, Time 0ms, Duration 46ms, Buffers 1, Size 16384B, MFSampleExtension_CleanPoint=0
In this sequence of calls, Windows Media Player sets the media types on the effect, notifies the effect that streaming is about to start, and processes one sample.
That’s all for now, but more examples are shown on the MSDN page dedicated to MFTrace. In the next post, we will share a few Perl scripts that automate trace analysis and use the power of GraphViz and GNUPlot to create graphical representations of topologies.