The rocket tale (Part II): Look at the time !

In this post I’ll try to explain what’s difference between all the different timing modes that CodeTrack provides. I’ll be using the same analogy as I did in part I, so if you didn’t read that yet: please go and do that first. Otherwise this will make no sense at all 🙂 (go ahead, I’ll wait).

Hi Res Wall Time

So let’s assume you’re the tracing expert again, and you walk into the factory to go and write down some timings. For the sake of simplicity, we’ll just trace 1 assembly line.
At the assembly line only 1 worker can actually do work and they have to wait to start doing their task if the previous worker completely finishes his own task.
The most obvious way to write down the time, is to go and read it from a clock that hangs at the wall of the factory entrance. This is what we will call Hi Res Wall Time.

18cd0b51ed68ed9f0ea5e9e857707fc0

Overhead

So now every time John Doe starts  producing a screw, this is what happens (let’s put some actual timings next to every event):

  1. John leaves his working post and comes to tell you he’s going to make a screw (10 seconds)
  2. you get up, run to the factory entrance, look at the time (1 minute)
  3. you run back to the assembly line (1 minute)
  4. you write down the time (10 seconds)
  5. John goes back to its working post (10 seconds)
  6. John starts his task (1 second)
  7. John produces a screw (10 minutes)
  8. John finishes his task (1 second)
  9. John leaves his working post and comes to  tell you he finished a screw (10 seconds)
  10. you get up, run to the factory entrance, look at the time (1 minute)
  11. you run back to the assembly line (1 minute)
  12. you write down the time (10 seconds)
  13. John goes back to its working post (10 seconds)
  14. John or one of his colleagues can now start again at 1)

It might seem a little exaggerated to split it up in such small subtasks, but most of these impact your tracing overhead (and thus your result).  So in total you’ve spent 2 minutes 31 seconds before the actual production of the screw and the same amount after the screw was finished. So 5 minutes 2 seconds overhead for a production time of 10 minutes.

You can clearly see, John will produce far less screws when you’re around 🙂

speed-slow-snails-ss-1920-800x450

Jim, a colleague of John working at the same assembly line, assembles the rocket with the screws John produced. This task takes 4 hours. So you might think that for Jim, the overhead will be so relatively small that it can be ignored.
Sadly, that’s not completely true. If a worker (Jim) depends on other workers (John’s screws), the overhead can turn into a real avalanche effect since every overhead for measuring sub tasks will be added to the parent tasks as well.
Not only does the factory slow down, it also might give a completely reversed view of Jim’s actual performance. It might look as if it took  Jim ages to screw together rocket parts, because John had to make 100 screws each with their own overhead. So this means that Jim already inherited Johns overhead (of 100 x 5min =8.3 hours), before he even started !

(Lo Res) Wall Time

Obviously the CEO doesn’t like the overhead you’re introducing, and Jim isn’t happy either. So what can be done about it ? We could try to reduce the overhead by not running back and forth to the factory entrance clock.

Wstressed-male-office-worker-holding-overtime-clock-overloaded-businessman-standing-modern-flooded-paper-work-over-time-30450754e cannot move the clock to the assembly line, but what we can do is hire a clock assistant. The clock assistant will constantly run back and forth between the factory entrance and the assembly hall. In the assembly hall is a huge whiteboard, were the assistant will write down the latest time.
This will drastically reduce the overhead of the tracing expert. As with everything in life, this comes with a cost: accuracy. The whiteboard wall time will at least differ with the entrance clock with a value of the duration of  1 assistant-round-trip.

Overhead Compensation

If the CEO doesn’t care for the factory slowing down, there’s another solution to our overhead problem (at least to the issue Jim is having). We can measure how long the events before and after a task (marked in blue) take and then subtract this overhead from the measured time. Of course we also have to subtract this overhead from all parent tasks as well.
I see you rolling your eyes and saying: “OK wiseguy, and how am I going to time the overhead of taking the time, that will take even more time !”. Correct! You could run back and forth to the clock and then subtract the 2 timings. This will give you an idea about the duration of taking the time. This will always be an estimation though, because there’s no guarantee that each round trip will take the same time. If we would do this for every measurement, the overhead will increase even more, so we could just do this every once in a while and then use the latest estimation.
Unfortunately the orange events cannot be compensated, because you’ve got no idea of the exact moment that John leaves or returns to his working place. Luckily, this overhead is quite small.
We could also do a combination of Lo-Res wall time and overhead compensation. The question is: Given the fact that 1 single overhead probably takes less time than the assistant-round-trip does this make any sense ?  I’m guessing not so much 🙂

Thread Cycles

Now imagine you have several assembly lines each peacefully minding their own business.
One assembly line (A) creates engine screws and assembles the engine. The other assembly line (B) assembles the rocket from the major parts (one of which is the engine).
Once assembly line B gives the order to produce an engine to assembly A, it needs to wait for A to finish. The complete task of assembly line A took 10 hours, assembly line B worked for 4 hours creating the assembled engine.
If you would be using the wall time method, it would look like assembly line A worked for 10 hours, while they were actually just waiting for 4 hours and really worked for 6 hours.

This is were Thread Cycles can help you out. Every 5 minutes, each assembly line teamlead needs to notify the accountant department how many minutes they have been really busy. You can request this information from the accountant department, but this department is a 10 minute walk away from the assembly hall. This will induce an unacceptable overhead. That’s why you have a tracing assistant running back and forth from the assembly hall to the accountant department. Just like with the wall time, this timing will be written on the whiteboard.

If you use this timing, the report will show how much time was spent while actually doing useful work. Although you need to take in account that these timings will not be 100% accurate.

 

BOOM !

If you would just do your tracing and at the end of the week walk out of the factory when it closes down for the weekend, you can hand over your report to the CEO. Done !

But imagine on Thursday evening the rocket factory explodes with an enormous bang and everything is turned to shreds (including you). The CEO will never know what was going on when the factory exploded.

2a94ac0f00000578-3163988-other_than_the_two_fire_fighters_who_were_injured_while_trying_t-a-58_1437064985683
Thats why every 30 minutes, a sub report is sent out to the tracing headquarters. This way the CEO might see what the reason of the explosion was. Unfortunately, sending this subreport again creates another overhead. I’m guessing, this is one the CEO is willing to take.

Conclusion

Let’s see what the analogy represents in the real world:

  1. John leaves his working post and comes to tell you he’s going to make a screw (10 seconds)
    • The CLR calls into an enter method hook
  2. you get up, run to the factory entrance, look at the time (1 minute)
    • CodeTracks profiling code is called and the PerformanceCounter is queried
  3. you run back to the assembly line (1 minute)
    • The Performance counter returns the current CPU clock cycles
  4. you write down the time (10 seconds)
    • CodeTrack does it’s thing and sometimes flushes data
  5. John goes back to its working post (10 seconds)
    • The CLR returns from the enter method hook
  6. John starts his task (1 second)
    • The actual method is called
  7. John produces a screw (10 minutes)
    • The actual method runs
  8. John finishes his task (1 second)
    • The actual method is done
  9. John leaves his working post and comes to  tell you he finished a screw (10 seconds)
    • The CLR calls into a leave method hook
  10. you get up, run to the factory entrance, look at the time (1 minute)
    • CodeTracks profiling code is called and the PerformanceCounter is queried
  11. you run back to the assembly line (1 minute)
    • The Performance counter returns the current CPU clock cycles
  12. you write down the time (10 seconds)
    • CodeTrack does it’s thing and sometimes flushes data
  13. John goes back to its working post (10 seconds)
    • The CLR returns from the leave method hook

CodeTrack offers all these advanced settings, so you choose the exact options you want.
They all have their specific properties and usages. You can find them while setting up a new session (Collect tab), in the options step under the ADVANCED expander:

profiling_options

If you don’t select any timing options, CodeTrack will go with Lo Res walltime.
You can select multiple timing modes (Hi/Lo res + Overhead Compensation + Thread Cycles) and then switch back and fourth between all measurements in the analysis phase.

Now you’re ready to go and build some rockets…

Get your free copy at www.getcodetrack.com
If you have any (codetrack) issues, feel free to let me know !
If you like it: please share with your fellow rocket-CEOs.

twitter_bg

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s