Chapter 8: Profilers

We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil.

— Donald Knuth, JON POSTEL, Structured Programming with go to Statements

What is a profiler?

According to wikipedia, profiling is is the investigation of a program's behavior using information gathered as the program runs (i.e. it is a form of dynamic program analysis, as opposed to static code analysis). The usual goal of performance analysis is to determine which parts of a program to optimize for speed or memory usage.

A logback profiler will help the developer to gather performance data. Essentially, a profiler consists of one or more stopwatches. Stopwatches are driven (started/stopped) by statements in the source code. An example, should make the point clearer.

Basic example

Example 8.1: Using the profiler ( logback-examples/src/main/java/chapter8/ProfilerUsageExample.java)

package chapter8; import ch.qos.logback.classic.stopwatch.Profiler; public class ProfilerUsageExample { public static void main(String[] args) { Profiler profiler = new Profiler("BASIC"); profiler.start("A"); doA(); profiler.start("B"); for (int i = 0; i < 5; i++) { doSubtaskTwo(i); } profiler.start("doOther"); doOther(); profiler.stop().print(); } ... cut

Running the above example will output the following output.

+ Profiler [BASIC] |-- elapsed time [A] 0.288 milliseconds. |-- elapsed time [B] 24.717 milliseconds. |-- elapsed time [Other] 22.085 milliseconds. |-- Total elapsed time [BASIC] 50.691 milliseconds.

Instantiating a profiler starts a global stopwatch. Each call to the start() method starts a new and named stopwatch. In addition to sarting a named stopwatch, the start() method also causes the previous stopwatch to stop. Thus, the call to profiler.start("A") starts a stopwatch named "A". The subsequent call to profiler.start("B") starts stopwatch "B" and simultanously stops the stopwatch named "A". Invoking the stop() on a profiler method stops the last stopwatch as well as the global stopwatch which was started when the profiler was instantiated.

Profiler nesting

Profilers can also be nested. By nesting profilers, it is possible to measure a subtask which itself has subtasks that need to be timed.