Archive for Logging
Gibraltar 3.0 New Feature Dive – Live Sessions
Posted by: | CommentsThe Gibraltar Agent has always supported viewing the real time log messages from an application, provided your application was a Windows application (WinForms and WPF) and you were the one running the application. But, what if you want to see what’s happening inside a Windows Service or a process running somewhere else? In Gibraltar 2.0 you had to have your process explicitly publish a snapshot of your log data up to a Hub or via email. This required you to code some way to signal your application when you wanted to publish information and then have all of the data collected in that process since it started get shipped to you.
For Gibraltar 3.0 we’ve introduced a new way of seeing your log data in real time: Live Sessions. When you enable live sessions you can view log data remotely, efficiently, in real time. In Analyst you’ll see a new node in the tree view called Live sessions. When you select that, you’ll see a list of all of the available sessions which you can pick from.
When you first click the Live View tab a data connection is established and you’ll get the last thousand messages that were logged. Once that data’s come across, new messages are shown as they are recorded. You can filter the display to show just messages of a particular severity or to search their text for a particular value.
This is your server, live!
If you switch away from one session to another the live view stream will continue to run in the background – keeping it current with the most recent thousand messages. Gibraltar takes steps to keep this memory efficient so you can have multiple live streams running at the same time without performance issues.
If you want to keep watching an application while you work you can double click it and get an independent window which will update in real time as long as the remote application is running.
Efficient over the Network
The data stream that’s used by Live Sessions is designed to be very efficient over networks. It is highly compressed (using the same techniques employed by the Agent to write log files), connection based, and only running when there is an active viewer monitoring the session. In real world scenarios the live stream for a busy server can be easily viewed over a low bandwidth, intermittent connection like a tethered phone or Mifi.
- If the connection is lost, the data stream restarts with the last message you received so it can show you all of the messages
- If no one is watching a live session then the data is buffered in the Agent but not sent across the network.
Safety First
There are a number of features designed to make sure live sessions don’t cause a problem to your application:
- Asynchronous, buffered transmission: The Agent publishes data to any set of listeners asynchronously from recording the log file to ensure slow network connections or network connectivity problems won’t slow down recording the main log file.
- Drop on overflow: If there are more log messages waiting to be sent than can be sent over the network new messages will be dropped instead of holding up the application. This is in contrast to the log file which will switch to synchronous while it catches up.
- Encryption optional: You can choose to enable SSL for live session communication so it will be encrypted end-to-end.
Live Sessions and Firewalls
The Live Session protocol is designed to work with most firewall configurations:
- All connections are outbound: The Agent and Analyst establish connections to the central server to communicate. No connections are directly created between the Agent and Analyst. This works well with NAT and often requires no explicit firewall rules or exceptions.
- Separate ports are used for Agent and Analyst: If you need to create a firewall rule you can create separate rules for Agent and Analyst traffic (ports 29970 and 29971 respectively)
- Connections are asynchronous: Many firewalls will simply fail to respond to attempts to connect to ports that aren’t open, causing very long timeouts. By performing all connections asynchronously this prevents the application from being unresponsive.
Try it out Today
If you’d like to check out Live Sessions for yourself, you’ll need to download the latest build of Gibraltar 3.0 and upgrade to the included Agent, Analyst and Hub. The Hub Server does the central relaying between agents and analysts so it has to be set up in the center. Live Sessions are not available with the subscription Hub Service operated by us at this time, you have to have your own private Gibraltar Hub.
Getting to Know Gibraltar – Adding Exceptions
Posted by: | CommentsIn my last post we set up a minimalist application, attached Gibraltar to it, and reported some trace information. In this post we’re going to build on that and add exceptions. First we are going to add an unhandled exception, so we change our code so that it looks like this:
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;
namespace GibraltarGettingStartedApp
{
class Program
{
static int Main(string[] args)
{
Trace.WriteLine("About to Blow up...");
int zero = 0;
Trace.Close();
return 1 / zero;
}
}
}
}
That should get the runtime’s panties in a bunch, let’s try it. 
Yep, that did it! Now, let’s see what Gibraltar logged…
Gibraltar knows we crashed and if we open up the record…
We know what the problem was, we can click the link and go right to the line in the source code and Gibraltar tells us what the user experience is going to be, “This fatal error will not be reported to the user, then the application will exit”. All and all, pretty cool.
As an aside, let me close down VS, I want to test if I click the link, will it open the file and go to the line? It does! That’s cool, though I notice that it only opens the actual file and not the solution or project that the file is in. Hmm, I’ll need to investigate that more as it’d be better if the entire solution was opened, don’t you think?
Let’s try running the same unhandled exception in a winforms application and see what happens. We’ll need to run the exe from the commandline, as the VS debugger will “get in the way” and try to do “clever stuff”, but when we do, we see the following dialog:
Here Gibraltar is giving us even more help. It’s popped up a dialog which will actually help us recover from the crash and carry on using our application. If we select “Restart Application” Gibraltar will restart the application for us and enable us to carry on using our application. Of course, this facility should only be used in a testing environment. In the real world, I don’t think it would be wise to restart and to continue using an application which had just suffered from a crash, as there is no way to know what state the underlying model is in. However, from a testing perspective, it’s an excellent tool.
Of course, the same information is recorded in Gibraltar:
Notice that the “Status” has been recorded as “Normal”. If we open the record we can see why:
It’s because we chose to continue the execution and shut down the application normally after.
Okay, let’s change our console application code to handle the exception…
using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;
namespace GibraltarGettingStartedApp
{
class Program
{
static int Main(string[] args)
{
Trace.WriteLine("About to Blow up...");
int zero = 0;
Trace.Close();
try { return 1 / zero; }
catch (DivideByZeroException e) { }
return 0;
}
}
}
And let’s see what difference that made to Gibraltar…
Hmm, as far as Gibraltar is concerned everything is normal, there is no sign of the handled exception. For a clue as to why that is, let’s examine logging best practices, you can read them at…
http://www.gibraltarsoftware.com/Support/Documentation/Logging_BestPractices.html
And they quite clearly state:
“We strongly recommend that in all cases where an exception is consumed within a catch block that you log the exception with an Informational severity rather than silently swallowing the error.”
Okay, so this states that if we handle an exception, and we want that fact recorded by Gibraltar, then we have to log it. That makes sense really. So, let’s change our code to the following:
using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;
namespace GibraltarGettingStartedApp
{
class Program
{
static int Main(string[] args)
{
Trace.WriteLine("About to Blow up...");
int zero = 0;
try { return 1 / zero; }
catch (DivideByZeroException e)
{
Trace.WriteLine("Error: " + e.Message);
}
Trace.Close();
return 0;
}
}
}
Now let’s see how that’s affected Gibraltar:
This time you can plainly see that the error has been recorded, which is good, but notice too that there’s no exception tab:
Of course, we should be able to do better and we can. If we use the TraceInformation method, and pass a formatted string, along with the exception, then Gibraltar will give us a much richer experience.
So, let’s change our code to use that method:
using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;
namespace GibraltarGettingStartedApp
{
class Program
{
static int Main(string[] args)
{
Trace.WriteLine("About to Blow up...");
int zero = 0;
try { return 1 / zero; }
catch (DivideByZeroException e)
{
Trace.TraceInformation("Error: {0}",e.Message,e);
}
Trace.Close();
return 0;
}
}
}
And let’s look at the information provided in Gibraltar:
This time, as you can see, we get the “Exceptions” tab. This is because Gibraltar scans the insertion variables and, if it finds one that is an exception, then it uses that as the exception for the log message (regardless of its severity). Pretty cool eh?
In this post we added an unhandled exception to your console application to see what effect that had on Gibraltar. We then added an unhandled exception to a winforms application so we could see the enhanced features available to us there and then we finished up by handling that exception and seeing why best practice is to log handled exceptions.
I hope you’ll join me next time as we continue our exploration of Gibraltar, until then, happy coding!
Gibraltar 3.0 New Feature Dive – Super sized Sessions
Posted by: | CommentsA major challenge customers have had with Gibraltar 2.0 is working with long running and large sessions. This stems from the early on design decision to target smart client applications for the first releases of Gibraltar. From this decision we made a series of assumptions – how large sessions would be, how people would want to count and interpret them, when they would get sent in, etc. For example, early beta versions we assumed by default that you only wanted to keep 50MB of total log data and each session would be around 5MB. Looking back, this just isn’t how things turned out at all.
Once you start using Gibraltar with server applications – like web sites or even windows services then a few things happen:
- Long Life: Gibraltar equates a session lifetime to the application domain it runs in. For windows services this could be months, possibly even years. For web sites it’s typically a day or less.
- Session Size: It’s hard to imagine in a single user smart client recording more than 50MB of information. Our analysis of log files we receive and our customers use indicates this is a pretty fair assumption. For a busy corporate line of business web application you can easily generate 500MB of log data each day.
- Submitting Sessions: By default, Gibraltar waits for a session to end before sending in the data. This works well with end-user applications but doesn’t match up with operating your own web sites or services. What use is it to find out a month later your Windows Service was having a problem? You could trigger sending data manually and even when an error happened, but if your session got to large this could be dangerous because we merged together all of the data first to send it.
The biggest problems people have with using Gibraltar 2.x in these situations is:
- If you log a lot of data, you need a lot of memory and processor to submit the data to be able to view it – about five times as much as the log data. To add insult to injury, every time it submitted the data it pushed it all to the server, and that got completely re-analyzed for issues then copied down to each Analyst. Very inefficient.
- You had to add code to your application to explicitly push the session to the server to see any of the data. And when you did you could run into the first problem.
No question about it, this sucks and it had to stop.
Editor’s Note: Not all of the optimizations discussed below have shipped in Gibraltar 3.0 Beta 2.
Smaller Data Files
Our original compression approach was based on a sampling of files between 5 and 50MB. It turns out that the files we really should worry about were in the 50 to 500MB range. Saving 25% on a 5MB file isn’t likely to impress anyone. Cutting 100MB off a log file makes a real difference. We’ve substantially revised how we compress files and will get an average of 65% reduction in size for typical files. That’s right – they’re now 1/3rd as big. This is all done with no impact on the throughput of the log system because of the asynchronous, queued approach Gibraltar uses to record data.
We also reduced the memory it takes in the Agent to perform this compression. Previously it was possible to use up to your maximum log file size in RAM (in extreme cases) while logging. To avoid the problem of merging fragments (which uses even more memory) some customers ran into this when they dramatically upped their log file sizes. Now the compression uses a fixed buffer size measured in KB to ensure it’s both efficient and predictable.
These smaller files have another advantage: We previously zipped files before they were sent to the hub to save network time. This would get us about a 40% reduction in file size but took time, processor, and disk space. With the new scheme there’s no advantage to doing this – the files would actually get slightly larger. So we can skip this step which saves time on both the client and server.
We’ve also added a feature to let you understand why your data files are as big as they are. In Analyst, you can open a session and then click File Stats on the Session Details tab.
Here’s the analysis we get for one of our Gibraltar Hubs we’re using for testing. It logged about 700,000 messages in a 24 hour period.
You can see that the average size of each log message is 57 bytes. Now that’s good stuff from a compression standpoint. The process also recorded a fair number of metrics and performance counters. There are metrics for each data operation, web service call, etc. and these add up to a total of about 350,000 individual samples at an average size of 31 bytes. All of the performance counter samples – 35,000 of them – came in at an average of 10 bytes. All in, the file was just over 50MB.
From this information you can get a good feel for what’s driving your log file size. Now, you may never care – but when you get into logging millions of messages and millions of metrics then it’s good to have around.
Incremental Data Files
For Gibraltar 3.0 we’ve changed it so that the individual file fragments Gibraltar stores data into (each representing a period of time) are never merged together – all the way down to Analyst. When data needs to be made available Gibraltar has always rolled over the current log file (called a session fragment) and started a new one. Previously these fragments all had to be merged together before the data could be sent anywhere off the computer. Now they’re each managed individually. Thanks to this change, each time your application wants to send data to the Hub only the fragments that haven’t already been sent are processed. Likewise when this data needs to be analyzed for issues or sent down to clients that want to view the details it’s just the new information.
We’ve also gone through the processes that send data – whether it’s to the Hub server, email, or files – and worked to eliminate unnecessary file copies that were being done previously in an overabundance of copies (these get expensive if you have a 300MB file) and minimize the memory required. The bottom line is that you can safely send session data at any time – regardless of how much data you’ve logged or how long your application’s been running.
Let Your Application Run Forever
Making the session files smaller and keeping them in fragments helps with large sessions, but when you have a really long application there are a few other things that kick into play. First, you want to make sure you can discard older log data off the computer (to keep down local disk space) even while the application was still running. In many cases, Gibraltar 2.x would end up throwing away the start of the session and all you’d have is the last 150MB of data (if you used the default limits). For 3.0, session fragments can be sent automatically as soon as the log file rolls over for any reason. The default limits of 50MB and one day mean that for each Windows Service you’d at least get a fragment every day – which would be sent up to the server and then pruned locally. You can still trigger sending data more often from within the application like you used to and it’ll work great.
The Hub server works better with this as well – it will analyze each fragment without having to load up information it’s previously worked through. This means you get steady updates and the memory required on the server is dramatically reduced. We’ve had customers with Gibraltar 2.x that had servers perpetually behind analyzing sessions because by the time they analyzed a large file they received another copy of it with just a modest amount of new information. Now this is a non-issue because the server can load just the new data and check it.
Of Course, You’d Like to see All of That
The final problem area for Gibraltar with very large sessions was viewing them in Analyst. Historically you could load up a session with between 1.2 and 2 million messages. More than that and it’d fail with an out of memory exception. This was because Gibraltar Analyst was a 32-bit only application. We’ve rewritten our graphing system to use the DevExpress XtraCharts like we use for Charting and that means we’re good to go for 64-bit in Analyst. If you have 8GB of RAM, you can use all of it for session data if you want. In practice this means you’re still limited to a session with perhaps 10-15 million messages. We’re going to work on that in a future release to really achieve our goal of infinite logging.
This is all fine and good, but it’s still missing something… The ability to handle the server-on-fire-right-now scenario we’ve all experienced at some time in our career. For the story on that, stay tuned for our next deep dive!
Getting to Know Gibraltar – Making a Start
Posted by: | CommentsHello there. My name is Gary Short and I’ve recently joined Gibraltar Software. Amongst the other things I’ll be doing (more details on those later) I’ll be evangelising the Gibraltar product.
Now I’ve never used the product and I don’t know anything about it, so I guess I’m on the same sort of learning curve as a new customer when they first download a trial version.
We all learn in different ways and at different speeds, but the way I learn best is through action centred learning, in other words, I like to “do stuff” to learn how “stuff works”. So, the best way for me to learn how to do something with Gibraltar, is to do something with Gibraltar. 
So what’s the simplest thing I can do to get something working? Well after having a quick look at the documentation, it seems to me that the simplest thing to do is:
- Configure a minimalist application for tracing
- Hook up Gibraltar
- Examine the data in Gibraltar.
Okay, so let’s do that!
Step 1. Configure a Minimalist Application For Tracing
Let’s work with the simplest thing, namely a console application with one method and a couple of calls to the Tracing API. Something like this should fit the bill:
using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;
using Gibraltar.Agent;
namespace GibraltarGettingStartedApp
{
class Program
{
static void Main(string[] args)
{
Trace.WriteLine("Entered method!");
Console.WriteLine("In the body of the method!");
Trace.WriteLine("Leaving method!");
}
}
}
And when we run this, it does pretty much as we’d expect it to do:
Step 2. Hook up Gibraltar
Firstly, start Gibraltar and from the and click the “Add Gibraltar Now” button:
Then, simply work your way through the wizard. Starting with selecting the project file for your application:
Next, since we’re doing the simplest thing possible, accept the default configuration:
Then deselect all the checkboxes.With the exception of “Allow Sessions to be Emailed to you”, which I can guess at, I have no idea what these do, but we’ll find out later. For now, we just want to do the simplest thing that’ll work.
And we’re done:
Okay so let’s run our application again.
Hmm, notice that the console window stays open this time, and we have to physically close it to make our application end – what’s happening here I wonder? We’ll come back and investigate that in a moment, but for now, let’s see what information is available in Gibraltar.
Step 3. Examine the Data in Gibraltar
Open Gibraltar and select “New Sessions”
and in the right hand pane, we see that we do indeed have information from our application!
Now it’s time to investigate that “application is still running” oddity. Looking at the information we can see that the “status” is “crashed”, even though we closed it down properly.
My guess as to what is going on here is that the Gibraltar Agent is holding open the application after the execution path has reached the end of the Main() method. We then closed the window manually, and because our application didn’t end in the way Gibraltar expected, it’s marked this event as a “crash”. It’s time to look up the documentation and find out what’s going on.
A quick read of the documentation at:
Shows us that indeed, when we are using a console application, we are responsible for ending the session. We can also see that there are a number of ways to do this, but since we are trying the simplest possible thing that will work, we’ll just add the Trace.Close() call to the end off our application. So now our code looks like this:
using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;
using Gibraltar.Agent;
namespace GibraltarGettingStartedApp
{
class Program
{
static void Main(string[] args)
{
Trace.WriteLine("Entered method!");
Console.WriteLine("In the body of the method!");
Trace.WriteLine("Leaving method!");
Trace.Close();
}
}
}
If we run our application now, we can see that our application closes when we get to the end of the Main() method. If we look in Gibraltar we can also see that our application has closed normally:
Okay, I think that is enough for this post. To help us learn how Gibraltar works, we’ve build a minimalist application and enabled Gibraltar to record our trace information. In the next post, we’ll build on these beginnings by looking at what happens when our application throws and error. We’ll also find out if Gibraltar deals with handled and unhandled exceptions differently.
Until next time, happy coding!
