Brian Hartsock's Blog

I have convinced another employee of mine to start a blog. Check out Robert Beheiter’s blog, first few posts on F#. Looking forward to future posts.

I travel every now and again with work. When I do, I tend to take a fairly large bookbag with way too much electronic equipment. Check out my setup last time I was in the Jungle Disk Atlanta office.

Since the first piece of computer software was created, there have been defects. We have came a long way since those days, but defects are still prevalent throughout every application. They are reported by testers or end users, and eventually make their way back to the software developers that created them. Or did they?

One thing I have observed over the past few years is the fact that almost all defects make their way back to software developers, but developers aren’t always the culprits. To make sense of this, you can categorize types of defects. I have noticed there are three different types of defects that seem quite common, Functional, Procedural, and Conceptual.

Functional defects are traditional bugs. I do XYZ, expect A but get B. Software developers are the culprit, and the right person to be fixing the defect (and hopefully using automated testing to prevent it from ever happening again).

Procedural defects stem from bad processes, which may look very similar to I do XYZ, expect A but get B. The reason they got B instead of A is rooted in the fact that a process wasn’t followed. For example, a new feature is introduced that changes how a user creates a widget. The documentation is never updated however, because the sticky note fell off the task board. Oops! To the user, this is a defect, but in all reality, the root cause a process problem.

Conceptual defects are the nastiest ones. These are the defects that stem from requirements, usability, or just bad features. Often parts of an application need to be rethought, removed, and vastly improved to resolve these issues. What do these issues look like?

A user can’t create a new widget. They can’t create the new widget because they haven’t met all the criteria to create new widget (but the criteria isn’t easily understood).

Why is it important to understand these categories? Because software developers can only really solve functional defects, but they often deal with procedural or conceptual defects daily. Being a software development manager, I see this all the time.

Functional defacts fall on the software developers.

Procedural defects fall on whoever is playing the role of project manager for a team.

Conceptual defects fall on whoever is playing the role of product owner/manager for the team.

It is important to have a system in place that can handle all types of defects, not just functional. Otherwise frustration will set in on your developers.

Every now and again, your build time gets so long you have to investigate what the cause is. Since Visual Studio uses MSBuild, it is possible to get very detailed build information.

The first step is getting into diagnostic mode. This will print out way too much information, but it is the only mode that prints out execution summaries for each project. To get into diagnostics mode, simply go to Tools -> Options -> Projects and Solutions -> Build and Run. From there, you can change the MSBuild verbosity to diagnostic.

Now just build (or rebuild). Then copy the build output to a txt file and save it somewhere.

The only problem with the output is the amount of information (300K lines on a rebuild of a medium size project). It has ton’s of valuable information, but an easy way to process it is needed. The biggest value, in my opinion, is the section at the end of every project where the Summary information about projects, targets, and tasks are displayed. To help retrieve this info, I wrote a quick little Powershell script.

 
param
(
    [string] $file = ""
)
 
if(!(test-path $file)){
    throw "$file not found"
}
 
function accumulate_and_print_project_info(){
    begin{
        $curr_project = ""
        $should_print = $false
    }
    process{
 
 
        if($_ -match "----- (re)?build (all )?started: project: (.*) -----"){
            $curr_project = $matches[3]
            "----- $curr_project -----"
            $should_print = $false
        }elseif($curr_project -and !$should_print -and $_.EndsWith("Summary:")){
            $_
            $should_print = $true
        }elseif($curr_project -and $should_print -and $_ -eq ""){
            $should_print = $false
        }elseif($should_print){
            $_
        }
    }
}
 
gc $file | accumulate_and_print_project_info

The output is going to look something like the following.

----- ControlPanel, Configuration: Development Any CPU -----
Project Performance Summary:
     2672 ms  C:\Users\brian.hartsock\Documents\Visual Studio 2008\Projects\Api\cp3\ControlPanel\ControlPanel.csproj   1 calls
Target Performance Summary:
        0 ms  CreateSatelliteAssemblies                  1 calls
        0 ms  _ComputeNonExistentFileProperty            1 calls
        0 ms  Clean                                      1 calls
        0 ms  _AfterCompileWinFXInternal                 1 calls
        0 ms  BeforeCompile                              1 calls
        0 ms  BeforeClean                                1 calls
        0 ms  AfterBuild                                 1 calls
        0 ms  GetTargetPath                              1 calls
        0 ms  _CheckForCompileOutputs                    1 calls
        0 ms  EntityDeploy                               1 calls
        0 ms  ResolveVCProjectReferences                 1 calls
        0 ms  _SetEmbeddedWin32ManifestProperties        1 calls
        0 ms  StyleCopForceFullAnalysis                  1 calls
        0 ms  CleanPublishFolder                         1 calls
        0 ms  BeforeBuild                                1 calls
        0 ms  CoreResGen                                 1 calls
        0 ms  BeforeRebuild                              1 calls
        0 ms  _CopySourceItemsToOutputDirectory          1 calls
        0 ms  AfterResGen                                1 calls
        0 ms  Build                                      1 calls
        0 ms  SetWin32ManifestProperties                 1 calls
        0 ms  AssignTargetPaths                          1 calls
        0 ms  CoreBuild                                  1 calls
        0 ms  AfterResolveReferences                     1 calls
        0 ms  Compile                                    1 calls
        0 ms  ResGen                                     1 calls
        0 ms  AfterClean                                 1 calls
        0 ms  Rebuild                                    1 calls
        0 ms  PrepareResourceNames                       1 calls
        0 ms  BuildOnlySettings                          1 calls
        0 ms  PrepareResources                           1 calls
        0 ms  CleanReferencedProjects                    1 calls
        0 ms  AfterMarkupCompilePass1                    1 calls
        0 ms  FileClassification                         1 calls
        0 ms  AfterCompile                               1 calls
        0 ms  CompileRdlFiles                            1 calls
        0 ms  BeforeResolveReferences                    1 calls
        0 ms  CreateCustomManifestResourceNames          1 calls
        0 ms  ResolveReferences                          1 calls
        0 ms  DesignTimeMarkupCompilation                1 calls
        0 ms  AfterRebuild                               1 calls
        0 ms  GetReferenceAssemblyPaths                  1 calls
        0 ms  PrepareForRun                              1 calls
        0 ms  AfterCompileWinFX                          1 calls
        0 ms  BeforeResGen                               1 calls
        1 ms  PrepareRdlFiles                            1 calls
        1 ms  GetCopyToOutputDirectoryItems              1 calls
        1 ms  SplitResourcesByCulture                    1 calls
        1 ms  _SplitProjectReferencesByFileExistence     1 calls
        1 ms  _GenerateCompileInputs                     1 calls
        1 ms  _GenerateSatelliteAssemblyInputs           1 calls
        1 ms  GetWinFXPath                               1 calls
        1 ms  EntityClean                                1 calls
        1 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
        1 ms  ResolveProjectReferences                   1 calls
        1 ms  PrepareForBuild                            1 calls
        3 ms  GetFrameworkPaths                          1 calls
        8 ms  CoreClean                                  1 calls
       14 ms  IncrementalClean                           1 calls
       17 ms  CopyFilesToOutputDirectory                 1 calls
       17 ms  _CleanGetCurrentAndPriorFileWrites         1 calls
       66 ms  ResolveAssemblyReferences                  1 calls
      399 ms  _CopyFilesMarkedCopyLocal                  1 calls
      519 ms  StyleCop                                   1 calls
      636 ms  CoreCompile                                1 calls
      974 ms  PostBuildEvent                             1 calls
Task Performance Summary:
        0 ms  Delete                                     2 calls
        0 ms  Message                                    6 calls
        0 ms  EntityDeploy                               1 calls
        0 ms  GetFrameworkSdkPath                        1 calls
        0 ms  CreateProperty                             1 calls
        0 ms  AssignTargetPath                           5 calls
        0 ms  MakeDir                                    2 calls
        1 ms  ConvertToAbsolutePath                      1 calls
        1 ms  AssignCulture                              1 calls
        1 ms  GetWinFXPath                               1 calls
        1 ms  FindAppConfigFile                          1 calls
        1 ms  ReadLinesFromFile                          2 calls
        1 ms  EntityClean                                1 calls
        2 ms  CreateItem                                 3 calls
        2 ms  WriteLinesToFile                           2 calls
        3 ms  GetFrameworkPath                           2 calls
       13 ms  RemoveDuplicates                           3 calls
       20 ms  FindUnderPath                              7 calls
       66 ms  ResolveAssemblyReference                   1 calls
      415 ms  Copy                                       6 calls
      515 ms  StyleCopTask                               1 calls
      635 ms  Csc                                        1 calls
      973 ms  Exec                                       1 calls

Now you should have all the data you need to figure out what is taking so long to build your project.

Some team members and I spent the better part of a few hours today researching a really weird bug we were seeing with our data access code built on NHibernate.

The basic symptoms were a duplicate key violation on a unique column in a table. This only happened under decent load, so reproducing in dev was pretty hard. To make matters more interested, it only happened with NHibernate 2.0. We started looking at MySQL logs and saw the following.

INSERT (value, unique_value) some_table VALUES ('some_value', 'some_unique_value');
-- Auto-increment ID column gets set to 10
SELECT LAST_INSERT_ID()
-- Returns 9
UPDATE unique_value='some_unique_value' AND value='other_value' WHERE id=9
-- Duplicate key exception because unique constraint is violated

Yes, SELECT LAST_INSERT_ID() was returning the wrong value. After digging through the NHibernate source code, it became pretty apparent what was happening. We weren’t using transactions (because the DB is MyISAM) and we found the following code.

// (Some ConnectionManager code)
public void AfterTransaction()
{
	if (IsAfterTransactionRelease)
	{
		AggressiveRelease();
	}
	else if (IsAggressiveRelease && batcher.HasOpenResources)
	{
		log.Info("forcing batcher resource cleanup on transaction completion; forgot to close ScrollableResults/Enumerable?");
		batcher.CloseCommands();
		AggressiveRelease();
	}
	else if (IsOnCloseRelease)
	{
		// log a message about potential connection leaks
		log.Debug(
			"transaction completed on session with on_close connection release mode; be sure to close the session to release ADO.Net resources!");
	}
	transaction = null;
}
 
private bool IsAggressiveRelease
{
	get
	{
		if (connectionReleaseMode == ConnectionReleaseMode.AfterTransaction)
		{
			return !IsInActiveTransaction;
		}
		return false;
	}
}
 
//Some AbstractSessionImpl code
 
protected void AfterOperation(bool success)
{
	using (new SessionIdLoggingContext(SessionId))
	{
		if (!ConnectionManager.IsInActiveTransaction)
		{
			ConnectionManager.AfterNonTransactionalQuery(success);
		}
	}
}
 
//And finally the AdoTransaction code
public bool IsActive
{
	get { return begun && !rolledBack && !committed; }
}

Basically, NHibernate will quasi-create an implicit transaction if it isn’t explicitly created. What’s weird is the scope of the transaction is just a single query. As you can see in the above code, I never called BeginTransaction() so tx.IsActive returns false, which indirectly makes the AbstractSessionImpl class think the transaction is over, which in turn indirectly triggers the ConnectionManager code to release the connection if the ConnectionReleaseMode is set to after transaction (which it is by default).

Whew!

Some outstanding questions though are why did this start happening with 2.0 and not 1.2? My guess is some code was refactored with how the last insert ID is retrieved, and in 1.2 it was impossible for it to have different connections. With 2.0, it is pretty easy to have different connection objects if concurrent operations are occurring.

Read more on ConnectionReleaseMode’s here.

(I hope this post made sense as I am super tired and have been learning NHibernate source code rapidly for the past few hours)