What may make non-optimized F# code faster than optimized code?

Question

So I've decided to give F# a try and ported one the algorithms I've written in C# to it. At one point, I have noticed that debug build run faster than the release one. I then played with the optimization settings and got these results:

The times show the total execution time of the algorithm over 100000 runs. I am using the F# compiler that comes with Visual Studio 2010 SP1. Target platform is Any CPU.

Opt off, tail calls off: 5.81s
Opt off, tail calls on : 5.79s
Opt on , tail calls off: 6.48s
Opt on , tail calls on : 6.40s

I am really puzzled by this - why does the optimization make the code run slower? The C# version of the algorithm does not exhibit this behavior (altho it is implemented in a slightly different way)

Here is a stripped down version of the F# code, it is an algorithm that finds patterns in molecules. All the code that this F# program relies on is written in F#.

namespace Motives
  module Internal = 
    type Motive = 
      { ResidueSet: Set<Residue>; AtomSet: Set<IAtom> }
      member this.Atoms : IAtom seq = 
        seq { 
          for r in this.ResidueSet do yield! r.Atoms
          yield! this.AtomSet
        }
      static member fromResidues (residues : Residue seq) = residues |> Seq.fold (fun (m: Set<Residue>) r -> m.Add(r)) Set.empty |> fun rs -> { ResidueSet = rs; AtomSet = Set.empty }
      static member fromAtoms (atoms : IAtom seq) = atoms |> Seq.fold (fun (m: Set<IAtom>) a -> m.Add(a)) Set.empty |>  fun atoms -> { ResidueSet = Set.empty; AtomSet = atoms }
      static member merge (m1: Motive) (m2: Motive) = { ResidueSet = Set.union m1.ResidueSet m2.ResidueSet; AtomSet = Set.union m1.AtomSet m2.AtomSet }
      static member distance (m1: Motive) (m2: Motive) = Seq.min (seq { for a in m1.Atoms do for b in m2.Atoms -> a.Position.DistanceTo(b.Position) })

    type Structure with 
      static member fromMotive (m: Motive) (parent: IStructure) (addBonds: bool) : IStructure = 
        let atoms = AtomCollection.FromUniqueAtoms(m.Atoms)
        let bonds = 
          match addBonds with 
          | true -> BondCollection.Create(atoms |> Seq.map (fun a -> parent.Bonds.[a]) |> Seq.concat)
          | _ -> BondCollection.Empty
        Structure.Create (parent.Id + "_" + atoms.[0].Id.ToString(), atoms, bonds)

    // KDTree used for range queries
    // AminoChains used for regex queries
    type StructureContext = 
      { Structure: IStructure; KDTree: Lazy<KDAtomTree>; AminoChains: Lazy<(Residue array * string) list> }
      static member create (structure: IStructure) =
        match structure.IsPdbStructure() with
        | false -> { Structure = structure; KDTree = Lazy.Create(fun () -> structure.Atoms.ToKDTree()); AminoChains = Lazy.CreateFromValue([]) }
        | true  -> 
          let aminoChains = new System.Func<(Residue array * string) list> (fun () ->
            let residues = structure.PdbResidues() |> Seq.filter (fun r -> r.IsAmino)
            residues
            |> Seq.groupBy (fun r -> r.ChainIdentifier)
            |> Seq.map (fun (k,rs) -> rs |> Array.ofSeq, String.concat "" (rs |> Seq.map (fun r -> r.ShortName)))
            |> List.ofSeq)
          { Structure = structure; KDTree = Lazy.Create(fun () -> structure.Atoms.ToKDTree()); AminoChains = Lazy.Create(aminoChains) }

    // Remember the named motives from named patterns
    type MatchContext = 
      { StructureContext: StructureContext; NamedMotives: Map<string, Motive> }
      static member merge (c1: MatchContext) (c2: MatchContext) = 
        { StructureContext = c1.StructureContext; NamedMotives = c2.NamedMotives |> Map.fold (fun m k v -> m.Add(k,v)) c1.NamedMotives }

    type MatchedMotive = Motive * MatchContext 

    type Pattern = 
      | EmptyPattern
      | GeneratingPattern of ( StructureContext -> MatchedMotive seq )
      | ConstraintPattern of ( MatchedMotive -> MatchedMotive option ) * Pattern
      static member matches (p: Pattern) (context: StructureContext) : MatchedMotive seq = 
        match p with  
        | GeneratingPattern generator -> generator context
        | ConstraintPattern (transform, pattern) ->
          Pattern.matches pattern context
          |> Seq.choose (fun m -> transform m)
        | _ -> Seq.empty

    let ringPattern (names: string list) =
      let fingerprint = 
        names 
        |> Seq.map (fun s -> ElementSymbol.Create(s).ToString()) 
        |> Seq.sort
        |> String.concat ""  
      let generator (context: StructureContext) =
        let rings = context.Structure.Rings().GetRingsByFingerprint(fingerprint)
        rings |> Seq.map (fun r -> Motive.fromAtoms r.Atoms, { StructureContext = context; NamedMotives = Map.empty })
      GeneratingPattern generator

  open Internal

  type MotiveFinder (pattern: string) =
    // I am using a hard coded pattern here for testing purposes
    let pattern = ringPattern ["C"; "C"; "C"; "C"; "C"; "O"]
    member this.Matches (structure: IStructure) =
      Pattern.matches pattern (StructureContext.create structure)
      |> Seq.map (fun (m, mc) -> Structure.fromMotive m mc.StructureContext.Structure false) 
      |> List.ofSeq 
      |> List.sortBy (fun s -> s.Atoms.[0].Id)

///////////////////////////////////////////////////////////////////
// performance test

let warmUp = (new MotiveFinder("")).Matches (StructureReader.ReadPdb(filename, computeBonds = true))
printfn "%i" (List.length warmUp)

let structure = StructureReader.ReadPdb(filename, computeBonds = true)
let stopWatch = System.Diagnostics.Stopwatch.StartNew()
let nruns = 100000
let result = 
  seq { 
    for i in 1 .. nruns do
      yield (new MotiveFinder("")).Matches structure 
  } |> Seq.nth (nruns-1)

stopWatch.Stop()
printfn "Time elapsed: %f seconds" stopWatch.Elapsed.TotalSeconds

EDIT2:

I seem to have narrowed down the problem to the implementation of the Set type.

For this code:

let stopWatch = System.Diagnostics.Stopwatch.StartNew()
let runs = 1000000
let result = 
  seq {
    for i in 1 .. runs do
      let setA = [ 1 .. (i % 10) + 5 ] |> Set.ofList
      let setB = [ 1 .. (i % 10) + 5 ] |> Set.ofList
      yield Set.union setA setB
  } |> Seq.nth (runs - 1)

stopWatch.Stop()
printfn "Time elapsed: %f seconds" stopWatch.Elapsed.TotalSeconds
printfn "%A" result

I get ~7.5s with optimization off and ~8.0s with optimization on. Still target = Any CPU (and I have i7-860 processor).

EDIT3: And right after I posted the previous edit I figured I should try it on lists only.

So for

let stopWatch = System.Diagnostics.Stopwatch.StartNew()
let runs = 1000000
let result1 = 
  seq {
    for i in 1 .. runs do
      let list = [ 1 .. i % 100 + 5 ]
      yield list
  } |> Seq.nth (runs - 1)

stopWatch.Stop()
printfn "Time elapsed: %f seconds" stopWatch.Elapsed.TotalSeconds
printfn "%A" result1

I get ~3s with opt. off and ~3.5s with opt. on.

EDIT4:

If I remove the seq builder and just do

let stopWatch = System.Diagnostics.Stopwatch.StartNew()
let runs = 1000000
let mutable ret : int list = []
for i in 1 .. runs do
  let list = [ 1 .. i % 100 + 5 ]
  ret <- list

stopWatch1.Stop()
printfn "Time elapsed: %f seconds" stopWatch.Elapsed.TotalSeconds
printfn "%A" ret

I get ~3s with optimization both on and off. So it seem that the problem is somewhere in optimizing the seq builder code.

Strangely enough, I wrote a test app in C#:

var watch = Stopwatch.StartNew();

int runs = 1000000;

var result = Enumerable.Range(1, runs)
  .Select(i => Microsoft.FSharp.Collections.ListModule.OfSeq(Enumerable.Range(1, i % 100 + 5)))
  .ElementAt(runs - 1);

watch.Stop();

Console.WriteLine(result);
Console.WriteLine("Time: {0}s", watch.Elapsed.TotalSeconds);

And the code happens to run almost twice as fast as the F# solution at ~1.7s.

EDIT5:

Based on the discussion with Jon Harrop I have found out the thing that is causing the optimized code run slower (I still don't know why tho).

If I change Motive.Atoms from

member this.Atoms : IAtom seq = 
  seq { 
    for r in this.ResidueSet do yield! r.Atoms
      yield! this.AtomSet
  }

to

member this.Atoms : IAtom seq = 
  Seq.append (this.ResidueSet |> Seq.collect (fun r -> r.Atoms)) this.AtomSet

then the program runs ~7.1s in both optimized and non-optimized version. Which is slower than the seq version, but at least consistent.

So it seems that the F# compiler just can't optimize computation expressions and actually makes them slower by trying so.

Answer 1

I can also observe your wrapper code and penultimate example running slightly slower with optimizations enabled but the difference is less than 10% and, although anomalous, I am not surprised that optimizations can sometimes slightly degrade performance.

I should note that your style of coding leaves a lot of room for optimization but without the entire source code it is not possible for me to help optimize it. Your example uses the following code:

let result1 =
  seq {
    for i in 1 .. runs do
      let list = [ 1 .. i % 100 + 5 ]
      yield list
  } |> Seq.nth (runs - 1)

when this is shorter, more idiomatic and orders of magnitude faster:

let result1 =
  Seq.init runs (fun i -> List.init ((i+1) % 100 + 5) ((+) 1))
  |> Seq.nth (runs - 1)

EDIT

In your comments below you say that you want to execute the function argument in which case I would not assume that Seq.nth will do this for you so I would use a for loop instead:

let mutable list = []
for i=1 to runs do
  list <- List.init (i % 100 + 5) ((+) 1)
list

This is still 9× faster than the original.