How to Make Things Faster

Chapter 19. Tracing

All of the optimization stories I’ve told so far have motivated and remotivated the three-word prescription, look at it. In the Phyllis story, the look at it step came to me in the form of an unintentional ambush. In the Nancy case, looking at her screen as she typed was the key to understanding that she was unaware of a helpful feature. Likewise, all I needed in Orange County to see the label-printing symptom was a good tour guide and my own two eyes.

But in the order confirmation problem in Orange County and the payroll problem in Dallas, looking at it was more complicated than just seeing something physical. How do you “look at” how a computer program spends time? The answer is, you trace it.

Tracing creates a stream of output that explains the steps that your program is executing. Tracing can be a feature of the program you’re diagnosing, or it can be a service provided by a separate program. In its simplest form, tracing is simply the execution of some extra print statements that write information to a file about the progress of the program being executed.

For example, a simple tracing feature for a procedure to process an invoice might look like this:

1.   procedure processInvoice(n) {
2.      if TRACING printf(TRC, “%s processInvoice(%d) {\n”, now, n);
3.      // the work of processing invoice #n goes here
4.      if TRACING printf(TRC, “%s }\n”, now);
5.   }

Then a program that processes many invoices inside of a loop would write trace data that looks like this:

 1. ...