Sorry for the awful pun, but now you’re probably thinking I’m mad, either that or you now have the lyrics of “How much is that doggy in the window” racing around in your head.
Anyhow, the point of this post is to show something that I’ve carped on about for some time and that is logging – or more specifically “Do you know the resources your logging framework is using, especially when its turned off”.
I’ve advocated method entry/exit logging for ages – indeed I posted about this some while ago. The point of this post is to show why you need to look into your logging code and the difference a bit of profiling can do.
I was in the scalability labs this week with a customer who had liberally sprinkled method entry/exit logging all through the code. Top marks. That said, the implementation needed some tweaking as it was relatively expensive. Logging is like electricity – you should only pay for it if you use it. If you’ve gone around your house and turned off all unnecessary electrical devices then you know the deal – get an energy meter, check how much juice your DVD/Telly/whatever uses on standby, and then religiously turn them off. The same is true of logging – if it’s off it shouldn’t be using any resources, and you can use profiling to work out how costly or otherwise it is.
So, what was the code that I saw. It’s as follows…
static void MethodUnderTest()
{
CustomerLogger.WriteTrace(string.Format(CultureInfo.InvariantCulture,
"Method Entered {0}", new object[] { "B1" }));
// Do stuff here
CustomerLogger.WriteTrace(string.Format(CultureInfo.InvariantCulture,
"Left {0}", new object[] { "B1" }));
}
As there were a lot of methods that had the same code, and many methods called many others, you can imagine that the number of calls to the WriteTrace method was very high, so anything I could do here to speed things up would have some effect to the application and was well worth doing.
So, what’s the problem with the above? It’s all about being lazy.
If logging is off (which is normally the natural state for an application in production) you would ideally like your logging code to have limited effect – i.e. it shouldn’t cost anything if it’s disabled. The problem with the above is that, regardless of the state of logging, you’re paying for the call to string.Format (and in the customers case some other stuff within the WriteTrace method too) which could be avoided.
I popped together a small example application to replicate just what the customer was doing here, and running it under the Visual Studio profiler I could see that the the current method of logging was (for 100,000 iterations) taking 11.5s, and my proposed solution was down at 4.5s for the same test. That’s a fair amount of time being wasted, but it gets more interesting.
The next tool I used to look at the issue was the most excellent (and free!) CLR Profiler. This has been around since the dawn of time (OK, sometime in 2002 ish I seem to recall) and it’s a tool that you really should download and use. What this showed me was the amount of memory that the current logging method was using (remember, logging is switched off)…
Here the graph shows that 99.69% of the memory used by the entire allocated was inside the TestCurrent method (which tests the current logging implementation). And only 620 bytes are allocated by my test method – which in effect does the same as logging is off. Yes, the same. If logging is turned off you really shouldn’t be allocating all of this junk, just to have it thrown away immediately when the logging class determines that no output is necessary.
You might ask – what’s allocating so much memory. Well, in the test I’m calling the candidate methods 100,000 times, and each test is calling down through 5 levels of method calls (which is a fair representation of what my customer was doing). So for one iteration that would be 10 calls to String.Format(), with the formatted string thrown away moments later. Each call was allocating a string, a string builder and a few other objects too.
The code I was using in the TestFast method was the MethodEntryExit logger I blogged about here. All I did to the customers code was remove their logging code and added in mine (which is trivial). Just to recap, I created a disposable class that is used as follows to write method entry/exit information (and timings too, if you so desire). Using it is a breeze…
static void MethodUnderTest()
{
using (MethodLogger.Log("MethodUnderTest",
LogOptions.Entry | LogOptions.Exit, GlobalSource))
{
Fast2();
}
}
The last parameter here is a TraceSource. If you’ve not come across this class before you should read up the essay (!) I wrote on logging in .NET over on CodePlex.
The moral of the story is – check how much you’re paying for logging if it’s off. There really should be little or no overhead!
I was writing a helper class today for WPF and had a IsDirty flag which was firing a PropertyChanged event. However, when I used this in my UI the element that was bound to this flag was not updating.
After a quick look through my code I noticed the following…
private void OnPropertyChanged(string property)
{
if (null != PropertyChanged)
PropertyChanged(null, new PropertyChangedEventArgs(property));
}
I’d mistakenly used null as the first parameter to the PropertyChanged handler. After changing the parameter to this everything started working as expected.
So the moral of the story is – WPF needs both the object raising the notification and the property changed events in order to work its magic.
[Note – this article is based on Workflow 4 Beta 1, some things will change for Beta 2]
First off let me apologise for the length of this post. If you just want the code, skip to the bottom.
I don’t know about you but some words just don’t seem to make their way into my skull very easily, and correlation is one of them. It doesn’t matter how many times I say it in my head, even really slowly “c-o-r-r-e-l-a-t-i-o-n”, it still makes little sense.
So, in the spirit of sharing I thought I’d post what I know about correlation (in as far as it’s used in Workflow 4), and add in some code to cement the subject. First off though I thought I’d pop upstairs and look at the dictionary definition of correlation so here goes…
- Correlate – have a relationship or connection in which one thing affects or depends on another
- Correlation – connection, association, link, tie-in, tie-up, relationship, interrelationship, interdependence, interconnection, interaction
Thanks to the “Concise Oxford English Dictionary” for the former definition, and the “Oxford Paperback Thesaurus” for the latter. I hope they won’t mind me using their definitions here but if they do then someone else wrote this article, it wasn’t me, honest. As an aside, the “Concise OED” is a bit of an oxymoron if you see the physical size of it, but then again if you saw the full OED then you’d realise why this was called the concise version. Anyhow, enough English language for now!
So, how does correlation apply to a workflow then?
In the old days (well, pre Workflow 4), the common way to deal with a workflow instance was to know it’s instance ID which was a GUID. You had a workflow definition (i.e. some XML or a coded workflow), and when you created an instance of that workflow definition you had a workflow instance, and it was uniquely identifiable by its workflow instance ID. Simple.
If I wanted to do anything with a WF 3.x workflow, all I needed to know was it’s GUID and I could load it up, send messages to it, find it in the persistence database and so on. When I created a workflow instance I could optionally choose to assign my own GUID to it rather than having the system generate one for me. Life was good.
Now, lets say you were exposing a workflow as a service. You might have a few operations defined on that service and want to call these in whatever order suited you. You’ll define the first operation (which effectively kicks off the workflow), then subsequent operations will be called on the same instance of the workflow. In traditional programming you would maybe implement an interface something like the following…
[ServiceContract]
public interface IStudent
{
[OperationContract]
Guid EnrollStudent(string name, DateTime dob);
[OperationContract]
void AddExamResults(Guid studentId, string examName, int mark);
[OperationContract]
void Graduate(Guid studentId);
}
So the initial operation is EnrollStudent, and this returns the GUID of that student. Then some time later (days/weeks/months/years) you call AddExamResults and pass through the GUID in order to hook up the results with the right student. Finally at some point in the future the Graduate method is called (OK, maybe they flunked, but I’ll keep this simple). That’s all fairly easy to understand.
Now, if you were doing this in the workflow world things would be a little different. As of now (Workflow 4 Beta 1) you can’t do contract first workflow services, so you need to define the service contract within the workflow itself. Hopefully this limitation will be fixed by the time Beta 2 drops as I quite like contract first development these days.
In the service contract I defined above, the thing that identifies one student from another is the GUID returned from the initial EnrollStudent method. You can conceptually see that this key uniquely defines the student instance, and as long as you use that every time you want to ‘talk’ to that student instance then everything will be just fine.
Moving this service into the world of Workflow 4, we need some identifier that does the same job – it ties my requests to an instance of a workflow. Suppose I have two clients. The first calls EnrollStudent and this constructs an instance of my workflow and then returns the unique ID back to the caller. The second client can call EnrollStudent and will get a different ID and so now there will be two distinct workflow instances ‘running’ (they may be persisted to the database). Now when I get calls to the AddExamResults method I need to have these go to the appropriate workflow instance, and it’s correlation that does that. You don’t have to use GUIDs by the way – correlation in WF 4 allows you to define anything in the message as the correlation ‘handle’ – indeed you can use multiple items in the message as this handle which is very cool indeed. However for this example I’m using just one thing – a GUID.
So, finally, we have my definition of correlation as it applies to WF 4…
- Correlation – hooks messages to the workflows they are intended to reach
OK, so that’s a fairly poor definition and I don’t think the OED will be knocking on the door any time soon asking me to write for them, but hopefully you get the drift. Enough waffle though, lets get to some code. I’ll try to emulate the above service contract with WF 4, and use code to call that service.
Example – Defining the Workflow
In this example I’ll use code throughout – no XAML here folks! First off I need to define some data contracts for the arguments I’m passing in to the service methods. These mimic the parameters I’m passing to the service contract I outlined above…
[DataContract(Namespace = "http://www.morganskinner.com")]
public class EnrollStudentArgs
{
[DataMember]
public string Name { get; set; }
[DataMember]
public DateTime DateOfBirth { get; set; }
}
[DataContract(Namespace="http://www.morganskinner.com")]
public class AddExamResultsArgs
{
[DataMember]
public Guid StudentId { get; set; }
[DataMember]
public string ExamName { get; set; }
[DataMember]
public int Mark { get; set; }
}
So here I have two data contracts, one for the EnrollStudent operation and another for the AddExamResults operation. I need to do it this way as there’s no way to define multiple arguments to the Receive activity at present (this will be coming in Beta 2). You would currently need to do this for every method that takes more than a single argument, and whilst it’s a bit of a pain to have to do it that’s just the way it is for now. Well actually that’s a bit of a lie, there is an activity that will do this in Beta 1 but some changes are afoot for Beta 2 so I decided to show you this method which works for now.
Now we need a workflow. For this example I’ve chosen to build the workflow up as follows…
- An initial call to the EnrollStudent operation is made. This kicks off a new workflow and passes in the EnrollStudentArgs, consisting of the Name and DateOfBirth. This data is stored away within the workflow and a new GUID returned to the caller.
- The workflow then sits in a loop, waiting for a call to AddExamResults or a call to Graduate.
- If AddExamResults is called the data is output to the console
- If Graduate is called then the loop will exit and the workflow will complete
So, the overall workflow will be defined roughly as follows …
I’ve simplified it a bit as in the workflow there are actually many more activities, but hopefully this image conveys the main structure. I’ll build the code up step by step and explain what the bits are as I go along.
The first thing you’ll need to define are some variables and the initial Receive activity…
// Correlation handle to link the initial receive to the subsequent send
Variable<CorrelationHandle> enrollHandle = new Variable<CorrelationHandle>();
// Arguments received from the initial call to EnrollStudent
Variable<EnrollStudentArgs> enrollArgs = new Variable<EnrollStudentArgs>();
// The generated student Id
Variable<Guid> studentId = new Variable<Guid>();
// The namespace I'm using for all of the contracts etc
string ns = "http://www.morganskinner.com";
// This Receive activity kicks off the whole workflow
Receive receive = new Receive
{
CanCreateInstance = true,
CorrelatesWith = enrollHandle,
OperationName = "EnrollStudent",
ServiceContractName = XName.Get("IStudent", ns),
Value = new OutArgument<EnrollStudentArgs>(enrollArgs)
};
The CorrelationHandle is used to link the initial Receive and the subsequent SendReply together. Here I’ve also defined that the output value from the Receive should be stored away in a variable called enrollArgs. This variable will be globally scoped in the workflow (not that it needs to be – I could have defined it locally). I’ve also defined the studentId variable which will be used to store the unique Id created by the code. In a real solution you might just pass this Guid up from the client in the initial call – however that would have been less for me to demonstrate so I chose this method instead.
What we have defined is now nearly enough to so the first stage of the workflow – the initial Receive, the computation of the Guid and the SendReply to pass this Guid back to the client. I say nearly enough – there is one more thing we need to define up front but I’m going to gloss over that just for a moment and show the workflow up to this point…
return new Sequence
{
Variables = { enrollHandle, enrollArgs, studentId },
Activities =
{
receive,
new WriteLine { Text = "Assigning a unique GUID" },
new Assign<Guid>
{
To = new OutArgument<Guid>(studentId),
Value=new InArgument<Guid> (Guid.NewGuid())
},
new WriteLine { Text = new InArgument<string>(env=>
string.Format("GUID assigned was '{0}'", studentId.Get(env)))} ,
new SendReply
{
CorrelatesWith = enrollHandle,
Value = new InArgument<Guid>(studentId),
Request=receive,
AdditionalCorrelations = {{ "StudentIdQuery", operationHandle}},
CorrelationQuery = new CorrelationQuery
{
SelectAdditional = { studentIdOutputQuery }
}
}
}
}
So here I’ve defined a Sequence, and inside it are the receive activity we’ve defined earlier (this cannot be defined inline as the SendReply activity needs a reference to it). I’ve added some WriteLine activities so that we can see what the workflow is up to, and then defined the SendReply which is where it all gets a bit hectic.
The first three properties are fairly simple – CorrelatesWith defines a correlation handle link between the SendReply and the earlier Receive. The Value is simply what we want to return from the SendReply, and Request=receive links this SendReply with the earlier Request activity.
Now, if you remember the API I wanted to expose, I want to return a Guid from the initial call and use this same Guid on subsequent calls to identify the workflow instance that should process that call. That’s what the AdditionalCorrelations and CorrelationQuery properties are defined for. What I’m defining here is a query that will strip out the return value (i.e. the Guid) and associate this with another correlation handle – in this case the operationHandle.
So, in order to get this to compile I need to define the following before defining the Sequence shown above…
// The correlation handle defined after the initial receive/send pair
Variable<CorrelationHandle> operationHandle =
new Variable<CorrelationHandle>();
// Define a message context
XPathMessageContext messageContext = new XPathMessageContext();
messageContext.AddNamespace("local", ns);
// This query retrieves the output argument sent from the SendReply
MessageQuerySet studentIdOutputQuery = new MessageQuerySet
{
{ "StudentId", new XPathMessageQuery("sm:body()/ser:guid", messageContext) }
};
studentIdOutputQuery.Name = "StudentIdQuery";
Here I’ve defined the second correlation handle which will be used by the subsequent calls from the client (AddExamResults and Graduate). Then I’ve defined the message context which is used when defining the XPathMessageQuery objects that are used within the MessageQuerySet. I’ve defined a namespace prefix of “local” to refer to the namespace of my classes – we’ll need this again later in the example when retrieving values passed up from the client.
The MessageQuerySet object is used to define which bits are stripped from the message. In this case I have just one named value - “StudentId”, and this comes from the rather cryptic “sm:body()/ser:guid” XPath statement.
Now I’m not here to give you a lesson in XPath (and indeed you wouldn’t want one from me either!). If like me you think that XPath is akin to Voodoo Magic then I wouldn’t blame you.
The sm:body()/ser:guid implies that I’m looking throughout the ‘body’ of the message message for the ‘guid’ element from the ‘ser’ namespace and returning that. If you look at the actual data returned from the SendReply activity on the wire you would see something like the following (I captured this using the most excellent Fiddler2 tool)…
HTTP/1.1 200 OK
Content-Length: 203
Content-Type: text/xml; charset=utf-8
Server: Microsoft-HTTPAPI/2.0
Date: Fri, 04 Sep 2009 09:15:52 GMT
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
<s:Body>
<guid xmlns="http://schemas.microsoft.com/2003/10/Serialization/">
ddafc236-bec4-4745-bc6d-882f5ab3b051
</guid>
</s:Body>
</s:Envelope>
Here you can probably infer that we’re using ‘ser’ as a prefix for the Serialization namespace. It makes sense now, but I don’t much like magic prefixes – there are a bunch that are currently defined and used within the framework but are not currently documented. The documentaton should be sorted before WF 4 is released. If you’re interested these constants currently live on the XPathMessageContext class.
With all that defined we’re at the point where we should have a working Receive and SendReply (and of course a few other activities). Now it gets even more interesting.
Now I want to be able to call either the AddExamResults or the Graduate methods. These both pass the Guid along on the wire, but the former also passes other information too. In order to get to the right workflow instance I therefore need to extract the student Id from these calls and match it up to my earlier extract.
For this to work I’ll need another couple of message query sets…
// Retrieve the AddExamResultsArgs.StudentId passed to AddExamResults
MessageQuerySet studentIdQuery = new MessageQuerySet
{
{ "StudentId",
new XPathMessageQuery
("sm:body()/local:AddExamResultsArgs/local:StudentId",
messageContext) }
};
// And this one retrieves the value passed in to the Graduate method
MessageQuerySet graduateId = new MessageQuerySet
{
{ "StudentId", new XPathMessageQuery("sm:body()/ser:guid",
messageContext) }
};
The first message query set defines the XPath that will strip out the value of the StudentId property from the AddExamResultsArgs class. You’ll see that I’ve included the ‘local’ namespace prefix for both of these elements – it’s necessary, you won’t get anywhere without it.
The second message query set is used for the call to the Graduate method – here I’m just passing up a simple Guid and so need to strip just that Guid out of the message.
With a couple more variables defined (a boolean flag ‘finished’ and a variable to record the exam results) and two more receive activities we’re pretty much sorted…
// A variable used to hold the exam results just added
Variable<AddExamResultsArgs> examResultArgs =
new Variable<AddExamResultsArgs> ( ) ;
// Flag indicating that we're done
Variable<bool> finished = new Variable<bool> { Default = false };
// This recieve activity waits for the AddExamResults operation to be called
Receive receiveAdd = new Receive
{
OperationName = "AddExamResults",
ServiceContractName = XName.Get("IStudent", ns),
Value = new OutArgument<AddExamResultsArgs>(examResultArgs),
CorrelatesWith = operationHandle,
CorrelationQuery = new CorrelationQuery
{
Select = studentIdQuery
}
};
// And this activity waits for the Graduate operation to be called
Receive receiveStop = new Receive
{
OperationName = "Graduate",
ServiceContractName = XName.Get("IStudent", ns),
CorrelatesWith = operationHandle,
CorrelationQuery = new CorrelationQuery
{
Select = graduateId
},
Value = new OutArgument<Guid>(studentId)
};
In the above I’ve defined the other receive operations that my workflow will process. These again need to define their operation names and the name of the service contract to which they belong, and the only other tricky part is to define the correlation information. The AddExamResults operation is passed an argument of the AddExamResultsArgs type, so I need to strip out the AddExamResultsArgs.StudentId in order to correlate this message with the workflow. That’s just what the CorrelatesWith and CorrelationQuery are doing.
The second operation is just passed a Guid, so again I’m using a query that will retrieve the Guid passed to the Graduate operation.
Finally we get to the rest of the workflow…
return new Sequence
{
Variables = { enrollHandle, enrollArgs, studentId,
finished, operationHandle },
…
new While
{
Condition = ValueExpression.Create<bool>
( env => !finished.Get(env)),
Body = new Pick
{
Branches =
{
new PickBranch
{
Variables = {examResultArgs},
Trigger = receiveAdd,
Action = new WriteLine
{
Text = new InArgument<string>
(env=>string.Format
("Student '{0}' received '{2}' in '{1}'",
examResultArgs.Get(env).StudentId,
examResultArgs.Get(env).ExamName,
examResultArgs.Get(env).Mark)
)
}
},
new PickBranch
{
Trigger = receiveStop,
Action = new Sequence
{
Activities =
{
new Assign<bool>
{
To = new OutArgument<bool>(finished),
Value = new InArgument<bool>(true)
},
new WriteLine { Text = new InArgument<string>
(env=>string.Format("Student {0} Graduated",
studentId.Get(env)))}
}
}
}
}
}
}
}
Here I’ve defined the While loop, and within it a Pick activity which is similar to the Listen from WF 3.x. It has any number of child branches and will wait until one of the branches completes. In this case my branches are awaiting calls to WCF methods that I’ve defined by using Receive activities.
The first branch schedules the Receive activity that awaits a call on the AddExamResults method (and writes this data out to the console when it arrives), and the second branch waits for the Graduate call to be made and then sets the boolean ‘finished’ flag so that the workflow completes.
Example – Hosting the Workflow
Now we have a workflow we need to host it. Again I’m just using code rather than XAML to show you all the stuff you need.
// Define the base address for the service
// Note - use the full name of the PC rather than localhost here
string serviceBaseAddress = "http://dev10-vpc:8080/StudentService";
using (WorkflowServiceHost host =
new WorkflowServiceHost(GetStudentWorkflow(),
new Uri(serviceBaseAddress)))
{
// Define the service namespace
string ns = "http://www.morganskinner.com";
// And add the endpoint
host.AddServiceEndpoint(XName.Get("IStudent", ns),
new BasicHttpBinding(),
serviceBaseAddress);
ServiceMetadataBehavior smb =
host.Description.Behaviors.Find<ServiceMetadataBehavior>();
// If none, add one
if (smb == null)
smb = new ServiceMetadataBehavior();
// Setup properties of the service metadata behavior
smb.HttpGetEnabled = true;
smb.MetadataExporter.PolicyVersion = PolicyVersion.Policy15;
// And set it
host.Description.Behaviors.Add(smb);
// Now open for business...
host.Open();
Console.WriteLine("StudentService is ready.");
Console.ForegroundColor = ConsoleColor.Red;
Console.WriteLine("Press <enter> to exit.");
Console.ResetColor();
Console.ReadLine();
host.Close();
}
Here I’ve defined the base address for the service to include the physical name of the machine I’m running on (dev10-vpc). If you use ‘localhost’ it will still work fine, however Fiddler2 won’t be able to pickup the traffic and display it for you.
I then construct a WorkflowServiceHost and add an appropriate endpoint to it. After that I’ve defined a metadata behaviour to permit clients to get the service metadata over Http (I could have added a metadata endpoint/binding instead). After that it’s just a case of opening the service and waiting for calls. You don’t need a .config file as all of the configuration has been done in code.
The last (and you’ll be glad to know, easiest!) part is creating the client.
Example – Creating a client
Construction of the client is simple. Add a service reference to the service (in my instance http://dev10-vpc/StudentService) and then call it. I’ve deliberately used different client instances here to prove that
static void Main(string[] args)
{
Console.WriteLine("Press a key to connect to the student service");
Console.ReadLine();
Guid studentId;
using (StudentService.StudentClient client = new StudentService.StudentClient())
{
studentId = client.EnrollStudent(
new EnrollStudentArgs { Name = "Fred Bloggs",
DateOfBirth = new DateTime(1980, 09, 04) }).Value;
Console.WriteLine("Student Id returned was '{0}'", g);
}
Console.WriteLine("Now press a key to call the service again");
Console.ReadLine();
ReportExamResults(studentId, "Maths", 90);
ReportExamResults(studentId, "English", 80);
ReportExamResults(studentId, "Woodwork", 100);
Console.WriteLine("Now press a key to call the Graduate operation");
Console.ReadLine();
// And finally graduate...
using (StudentService.StudentClient client = new StudentService.StudentClient())
{
client.Graduate(studentId);
}
}
private static void ReportExamResults(Guid studentId, string examName, int mark)
{
using (StudentService.StudentClient client = new StudentService.StudentClient())
{
client.AddExamResults(new AddExamResultsArgs
{
StudentId = studentId,
ExamName = examName,
Mark = mark
});
}
}
So there you have it. A worked example of correlation in Workflow 4 Beta 1. If you want to download the code for this sample please click here.
The very first talk I gave on .NET was on custom attributes – some time way back in late 2000 or early 2001. At the time I was espousing the benefits of using custom attributes to add on details of unit tests and bug fixes.
There have been many additions to .NET since then and I spied a couple of *really* cool new attributes in .NET 4 the other day so had to share them.
Enter (drum roll please) :-
- [Optional]
- [DefaultParameterValue]
Yay!
These are (I believe) a real productivity boost, and will make your code much easier to read. I bet you have some code like the following hanging around, don’t you…
public class Thingy
{
public Thingy()
: this("Default", -1)
{
}
public Thingy(string name)
: this(name, -1)
{
}
public Thingy(string name, int whatever)
{
_name = name;
_whatever = whatever;
}
// Other code...
private string _name;
private int _whatever;
}
Now there’s nothing desperately wrong with this, although I feel that 3 constructors is a bit ugly, I’d rather just have one. And what if I want to change the default value for the ‘whatever’ value – there are two places it’s used in the code above and I’d need to update both which is a bit on the fragile side.
With these swanky new attributes I can have just the one constructor…
public class Thingy
{
public Thingy([Optional, DefaultParameterValue("Default")] string name,
[Optional, DefaultParameterValue(-1)]int whatever)
{
}
}
Now that’s a whole lot better if you ask me! My defaults are in one place, I have only one constructor rather than three (obviously this works on methods too), and Intellisense and the C# environment understand the [Optional] attribute and present the appropriate stuff to me.
Now as if that wasn’t enough we’ve updated C# to support this without even having to write attributes (thanks to Wes Haggard for pointing this out to me)…
public class Thingy
{
public Thingy(string name = "Default",
int whatever = -1)
{
}
}
Ooh, how cool is that? All in all I’m very happy with this little addition to .NET and C#.
Polymorphism in any OO language is taken as a given – and people would be shouting about it a lot if a language didn’t support it. However, when you’re writing a service interface with WCF you might also want to permit some form of polymorphic behaviour at runtime.
I was working with a customer yesterday and they wanted to be able to extend their system by adding in custom commands. A command might be something like “Print customer record” or “Add customer to ringback queue”. Some of these commands could be executed locally on the client PC, however others might need to be sent up to the server.
On the day I came up with some suggestions but had a nagging doubt that what I’d created wasn’t as great as it could be. Now after a sleep and some more thinking I’ve realised the error of my ways.
The typical Command pattern espoused by the GOF is to have a command object that knows how to execute itself. So in .NET you might dodge up an ICommand interface as follows :-
public interface ICommand
{
void Execute();
}
Then you would create subclasses of this command object and be off on your merry way. Note that you could also use the ICommand interface that already exists in the framework – I’m a great one for reusing what’s already available and not re-inventing the wheel. That’s not really appropriate in this instance as I my commands will be remotely executed.
Now, what I want to do is have some commands executed on the server – for the sake of argument I’ll call these ‘Remote commands’. So when the Execute() method is called, what I actually want to call is a WCF service (and pass up something representing the command to the server). To do that I need to be able to pass up an arbitrary collection of arguments. I could use a dictionary but a discrete class feels better :-
/// <summary>
/// The command arguments class allows arbitrary commands to be executed
/// </summary>
[DataContract]
public class CommandArguments
{
}
And then I might need a derived class for adding a customer to a ringback queue…
[DataContract]
public class CustomerRingbackArguments : CommandArguments
{
/// <summary>
/// The ID of the customer we'll ring back
/// </summary>
[DataMember]
public int CustomerId { get; set; }
/// <summary>
/// The duration until we call them back
/// </summary>
[DataMember]
public TimeSpan RingbackWhen { get; set; }
/// <summary>
/// The reason for the call
/// </summary>
[DataMember]
public string Reason { get; set; }
}
So far so good. Now I need a service that I can call and pass these command arguments to…
/// <summary>
/// This service executes commands
/// </summary>
[ServiceContract]
public interface ICommandService
{
/// <summary>
/// Execute the command associated with the passed arguments
/// </summary>
/// <param name="arguments">Arguments to be used by the command when executed</param>
[OperationContract]
void Execute(CommandArguments arguments);
}
If I were then to code up the service and try to use it I would not be able to pass up an instance of my CustomerRingbackArguments class as WCF doesn’t know about the type. Typically in this case you would attribute up the service as shown below…
[ServiceContract]
[ServiceKnownType(typeof(CommandArguments))]
public interface ICommandService
The problem here though is that for every new CommandArguments derived class I would need to update this service contract. With a couple of command argument derived classes then that wouldn’t be too much of an issue, but what if I were to have 20 or 200 different command argument classes? That would start to make my interface look pretty awful. There is a better way – and one I only noticed today.
The ServiceKnownType attribute can be used to indirectly specify which types are used by the service contract. So, rather than attributing up your code you can define a static method (even on another class) which returns all types that the service interface should use in (de)serialisation.
To use it just choose another overload of the ServiceKnownType attribute :-
[ServiceContract]
[ServiceKnownType("GetKnownTypes", typeof(CommandServiceHelper))]
public interface ICommandService
Now when WCF is looking for types it will call the static method GetKnownTypes on my CommandServiceHelper class. This method is defined as follows :-
public static IEnumerable<Type> GetKnownTypes(ICustomAttributeProvider provider)
All you need to do here is round up all of your CommandArguments derived classes and you’re away! Now you will also need some mechanism to determine just what happens on the server when you get a given CommandArguments derived class sent up to the server, but that’s typically going to be a simple type based lookup mechanism (aka dictionary). I’ll leave that up to you to sort out.
It just goes to prove yet again that old adage – every problem in computing can be solved by another level of indirection.
I’ve had a rather frustrating afternoon but it’s all sorted now.
I’ve recently repaved my laptop with Windows 7 RC and installed loads of stuff at the same time, including VS2010 Beta 1. I’ve also more recently installed VS2008 as I needed it for the Ukadc.Diagnostics project that myself and Josh are collaborating on.
Now today I wanted to install something else, and found I couldn’t. I kept getting an error that was stating that there was already an installation in progress. Then a couple of Windows Updates failed too, so I knew something was amiss. After a bit of hunting around I found the rogue process – “msiexec /v” was the command line which I traced back to the Windows Installer service, and it was spawning off all sorts of other installations. Repeatedly. Without stopping. And it was using up to 50% of my CPU (which I’d obviously not noticed – but now I’ve sorted it I can really tell the difference!).
I then went for a hunt in the event logs and sure enough I found the culprit almost straight away – there were *thousands* of entries as follows :-
Detection of product '{AA4A4B2C-0465-3CF8-BA76-27A027D8ACAB}', feature 'VSTA_IDE_12590_x86_enu',
component '{FF4A39EF-8F8B-4557-9F81-50DC44C6D30A}' failed. The resource
'C:\Program Files (x86)\Microsoft Visual Studio 9.0\Common7\IDE\PublicAssemblies\en\' does not exist.
Well – that’s a fairly useful error message. I created the directory and my CPU is back to normal. The Windows Installer service is now dormant, and my PC is 50% faster doing what I want it to do.
So, if you’re having problems similar to mine check out MsiExec and see if you’ve got tons of entries in the event log.
If you’re running in a terminal services environment, or have multiple instances of a given application running on your machine, this tip will help you to work out which process is which in Perfmon. To see the issue, I’ve created a simple Windows Forms application and run up three instances of it on my machine. When I go into Perfmon, which process is which?…
You’ll see here that I have 3 instances of my test application - TestWinFormsApp, TestWinFormsApp#1 and also TestWinFormsApp#2. So, if I want to capture counters for a specific one of these (and maybe do some other stuff like taking process dumps at the same time) how can I do that as I don’t know the process ID?
Well, you can use Perfmon to display the process ID for you. Scroll down to the ‘Process’ section, choose ‘ID Process’ and then select your process instances and click on Add.
You’ll then have the process ID captured for you by Perfmon – it’s shown as all of the figures on the graph, so in the following my process ID is 5896…
Armed with the knowledge of the process ID, you can now capture Perfmon stats for a given instance (say TestWinFormsApp#1 in the above), and also use adplus –hang –p 5896 to get a memory dump of the same process at the same time. I needed this information to help a customer take some memory dumps and perfmon stats for me, so thought it might come in useful for someone else.
If you don’t know what adplus is, skip over to the Debugging Tools for Windows site, download and enjoy.
I was doing some investigation on a customer site and needed to use adplus.vbs to take process dumps, however I was forever getting the above error and couldn’t for a while work it out. I thought I must have typed in the wrong process id, but after checking and double checking I wasn’t, so I headed off for my favourite search engine and found this post by Jon Robbins which was close but not quite right. However it gave me the idea I needed to track down the issue.
Looking at the current version of adplus.vbs, the code that parses the output of TLIST was as follows…
' removing the first four chars; they are always "0 32" (it used to be only 2 chars - it didn't have the 32)
strAux = Right(strAux, StrLength - 4)
However – this doesn’t work under terminal services as the output you’ll be parsing is something like the following :-
12 32 9612 Blah.exe
Command Line: "C:\Program Files\Whatever\Blah.exe"
0 32 6508 dllhost.exe Svcs: COMSysApp Mts: System Application
Command Line: C:\WINDOWS\system32\dllhost.exe /Processid:{02D4B3F1-FD88-11D1-960D-00805FC79235}
13 32 11544 AcroRd32.exe
Command Line: "C:\Program Files\Adobe\Reader\AcroRd32.exe" "C:\Jabba\Yoda_Rules.pdf"
4 32 10816 iexplore.exe Title: Install Debugging Tools for Windows 32-bit Version - Microsoft Internet Explorer
Command Line: "C:\Program Files\Internet Explorer\iexplore.exe"
0 32 2596 msiexec.exe Svcs: MSIServer
Command Line: C:\WINDOWS\system32\msiexec.exe /V
Now, you might have noticed the ‘12 32 9612’ entry or the ‘13 32 11544’ entry. Chopping 4 characters from the front of these will yield a process ID of ‘2’ with the current script which isn’t correct. At best you’ll get an error, at worst you’ll get a dump for process ID 2 and that’s not the one you’re after.
To fix this you’ll need to modify your version of adplus.vbs. I’ve raised the bug internally and understand it’ll be fixed in the next release of the debugging tools for windows package. To modify the file do the following :-
(1) Go to line 2190 – the comment “removing the initial part we dont need [group] 0 32”
(2) Comment out everything from there to line 2208, “arrAux= split(strAux," ",-1,1)”
(3) Paste in the following code
'If this works it was modified by Morgan Skinner.
'If not I don't know who modified it.
arrAux = Split (LTrim(strAux))
If InStr(arrAux(0), "[") = 1 Then
'If item [0] begins with '[' then we're on Windows 7+ so are
'interested in everything from item 3 and onwards
k = InStr(strAux, arrAux(3))
Else
'If not we're interested in everything from item 2 onwards
k = InStr(strAux, arrAux(2))
End If
'I now have the position of the process ID string in the strAux string.
'Use that to cobble up the arrAux variable to what's expected
strAux = Right(strAux,Len(strAux)-(k-1))
arrAux = Split(strAux)
What you should end up with is something that looks like the following :-
' removing the initial part we dont need [group] 0 32
' [group] was introduced in win7
' strAux = LTrim(strAux)
' StrLength = Len(strAux)
' If instr(strAux, "[") = 1 then
' k = instr(strAux, "]")
' strAux = Right(strAux, StrLength - k)
' strAux = LTrim(strAux)
' StrLength = Len(strAux)
' End If
' ' removing the first four chars; they are always "0 32" (it used to be only 2 chars - it didn't have the 32)
' strAux = Right(strAux, StrLength - 4)
' 'strAux = Right(strAux, StrLength - 2)
' strAux = LTrim(strAux)
' arrAux= split(strAux," ",-1,1)
'*** If this works it was modified by Morgan Skinner.
'*** If not I don't know who modified it.
arrAux = Split (LTrim(strAux))
If InStr(arrAux(0), "[") = 1 Then
'If item [0] begins with '[' then we're on Windows 7+ so are
'interested in everything from item 3 and onwards
k = InStr(strAux, arrAux(3))
Else
'If not we're interested in everything from item 2 onwards
k = InStr(strAux, arrAux(2))
End If
'I now have the position of the process ID string in the strAux string.
'Use that to cobble up the arrAux variable to what's expected
strAux = Right(strAux,Len(strAux)-(k-1))
arrAux = Split(strAux)
'*** End modifications
set g_CurrentProcesses(PCount) = new RunningProcess
All of the new code is in bold.
This seems to work OK on my system – but as ever your mileage may vary.
I’ve been running WHS since an internal beta on a box that really wasn’t quite what I wanted – in that it was way too large. As far as I’m concerned a home server should be a small appliance that sits on your network, is on all the time, and consumes as little wattage as possible. My previous version wasn’t too bad in the wattage area but left a little to be desired in terms of size as it was based around a Coolermaster Centurion case.
So, I’ve been planning the build of a new home server for some months – I had most of the bits but the elusive part was the case. I wanted something that was as small as possible, but had room for at least 3 hard drives. With the capacity of HDD’s now I don’t think I’ll ever need more than 3 drives – and should mean I can swap one out to upgrade it with all likelihood that the other two will be able to balance my storage between them.
A few days ago I noticed that the ITX Warehouse had the new Morex Cubid 6600 case in stock. This fulfilled my main requirements, the first being that it should accommodate 3 disks and the other was that it should take a standard ATX power supply. The other contender was the most beautiful Silverstone SG04B but that was a fair bit pricier, and also a fair bit larger.
I eagerly awaited the arrival of the case and it came yesterday, so this evening I spent some time building the machine. I’d also purchased a Zalman ZM-NBF47 passive Northbridge heat sink and a pair of WD 1TB Green Power 32MB buffer SATA drives. I went for the 1TB drives as these were a load cheaper than the 2TB drives, and I know that by the time I grow out of the two drives I have that the 2TB’s will be as cheap as chips. I can then pop a 2TB in, let it rebalance, and when the time comes I can swap out the non-system 1TB drive for something larger again. My last WHS had about 1.8TB of storage and I only ever used about 600Mb so I have plenty of space to play with for now.
The Build
So, on with the build. I’m using the Intel D945GCLF2 dual Atom motherboard which has a fan on the Northbridge and it’s not the quietest of fans to be fair. I removed this and its heat sink and after cleaning the chip of any residual compound I then test attached the Zalman, at which point I realised that it wouldn't fit. There were two problems – one being the physical shape of the heat sink, the other being the metal bars that attach it.
I did some work on the metal bars to get them to work for me, and then splayed the fins of the heat sink as shown in the image below.
Here on the left image you can see that I have bent the fins away from one side as I had to make room for it to clear the stick of RAM. Looking down from the top you’ll see that the attaching arms have been splayed out a little, and I also had to reverse the part that attaches to the heat sink. Anyhow with that done I could fill the case with all its goodies. I removed the existing PSU and inserted my new one (well, the one I’ve had in my other WHS box for a while). This was the Xilence XP420 model and it looks the business inside the case as shown below. Whilst there is no direct pathway from the fan on top of this PSU over the motherboard, in use it is suprisingly cool in the top of the case.
I went to town with cable ties as there was so little space in the case that I wanted to ensure the maximum airflow. The bundle of cables towards the bottom left of the photo are extras that I’ve tied up out of the way – the wires not tied in place are waiting to be connected to the appropriate sockets on the motherboard. The image on the right shows one of the drives in place (the other is in the left hand image at the top, which is the front of the case when it’s oriented correctly). I used a slot on the left hand side of the case to feed up the SATA cables. There was a small fitting for another hard drive on the right of the case but I removed that for now to get better airflow from the fan. I can always pop it back again when I add a 3rd hard drive.
Then I inserted the motherboard – a tight squeeze. I found it better to attach the IO mounting plate to the motherboard before sliding it in – and had to be careful of the wires whilst doing this as there was so little space and I didn’t want to cut one on the side of the PCB or one of the edges of the case.
The last two photos show the motherboard in place with the cables fairly neatly tied out of the way, and the last shot is of the machine once built next to a DVD drive that I used when installing the operating system. I didn’t want this in the case full time so just installed with it connected and then removed it. The DVD drive gives you some idea of the scale of this box – it really is small and perfectly formed. The front is a little bit on the plasticy side but that’s the only bad thing I have to say about the case.
The Results
So, was it worth it? Oh yes.
My old WHS was a bit on the noisy side to say the least. It also drew about 80w when idle, a little more whilst making a backup. I couldn’t leave it on all the time as it was simply too noisy (as I work in my office at home and it was distracting).
The new box consumes roughly half that – about 40w when idle and currently 43.1w whilst backing up my media centre box to it. The media centre is across the room and I can hear its disks, whereas the WHS box is currently next to me on the floor (waiting for pride of place on a shelf) and I can only hear a low hum from the fan and the odd disk write which doesn’t happen very often – I guess that’s the 32Mb buffer doing its thing well.
It’ll cost me about £3 a month to run if I leave it on all the time. I purchased a plug-in wattage monitor from Maplin here at the recommendation of a colleague from which I got these figures.
The Bits
Here’s a list of all the bits I used when building the box.
| Case | Morex Cubid 6600 |
| PSU | Xilence XP420 |
| Motherboard | Intel D945GCLF2 |
| RAM | Corsair value select 2GB DDR2 667Mhz |
| Northbridge Heatsink | Zalman ZM-NBF47 |
| Operating System | Windows Home Server with Power Pack 1 |
| Disks | 2 * Western Digital WD10EADS 1TB 32Mb Cache |
I used various suppliers for the parts – ITX Warehouse for the case, Micro Direct for the motherboard, RAM and Zalman heat sink, Aria for the hard drives and the PSU was probably from Aria too. Aria and MD are a short drive for me so I can shop around to get the best price without having to pay for postage.
If you develop .NET client applications that are deployed to users over Terminal Services (TS) or Citrix then this is the post for you. Why? – well, there’s a bit of an issue that not a lot of people know about, and it can really ruin your day. First off some preamble about how we got here and why it’s an issue. I’ll then present a solution.
When a process runs on Windows it typically has some executable code and some data. To vastly simplify this let’s just say that the memory space taken up by my application includes different pages, some code - some data. There may well be other types of stuff in memory but that’s not important to this discussion at the moment. My application runs, loads up code into the pages allocated for code, and loads up data into the pages allocated for data. We’ll call these ‘Private’ memory pages.
Then another instance of my application is started on the same machine. This could be me running a new instance on my own desktop, so I now have two windows open doing the same thing, or (and this is the more critical one) it could be another user on the same server running the application over TS or Citrix.
Now, memory is a scarce resource as there’s never enough of it. (As an aside, that’s a bit of a lie to anyone who has been tinkering with computers for nearly 30 years and who started with 1K and still got it to do something, but what the heck).
With multiple instances of my application running, it stands to reason that I’m using up more memory. And as you’ll know if you found this post after the event, running out of memory can happen on a Terminal Server/Citrix farm when you have a boatload of users logged in.
As memory is such a scarcity, it would be nice to squeeze as much use out of what you have.
Tada: Shared Pages
Windows has a facility whereby memory pages can be marked as ‘shareable’. What this means in practice is that some pages from a given process can be shared by another process, and indeed could be shared with many processes. And what’s typically in these shared pages you might ask – well code of course. As code doesn’t change (more on that lie in a moment!) then it makes sense for the operating system to share pages between instances of the same application, which would minimise the total number of pages used in a multi-user environment such as TS or Citrix. Cool!
Now, back to that lie about code not changing. When you write a .NET application and compile it up, you get an executable that contains code, right?. Wrong – you get an executable that contains IL, which is in effect code, but until someone brings out a general purpose CPU that understands IL it’s not executable – it needs to be converted into code by the JIT compiler.
Now then, guess what happens when the JIT gets hold of your ‘code’. Well, it compiles it of course – but here’s the critical thing, it compiles your code into Private pages. And what’s special about Private pages – well the clue is in the name, they’re private to your process, meaning that JITted code cannot be shared between processes. Eek!
So, your swanky .NET client application may be easy to write and debug, but it’s memory footprint on a TS/Citrix box is less than stellar. Never fear though, there is a way out of this conundrum.
Enter stage left: NGEN
You may never have found a use for NGEN (the Native Image Generator), and indeed you might not even know such a beast exists – so for those of you who don’t know, what NGEN does is pre-compile all of the IL into x86/x64 assembly language and stores the compiled image on disk to be used when needed.
A lot has been written about NGEN and how it can affect the startup performance of your application, but a less well known feature is that using NGEN you can also affect the amount of memory used by multiple instances of your application.
Note: If you’re thinking “Hey, I can save memory on all my .NET apps using NGEN” you would be wrong. This stuff really only makes sense if your app is being run over TS/Citrix.
The critical thing to understand about NGEN is that whilst it compiles your code, it also marks the code pages as shareable, so that multiple instances of your application can share parts of the memory space used by the first instance. And that’s really useful if you’re running under Terminal Services.
In the image on the left I have two executables (Instance A & B) containing code and data pages. There’s a 1:1 correspondence between how big my .exe is and how much physical memory is used up overall. With two processes running I use double the space of running one instance of the process.
On the right hand side however there’s only half of the code pages in memory as the code is shared between my two application instances (C & D). Note – this is a vast over simplification, and you are unlikely to be able to share all of the code pages from any given .exe, but you will be able to share a lot of them so it’s worth trying.
Tooling – How to find out you have a problem
The Windows Resource Kit includes a tool called vadump (Virtual Address Dump) which is available for download here. It’s a cool tool but has recently been joined by the most excellent VMMap available from the Sysinternals site. This is a really cool new tool by Mark Russinovich and Bryce Cogswell and shows the same sort of information as vadump but in a Window (rather than a command prompt ala vadump).
To provide some examples from vmmap I created a simple .NET application which contains a fair bit of code. As I don’t like writing any more code than I need to I wrote a program to write a program that contained a load of code. I needed a decent amount of code in the application so that the figures would make some sense – if I had only a small amount of code in my .exe then the amount of pages used by the JITter vs. NGEN wouldn’t be significant.
| Image | Output from VMMap |
| Original image, single instance running, not using NGEN |  |
| Single instance running after NGEN |  |
| Second instance running after NGEN |  |
If you compare the first row from the shareable WS column you’ll see that the NGEN assembly has roughly 9Mb more shareable code than the original image. I know, 9Mb isn’t a huge amount, but it is a sizeable chunk if you run several users off the same box, and this was from one (admittedly large) .NET assembly. My app was about 3.5 Mb on disk – an application I’ve been working on from one of my customers is just over 40Mb as it includes a bunch of controls from 3rd parties and a whole host of other code.
Assuming I could get the same sort of benefit by running NGEN over my customers application then I might save 100Mb (!) per running instance. It doesn’t take a lot of users to make that significant – the 11th user would bring us to a saving of around 1Gb. Now we’re talking.
When you run NGEN it finds referenced assemblies (i.e. those that have a hard assembly reference from the main .exe). If you are dynamically loading assemblies then NGEN won’t find these so that’s another place where VMMap can be of help. If you run it up on your application then you can see which images are loaded that are using NGEN (well, you can when you know what you are looking for).
If you run VMMap the main part of the screen shows a list view. The .exe I’m running was called ShowNGENMemory.exe, so you need to scroll down the display to look for ShowNGENMemory.ni.exe. The .ni part indicates that this is a native image. If there’s an assembly with no corresponding .ni image then exit the app, run NGEN over the offending assembly and try again.
Setting Base Addresses
One other thing you should do to all of your assemblies is set a base address. What’s that I hear you say? Well, when Windows loads any image file (.exe, .dll) it looks for a base address – this is effectively the ‘preferred address’ in virtual memory where that image would like to load. The loader reads the base address, checks that address is free, and if so loads up your image. If however that address is already taken (i.e. something else loaded at your base address, or there’s an image loaded whose footprint goes over your area of memory) then we have some extra work to do. And as you can guess, this work takes time – we’re essentially going through the module and changing addresses). For a thorough examination of rebase please see the article here – it may be old but still a great read. This is less important with managed assemblies but still relevant.
Setting a base address is also a great idea due to the way pages are shared by the operating system. In short, if we need to swap out a given image then if that image was loaded at its preferred base address it can simply be thrown away. If an image is not at it’s preferred base address then the image will be stored in the page file, which obviously takes time to write to and subsequently read from.
To set a base address, just go to the ‘Build’ tab of your project properties window and click on the ‘Advanced’ button. There you’ll see the following dialog and at the bottom is the base address.
You really only need to set base addresses on DLL’s – the default is 0x400000 but you should change this for all of your assemblies. You can test relocations using another Sysinternals tool – ProcessExplorer. When you run this for the first time, click on Options –> Configure Highlighting, and make sure you check ‘Relocated DLLs’ at the bottom (it’s off by default)…
I always use red as it makes them stand out. Then run your application and look for relocations – you’ll need to be viewing DLL’s Ctrl+D) and have the lower pane view on (Ctrl+L).
Note: On Windows Vista, Windows Server 2008 and above we have a new feature called ASLR (Address Space Layout Randomisation) which is primarily there to make the job of a hacker a little less fun. In essence we move the locations of images in a random manner, so that exploits targeting a given memory address have much less chance of being effective. So, on a system with ASLR you’ll notice few if any Relocated DLL’s. I’ve kept this session in as I know plenty of people still running Windows Server 2003 in production environments, so rebasing is still a good idea.
To Conclude
Hopefully this post has provided you with enough information to go out and grab some memory back on your TS/Citrix boxes. There’s another upside to running NGEN on your code – it’ll start up faster! This is because with a regular .NET application we have to JIT the code as we call it. With NGEN this has already been done, which generally means you get snappier application startup.
The ideas presented here are really only necessary when running your application under Terminal Services or Citrix. For regular client applications that’s unnecessary, but when running under TS/Citrix I’d say it’s not important, it’s imperative.
One last thing for application vendors out there – why not add another page to your installation application that asks the user if they are running in a TS/Citrix environment? Then you can do the right thing and NGEN the application and all dependant assemblies as part of the install and save everyone a load of grief.
And lastly, don’t be tempted to use Task Manager to work out how much memory your application is using. It lies. Well, that’s a bit unfair really – it reports a reasonable number but doesn’t include any information about shared pages, so might report you are using 200Mb when you’re actually sharing 100Mb of that with several other users. To get a real picture of how much RAM a given application uses then give vadump of vmmap a go.
I’ve been invited to do a session in Coventry for the NxtGenUG – this will be run on Monday June 15th at the Coventry flying club. If you fancy knowing some more about the new stuff in Workflow then please sign up here. I’ll cover a lot of detail on the new classes and functionality in WF v4, describe a bit about rehosting the designer and also do loads of demos.
In my role as an ADC I often get to run customer labs – this is where we take a customers application, install it on the hardware we have in Reading, and then exercise a number of load tests against it to see what opportunities there are for performance and scalability tweaking.
Just before Christmas I was in the labs with one of my customers who have a high-profile site due to go live in a few months. I’ve been working with them for about 18 months and they now have a really scalable architecture which, based on the numbers we got in the labs, should deal with all the load likely to be chucked at it.
Anyhow, one of the new bits of kit I got to play with this time was a Big-IP box from F5. It’s a hardware load balancer and I must say I was very impressed with its capabilities so thought I should blog about it.
First off, a picture of the architecture :-
At the top we have our load injectors – there were 8 of these during testing. Each request goes through the Big-IP box which executes code against the request (known as an iRule, more on those in a bit), and then the request ends up on one ‘node’ or another – here ‘node’ applies to a group of servers, in our case containing four physical servers and a local database server. Then we have the main database behind the scenes – we were using SQL Service Broker for communication between the node database and the back-end database.
Now, the reason we were using this load balancer wasn’t just to balance load – based on the way the system was setup we wanted to partition requests based on some criteria, as in actuality we had partitioned user data across the nodes. A simplistic example would be all users with surnames ‘A’ - ‘M’ would be redirected to node 1, all others to node 2. Originally we had some code on the nodes which would decide if the request was appropriate for the node it had come in to, and if not pass it on to the appropriate node. However, with the Big-IP box we were able to make this choice on the load balancer itself, thus minimising the code on the nodes and also simplifying any changes that might need to be made into one place. It’s possible to partition load based on any criteria you can think up – maybe geographical (load from South Africa goes to a server in Johannesburg, load from the UK goes to a node in Manchester), maybe based on availabilty (the last request to node1 timed out, so try node 2 for now), or a host of other criteria.
In order to do our partitioning scheme we had to write an iRule. An iRule is some code that is executed on the Big-IP box on a given event – it uses a fairly simple yet powerful syntax (based on a version of TCL) which is tailored to suit the environment. There are custom commands that have been added to the language by F5, and some standard TCL commands have been removed too. The language is targeted to do one thing well – and this it does! The iRule is compiled and is then executed based on the particular event or events it has been defined for. For a definition of the events you can handle see here.
The rule we came up with was as follows :-
when HTTP_REQUEST
{
log local0. "in HTTP_REQUEST"
if {[HTTP::uri] starts_with "/node1"}
{
pool Pool1;
log local0. "pool1 selected"
#Remove node1 from the uri
set uri [string range $uri 4 end]
HTTP::uri $uri
}
elseif {[HTTP::uri] starts_with "/node2"}
{
pool Pool2;
log local0. "pool2 selected"
#Remove node1 from uri
set uri [string range $uri 4 end]
HTTP::uri $uri
}
}
This just checks the incoming URL for either ‘/node1’ or ‘/node2’ and then chooses an appropriate pool to direct that request to using the pool statement. As the URI includes the node we also wished to remove this from the URI before forwarding the request – so there’s a little string manipulation going on here too. The log statement emits debug information which can be viewed as necessary in a separate console – this comes in handy when you are writing the rule to ensure it’s doing what you need.
When a request turns up on the Big-IP box it goes through the following pipeline :-
As you can see you can plug in an iRule at any stage in the request processing. You can also do stuff without requiring code – such as caching frequently used pages or images so that the request never touches your actual server. The Big-IP box has some fairly beefy hardware inside so whilst rules are executing in x86 assembly language, some parts of the processing are offloaded to specialized hardware – such as SSL processing.
For some further information on iRule development see the F5
devcentral site – which has loads of examples and is really useful when you’re trying to learn how to construct rules. Chances are there’s one up there you can re-use rather than writing a new one! There’s even a .NET API you can use to talk to the Big-IP box, and also PowerShell access if that’s your thing.
All in all I was very impressed!
Frequently in my role I see code that is doing something like the following :-
After Time (x) Do (y). Repeat ad infinitum. No user interface.
I’ve deliberately put this in nothing approximating code as that’s what this article is about. Now, before reading the rest of this article ask yourself this – how would you do the above?
I’m prepared to bet you came up with one of the following answers :-
Option 1 : The dedicated thread
public static void Main()
{
Thread t = new Thread(new ThreadStart(ThreadFunc));
t.IsBackground = true;
t.Name = "Worker";
t.Start();
// Other code here omitted for clarity
}
private static void ThreadFunc()
{
while(true)
{
Thread.Sleep(x);
y();
}
}
The problem here is I cannot shut down the worker thread cleanly as it’s in a tight loop. And I’m running up a thread to have it most probably sleep for most of its lifetime.
Option 2 : A Timer
OK, a Timer you say – but which one? A System.Timers.Timer, a System.Threading.Timer or a System.Windows.Forms.Timer? Confused – you should be. And then you could also look at the System.Windows.Threading.DispatcherTimer too.
If you were choosing one of these to do the job I’m after you would probably pick System.Threading.Timer as it’s pretty light weight and does just what I need. MSDN suggests the following information about when to use these timer objects :-
- The Windows timer (System.Windows.Forms.Timer) is designed for a single-threaded environment where UI threads are used to perform processing. The accuracy of Windows timers is limited to 55 milliseconds. These traditional timers require that the user code have a UI message pump available and always operate from the same thread, or marshal the call onto another thread. For a COM component, this would be detrimental to performance.
- The server-based timer (System.Timers.Timer) is designed for use with worker threads in a multi-threaded environment. Because they use a different architecture, server-based timers have the potential to be much more accurate than Windows timers. Server timers can move among threads to handle the raised events.
- The thread timer (System.Threading.Timer) is useful in scenarios where messages are not pumped on the thread. For example, the Windows-based timer relies on operating-system timer support, and if you are not pumping messages on the thread, the event associated with your timer will not occur. The thread timer is more useful in this case.
Option 3 : Some hand-baked approach
Maybe you maintain a list of all timers, so that you can use a dedicated thread to service all of these, and all you do is sleep until the next event is due, process that event, and then calculate the next time you need to wake up.
Is there another way?
I’d advocate none of the above. Heresy? – Maybe. But then again maybe you don’t know about the other way of doing this, all supported in the .NET framework – and been there since version 1.0 hit the streets some 8 years ago or so. Arise sir API, and make yourself known to us :-
ThreadPool.RegisterWaitForSingleObject ( ... )
It might not be immediately clear what RegisterWaitForSingleObject is up to, or how you could use this to solve the initial problem I posed, but all will be revealed.
The documentation for this method states “Registers a delegate to wait for a WaitHandle, specifying something as the timeout”. So how does that apply to our situation then?
Option 4 : RegisterWaitForSingleObject
The important thing to note is that this method can repeatedly call your delegate. And it does this as long as you like. In addition you also get the opportunity to alert this function (i.e. manually force it to run) which could be useful. Say for example you have a background thread that periodically checks for new messages – but you also want to be able to kick this processing off manually too in response to some user input. RegisterWaitForSingleObject is perfect in this case.
So lets get to some code. The first example calls my periodic function every 1000ms.
class Program
{
static void Main(string[] args)
{
AutoResetEvent exit = new AutoResetEvent(false);
RegisteredWaitHandle h = ThreadPool.RegisterWaitForSingleObject(exit, new WaitOrTimerCallback(ThreadFunc),
null, 1000, false);
Console.WriteLine("Running - press enter to stop");
Console.ReadLine();
}
static void ThreadFunc(object state, bool timedOut)
{
Console.WriteLine("Thread running - {0}", timedOut ? "Timeout" : "Signalled");
}
}
So here I have constructed an AutoResetEvent, then called RegisterWaitForSingleObject. My ThreadFunc corresponds to the WaitOrTimer delegate definition by taking a state object (this is the null passed into the RWFSO call) and a flag indicating that a timeout occurred, rather than the waitable object being set.
If you run this you’ll see the ‘Thread running – Timeout’ message show up roughly every second.
Now the WaitHandle you use has a bearing on your function being called – or rather the number of times your delegate is called. I’ve used an AutoResetEvent which is effectively reset once something has read it. So, if I were to call Set() on the event then the delegate would be called once, and it would output ‘Thread running – Signalled’.
If I were to use a ManualResetEvent and call Set() on it, I’d then get loads of ‘Thread running – Signalled’ messages, until I manually reset the event. It’s an important point to note – if the event stays signalled then the callback method will be called repeatedly.
The other important thing to note is that if you signal your event then the thread function will be called at least once. This is good – as you can use this behaviour to your advantage.
Say you’re writing a Windows Service which periodically wakes up and does some work. You’ve probably got some code in the OnStop() service method to wait around and close things down gracefully. How about using an event to notify your code that it’s time to stop? This would be an ideal way to utilise RWFSO and the code is presented below :-
public void OnStart()
{
_stop.Reset();
_registeredWait = ThreadPool.RegisterWaitForSingleObject(_stop,
new WaitOrTimerCallback(PeriodicProcess), null, 5000, false);
}
public void OnStop()
{
_stop.Set();
}
private void PeriodicProcess(object state, bool timeout)
{
if (timeout)
{
// Periodic processing here
}
else
// Stop any more events coming along
_registeredWait.Unregister(_stop);
}
private ManualResetEvent _stop = new ManualResetEvent(false);
private RegisteredWaitHandle _registeredWait;
So in the OnStart method I setup the ManualResetEvent which is used to indicate the service is stopping, and then register a wait.
In the callback function I check if there was a timeout in which case the periodic process can continue, otherwise if the event object has been signalled I can unregister the wait which will stop any further invocations of the PeriodicProcess function.
One last thing
With the code above I’ve had to store the RegisteredWaitHandle so that I can call Unregister later. Another method you can employ (which doesn’t require this storage) is to pass ‘true’ as the last parameter to RegisterWaitForSingleObject. This gives you a one-shot timer, which may sound useless if what you want is periodic execution, but you can then use the function as follows :-
public void OnStart()
{
_stop.Reset();
ThreadPool.RegisterWaitForSingleObject(_stop, new WaitOrTimerCallback(PeriodicProcess), null, 5000, true);
}
public void OnStop()
{
_stop.Set();
}
private void PeriodicProcess(object state, bool timeout)
{
if (timeout)
{
// Periodic processing here
// Then queue another wait
ThreadPool.RegisterWaitForSingleObject(_stop, new WaitOrTimerCallback(PeriodicProcess), null, 5000, true);
}
}
private ManualResetEvent _stop = new ManualResetEvent(false);
Here I’m simply making another call to RegisterWaitForSingleObject within the PeriodicProcess method. Note that using this method may be easier from the perspective of having one less instance variable, but it does mean that your episodic execution is now not necessarily running evenly. With the old method, we could get a callback every (say) 5 seconds, whether the previous one had finished or not. With the above solution we do one set of periodic processing, then wait 5 seconds, and then do another set. Obviously this second way of processing may be advantageous to you – that’s your call, I’m just here to point it out.
Hopefully this has helped you understand how to use RegisterWaitForSingleObject, and maybe provided you with another way to execute episodic functions.
Frequently you need to add in some form of logging in your code on method entry and exit points, and typically this is done in a way which over-burdens you (the developer) with a fair bit of extra code.
Now, the universal panacea would be to be able to just attach logging around your code without having to change a line, but unless you are using a third party framework which provides some form of AOP style code injection such as PostSharp you are out of luck. Assuming you (a) want to add in logging and (b) don't want to take a dependency on another project, what's the easiest way to add in method logging? I'll aim to show that in this blog entry.
First off though lets define some pre-requisites that our logging should have :-
- As easy to add as possible by limiting the amount of code that is needed
- Simple to extend with extra information – such as logging method timings
- Easy to switch on and off, and lightweight too
I’ll hopefully satisfy each of these in the upcoming sections.
Apologies for the length of this post, but it just seemed useful to go into a load of detail on this seemingly simple topic!
#1 – Easy to Use
To satisfy #1 I’ll employ a fairly standard model – that of using a disposable class. In it’s simplest incarnation you could write a class such as the following to log method entry and exit :-
public class MethodLogger : IDisposable
{
public MethodLogger(string methodName)
{
_methodName = methodName;
// Log method entry here
}
public void Dispose()
{
// Log method exit here
}
private string _methodName;
}
Obviously this won’t actually do any logging but shows the principle. To use the above in your code you might alter your method as follows :-
public void YourCode()
{
using (new MethodLogger("YourCode"))
{
// Write your stuff here
}
}
So here all I’ve done is added the using clause around the code within the method. The MethodLogger class will take care of emitting entry data in its constructor, and as it implements IDisposable we can write code in the Dispose() method to emit the method exit information. That’s one line less code you need to add into your method in order to emit this end of method information, so I reckon that’s #1 just about sorted. So far so good.
Just as an aside – I’ve used this pattern elsewhere over the years. One favourite spot was changing the Cursor in a WinForms app – my CursorChanger class would simply get the current cursor in its constructor, replace this with the wait cursor, and then reset the cursor to what it was originally in the Dispose method. Job done.
#2 – Easy to extend
Now at the moment I don’t feel my MethodLogger class is really much good – we’ll ignore the fact that nothing comes out of it for the moment, I’m talking about the usage of the class. I can think of several options you might want to choose when constructing the logger which are not mutually exclusive :-
- Log Entry
- Log Exit
- Log Time In Function
You may be able to think up some more. This seems like an ideal place for an Enum. In addition I’m not so happy with the code I wrote above as it’s always creating a MethodLogger for me. What if method logging is turned off for some reason? There’s not much need to construct a class which does nothing is there, so how could I ensure that an object is only instantiated as needed? And what about the call site where I have the using clause – I shouldn’t need to change the call site if logging is turned off, should I?
If you look at the code emitted into an assembly by the using statement, it looks much like the following :-
IDisposable obj = new MethodLogger("YourCode");
try
{
// Write your stuff here
}
finally
{
if (null != obj)
obj.Dispose();
}
I can use this null check to my advantage. Rather than use new MethodLogger(…) I can create a static method which can be used to return either a MethodLogger instance, or null if logging has not been enabled. Thus the call site remains the same. Cool. The updated MethodLogger would then be something like this (I’ll get to turning the class off/on in section #3) :-
/// <summary>
/// Options used when logging a method
/// </summary>
[Flags]
public enum LogOptions
{
/// <summary>
/// Log entry into the method
/// </summary>
Entry = 0x01,
/// <summary>
/// Log exit from the method
/// </summary>
Exit = 0x02,
/// <summary>
/// Log the execution time of the method
/// </summary>
ExecutionTime = 0x04,
/// <summary>
/// Log all data
/// </summary>
All = 0xFF
}
public class MethodLogger : IDisposable
{
/// <summary>
/// Log method entry
/// </summary>
/// <param name="methodName">The name of the method being logged</param>
/// <param name="options">The log options</param>
/// <returns>A disposable object or none if logging is disabled</returns>
public static IDisposable Log(string methodName, LogOptions options)
{
// If logging off then return null, else
return new MethodLogger(methodName, options);
}
/// <summary>
/// Ctor now private - just called from the static Log method
/// </summary>
/// <param name="methodName">The name of the method being logged</param>
/// <param name="options">The log options</param>
private MethodLogger(string methodName, LogOptions options)
{
_methodName = methodName;
_options = options;
if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
{
_sw = new Stopwatch();
_sw.Start();
}
if ((_options & LogOptions.Entry) == LogOptions.Entry)
{
// Log method entry here
}
}
/// <summary>
/// Tidy up
/// </summary>
public void Dispose()
{
if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
{
_sw.Stop();
// Log _sw.ElapsedMilliseconds
}
if ((_options & LogOptions.Exit) == LogOptions.Exit)
{
// Log method exit here
}
}
private string _methodName;
private LogOptions _options;
private Stopwatch _sw;
}
That’s starting to look much better to me. I have defined the LogOptions enum and provided Entry, Exit and ExecutionTime as the available options. There may well be more you would wish to consider.
I’ve also changed the visibility of the MethodLogger constructor so that it’s now only possible to create one of these when using the static Log method. For the client the code is a little different but still very legible :-
public void YourCode()
{
using (MethodLogger.Log("YourCode", LogOptions.All))
{
// Write your stuff here
}
}
You may also have noticed that I’m also constructing a Stopwatch instance within the MethodLogger class if you choose to log the method time. There are other things you might want to do here – and all of them have little bearing on the caller. Maybe you want to update a performance counter based on the method name, so you can see statistics such as ‘number of calls’, ‘average execution time’, ‘number of calls/sec’ and so on. There’s no reason why you couldn’t hide this behind the facade of the MethodLogger.Log call.
#3 – Easy to switch on and off, lightweight too
So at present there is no code within the class to dial up or down the logging, and as there’s a logging framework within .NET already (the much improved as of .NET v2 System.Diagnostics classes – see here for a great intro by yours truly) I might as well use that as it includes the ability to turn on and off logging by using a switch.
If you’ve not boned up on the TraceSource class I’d urge you to read the article I linked to above, as knowledge of trace sources is necessary for the following section.
So, in order to be able to trace data somewhere we need a trace source. The MethodLogger class will use this source to raise events – such as the entry and exit events shown above. If you look at the TraceSource class you’ll notice that the methods typically include an integer ID – this could be used as some form of method name map, but in my code I’ve ignored this parameter and set to zero. With the addition of the TraceSource the call to MethodLogger would look something like this :-
using (MethodLogger.Log("YourCode", LogOptions.All, source))
{
// Write your stuff here
}
Notice the last parameter – this is our trace source.
Now you might be wondering why I pass through the name of the method into the Log call. Couldn’t I just use reflection to get the call stack and work out which method I’m in? Well yes, I could, but do you know how much overhead that gives at runtime? To check this out I wrote a simple test which made 100,000 calls to a method. One method I passed a string value to which simulates the name of the method from my logging class. The other used the StackTrace/StackFrame/MethodInfo classes in .NET. For 100,000 iterations the string based method barely registered – I measured 1ms. For the StackTrace based one I measured a whopping 5126ms – yes, that’s several orders of magnitude slower.
Now think about this – the logging code is likely to get into all methods. It needs to be as lean and mean as possible. Whilst you pay for this in the fact you need to use a method name as part of the method call, I believe the benefit in speed far outweighs this minor bother.
So, it’s fairly lightweight, but can I switch it on and off? Of course – you just need a bit more code in the Log method which works out whether the options selected (i.e. LogOptions), and the logging level on the TraceSource will result in anything being emitted. If the log level is set too low (such as just for Critical errors) there is no need to construct our disposable logger class – as it’s output will never be written out. Again a little work up front within the code reaps benefits of potentially fewer objects constructed and hence less work to do. The check inside the Log function is shown below :-
/// <summary>
/// Log method entry
/// </summary>
/// <param name="methodName">The name of the method being logged</param>
/// <param name="options">The log options</param>
/// <param name="source">The TraceSource that events are written to</param>
/// <returns>A disposable object or none if logging is disabled</returns>
public static IDisposable Log(string methodName, LogOptions options, TraceSource source)
{
IDisposable logger = null;
// Check if ExecutionTime logging is requested, and if so log if Verbose
// logging (or greater) is chosen
bool shouldCreate = ((options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
& ((uint)source.Switch.Level > (uint)SourceLevels.Warning);
// If not logging ExecutionTime, see if ActivityTracing is on, and if so log only
// if Entry or Exit tracing is requested
if (!shouldCreate)
shouldCreate = ((source.Switch.Level & SourceLevels.ActivityTracing)
== SourceLevels.ActivityTracing) &
(((options & LogOptions.Entry) == LogOptions.Entry) |
((options & LogOptions.Exit) == LogOptions.Exit));
// Check if we actually need to log anything
if (shouldCreate)
logger = new MethodLogger(methodName, options, source);
// Will return null if no method logger was needed - which will effectively
// be ignored by a using statement.
return logger;
}
So now we have a trace source, have code that checks if we need to be created, the next bit is to write out the log events which is pretty trivial. All I need to do is call the appropriate method on the TraceSource class and we’re away. The final incarnation of the code is shown below :-
public class MethodLogger : IDisposable
{
/// <summary>
/// Log method entry
/// </summary>
/// <param name="methodName">The name of the method being logged</param>
/// <param name="options">The log options</param>
/// <param name="source">The TraceSource that events are written to</param>
/// <returns>A disposable object or none if logging is disabled</returns>
public static IDisposable Log(string methodName,
LogOptions options,
TraceSource source)
{
IDisposable logger = null;
// Check if ExecutionTime logging is requested, and if so log if Verbose
// logging (or greater) is chosen
bool shouldCreate = ((options & LogOptions.ExecutionTime) ==
LogOptions.ExecutionTime) &
((uint)source.Switch.Level > (uint)SourceLevels.Warning);
// If not logging ExecutionTime, see if ActivityTracing is on, and if so
// log only if Entry or Exit tracing is requested
if (!shouldCreate)
shouldCreate = ((source.Switch.Level & SourceLevels.ActivityTracing)
== SourceLevels.ActivityTracing) &
(((options & LogOptions.Entry) == LogOptions.Entry) |
((options & LogOptions.Exit) == LogOptions.Exit));
// Check if we actually need to log anything
if (shouldCreate)
logger = new MethodLogger(methodName, options, source);
// Will return null if no method logger was needed - which will
// effectively be ignored by a using statement.
return logger;
}
/// <summary>
/// Ctor now private - just called from the static Log method
/// </summary>
/// <param name="methodName">The name of the method being logged</param>
/// <param name="options">The log options</param>
private MethodLogger(string methodName, LogOptions options, TraceSource source)
{
_methodName = methodName;
_options = options;
_source = source;
if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
{
_sw = new Stopwatch();
_sw.Start();
}
if ((_options & LogOptions.Entry) == LogOptions.Entry)
_source.TraceEvent(TraceEventType.Start, 0, methodName);
}
/// <summary>
/// Tidy up
/// </summary>
public void Dispose()
{
if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
{
_sw.Stop();
_source.TraceInformation("Method {0} execution time {1}ms",
_methodName,
_sw.ElapsedMilliseconds);
}
if ((_options & LogOptions.Exit) == LogOptions.Exit)
_source.TraceEvent(TraceEventType.Stop, 0, _methodName);
}
private string _methodName;
private LogOptions _options;
private Stopwatch _sw;
private TraceSource _source;
}
Apologies for the length of this post on something so seemingly trivial.
There’s still more you can do to the code – for example you might want to log the parameters on method entry, but I’ll leave that as an exercise for the reader.
Hopefully this has proven that adding in method entry/exit code in .NET isn’t too onerous a task, and you can add on extra capabilities such as performance counters fairly easily to the model presented here.
Have you entered parallel universe? Am I speaking double Dutch? Nope, I'm just proud of my roots as a Cornishman. The blog title roughly translated means 'Sons of Cornwall', and the title of this post means 'Hello' (well, the closest approximation of Hello in Cornish, as there isn't actually a word for Hello). OK, that's enough of a language lesson for now - and to be fair I don't and never have spoken Cornish. Mind you I do know a good few pub names in Cornish. :-)
I'm an Application Development Consultant and work for Microsoft in the UK - I've been here since December 2001 and prior to that I worked for 12.5 years for a software house in Altrincham, working on LIMS (Laboratory Information Management Systems). That was a cracking job but it was time for me to move on and I've found another cracker at Microsoft. Anyhow that's enough wittering, on to the technical stuff.
