Sunday, February 22, 2015

A .Net Guide to Logging with Log4Net

Overview
Logging is one of those things that I never saw the value of until I had to support code in production. I immediately saw the value of logging, since you cannot just attach a break point and view the state of your application. Logging is really the only option. This post will cover the basics of logging with Log4Net and Common.Logging, and some nifty advanced things you can do with the tools.

Log4net
There are a few important features that log4net providers. It has a variety of appender's that you can write your logs to. It allows for hierarchical logging that allows you to set different log levels in different parts of the application. Lastly, it allows for logging levels to be adjusted on the fly as the application is running.

Common.Logging
Is a wrapper for several different logging frameworks in .net. You don't have to use it, I just haven't use log4net without it, so my examples will be focused on it.<br />

Setup
You will need to do a few things to get logging working. I have created a sample console hello world application here The basic steps are as follows
  1.  Install the Common.Logging.Log4net package
  2. Add the correct configuration to the app.config or web.config of your project
  3. Add a second XML file that contains the configuration for log4net
  4. Add XmlConfigurator.ConfigureAndWatch() to your application's startup routines
  5. Profit
Putting the log4net configuration allows for the logging to be adjusted on the fly. You can put your log files directly in the web or app config if you don't need to adjust them while the application is running.

Logging Levels
Log4Net has 6 different levels of logging

  • All
  • Trace
  • Debug
  • Info
  • Warn
  • Error
  • Fatal
The logging levels build on each other. For example, setting your logging level to Warn, will capture everything in Error and Fatal. The most important thing to know about logging levels is that before you add any logging to your application you must decide on what information should go in which logging level. You want your entire application to have consistent logging levels, and this requires some careful thought and consideration.

Log4net also has the ability to check that a log level is enabled before logging. This is useful when you need to log something that could be a performance issue, such as serializing data. There are two methods you can use.

Lamda

logger.Debug(() => { //Expensive Logging Goes Here });

If Statement

if (logger.IsDebugEnabled)
{
      //Expensive Logging Goes Here
}

Hierarchical Logging
You should be defining your logging with the full namespace of the class that the logger is in. You should also define a logger per class, so you know where the log is coming from. This is important when setting up your logger. If you give all of your loggers in code the same name, you cannot take advantage of Hierarchical logging. For example if I have the following namespace in my application

Application.Service.BusinessLogic

If I define my logger in configuration as "Application" It will log everything in the Application Namespace. If I define my logger in configuration as "BusinessLogic" I will only get logging from the BusinessLogic namespace. Consistent application of logging names will make it easy to target specific information as you need it. I will use a statement like this to define my logger.

 private static readonly ILog _logger = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);

Also if you have defined multiple loggers, such as a logger in both Application and BusinessLogic, you will get the logs in two places if they point to different appenders. You can set a property on the logger called "additivity" that prevents this. See the examples here under the appenders section for more information.

Appenders
There are many appenders you can log to from file to email to telnet. The RollingFileAppender is one of the most common appenders, and allows you to log to rolling files. I also like to setup the DebugAppender so I can see logging message in my development environment as I am debugging. The ConsoleAppender is another useful appender if you plan on writing a console application and want your logs to show up in the console.

Logging Layout
You may want to control how the log file actually looks. You can do so by specifying a layout in the configuration. The layout looks like this:

 <conversionPattern value="%message * %date * %thread * %-5level * %logger * %newline" />

In my example project, this would write the following log to file.

Hello World * 2015-02-21 18:51:51,265 * 8 * INFO  * Log4NetDemo.Program * 

Log4net has some default values that you can use.  See the documentation here on all of the different built in information you can add to your logs.

Custom Properties
If the default properties are not enough, you can also add custom properties to your logs. This allows you to add common information to your logs without having to add that information to every log statement.

// Thread properties
log4net.LogicalThreadContext.Properties["CustomColumn"] = "Custom value";
log.Info("Message");

//Global properties
log4net.GlobalContext.Properties["CustomColumn"] = "Custom value";

You can insert custom properties on both the current thread, and globally. You can reference the properties in you log file by using %properties{CustomColumn} in the conversionPattern section.
 
What should I Log?
When you first start adding logs to your application, you may not know exactly what to log. When writing new code, or fixing bugs in existing code, think about how you would troubleshoot this in a production environment if there wasn't an exception with a stack trace. Depending on the method you may want to capture parameters and objects to ensure the correct data is being passed around. You may want to log points where you make a decision in your application so you can trace the flow of logic. Every time you work on a difficult to troubleshoot problem, think about how additional logging would have made that problem easier to fix. 

Additional Tools
Here are a few tools that I have found useful when working with logs

BareTail A very nifty log viewer. Allows you to highlight logs based on keywords. Monitors logs in real time. This has replaced notepad++ for me as a general log viewer, especially when logging a lot of data.

Log Parser Lizard This is another really useful tool. It allows you to write SQL style statements against a log file. How awesome is that? Scott Hanselman has a good blog post about it here .








Sunday, January 25, 2015

Troubleshooting Memory Leaks in Production


Overview

If your a .net developer, you may never need to investigate an application that is leaking memory. If so, consider yourself very fortunate. However, if you do find yourself in the troubling position of having a memory leak in production, that you are unable to reproduce on your development machine, this post will give you a good starting point.

Memory Leaks in .Net

I could write a whole blog post on just the different types of leaks in .net. Here is an excellent post about the different types of leaks.

http://alexatnet.com/articles/memory-leaks-in-net-applications

Monitoring For Leaks

Perfmon is your best friend here. It has performance counters for about anything you would want to monitor. For Capturing memory leaks there are a few counters you will want to setup and watch.
These are five of the most important counters that you will want to monitor. Monitor first, because this narrows down the potential causes of the leak, and lets you narrow your focus when searching for a possible cause. I've listed the common behaviors of a leaking application below.



Private Bytes Increasing, Bytes in All Heaps remains constant

You have an unmanaged code leak. Are there any parts of the application that use COM or external non .net libraries?

Bytes in All Heaps Increasing

You have a leak in managed code. There are many different things that could be causing this. Take a look at both the Gen2 heap size and the Large Object Heap Size. Depending on which one is growing, could point you towards it being a large object that is not being collected, or smaller objects.

Current Assemblies Increasing

If your current assemblies are going up over time, you are leaking dynamically generated assemblies.  There are a few different things that could be causing this, but the most obvious is XmlSerializer
There are only 2 Constructors XmlSerializer(type) and XmlSerializer(type, String) where the dynamic assembly is cached correctly. If you use any other constructors here a dynamic assembly will be created every time you create a new instance of the serializer. So, make sure you only have a single instance.

Memory Leak Tools

There are several few tools out there, some paid, and some free, that help find memory leaks. Redgate and Scitech have paid offering and those tools are very nice. You can go this route, if you have the money to spend, and do pretty well. However, I don't think you can ever have too many tools in your toolbox and there are some free tools that are just as useful as their paid counterparts.

Process Explorer

Even though Process Explorer isn't a memory leak tool, it is worth mentioning as every developer should be familiar with it. It has a whole wealth of information related to running processes. It Particular is the ability to view real time CPU usage of threads (nice when tracking down a hang), and loaded assemblies in memory. You can use this feature if you suspect an assembly leak to see how many dynamic assemblies have been loaded.

VMMap

Another useful SysInternals tool. This tool shows you a live view of the memory your process is using, and breaks down the memory into addresses.

PerfView

This is another really nice performance tool from Microsoft. Its a bit complicated to use, but it makes up for that with the powerful features it offers. It can capture memory dumps from a running process without pausing the process(Very nice in production). It also has the ability to profile more than just memory. It has the ability to collect real time information about GC, and also profile the CPU usage of your application. Channel 9 has some great tutorials about it, and I would go watch them to get an understanding about how it works.

Debug Diag

This tool is a must have in your toolbox, especially if you are trying to get good dumps from a service running under IIS. It allows you to dump processes, setup triggers to take dumps, etc. It also has analysis tools, that allow you to quickly get a report about a dump. It has a nifty heuristic that it uses to calculate the likelyhood of a module causing the leak, if you set it to monitor for leaks. It doesn't have the drill down capabilities of the more complicated tools, but its very easy to use, and gives a nice overview of whats going on in your application at the time the dump was created.

WinDbg

This is the oldest and most well known debugging tool. Its a powerful tool, but its also the most complicated debugging tool of all of the tools. It is a challenge to get setup and running correctly. I personally would only use this as a last resort, if you need some information that isn't available to you in all of the other tools out there.


The Hard Part
 Now your at the hard part. Your pretty sure you have a leak somewhere. You actually need to find the leak. If you look at some of the simple tutorials, they make it look so easy. I've never had a memory leak that was really easy to find. Usually because I am looking at a WCF or Asp.Net application, which seems to make it more difficult to track down. Here is a rough idea of how to proceed, if your not using a commercial tool that has one click profiling and gathering.

Learn your tools
Before you march off to production and start capturing information, spend some time learning about the tools you are using. Especially getting the dumps correctly. You want to make sure you are capturing a dump that you can actually use, so you don't waste time there. You also want to make sure that the method you are using to capture your dump doesn't impact the business. Nobody wants to be responsible for killing the uptime chart, because they didn't understand how their dump is captured. You also need to have a basic understanding of how GC works, and how Leaks can occur.

Capture dumps over time
 If you are using DebugDiag, you want to enable the memory leak detection. You want to capture a few dumps spread out over some amount of time. Try to capture the first dump after your application or service has warmed up/initialized.  That will reduce the amount of noise when you compare two dumps.

Diff the Dumps
Looking at a single dump only provides a snapshot in time. You have no idea what is going on inside the application though at the time the dump was created. Tools like Perfview, DebugDiag, and the paid tools can take two dumps and do a diff between them. This allows you to see what has changed over time.

Filter out the Noise
This is the hard part. You need to have a good grasp of your application to understand what is noise and what is not. If the issue isn't obvious you might spend a fair amount of time doing this. It is useful work though, because if you ever have a second memory leak, you will already know what stuff is most likely still noise.



Conclusion
I hope you found this article useful as a good starting point for investigating memory leaks. There is no magic bullet when it comes to finding and resolving leaks, and you may spend days and weeks tracking them down. Practice makes it easier, but hopefully you don't have much opportunity to practice.  Like everything else, it just takes hard work, tenacity and good Google skills.

Saturday, January 17, 2015

An overview of writing a 6502 emulator

Overview

If you are interested in writing an emulator for a CPU, this is a good guide on getting started. If your interested in emulation, starting out with a simple emulator makes more sense. If you eventually want to write a more complicated emulator, the 6502 is simple enough that it isn't overwhelming, yet complex enough that it contains a good number of concepts that a more complicated CPU would have.

Basic Components and Concepts of the 6502

There are a few components and concepts of the 6502 that you will need to understand. This is just a brief overview of concepts, and there are many wonderful informative guides about these concepts. I recommend reading from several sources to get a deeper understanding

Stack:
This is a special location in the memory between $0100 and $01FF. The stack is a LIFO (Last In First Out) type of object. Its used as a temporary storage location. There is no protection against overflows. Its also fixed in place. The stack starts at the top of memory.

Registers:
Registers are used to hold small bits of information in the CPU. They are usually extremely fast to use, and are used to perform math operations, etc. They may also hold special processor flags, or pointers and counters to different places in memory.
  
Addressing:
The 6502 has 13 different ways that memory can be addressed.

Instructions:
The 6502 has 56 official instructions or OP Codes. The instructions are what carry out the work.

Memory:
This isn't actually a part of the 6502, memory would be a separate set of chips in a real device. For the purpose of an emulator though, the memory is considered a part of the CPU. There are a few special places in memory. there is a maximum of 64kb of memory, and all of the values in memory are values from 0-255.

The first 256 bytes of memory is the Zero Page memory.
The next 256 bytes of memory is the stack.
The last 6 bytes of memory contain 3 special addresses. At $FFFA - $FFFB is the Non-Maskable Interrupt address $FFFC-$FFFD is the power on reset address. and $FFFE - $FFFF contains the BRK/IRQ address.  These addresses are used by the CPU to find the code that gets executed when one of those specific events occur.

The rest of the memory can be divided up however the hardware dictates.


Where do you begin?

The hardest part, at least for me, was figuring out where to begin. There is a lot of information to absorb, and it will take some time to build up a mental model about how things work. The documentation online will only take you so far, and you are likely to encounter gaps.

 You are going to start by writing a method that performs a single CPU Operation. Mine ended up looking like this.


     Inside the ExecuteOpCode(); is a giant switch statement that switches on the CurrentOpCode value. You will want to write code that implements each instruction inside your switch statement. Start with the easy addressing modes, and make sure they work before doing the more difficult ones. The bulk of the work is going to be getting those instructions working correctly, if the behavior deviates at all from the real CPU, it won't work correctly.

You will also need to implement all of the Processor Flags and Registers an make sure they are being set and cleared. The Overflow and Negative flags are probably the most confusing flags, and I remember them giving me some trouble when dealing with Addition and Subtraction. 

Other Functionality

There is some other functionality you will need to add in order for things to work correctly. You will want to emulate the PowerOn and reset functions. You will also need to implement Interrupt Requests and NonMaskableInterrupts. 

You also are going to want some set of tooling to verify that things are working correctly. I wrote a really fancy test harness that shows all of the information at a glance, allows me to load and save the state of my program, set breakpoints, etc. You don't need to get this fancy, but it doesn't hurt, especially if you have limited knowledge of emulation and assembly language.

How will you know it works?

You need to test and then test some more. I ended up with just under 1000 unit tests. Most of my tests just loaded an opcode into memory and ensured that it worked correctly. Once you have implemented all of the opcodes, your next focus will probably be on some integration testing. I used a wonderful and very thorough test program by Klaus Dormann https://github.com/Klaus2m5/6502_65C02_functional_test that he wrote to test 6502 hardware that he was building. There are other test programs too. If your goal is emulating a specific device, there may be additional specific test programs.


Useful Links

http://visual6502.org/wiki
http://homepage.ntlworld.com/cyborgsystems/CS_Main/6502/6502.htm
http://www.atariarchives.org/alp/
http://en.wikipedia.org/wiki/MOS_Technology_6502
http://www.obelisk.demon.co.uk/6502/
http://www.6502.org





Saturday, January 10, 2015

Writing an NES Emulator: Work has Started

dotnetNES


I have officially broke ground on my new project. You can check the progress out here. You won't see much progress yet thought. This is the layout of the project. Just three simple projects.

  • Client - WPF Client
  • Engine - Class Library
    • Main
    • PPU
    • APU
    • Utilities
  • Tests - Class Library
I will be using folders and namespaces to segregate my code in the engine project. I plan to use WPF on the client along with MVVM. for MVVM I will be using the MVVM.Light Project, as its something I am familiar with. I am a big proponent of unit tests, and I include them in nearly every personal project I undertake. I'm relying on Nunit for unit testing, for the same reason as before, its something I am familiar with, and it does everything I need it to do.


The first task I have knocked out, is writing a cartridge loader. As a first task to get the project moving along, it seemed like something that would be pretty easy to implement. I used Jon Skeet's post on Loading Binary Files to handle loading the raw binary.  These two documents

where used as a reference guide when implementing the loader. I skipped some of the functionality, mainly the Players Choice Stuff, as I do not plan to implement any of that logic. I know that I planned to start testing the CPU first, however, most of the test programs are NES roms!

My next step will be to get the 6502 working with the loader, and get some tests added to run the NES tests.

Tuesday, January 6, 2015

Writing an NES Emulator: Overview

Writing a NES Emulator

I previously completed a project that emulated a 6502 processor. It was my first venture into the world of emulation, and I enjoyed it. I always wanted to turn the 6502 into something more though, namely an emulator of a game console. Originally, I thought about writing an ATARI 2600 emulator but after spending a lot of time thinking about it, I have finally settled on the NES system. There are a couple of reasons why I decided on the NES over the ATARI, the biggest reason being that the NES was my first real game machine, and it holds a fondness in my heart more than just about any other machine. Hopefully, by picking a machine that I have nostalgia for increases my chance of success.

Now, lets define some parameters that I want to operate under, so I have a clearly defined goal to reach.  I am shooting for a basic emulator, one that lacks anything but the most basic features required to get some of the NES games up and running. An outline of my plan is below

  1. Make sure that the basic CPU tests for the NES pass. I am not planning on worrying about implementing the illegal opcodes that only a small number of games use. I used a pretty comprehensive test program to validate the 6502 previously, so this should be quick, and give me a change to re-familiarize myself with the code I wrote.
  2. Get the graphics emulation working. I'll need to figure out how to emulate the PPU, which is the chip that drives the graphics.
  3. Get the audio emulation working. This should be a fun challenge!
  4. Input. This will be the easiest of the tasks I have to complete.
  5. Miscellaneous stuff. Things like loading the cartridge, and anything else
My basic plan all laid out in front of you. What could possibly go wrong?

You can check out the source here 

 Additional Posts
Work Has Started
6502 Overview
New Years Resolutions

     It's a new year, and this being the first post of my new blog, I have decided to write down some resolutions I have for the year. These are things that I would like to accomplish this year.

  1. Do Something with my 6502 simulator that I finished last year. That project is/was basically feature complete, but I always wanted to take it and build an emulator. This year I plan to do that, and hopefully write some blog posts about it.
  2. Wrap up the chess engine. I still have some work left on the engine before releasing it. I also want to write some about it. 
  3. Write more blog posts!