Debugging DICOM Query/Retrieve Communication

I recently had the questionable pleasure of writing a DICOM Q/R-module, for communication with a PACS. A future post may be dedicated to letting some steam out, and listing in detail the reasons I consider DICOM to be the worst standard I came across – but this post is meant only to give one (hopefully) substantial development tip, for fellow DICOM warriors.

Suppose, for example, the functionality you’re debugging is querying a PACS for the list of imaging studies performed on a particular patient.

First, get your hands on some DICOM utility that does the work you’re trying to do (IDoImaging had tons of these.). I used JDicom and will refer to it below for brevity, but really, any will do.

Medical Connections, makers of DicomObjects, give away free access to a custom DICOM server specifically designated as ‘A public resource for all DICOM developers to use for testing’. It supports all Query/retrieve service class commands. It accepts any AE title, and responds to the sending AE. As of this writing, its URL is http://www.dicomserver.co.uk and its IP is 87.106.65.167 – but check the link, as it had changed only recently.

What’s so useful about the Med-Conn server is that it dumps a very, very detailed log of all activity – down to every single DICOM element, in every message, in every association it handles.  Partial dump sample:

14:01:15 (8941) IN  Command = 30
14:01:15 (8941) IN  SOP Class = 1.2.840.10008.1.1
14:01:15 (8941) IN  Verification request Received
14:01:15 (0) in main Send Verify Received
14:01:15 (8941) OUT  (0000,0000) 0004 UL 66 (0x42)
14:01:15 (8941) OUT  (0000,0002) 0012 UI 1.2.840.10008.1.1
14:01:15 (8941) OUT  (0000,0100) 0002 US 32816 (0x8030)
14:01:15 (8941) OUT  (0000,0120) 0002 US 1 (0x1)
14:01:15 (8941) OUT  (0000,0800) 0002 US 257 (0x101)
14:01:15 (8941) OUT  (0000,0900) 0002 US 0 (0x0)
14:01:38 (8941) IN   (0000,0000) 0004 UL 56 (0x38)
14:01:38 (8941) IN   (0000,0002) 0012 UI 1.2.840.10008.1.1
14:01:38 (8941) IN   (0000,0100) 0002 US 48 (0x30)
14:01:38 (8941) IN   (0000,0110) 0002 US 2 (0x2)
14:01:38 (8941) IN   (0000,0800) 0002 US 257 (0x101)
14:01:38 (8941) IN  Command = 30
14:01:38 (8941) IN  SOP Class = 1.2.840.10008.1.1
14:01:38 (8941) IN  Verification request Received
14:01:38 (0) in main Send Verify Received
14:01:38 (8941) OUT  (0000,0000) 0004 UL 66 (0x42)
14:01:38 (8941) OUT  (0000,0002) 0012 UI 1.2.840.10008.1.1
14:01:38 (8941) OUT  (0000,0100) 0002 US 32816 (0x8030)
14:01:38 (8941) OUT  (0000,0120) 0002 US 2 (0x2)
14:01:38 (8941) OUT  (0000,0800) 0002 US 257 (0x101)
14:01:38 (8941) OUT  (0000,0900) 0002 US 0 (0x0)

Quoting the Medical-Connections page:

The live log files are available at the following URL :

http://dicomserver.co.uk/logs

Note that the log files may contain a mixture of your own and other users’ activity, but they restart every hour in order to keep the size manageable.

- but do check back the original link, to validate the logs address.

Next – hook up both JDicom and your own software to communicate with the Med-Conn server. Take a first pass with JDicom – either upload your own sample study (make sure you anonymize!), or query the UIDs of some patients & studies lying around there.

Just before you start, save a copy of the current log. Perform the desired transaction using JDicom (i.e., the tool that works). Update the log page and save a 2nd copy. Now, diff the two logs (image below is illustrating Araxis usage). The difference you are seeing is nothing less than a complete trace of a correct form of the transaction you’re trying to perform.

Lastly, repeat the process with your own software in place of JDicom (i.e., use the tool that needs fixing). You end up with a complete trace of the transaction YOU are invoking.

Diff these two!

Some of the differences you’ll spot are supposed to be there (e.g., various association UIDs) – but after a minute or so of noise cleanup, the important difference (a.k.a, the bug) would easily jump into view.

Enjoy!

Sound Alerts on VS Events – Revisited

I started using the sound alerts on a machine with VS2008 express – and I just learnt that this tweak works for VS2003 and VS2008 but not VS2005. Here’s how it (apparently) came about:

First, MS deliberately took it out. Quoting Paul Harrington: “The audio cues were removed for performance reasons. Initializing the multimedia DLLs to play the sounds was costing several hundred milliseconds in some high priority performance scenarios.”

That was a weird move – made even weirder by not removing the control panel options for setting build event sounds.

Indeed, MS got a lot of heat from devs and changed their mind – both on that same forum thread (quoting Harrington again: “We made the wrong engineering decision to remove the feature..”), and on MS connect. The feature happily returned on VS2008.

Sound alerts on VS events

When a build is more than a few seconds, I often drift off – to either productive or unproductive activity, but anyway into something I must snap out of. So for me personally, the following just discovered tweak can be a noticeable productivity enhancer:

You can select sounds for VS to play on the following events -

• Build succeeded,
• Build Failed,
• Build Canceled,
• Breakpoint hit.

In a remarkable display of weird UI design, these are set nowhere near Visual Studio, but rather under Control Panel / Sound and Audio Devices. In the ‘program events’ list, scroll down to ‘Microsoft Visual Studio’, and choose your sounds.

Coding Binary as Binary

If you’re comfortable with hex, you have no business in this post.  If on the other hand, when faced with a mask like 0xFFA8 you’re forced – like me – to translate it on paper into 11111111 10101000,  then by all means, read on.

Being the hex-challenged (hexicapped?) that I am, I badly need to somehow express 0x7F800000 as (0111 1111 1000 0000 0000 0000 0000 0000). With some nerve, I’m not willing to sacrifice any run-time performance to get there.  Good news are, this can be done. Better news are, it involves some neat preprocessor and metaprogramming tricks!

C++ Template Metaprogramming gives an excellent starting point:

template <unsigned long N>
struct binary
{
   static unsigned const value
     = binary<N/10>::value << 1   // prepend higher bits
       | N%10;                    // to lowest bit
};
template <>                           // specialization
struct binary<0>                      // terminates recursion
{
static unsigned const value = 0;
};
// usage:
unsigned const five  =  binary<101>::value;

This trick of recursive template instantiation is already considered standard metaprogramming, and will not be covered here. Sadly, an attempt to apply it directly to real-life constants -

unsigned const mask  =  binary<01111111100000000000000000000000>::value;

Fails miserably. A decimal literal like 1111111100000000000000000000000 goes way above anything the tokenizer can interpret as an integer. In fact, the largest such constant is 18446744073709551615LL,  which still is 11 orders of magnitude too low.

Ok then, that one is easy: let’s break the input into 4 arguments:

unsigned const mask  =  binary4<01111111, 10000000, 00000000, 00000000>::value;

We can apply the template recursion on each argument separately, and eventually shift the four results and push them into a single DWORD.  Why oh why then, do we still get ridiculous failures??

Alas, the real fun begins: a leading zero is interpreted as an octal prefix! An argument like 01111111 is interpreted as the decimal 299593 – and the template recursion breaks entirely.

What if we create a separate template recursion, specifically for octal numbers? Doesn’t seem so hard, just replace N%10 with N%8 in the code. But wait… how can we know whether an argument was originally interpreted from an octal literal (01111111) or a decimal (1111111)?

Pushing forward – let’s take the less-than-elegant assumption that each argument is exactly 8 binary digits. The highest number to be interpreted as octal in this setting is 01111111, which is 299593 in decimal.  We can just compare: any argument equal to or below 299593 is subject to an octal template recursion, and any argument above – to a decimal one.

Ummm, wait. we need to perform that comparison, and branch on its result at compile time.

This is in fact possible, and the given reference is an excellent source for such tricks (hints: grok boost::mpl::bool_, and trade specialization for overloading). Anyway, for me personally, this is also where the fun stops. A much dumber approach is in order, and luckily – one exists. We can pre-process the input to pad 1 to its left, and subtract 100000000 in the code.

#define PAD1(N) (1##N)
#define BINARY32(N1, N2, N3, N4)   binary4<PAD1(N1), PAD1(N2), PAD1(N3), PAD1(N4)>::value

template<DWORD N>
struct binary_Unpad
{
	// for now assume input is 1 + 8 binary digits
	static const DWORD Unpadded = N - 100000000,
			value = binary<Unpadded>::value; // back to classic recursion
};

template <DWORD N1, DWORD N2, DWORD N3, DWORD N4>
struct binary4
{
	static const DWORD val1 = binary_Unpad<N1>::value,
			val2 = binary_Unpad<N2>::value,
			val3 = binary_Unpad<N3>::value,
			val4 = binary_Unpad<N4>::value,

			value = ( (val1 << 24) |
						(val2 << 16) |
						(val3 << 8)  |
						(val4) ) ;
};

It is also possible to assert on input digits being 0/1, and on being exactly 8 such digits. Personally, I was very happy at this point, to just be able to write-

#define  FLOAT_EXP_MASK     BINARY32(01111111, 10000000, 00000000, 00000000)

Some day I’ll write about viewing binary as binary – more autoexp stuff coming up there.

Naming threads

There is a nice feature that is all but undocumented, and has next to no web presence too:  you can give your threads meaningful names.

While this is trivial in managed code, it is hardly obvious for native.  The TIB (the internal thread administration data table) does not include a name slot, so there’s not much use looking for some SetThreadName(…) API in win32.

Anyway, the MS debuggers (both Visual Studio and the WinDbg family) have a secret trap door just for that:  the exception 0x406D1388.  When raised, the debugger (obviously) gets a first-chance of handling it. This exception can carry thread-naming info, in an undocumented THREADNAME_INFO type, and the debuggers can interpret this info and internally attach that name to that thread ID.  A quick rehash of the MSDN code:

//
// Usage: SetThreadName ("CurrentThread");
//        SetThreadName ("OtherThread", 4567);
//

typedef struct tagTHREADNAME_INFO
{
   DWORD dwType; // must be 0x1000
   LPCSTR szName; // pointer to name (in user addr space)
   DWORD dwThreadID; // thread ID (-1=caller thread)
   DWORD dwFlags; // reserved for future use, must be zero
} THREADNAME_INFO;

void SetThreadName( LPCSTR szThreadName, CONST DWORD dwThreadID = -1)
{
   THREADNAME_INFO info;
   info.dwType = 0x1000;
   info.szName = szThreadName;
   info.dwThreadID = dwThreadID;
   info.dwFlags = 0;

   __try
   {
      RaiseException( 0x406D1388, 0, sizeof(info)/sizeof(DWORD), (DWORD*)&info );
   }
   __except(EXCEPTION_CONTINUE_EXECUTION)  {}
}

This can be a valuable debugging aid in multi-threaded apps – which today amounts to practically all of them.

Debugging Native Memory Leaks, Part 1: LeakDiag

Leaking memory is probably the single most painful aspect of native code – its the reason managed was ever born.

At work, our code routes ‘new’ calls through_aligned_malloc_dbg. This CRT API, along with cousins like _malloc_dbg and _calloc_dbg, takes extra parameters containing a file name and line number, and so enables the CRT to report the exact location of an unreleased allocation upon process termination:

Sadly, this is useful only in the handful of cases where the code allocates directly. What if the offending allocation is performed via some common container routine? Even worse – what if the leak is properly de-allocated in destructors at shutdown time?  The CRT support would be of no use. Wouldn’t it be nice if we could see the entire stack that allocated unreleased memory?

There are two powerful, free, and vastly different tools from Microsoft, that achieve just that.

Enter LeakDiag!

I’m actually not sure how public this tool is. Two of its components, LeakDiag and LDGrapher are available on the public MS FTP, but a third one, LDParser, seems to be available only by Microsoft Premier Support. Anyway, both LDParser and LDGrapher only format the output, and LDGrapher can do most (but not all!) of what LDParser does.

LeakDiag does its magic by using Detours technology (fascinating read!) to intercept memory allocators calls. Detours enables interception of any API, and not just replace it but extend it – that is, it preserves the original function, and enables calling it via a so called ‘trampoline’ stub.  LeakDiag allows you to specify various low-level allocators, and once activated it intercepts them and adds stack-walking functionality to them.

To demonstrate, consider the leaking code here (adapted from a UMDH demo) :

#include "stdafx.h"
#include
#include

void LeakyFunc1();
void LeakyFunc2();
void LeakyFunc3();
void LeakHere(int value);

int _tmain(int argc, _TCHAR* argv[])
{
  printf("Activate LeakDiag tracking here...nn");
  _getch();
  printf("Take first log now...nn");
  _getch();

for (int i=0;i<1000;i++)
{
  LeakyFunc1();
  LeakyFunc2();
  LeakyFunc3();
}

  printf("Take second log..nnPress any key to exit application...n");
  _getch();

  return 0;
}

void LeakyFunc1() { LeakHere(500);  }

void LeakyFunc2() { LeakHere(1000); }

void LeakyFunc3() { LeakHere(1500); }

void LeakHere(int value) { char * cBuff = new char[value]; }

Start LeakDiag and run your program.  In the LeakDiag window select view/Refresh (just a good habit, meaningful if it was already running), and select your process at the list (in this example:  LeakyApp.exe).  At the first wait for input (and generally, as early as you can in the program), start the LeakDiag C Runtime allocator:

This activates the API interception in your selected process (LeakyApp.exe), for your selected API (CRT allocator).

Focus back to LeakyApp.exe and press any key.  At the second and third waits for input, take a LeakDiag log:

Click anything again to end the program. LeakDiag dumps his logs as xml files, by default into %LeakDiag dir%/logs.  The files are quite readable and it is occasionally useful to manually dig in – but to gain some insight into large dumps (or many dumps), LDGrapher can help tremendously.

Start LDGrapher.  Open all the allocation logs you dumped. A multi-line graph would appear, where every line represents a specific recurring allocation stack. The stack responsible for most allocations is coloured red, the rest are yellow. Each x-tick is a specific log dumped.  And the useful part: click any circle, representing an allocation stack at a specific log, and inspect the complete stack leading to that allocation, along with source file names and line numbers!

While this is mega-cool as is, it can be further tweaked in many ways. You can intercept and dump different allocators. If you’re hunting for a leak of a known size, you can limit the dump to include just that size (or a size range). You can use DbgHlp StackWalk to overcome FPO (which you shouldn’t use in your own code anyway!), and some more.

However,  LeakDiag has one significant flaw – that I think amounts to just a weird design choice (that is, I can’t understand when it would be helpful): all its functionality (except the GUI) seems to run in the target process. You can actually see LeakDiag messages in your debugger.

That can make delicate control quite hard. For one, you cannot place breakpoints in locations where you want a dump. (hence,the ‘getch’ in the code sample).  For two, suppose you’re not continuously leaking memory – but just forgot to release some. Wouldn’t it be nice to be able to take an allocation dump just before the process terminates, and see whatever still needs releasing?  Alas, you cannot do this with LeakDiag, as any code you intend to run immediately before terminating would not run.

The solution (hint, UMDH), would have to wait for another post.