Analyzing Visual Studio Build Performance

Posted on December 22, 2009 by bhartsock

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.

NHibernate Connection Release Modes

Posted on December 17, 2009 by bhartsock

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)

Find Orphaned Solution Files

Posted on December 7, 2009 by bhartsock

Each day, I am becoming more and more OCD. Tonight I wrote a script that will analyze a Visual Studio csproj file and compare it to the files in the directory. The main goal being an easy way to find orphaned files that might still be in version control. It probably only works on very vanilla projects, but I figured I would share anyways.

# find-orphanedFiles.ps1
#
# Compare files in a Visual Studio project file to the actual files in the directory
#
# Usage:
# .\find-orphanedFiles.ps1 Project\FooBar.csproj
# .\find-orphanedFiles.ps1 Project\FooBar.csproj -exclude "*.csproj","*.csproj.user","svn.ignore"
 
param
(
    $csProjFile,
    $exclude = ("*.csproj*")
)
 
function custom-gci($path=(get-location)){
    gci $path -exclude $exclude | 
    %{
        if($_.PSIsContainer -and ($_.name -ne "bin" -and $_.name -ne "obj")){
            custom-gci $_
        }elseif(!($_.PSIsContainer)){
            $_
        }
    } 
}
 
if(!(test-path $csProjFile)){
    throw "File $csprojFile does not exist"
}
 
$dir = split-path $csProjFile
$csProjfile = split-path $csProjFile -leaf
 
push-location $dir
 
$x = [xml] (gc $csProjFile)
 
$filesInProject = $x.Project.ItemGroup | 
    foreach {
        if($_.Compile) { 
            $_.Compile
        }elseif($_.None){
            $_.None
        }elseif($_.Content){
            $_.Content
        }elseif($_.EmbeddedResource){
            $_.EmbeddedResource
        }
    } | 
    select -expand include | 
    resolve-path | 
    gi | 
    select -expand fullname
 
$filesInDir = custom-gci |
    select -expand fullname
 
compare-object $filesInProject $filesInDir
 
pop-location

Don Norman – Ten Rules for Successful Products

Posted on December 2, 2009 by bhartsock

Don is #2 on my list of speakers from Business of Software 2009. Don forces you to understand how people are using your product. It sounds simple, but most companies have a different outlook on their product than their customers. Here are his 10 rules for successful products.

Everything is a product. Everything is a service. You can’t have one without the other. The software you create is a product, but the experience you provide is your service. Don’t forget about one of these principles while focusing on the other.

Don’t be too logical. This might be the downfall of 99% of all developers. We are wired to think about the logical steps to perform an action, but users have emotion which plays the major role in their decisions. Usability testing is the best way to truly see how someone will use your product.

Design systems. Think about the iPod + iTunes + Add-ons or Kindle + Amazon + Verizon. This goes back to the above. Think about the entire service your product is providing, not just the functionality the product contains. A complete system solves the entirety of a customers problem. If you only solve a small portion of their problem, the experience is going to be lacking.

The other main points, which I think are fairly self explanatory.

It’s all about the experience
Memory is more important than actuality – Make the beginning and ending memorable
Complexity is good, Complicated is bad
Design for the real world.
Design for the people.
It’s all about the experience

Check out Don’s books if you want to hear more.

Brian Hartsock's Blog

The exciting life of a software developer and nerd

Monthly Archives: December 2009

Analyzing Visual Studio Build Performance

NHibernate Connection Release Modes

Find Orphaned Solution Files

Don Norman – Ten Rules for Successful Products