We now have implemented a working fire effect in a form that’s extremely easy to read.  The intention of the code is clear, our functions are nice and modular, and the algorithms are clear.  However, we need to deal with some performance issues.  For that, we’ll take a small digression.

At this point, if performance is of utmost importance, we might consider simply porting our script to a compiled C# cmdlet.  However, we’ll continue this in MSH, applying highly-targeted optimizations to bring the performance up to an acceptable level.

When tackling performance problems, the first rule is to measure the problem.  I can’t stress this highly enough.  It stuns (and saddens) me when I see people parade around on an optimization binge without ever enlisting the help of a profiler, or other measurement tool.  Unless you can guide your optimization efforts with hard performance data, you are almost certainly directing them to the wrong spots.  Random cute performance hacks will quickly turn your code to garbage, often with no appreciable performance gain.  I’ve done my fair share of micro-optimization, but it’s always been under the guidance of hard data to support it. 

Now, let’s investigate sources of our performance problems by measuring them.

The easiest way is to probably comment out function calls to see their effect on our refresh rate.  If we comment out the calls to both updateBuffer and updateScreen in our Main function, then we get about 8,000 frames per second.  If we comment out only the call to updateBuffer, we get about 3.7 frames per second.  If we comment out only the call to updateScreen, we get about 0.54 frames per second.  We can continue to comment out chunks of code, slowly determining what causes the most drastic effect on our script’s performance.

However, that’s not very elegant.  It’s slow, and inefficient.  We should really rely on a profiler to provide us the information we need.  But MSH doesn’t have a script profiler.

Is that going to stop us?  Not in the least.  In fact, it will barely slow us down.  With a surprisingly small amount of bubble gum and handy twine, we’ll write our own – in MSH, of course.

There are two approaches one can take when writing a profiler.  The first is an instrumenting profiler, and the second is a sampling profiler.

Instrumenting profilers inject code at the beginning and end of every call to measure the time spent in that call.  The idea is fairly straight-forward, but the technique is fairly invasive.  The instrumentation process itself can skew the performance profile of a program, so the profiler needs to calibrate itself to account for that.  In addition, robust code instrumentation is extremely difficult.  Binary instrumentation is much easier, so nearly all instrumenting profilers take this approach.

Sampling profilers semi-randomly peek into a program to see what statement it is currently executing.  If we see the program executing a certain statement half of the times we check, we can be fairly confident that our program is spending about 50% of its time executing that statement.  Likewise, if we see the program executing a certain statement 8 out of the 50 times we check, we can be fairly confident that our program is spending about 16% of its time executing that statement.  When we apply this idea to a much larger sample set, we can fairly accurately map the execution time of each individual statement.

We’re going to primarily implement a sampling profiler for several reasons:

• There is no concept of an MSH Script Binary.  If we implement an instrumenting profiler, we have only the very perilous path of mangling the script itself.
• Monad has several bits of infrastructure available that make a sampling profiler surprisingly easy to implement.

So how do we peek in on the MSH engine to see which line of script it’s currently executing?  Very indirectly. 

1. Turn on MSH script tracing (at level 1,) as outlined as part of Jon Newman’s excellent series of posts.
   MSH:116 C:\Temp >set-mshdebug –trace 1
2. Turn on file logging for our session:
   MSH:117 C:\Temp >start-transcript
3. Start our script

Once the script starts, we get entries similar to this in the transcript log for our session:

(…)
DEBUG:  113+             $colour = $screenBuffer[$baseOffset]
DEBUG:  114+             $colour += $screenBuffer[$baseOffset - 1]
DEBUG:  115+             $colour += $screenBuffer[$baseOffset + 1]
DEBUG:  116+             $colour += $screenBuffer[$baseOffset +
$windowWidth]
(…)

Now, we can see what line of script the engine is currently executing by looking at the last bit of output that made it to the log.

Here is an example of the output – we’ll go over the code next time:

Breakdown by line:  
----------------------------  
 15%: Line  123 -             if($colour -lt 20) { $colour -= 1 }  
 14%: Line  122 -             if($colour -le 70) { $colour -= 3 }  
 11%: Line  124 -             if($colour -lt 0) { $colour = 0 }  
 10%: Line  128 -             $tempWorkingBuffer\[$baseOffset -  
  8%: Line  117 -             $colour /= 4.0  
  7%: Line  121 -             if($colour -gt 70) { $colour -= 1 }  
  6%: Line  154 -             $nextScreen\[$row, $column\] = \`  
  6%: Line  113 -             $colour = $screenBuffer\[$baseOffset\]  
  6%: Line  115 -             $colour += $screenBuffer\[$baseOffset + 1\]  
  6%: Line  116 -             $colour += $screenBuffer\[$baseOffset +  
  5%: Line  114 -             $colour += $screenBuffer\[$baseOffset - 1\]  
  5%: Line  109 -             $baseOffset = ($windowWidth \* $row) +  
  0%: Line   90 -         if($random.NextDouble() -ge 0.20)  
  0%: Line  152 -         for($column = 0; $column -lt $windowWidth;  
  0%: Line   94 -             $screenBuffer\[($windowHeight - 2) \*

Breakdown by marked regions:  
----------------------------  
  6%: updateScreen  
  0%: startFireLastRow  
 93%: propigate  
  0%: Unmarked  
  0%: main

[Edit: Monad has now been renamed to Windows PowerShell. This script or discussion may require slight adjustments before it applies directly to newer builds.]