Profiling

Profiling answers where the time goes, and the first tool is a clock around a loop you suspect. The second is a counter of operations, which is deterministic and needs no timing at all. This lesson uses both, and the result is a measurement you can repeat rather than a number you remember.

Timing a hot loop

The monotonic clock from lesson 59 wraps the call, and the difference of two timespec values is the elapsed time. The loop must do real work and the result must be used, or the optimiser may remove it. Here the total is printed, which keeps the loop alive.

#include <stdio.h> #include <time.h> static long work(int n) { long total = 0; for (int i = 0; i < n; i++) { total += (long) i * i; } return total; } int main(void) { struct timespec start; struct timespec end; clock_gettime(CLOCK_MONOTONIC, &start); long total = work(5000000); clock_gettime(CLOCK_MONOTONIC, &end); long long ns = (end.tv_sec - start.tv_sec) * 1000000000LL + (end.tv_nsec - start.tv_nsec); printf("total: %ld\n", total); printf("elapsed: %lld ns\n", ns); return 0; }

gcc -O2 -Wall -Wextra hot.c -o hot
./hot

total: 4773166019248396768
elapsed: 3798695 ns

The total is the sum of squares up to five million, computed with 64-bit arithmetic; the elapsed time is under four milliseconds on this machine. The number changes with the load and with the build, so a single run is an indication, not a benchmark.

The same loop optimised

The same source built at -O0 and at -O2 gives the same answer and two different times. The optimised version keeps the loop variable in a register and can replace the accumulation with a closed form, so the gap is a direct measure of what the flag bought.

#include <stdio.h> #include <time.h> static long work(int n) { long total = 0; for (int i = 0; i < n; i++) { total += (long) i * i; } return total; } int main(void) { struct timespec start; struct timespec end; clock_gettime(CLOCK_MONOTONIC, &start); long total = work(5000000); clock_gettime(CLOCK_MONOTONIC, &end); long long ns = (end.tv_sec - start.tv_sec) * 1000000000LL + (end.tv_nsec - start.tv_nsec); printf("total: %ld\n", total); printf("elapsed: %lld ns\n", ns); return 0; }

gcc -O0 -Wall -Wextra hot.c -o hot0
./hot0
gcc -O2 -Wall -Wextra hot.c -o hot2
./hot2

total: 4773166019248396768
elapsed: 18266134 ns
total: 4773166019248396768
elapsed: 3882336 ns

The unoptimised run took about eighteen milliseconds and the optimised one about four, a factor of nearly five. The exact ratio varies with the compiler and the machine; the direction is the stable part. Profiling an -O0 build tells you where the source spends time, not where the release spends it.

Counting instead of timing

A counter is the profiling tool with no noise: increment it once per iteration or per comparison and the result is the same on every run. The loop below counts its own iterations, which is trivial here but becomes useful when comparing two algorithms on the same input.

#include <stdio.h> static long work(int n, long *operations) { long total = 0; *operations = 0; for (int i = 0; i < n; i++) { total += (long) i * i; (*operations)++; } return total; } int main(void) { long operations = 0; long total = work(1000000, &operations); printf("total: %ld\n", total); printf("operations: %ld\n", operations); return 0; }

gcc -O2 -Wall -Wextra count.c -o count
./count

total: 333332833333500000
operations: 1000000

The count is exact and repeatable, and the time is not. The count says nothing about cost per operation, so the two measures answer different questions: the clock says how long, the counter says how much work. A change that reduces the count but not the time has moved the cost somewhere else.

Integer division and gprof

The classic timing bug is integer division before the conversion to seconds. clock_t divided by CLOCKS_PER_SEC throws away the fraction, and a short measurement becomes zero:

#include <stdio.h> #include <time.h> int main(void) { clock_t start = clock(); long total = 0; for (int i = 0; i < 1000000; i++) { total += i; } double seconds = (clock() - start) / CLOCKS_PER_SEC; printf("total: %ld\n", total); printf("seconds: %.3f\n", seconds); return 0; }

gcc -Wall -Wextra divide.c -o divide
./divide

total: 499999500000
seconds: 0.000

The division happens in clock_t arithmetic and only the result is converted to double, so the sub-second remainder is lost. Casting one side to double first gives the fraction: (double) (clock() - start) / CLOCKS_PER_SEC.

The other half of this section is a tool that is not available here: gprof needs -pg and a startup object that this Alpine image does not ship (the link fails with cannot find gcrt1.o), so no gprof profile is shown on this page. The clock and the counter are the profiling tools that work in this container; a distribution that packages the profiling runtime can add gprof without changing the code.

Exercises

  1. Time the work loop for n = 1 000 000 and n = 2 000 000 and check whether the time doubles.
  2. Add a counter to the linear and binary search of lesson 49 and compare the counts for the last element.
  3. Fix the integer division in the mistake program with a cast and measure a loop long enough to print a nonzero time.

Questions

A new set of questions in a new order every time. Choose one answer for each, then check.

  1. Why must the result of a timed loop be used?

    Answer

    The optimiser may remove the whole loop otherwise

    A computation with no visible effect can be deleted, which makes the measured time meaningless.

  2. What does an -O0 versus -O2 timing comparison show?

    Answer

    The optimised build is much faster on the same work

    The optimiser keeps values in registers and can replace the accumulation, so the release build does less work.

  3. Why is an operation counter useful next to a clock?

    Answer

    It is exact and repeatable on every run

    The count does not depend on load or timing noise, while the clock answers how long the work took.

  4. What is wrong with (clock() - start) / CLOCKS_PER_SEC?

    Answer

    The division is integer before the conversion

    Both operands are integer types, so the fraction is lost before the result becomes a double.

  5. What total does the hot loop print?

    Answer

    4773166019248396768

    The sum of squares overflows long here and wraps to that value, which both builds happen to print.

  6. What does this program report? #include <stdio.h> int main(void){ long total=0; long operations=0; for(int i=0;i<1000000;i++){ total+=(long)i*i; operations++; } printf("%ld %ld\n",total,operations); return 0; }

    Answer

    333332833333500000 1000000

    The loop adds the squares and increments the counter once per iteration, so the count is one million.

  7. What does the integer-division bug print for the seconds?

    Answer

    seconds: 0.000

    The sub-second difference is discarded before the conversion, so the printed value is zero.

  8. What happens when the -pg build is attempted here?

    Answer

    The link fails because gcrt1.o is missing

    The Alpine image does not ship the profiling startup object, so the link stops with cannot find gcrt1.o.

  9. Which casting fixes the lost fraction in the timing code?

    Answer

    (double) (clock() - start) / CLOCKS_PER_SEC

    One operand is converted to double before the division, so the remainder survives as a fraction.

  10. What does profiling an -O0 build tell you?

    Answer

    Where the source spends time, not the release build

    The optimiser changes the code substantially, so an unoptimised profile is a guide to the source shape, not the release cost.

The code on this page was run with gcc (Alpine 15.2.0) 15.2.0 on Alpine Linux 3.24.3 (x86_64) in a Docker container.

Article author: Arthur Isaev