Alois Kraus

blog

  Home  |   Contact  |   Syndication    |   Login
  133 Posts | 8 Stories | 368 Comments | 162 Trackbacks

News



Archives

Programming

When I start a new project for a small tool I sprinkle throughout my code some Console.WriteLine calls to see what is going on and to report errors. I am quite sure that 99% of all developers work this way except for the TDD elite which do start with a MEF container and injectable tracer and logger interfaces right from the beginning. When the tool proves to be useful it is extended a little bit here and there and other people start using it. Perhaps it is used in a script or it is put in an Run key to be started every time the user logs on or it does get a nice WPF UI…

Errors do still happen but the Console output goes nowhere now. If you e.g. switch from a Console Application project type to a Windows Application in the Visual Studio project settings there is no hidden magic going on. The project type is a simple tag in the PE file which does nothing for a console app and for a Windows application it detaches upon start from the console (if any) it was started from to free the command prompt for the next application you want to start. When your users report problems with your tool you have just lost your console output you did rely on. At this point you tell the users to switch on tracing and to log the data to a file with the hidden –debug switch your application surely has. But for this to happen you need to take an extra library dependency or to copy quite a bit of code into your still small project and you need to exchange all Console.WriteLine calls with calls to your tracing library. That is overkill for many small tools which are useful because they to spare enough time to justify the time spent on coding them.

Before you throw out your Console.WriteLine calls to get your diagnostics abilities back  you can sidestep the problem by redirecting the Console.Out TextWriter instance to your own intercepting TextWriter instance. You can still print to the console but you can now easily write the output to a secondary (or even tertiary) location. It can be a log file or an ETW TraceListener or the diagnostics window in your WPF application. The following example shows how to write your console output to ETW with jus a few additional lines of code.

using Microsoft.Diagnostics.Tracing;
using System;
using System.IO;
using System.Text;
using System.Threading;

namespace ConsoleRedirector
{
    class Program
    {
        static void Main(string[] args)
        {
            // Simply wrap your Main method with this using statement and all output goes to 
            // ETW, DebugOutput or a log file without the need to touch or change existing Console.WriteLine calls
            using (new ForwardWriter(WriteToETW, WriteToETW))
            {
                for (int i = 0; i < 1000; i++)
                {
                    Console.WriteLine("Writing event {0}", i);
                    Thread.Sleep(1000);
                }
            }
        }

        static void WriteToETW(string line)
        {
            ConsoleEventSource.Log.Write(line);
        }

        /// <summary>
        /// Forward Console.Write and Console.WriteLine calls to your handler to redirect them to alternate locations
        /// </summary>
        class ForwardWriter : TextWriter
        {
            /// <summary>
            /// Original TextWriter from Console.Out
            /// </summary>
            TextWriter Orig;

            /// <summary>
            /// Redirect Console.Out with this instance and forward Console output to passed handlers.
            /// </summary>
            /// <param name="onWrite">Receives strings from Console.Write</param>
            /// <param name="onWriteLine">Receives strings from Console.WriteLine</param>
            public ForwardWriter(Action<string> onWrite, Action<string> onWriteLine)
            {
                Orig = Console.Out;
                Console.SetOut(this);
                if (onWrite != null)
                {
                    OnWrite += onWrite;
                }

                if (onWriteLine != null)
                {
                    OnWriteLine += onWriteLine;
                }
            }

            /// <summary>
            /// Create a new forwarder. To receive the output you need to subscribe to the events OnWrite and OnWriteLine
            /// </summary>
            public ForwardWriter()
                : this(null, null)
            {
            }

            /// <summary>
            /// Is fired when Console.Write call happened
            /// </summary>
            public event Action<string> OnWrite = (str) => { };

            /// <summary>
            /// Is fired when Console.WriteLine call happened
            /// </summary>
            public event Action<string> OnWriteLine = (str) => { };

            public override Encoding Encoding
            {
                get { throw new NotImplementedException(); }
            }

            /// <summary>
            /// All overloads of Console.WriteLine call finally this overload 
            /// </summary>
            /// <param name="value"></param>
            public override void WriteLine(string value)
            {
                Orig.WriteLine(value);
                OnWriteLine(value);
            }

            /// <summary>
            /// All overloads of Console.Wrie call finally this overload
            /// </summary>
            /// <param name="value"></param>
            public override void Write(string value)
            {
                Orig.Write(value);
                OnWrite(value);
            }
        }

        /// <summary>
        /// ETW event provider for redirected Console messages
        /// </summary>
        [EventSource(Name = "ConsoleLog", Guid="{7B25937F-14D7-4BFF-BD7D-2A0C00ABA1EE}")]
        sealed class ConsoleEventSource : EventSource
        {
            public static ConsoleEventSource Log = new ConsoleEventSource();

            /// <summary>
            /// Write a console message
            /// </summary>
            /// <param name="Message"></param>
            public void Write(string Message)
            {
                WriteEvent(1, Message);
            }
            private ConsoleEventSource():base(true)
            { }
        }
    }
}

Now you can leave your precious Console.WriteLine calls in your code and you still can get full diagnostic by forwarding your output to ETW or a simple log file by adding a simple using statement to your Main method. This is of course not perfect but for small tools it is often enough to get the job done. The ETW writer works not only with .NET 4.5 but you can also Target .NET 4.0 apps if you get the Microsoft.Diagnostics.Tracing.EventSource package via Nuget (be sure to check beta packages) which does target .NET 4.5 but it works with .NET 4.0 as well. The nice thing about ETW is that you can enable it for an already running application and you get the full output without any registration steps. The ETW Provider introduced with .NET 4.5 creates from the declaring class via reflection. With the Windows Performance Toolkit you can capture with WPR by creating your own profile to capture your ETW events with a wprp file like

<?xml version="1.0" encoding="utf-8"?>
<WindowsPerformanceRecorder Version="1.0">
<Profiles>
<EventCollector Id="EventCollector_MyEventSource" Name="ConsoleTraces">
<BufferSize Value="1024" />
<Buffers Value="200" />
</EventCollector>
<EventProvider Id="ConsoleEventSource" Name="7B25937F-14D7-4BFF-BD7D-2A0C00ABA1EE" />

<Profile Id="ConsoleTraces.Verbose.File" Name="ConsoleTraces" Description="Console Traces" LoggingMode="File" DetailLevel="Verbose">
<Collectors>
<EventCollectorId Value="EventCollector_MyEventSource">
<EventProviders>
<EventProviderId Value="ConsoleEventSource" />
</EventProviders>
</EventCollectorId>
</Collectors>
</Profile>
<Profile Id="ConsoleTraces.Verbose.Memory" Name="ConsoleTraces" Description="Console Traces" Base="ConsoleTraces.Verbose.File" LoggingMode="Memory" DetailLevel="Verbose" />
</Profiles>
</WindowsPerformanceRecorder>

image

As you can see the provider name is derived from the EventSource Name attribute, the Task Name is the called method and the Message field is the parameter name passed to to the Write method. This magic is only possible because this ETW provider creates an ETW manifest file via reflection from your class, method and method parameters which is written an an extra ETW event to the etw event stream which is later parsed by WPA to make this nice visualization possible. As added bonus you do not need to put the process and thread id to your messages anymore because the ETW infrastructure will capture it for you.

You can create from your class also a “classic” ETW manifest file which you can register with wevtutil –im xxx.man as usual. You can get the manifest string via

EventSource.GenerateManifest(typeof(ConsoleEventSource), Assembly.GetExecutingAssembly().Location)

from where you can save the returned string to a file and register it. The beta NuGet package seems to have problems because it did not work and did throw a NullReferenceException inside it. But the .NET 4.5 EventSource class in mscorlib works as expected.

For the simple ETW provider I get this manifest:

ConsoleTraces.wprp

<instrumentationManifest xmlns="http://schemas.microsoft.com/win/2004/08/events">
 <instrumentation xmlns:xs="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events">
  <events xmlns="http://schemas.microsoft.com/win/2004/08/events">
<provider name="ConsoleLog" guid="{7b25937f-14d7-4bff-bd7d-2a0c00aba1ee}" resourceFileName="D:\Media\Blog\ConsoleRedirector\ConsoleRedirector\bin\Debug\ConsoleRedirector.exe" messageFileName="D:\Media\Blog\ConsoleRedirector\ConsoleRedirector\bin\Debug\ConsoleRedirector.exe" symbol="ConsoleLog">
 <tasks>
  <task name="Write" value="65533"/>
 </tasks>
 <opcodes>
 </opcodes>
 <events>
  <event value="1" version="0" level="win:Informational" task="Write" template="WriteArgs"/>
 </events>
 <templates>
  <template tid="WriteArgs">
   <data name="Message" inType="win:UnicodeString"/>
  </template>
 </templates>
</provider>
</events>
</instrumentation>
<localization>
 <resources culture="de-DE">
  <stringTable>
  </stringTable>
 </resources>
</localization>
</instrumentationManifest>

These embedded manifests have he benefit that you do not need to be an administrator to register the manifest in the system. But since you have not registered your provider it will also no longer show up as registered ETW provider (xperf –providers).

Instead of a .wprp file you can also directly call xperf to collect your traces. To enable stackwalks every 1ms and full managed call stacks you need this xperf calls to enable profiling:

xperf -start ClrSession -on e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x98:5  -f "%temp%\clr.etl" -buffersize 128 -minbuffers 256 -maxbuffers 1024 -on LOADER+PROC_THREAD+PROFILE -stackwalk Profile -f "%temp%\kernel.etl" -buffersize 128 -minbuffers 256 -maxbuffers 2048
xperf -start TraceSession -on 7B25937F-14D7-4BFF-BD7D-2A0C00ABA1EE -f "%temp%\traces.etl" -buffersize 128 -minbuffers 256 -maxbuffers 1024

 

To stop tracing you need to call

xperf -start ClrRundownSession -on e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x118:5+a669021c-c450-4609-a035-5af59af4df18:0x118:5 -f "%temp%\clr_DCend.etl" -buffersize 128 -minbuffers 256 -maxbuffers 512
set XPERF_CreateNGenPdbs=1
set _NT_SYMBOL_PATH=srv*%TEMP%\combined.etl.NGENPDB
xperf -stop TraceSession ClrSession ClrRundownSession -stop -d "%temp%\combined
.etl"

It is a bit cumbersome but you can easily create a batch script to collect only the data you actually want. If you use the WPRUI tool it will not only collect the configured data but it will collect CPU and Disk activity always which generates quite a lot of data. But if you use the command line tool then you collect only what you did specify in the wprp file. Then you only need to execute:

wpr -start consoleraces.wprp

wpr -stop traces.etl

to get your hands on your data. Although nice it is still problematic for installed machines on customer sites where you are usually not allowed to install additional software to find the bug. This is often the case in clinical environments where data integrity is taken really serious. It would help to make the WPR tool open source so it is possible to deliver the ETW recording tool along with the product software which is currently not possible since the ADK license does not permit to redistribute any part of it. You can resort back to logman for simple cases but if you want to enable managed stackwalks you need xperf or related tools to make it work.

posted on Wednesday, August 21, 2013 10:24 AM

Feedback

# re: From Console.WriteLine To ETW 8/31/2013 7:32 PM Jon
Alois, your blog is great but you write "do" too much, as well as its variants such as "does". This can be jarring for a native English speaker to read. For example, instead of "When I do start a new project, I do sprinkle thoroughout my code" write "When I start a new project, I sprinkle throughout my code". Instead of "to be started every time the user does log on" write "to be started every time the user logs on".

# re: From Console.WriteLine To ETW 8/31/2013 10:58 PM Alois Kraus
Fixed. Thanks for the feedback. I really want to improve my writing skills.

Post A Comment
Title:
Name:
Email:
Comment:
Verification: