Measuring Progress

Recently I was asked to help out on a project that was not as productive as expected. My first question about where they are and where they should be, it became quickly obvious that they did not know. They perfectly knew that they are well behind but they were not able to quantify the deficiency. How could that be? All team members were always focused and working hard. So it was not a people problem, but rather a measuring problem.

How do you measure progress? There are two sides to the equation. Work to be done and completed work. Progress is the amount of the completed 'done' side in relation to the 'to be done' side. In order to have progress you need to move finished work from one side to the other. But, what means finished and when can we stick the 'done' label on something?

That gives us two entities we need. I call them 'Unit of Work' (UOW) and a definition of 'Done'.

UOW could be anything, however it needs to be well defined and understood from every single team member. The foremost important thing is that there is no miss-understanding about size, scope and dependencies. In the agile world this is a 'User Story' (US). In RUP a 'Use Case' or otherwise a requirement. Since this is about agile, I will use US in this article.

Each user story provides value to the customer and has three main attributes. These are priority, description and effort estimate. Priority is given by the customer, the customer has the right to choose what is the most important to them. The description should be done by both developers and customers to make sure that both have the same understanding. During that process the US is also estimated. The estimate can be of any unit; for simplicity lets use days. This has to be done for every wanted US for the first release. (personally I prefer story points [1])
Now we have on side of the equation, we call this the product backlog. A number of US with a description, a priority. Higher priority US are done first. Finally, the sum of all the effort estimates, in our case a number of days. Now, we can measure progress.

Progress = 100 / Total Effort Estimate * Done

Please, be aware that this is an estimate and we allow them to change. The customer even has the right add, remove or change US. But all those changes to the US product backlog will also adjust the progress as the total effort estimate will be affected. Depending if it is a date or feature driven project, you can adjust accordingly and see what the impact is.

Now, let's have a look at a definition of Done. When is something done? In the case of software one could say that something is done once the functionality is usable. Is this sufficient? I don't think so, as there are several Dones which have to be completed before a US can be labeled as Done. I call them the 4Ds.

The 4 Dones:

1. D1: Done Implementing -- Functionality is implemented and works
2. D2: Done Unit Testing -- Automatic unit tests can repeatably proof that code is working
3. D3: Done Acceptance -- The customer likes what she sees and accepts it
4. D4: Done QA -- QA signs of

The first done is what was sufficed in a pre agile world. In a TDD environment steps 1. and 2. are basically one. However, I still like to keep them separate as a mental reminder as not every team is doing TDD. As for the customer acceptance, this would typically happen in a showcase at the end of an iteration. You demo the code and answer upcoming questions. Finally, you give it to QA and they make sure it passes all acceptance criteria defined by the US. Step 4. can actually start before step 3. and maybe even be in parallel with 1. and 2.

A US can be moved from the 'to be done' side -- the product backlog -- to the completed side if a US is D4, i.e. all four done criteria have been fulfilled. Not, earlier! A story is either done or not, there is nothing in between. A story needs to have at least a 2D state to be showcased to the customer. Unfinished US are of no value to the customer.

Assuming the size of our product backlog is 100 days and as of now the sum of D4 US is 40 days we can claim to have a 40% completion. Now, if the customer adds a couple of new US with the effort estimates summing up to 20 days we will fall back to 33%.

This is a good start, but are we able to answer the question about when the project will be finished? First, we will never be able to guarantee a specific date, however we can use historical data to make a good estimate. Let's say it took us 6 iterations to complete the sum of 40 days. That makes ~6.5 per iteration. 60 days are left in the product backlog; 60/6.5 = ~10. (with the rounding, don't be obsessed with precision; I like to err on the cautious side) If there are no significant changes we can be pretty confident to complete the project in 10 iterations. Also, it should be obvious that all the iterations are strictly time boxed and of fixed length -- No exemptions!

In order to measure progress we need tangible units like US and a clear definition of done. All US stories with their effort estimate are the product backlog. Once we have those we can measure the project progress. If we work with those units in a iterative framework, we are actually able to provide an end date with a certain degree of confidence.

[1] Agile Estimating and Planning

Testing and Handling Logging in Java

Logging is a great way to communicate the systems past steps and state for debugging. Often, they are the last resort to get an idea about what is happening in a remote system.
But, not all is shiny. Usually, the log entries are printed onto the console and to a file. The later one is no problem, however, the first one can be a pain point.
How? Assuming you have an application with a good suit of unit tests. Say a couple of hundreds so that the output of running the tests does not fit on one screen any more. Now, when you run the tests, you get a few lines for each test and a bunch of logging informations. This is called noise. It gets even worse if the output is laced with exception stack traces. Sure, there are cases were you want to test error conditions and those will cause exceptions in return. However, consider yourself new to a team and you just setup a new sandbox, a good corporate citizen as you are, you run all the tests before you pick up your first user story to work on. But, what is this? The screen is scattered with exceptions in the test output. I would be scared and would assume that I did something wrong during setup. The noise drowns out the real state of the system -- a build system should communicate the health of the system in a unambiguous way. This is a risk which can be avoided easily.

Logging -- which was added to Java 1.4 -- allows you to add a filter. With that filter you can intercept and decide which logs to actually log.
Also, you have to make sure to use the same logger as the one you want to suppress. Just use the same string as identifier for both. I usually use the name of the class from the class object itself.

Logger LOG = Logger.getLogger(Example.class.getName());

once you have the logger instance, you add a filter which deals with the log record and suppresses its logging.

logger.setFilter(new Filter()
{
 public boolean isLoggable(LogRecord logRecord) {
   if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
        // deal with log record
   }
   return false; // suppress logging  }
});

Here the code for a small Example

public class Example {
  private static final Logger LOG = Logger.getLogger(Example.class.getName());
  public void foo() {
    LOG.info("entering");
    try {
      willFail();
    } catch (Exception e) {
      LOG.logp(Level.SEVERE, Example.class.getName(),
               "foo", "something bad happened", e);
    }
    LOG.info("exiting");
  } 
  private void willFail() throws Exception {
    throw new Exception("ERROR MSG");
  }
}

And here the matching test

public class ExamleTest extends TestCase {
  private Example example;
  private Logger logger;
  private List logRecords;

 protected void setUp() throws Exception {
   example = new Example();
   logger = Logger.getLogger(Example.class.getName());
   logRecords = new ArrayList();
 }

 public void testFooLogsSevereIfFailure() {
   logger.setFilter(new Filter()
   {
     public boolean isLoggable(LogRecord logRecord) {
       if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
         logRecords.add(logRecord);
       }
       return false;
   }});

   example.foo();

   assertEquals(1, logRecords.size());
   assertEquals("something bad happened", logRecords.get(0).getMessage());
   assertEquals("ERROR MSG", logRecords.get(0).getThrown().getMessage());
 }

 public void testFooLogsEntryAndExit() {
   logger.setFilter(new Filter()
   {
     public boolean isLoggable(LogRecord logRecord) {
       if (logRecord.getLevel().intValue() == Level.INFO.intValue()) {
         logRecords.add(logRecord);
       }
       return false;
   }});

   example.foo();

   assertEquals(2, logRecords.size());
   assertEquals("entering", logRecords.get(0).getMessage());
   assertEquals("exiting", logRecords.get(1).getMessage());
 }
}

With this you remove the noise from running your tests as this

ExamleTest,testFooLogsSevereIfFailure
May 5, 2008 9:50:18 PM Example foo
INFO: entering
May 5, 2008 9:50:18 PM Example foo
SEVERE: something bad happened
java.lang.Exception: ERROR MSG
 at Example.willFail(Example.java:20)
 at Example.foo(Example.java:11)
 at ExamleTest.testFooLogsSevereIfFailure(ExamleTest.java:33)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at junit.framework.TestCase.runTest(TestCase.java:164)
 at junit.framework.TestCase.runBare(TestCase.java:130)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:120)
 at junit.textui.TestRunner.doRun(TestRunner.java:121)
 at com.intellij.rt.execution.junit.IdeaTestRunner.doRun(IdeaTestRunner.java:65)
 at junit.textui.TestRunner.doRun(TestRunner.java:114)
 at com.intellij.rt.execution.junit.IdeaTestRunner.startRunnerWithArgs(IdeaTestRunner.java:24)
 at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:118)
 at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:40)
May 5, 2008 9:50:18 PM Example foo
INFO: exiting

Process finished with exit code 0

becomes that

Process finished with exit code 0

The second line shows you that the tests passed (exit code 0) with no errors. All you need to know. No noise!
Best of all, you now actually test a specific exception to be thrown if a certain condition occurs. So, if a fellow programmer removes the exception with or without intention you get at least a raised finger in form of a failing test. That should lead to a conversation which again makes sure that the situation is resolved accordingly. Agile is about communication!

Note: This applies only for the JDK logger. log4j does not feature a filter which can be modified at runtime. I haven't spent lots of time investigating, but as of now I did not discover a work around. Drop me a line if you figured that one out ;)