An Addition to the Musical Family

§ August 3, 2008 04:51 by beefarino |

Summer's been a musical blast so far.  About a month ago I got to experience Tom Waits live at his show in Atlanta's stunning Fox Theatre (you can listen to the entire 2.5 hour show here thanks to NPR; you can actually hear me - I'm the one screaming, clapping, and singing along).  It was my second live Waits show, the first being the Asheville, NC stop of his Orphans tour in 2006.  Seeing Waits live was a life goal I had written off until two years ago; that I've been able to experience him perform over five hours of live material I consider a true blessing (and now I know where my lost luggage ends up, thanks Tom).

More recently, I returned from a family gathering in Pigeon Forge, TN.  On the way we passed through Gatlinburg where I got to meet Mark Edelman at Smoky Mountain Dulcimers.  I'd never played an mountain lap dulcimer before, but I can play a lot of guitar and a little banjo so I was a quick study.  If you don't know, they have four strings - three tuned to A and one to D - and they're fretted to the major scale starting at the 5th.  Two of the A-tuned strings are positioned close together, like the strings on a 12-string guitar; they're used for the melody.  The other two strings (AD) serve as harmony.  The effect is something like the chanter and drones on a bagpipe.  Once you get the physical aspects of playing the instrument down, getting it to make music is pretty easy and a lot of fun.  I liked them enough to pick one up - the traditional hourglass beauty you can see in the picture for this post.  It's as much for my girls as myself.  I think it will be a great way to expose them to stringed instruments.  In fact - and this is no lie - I've got my 3-year-old strumming out "Twinkle Twinkle Little Star" and "You are my Sunshine" while I help her little hand hold the noter down!



Using Overlapped I/O from Managed Code

§ July 26, 2008 04:01 by beefarino |

I've been working on a project that requires some low-level device driver interaction using the DeviceIoControl Windows API call.  Without going into too much detail, the driver's programming interface requires a thread-heavy implementation to monitor low-level GPIO inputs for signal changes.  Fortunately Windows has built-in an asynchronous programming mode called Overlapped I/O that saves me the overhead of having to manage a bunch of threads for such low-level tripe.  In a nutshell, Overlapped I/O is the backbone of the asynchronous reading and writing of files and network streams in the .NET framework.

Unfortunately, there is no managed equivalent for device communication in the .NET framework; hand-rolling access to the DeviceIoControl API call is simple enough, but leveraging overlapped I/O from managed code requires some digging.  There are very few examples available, so I decided to post one in case anyone else out there happens to be working on such obscure (but very interesting!) projects too.

There are five steps to leveraging Overlapped I/O from managed code:

  1. Access the relevant routines from Kernel32.dll via P/Invoke;
  2. Create a file/device/pipe handle tagged for overlapped I/O;
  3. Bind the handle to the managed Thread Pool;
  4. Prepare a NativeOverlapped pointer;
  5. Pass the NativeOverlapped pointer to the relevant Win32 API (DeviceIoControl in my case).

Kernel32 P/Invoke

Using overlapped I/O requires some direct access to routines from kernel32.dll.  Below is the a static class that imports the routines and defines the constants needed.  If you have any questions or suggestions please feel free to post a comment.

using System;
using System.Runtime.InteropServices;
using System.Threading;
using Microsoft.Win32.SafeHandles;
namespace PInvoke
{
    /// <summary>
    /// Static imports from Kernel32.
    /// </summary>
    static public class Kernel32
    {
        const uint Overlapped = 0x40000000;
        
        [ Flags ]
        public enum AccessRights : uint
        {
            GENERIC_READ                     = (0x80000000),
            GENERIC_WRITE                    = (0x40000000),
            GENERIC_EXECUTE                  = (0x20000000),
            GENERIC_ALL                      = (0x10000000)
        }
        [ Flags ]
        public enum ShareModes : uint
        {
            FILE_SHARE_READ                 = 0x00000001,
            FILE_SHARE_WRITE                = 0x00000002,
            FILE_SHARE_DELETE               = 0x00000004  
        }
        public enum CreationDispositions
        {
            CREATE_NEW          = 1,
            CREATE_ALWAYS       = 2,
            OPEN_EXISTING       = 3,
            OPEN_ALWAYS         = 4,
            TRUNCATE_EXISTING   = 5
        }
        [ DllImport( "kernel32.dll", SetLastError=true, CharSet=CharSet.Unicode ) ]
        public static extern SafeFileHandle CreateFile(
            string lpFileName,
            uint dwDesiredAccess,
            uint dwShareMode,
            IntPtr lpSecurityAttributes,
            uint dwCreationDisposition,
            uint dwFlagsAndAttributes,
            IntPtr hTemplateFile
        );
        [ DllImport( "kernel32.dll", CharSet=CharSet.Unicode ) ]
        public static extern void CloseHandle(
            SafeHandle handle
        );
        [ DllImport( "kernel32.dll", SetLastError=true, CharSet=CharSet.Unicode ) ]
        unsafe public static extern bool DeviceIoControl(
            SafeHandle hDevice,
            uint dwIoControlCode,
            IntPtr lpInBuffer,
            uint nInBufferSize,
            IntPtr lpOutBuffer,
            uint nOutBufferSize,
            ref uint lpBytesReturned,
            NativeOverlapped *lpOverlapped
        );
    }
}

Creating the Device Handle

In order to leverage asynchronous I/O against the device handle, it needs to be opened specifically for asynchronous operations.  To do this use the CreateFile API call, passing the device path as the lpFileName parameter and specifying the Overlapped flag in the dwFlagsAndAttributes parameter:

SafeFileHandle deviceHandle = Kernel32.CreateFile(
    devicePath,
    ( uint )( Kernel32.AccessRights.GENERIC_READ | Kernel32.AccessRights.GENERIC_WRITE ),
    ( uint )( Kernel32.ShareModes.FILE_SHARE_READ | Kernel32.ShareModes.FILE_SHARE_WRITE ),
    IntPtr.Zero,
    ( uint )( Kernel32.CreationDispositions.OPEN_EXISTING ),
    Kernel32.Overlapped, // note the OVERLAPPED flag here
    IntPtr.Zero
);                    

Binding the Device Handle to the Thread Pool

The Windows Thread Pool manages 1000 threads per process dedicated to nothing but handling overlapped I/O.  In order to make use of them, it is necessary to "bind" the device handle returned by calling CreateFile to the thread pool.  This is done using the ThreadPool.BindHandle call:

ThreadPool.BindHandle( deviceHandle );             

The API documentation for BindHandle gives almost no indication as to it's purpose, but I've found this call is absolutely necessary in order to receive notifications of asynchronous operations.  (If you're interested in the details of what this call actually accomplishes, it seems to bind the handle to an I/O Completion Port owned by the Thread Pool; check out Chris Brumme's comments from this post on his blog for more.)

Creating a NativeOverlapped Pointer

Creating a NativeOverlapped pointer to pass to the DeviceIoControl API is relatively simple:

Overlapped overlapped = new Overlapped();
NativeOverlapped* nativeOverlapped = overlapped.Pack(
    DeviceWriteControlIOCompletionCallback,
    null
);             

After creating an instance of the Overlapped class, use its Pack method to create a pointer to a NativeOverlapped structure; the layout of this structure is byte-for-byte identical to the Win32 OVERLAPPED structure, which makes it suitable for passing directly to unmanaged API calls.  Note that the pointer returned by Overlapped.Pack() is fixed (pinned) in memory until the pointer is passed to Overlapped.Unpack and Overlaped.Free.

The first parameter to Overlapped.Pack is an IOCompletionCallback delegate that will be called when the overlapped I/O operation completes.  The second argument could be an array of objects representing buffers of memory used for passing data to and from the device driver; to keep this post as simple as possible I'm leaving that feature out of the example code.

The IOCompletionCallback delegate is mandatory and follows the following pattern:

unsafe void DeviceWriteControlIOCompletionCallback( uint errorCode, uint numBytes, NativeOverlapped* nativeOverlapped )
{    
    try
    {
        // ...
    }
    finally
    {
          System.Threading.Overlapped.Unpack( nativeOverlapped );
          System.Threading.Overlapped.Free( nativeOverlapped );
    }
}

The errorCode parameter will be 0 on a successful overlapped I/O operation, or a standard Win32 error code on a failure.  The numBytes parameter will contain the number of bytes received from the operation.

With whatever else needs to happen post-I/O, the fixed NativeOverlapped pointer must be unpacked and freed, or the application will both leak memory and fragment the managed heap over time.

Passing the NativeOverlapped Pointer to DeviceIoControl

With a NativeOverlapped pointer in hand, call DeviceIoControl:

 

const int ErrorIOPending = 997;
uint bytesReturned = 0;
bool result = Kernel32.DeviceIoControl(
    deviceHandle,
    ( uint )ioCtlCode,
    IntPtr.Zero,
    0,
    IntPtr.Zero,
    0,
    ref bytesReturned,
    nativeOverlapped
);
if( result )
{
    // operation completed synchronously    
    
    System.Threading.Overlapped.Unpack( nativeOverlapped );
    System.Threading.Overlapped.Free( nativeOverlapped );
}
else
{
    int error = Marshal.GetLastWin32Error();    
    if( ErrorIOPending != error )
    {
        // failed to execute DeviceIoControl using overlapped I/O ...
        
        System.Threading.Overlapped.Unpack( nativeOverlapped );
        System.Threading.Overlapped.Free( nativeOverlapped );
    }
}

 

The nativeOverlapped pointer and overlapped device handle cause the kernel to attempt an asynchronous execution of DeviceIoControl.  

The call will return immediately with a boolean result whose semantics are a bit awkward.  If the result is true, it means the operation completed synchronously as opposed to asynchronously.  A false result indicates the operation may have be executing asynchronously.  To verify this, check the Win32 error code via Marshal.GetLastWin32Error: if it's ERROR_IO_PENDING (997), the DeviceIoControl operation is executing asynchronously and the IOCompletionCallback delegate will be called when the operation is finished; otherwise, the error code will indicate why DeviceIoControl failed to execute asynchronously.

If DeviceIoControl executes synchronously, or if it fails to execute asynchronously, the NativeOverlapped pointer must still be unpacked and freed to avoid leaking memory and fragmenting the managed heap.

That's the nut of using Overlapped I/O from managed code.  If you do end up using this for something, please drop me a line, either as a comment to this post or using the contact link on this site; I'd love to hear what you're working on!



On Smarts, Curiosity, and Learning

§ July 6, 2008 14:22 by beefarino |

Justin Etheredge recently posted Being Smart Does Not a Good Developer Make, in which he offers several important perspectives in his usual good-hearted way; the one that sparked my neurons was that drive and curiosity are more valuable than raw knowledge to becoming a "good developer."

I whole-heartedly share this perspective.  This is probably due to the fact that I've painted myself into a professional corner in many respects.  I have no formal education in my chosen profession of software engineering, which has historically put me at a disadvantage in job interviews, when I push to lead a project, and in a lot of interaction with my peers.  Nevertheless, I've been able to land the jobs, get the project leads when I want them, and feel confident - if reservedly so - talking with my fellow engineers without sounding like a total poser.

I attribute my success to three things:

  1. I've been pretty lucky with my opportunities;
  2. I'm insatiably curious about most things;
  3. I have two degrees in psychology. 

Justin calls software engineering a meta-industry; likewise, psychology is probably the second-best example of a meta-science I can think of (with first place going to cryptography).  Digesting all that research on learning, perception, and memory has given me a significant leg-up when it comes to learning new things, understanding someone else's perspective, and communication.

I honestly believe that having and honing these skills is what keeps me employed as a software engineer.

If it was possible for me to add any value to Justin's post, it would be to not limit your exploration to your career.  Learning is an active, forceful process - go find something that interests you and relate it back to software design and engineering.  Psychology may not be your bag, but learning opportunities abound.  Here are two ideas I've taken from my own personal history:

Design and build a birdhouse (or, if you have some modest woodworking skills, a tree house or bookshelf).  If you really want a challenge, have someone else design it.  What sort of problems did you hit during design vs. construction?  How well did you estimate your materials?  What sort of mistakes ended up in the final product, and how would you avoid them next time?

Cook a menu by a fickle four-year-old.  This is a great exercise in communicating across domains of expertise: you could be a Master Chef, but you'll have no idea how to make Glittery Rainbow Unicorn Fishsticks or Chocolate Marshmallow Beans and Rice without some discussion.  Moreover, try explaining to them why their culinary delights don't taste as delightful as they expected.  Work with them to hone their ideas and produce something palatable.  Think about the communication problems you experienced and how you worked around them - they have a lot in common with communication problems you experience at work.



Log4Net Tutorial pt 5: Using Logger Objects

§ June 26, 2008 07:40 by beefarino |

We've done a lot log4net configuration in the last few tutorials; time to mix in some code and discuss loggers.  This post is meant to show you the most common pattern of logger use.

Crack open Visual Studio, create a new console project, and add a reference to the log4net assembly.

Add the following application configuration file to the project:

<configuration>
  <configSections>
    <section name="log4net"
      type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>

  <log4net>

    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Add the following code to your program.cs file:

namespace Tutorial5_Loggers
{
    class Program
     {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log.Info( "this is an info message" );
            Console.ReadLine();
        }
    }
}

The logger object is created on line 5 via a the call to LogManager.GetLogger.  Compile and run and check out the output; it'll be similar to the following:

Tutorial5_Loggers.Program [INFO]- this is an info message

The first item in the log entry printed to the console is the name of the logger object that issued the log entry.  Because GetLogger was passed a reference to my Program type, the logger name is the fully qualified type name of the Program object.

Add another class to the project:

namespace Tutorial5_Loggers
{
    class MyClass
    {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        public static void WriteLog()
        {
            Log.Info( "this is an info message" );
        }
    }
}

and add a call to MyClass.WriteLog to your Main method (see line 7 below):

static void Main( string[] args )
{
    log4net.Config.XmlConfigurator.Configure();

    Log.Info( "this is an info message" );

    MyClass.WriteLog();
    Console.ReadLine();
}

Compile and run, and note the logger name in the second log statement matches the type name of MyClass:

Tutorial5_Loggers.Program [INFO]- this is an info message
Tutorial5_Loggers.MyClass [INFO]- this is an info message

Hierarchical Logger Configuration

You can use loggers this way to isolate logging concerns across your objects, and I wholly recommend you do so.  This will enable you to throttle and direct log output from individual loggers using log4net's hierarchical configuration mechanism.

Update your app.config to the following:

 
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>

  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="false"/>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
    </root>
    <logger name="Tutorial5_Loggers">
      <level value="ALL" />
      <appender-ref ref="FileAppender" />
    </logger>
    <logger name="Tutorial5_Loggers.Program">
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </logger>
    <logger name="Tutorial5_Loggers.MyClass">
      <level value="ALL" />
    </logger>
  </log4net>
</configuration>

On line 12 we add a file appender to the mix; lines 23-33 provide configuration for specific logger objects.  Note that the logger names correspond directly to the namespace-qualified type names and namespaces from our project.  Specifically:

  • on line 23 a logger is configured specifically for the "Tutorial5_Loggers" namespace; this logger is configured to write logs to the file appender;
  • on line 27, a logger is configured for the Program class; this logger is configured to write logs to the console;
  • on line 31, a logger is configured for the MyClass class; this logger is not configured with an appender.

Compile and run, and you'll notice that:

  • the console output displays only the log statement from the Program class;
  • a "log-file.txt" file is written in the application folder, and this file contains the log statements from both the Program and MyClass types.

Now change the level value for the Tutorial5_Loggers.MyClass from ALL to OFF:

<logger name="Tutorial5_Loggers.MyClass">
  <level value="OFF" />
</logger>

Compile and run, and note that the log-file.txt file no longer contains the log statement from the MyClass object.  

This hierarchical configuration system can be incredibly useful; a common practice is to disable logging of "verbose" objects by targeting their specific type with a logging level set to OFF; another is to provide a "specific-needs" logger configured with a special appender, such as a gateway to the windows event log or a remote log viewer.  However, the system has a few caveats you need to know about:

  • appenders accumulate through the hierarchy: if the Program class and Tutorial5_Logger namespace are each configured to append to the console, any log from the Program class will show up twice in the console (once for the class logger and once for the namespace logger);
  • logger levels deeper in the hierarchy trump the shallow ones: if the Program class logging level is set to ALL and the Tutorial5_Logger namespace logging level is set to OFF, logs from the program class are still written to the appenders configured for Tutorial5_Logger.

Coming Up

The first 5 tutorials have given you some pretty heavy-hitting abilities.  Next time I'll discuss associating context to log messages, which can provide invaluable debugging information.