I have, since using Valgrind (and reading a bit of its documentation) some years ago, developed much respect for it. It is quite an advanced tool, and though its primary use is detecting memory leaks, I am here going to explore its other functionality... calculating the cost of each line of code in the CPU. This is useful when tuning programs for performance.

Following is example code; it accepts 2 arguments, a filename and text that will be written to that file:

#include <string.h>
#include <errno.h>
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>

int
main (int argc, char **argv)
{
    char path[0xFF];
    char content[0xFF];
    int fd;
    ssize_t written;

    if (argc < 3) {
        fprintf (stderr, "usage: %s <filename> <content>n", argv[0]);
        return 1;
    }

    strcpy (path, argv[1]);
    sprintf (content, "%sn", argv[2]);

    fd = creat (path, S_IRWXU);
    if (fd == -1) {
        fprintf (stderr, "open error: %s ('%s')n", strerror (errno), path);
        return 1;
    }

    written = write (fd, content, strlen (content));
    if (written == -1) {
        fprintf (stderr, "write error: %s ('%s')n", strerror (errno), path);
        return 1;
    }
    return 0;
}

Build command (using GCC 4.8.1):

gcc -Wall -pedantic -g play.c -o play

System details:

$ uname --all
Linux thome 3.11-trunk-amd64 #1 SMP Debian 3.11-1~exp1 (2013-09-12) x86_64 GNU/Linux
$ sudo lshw -class processor
*-cpu
     description: CPU
     product: Intel(R) Core(TM) i5-2410M CPU @ 2.30GHz
     vendor: Intel Corp.
     physical id: 4
     bus info: cpu@0
     version: Intel(R) Core(TM) i5-2410M CPU @ 2.30GHz
     serial: To Be Filled By O.E.M.
     slot: CPU 1
     size: 2300MHz
     capacity: 4GHz
     width: 64 bits
     clock: 100MHz
     capabilities: x86-64 fpu fpu_exception wp vme de pse tsc msr
     pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts
     acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp
     constant_tsc arch_perfmon pebs bts rep_good nopl xtopology
     nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor
     ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2
     x2apic popcnt tsc_deadline_timer xsave avx lahf_lm ida arat epb
     xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid
     aes cpufreq
     configuration: cores=2 enabledcores=1 threads=2

Running the resulting binary with Callgrind:

$ valgrind --tool=callgrind --callgrind-out-file=out ./play filename
filecontent
==5308== Callgrind, a call-graph generating cache profiler
==5308== Copyright (C) 2002-2012, and GNU GPL'd, by Josef Weidendorfer
et al.
==5308== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright
info
==5308== Command: ./play filename filecontent
==5308==
==5308== For interactive control, run 'callgrind_control -h'.
==5308==
==5308== Events    : Ir
==5308== Collected : 107520
==5308==
==5308== I   refs:      107,520
$ cat filename
filecontent

And finally, seeing closely the cost of each function call, where Ir stands for Instruction cache reads, which you can read as number of CPU instructions. I have used tree=calling option so that I can see the cost of all operations called by a parent (marked with a *) :

$ callgrind_annotate --tree=calling out play.c
---++++++--
Profile data file 'out' (creator: callgrind-3.8.1)
---++++++--
I1 cache:
D1 cache:
LL cache:
Timerange: Basic block 0 - 22326
Trigger: Program termination
Profiled target:  ./play filename filecontent (PID 5308, part 1)
Events recorded:  Ir
Events shown:     Ir
Event sort order: Ir
Thresholds:       99
Include dirs:
User annotated:   play.c
Auto-annotation:  off

---++++++--
Ir
---++++++--
107,520  PROGRAM TOTALS

---++++++--
Ir  file:function
---++++++--

24,113  *  /build/eglibc-TepTGA/eglibc-2.17/elf/dl-lookup.c:do_lookup_x [/lib/x86_64-linux-gnu/ld-2.17.so]
1,053  >   /build/eglibc-TepTGA/eglibc-2.17/elf/dl-misc.c:_dl_name_match_p (25x) [/lib/x86_64-linux-gnu/ld-2.17.so]
13,423  >   /build/eglibc-TepTGA/eglibc-2.17/elf/dl-lookup.c:check_match.9345 (88x) [/lib/x86_64-linux-gnu/ld-2.17.so]

18,264  *  /build/eglibc-TepTGA/eglibc-2.17/elf/dl-lookup.c:_dl_lookup_symbol_x [/lib/x86_64-linux-gnu/ld-2.17.so]
38,589  >   /build/eglibc-TepTGA/eglibc-2.17/elf/dl-lookup.c:do_lookup_x (94x) [/lib/x86_64-linux-gnu/ld-2.17.so]

15,836  *  /build/eglibc-TepTGA/eglibc-2.17/elf/../sysdeps/x86_64/dl-machine.h:_dl_relocate_object
13  >   /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/memmove.c:memcpy@GLIBC_2.2.5 (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
81  >   /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/strcmp.S:strcasecmp (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
6  >   /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/strcmp.S:strncasecmp (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
7  >   /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/memset.S:memset (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
51,501  >   /build/eglibc-TepTGA/eglibc-2.17/elf/dl-lookup.c:_dl_lookup_symbol_x (86x) [/lib/x86_64-linux-gnu/ld-2.17.so]
18  >   /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/../memcpy.S:memcpy (1x) [/lib/x86_64-linux-gnu/ld-2.17.so]
67  >   /build/eglibc-TepTGA/eglibc-2.17/time/../sysdeps/unix/sysv/linux/x86_64/time.c:time (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
67  >   /build/eglibc-TepTGA/eglibc-2.17/time/../sysdeps/unix/sysv/linux/x86_64/gettimeofday.c:gettimeofday (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
6  >   /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/strnlen.S:strnlen (1x) [/lib/x86_64-linux-gnu/libc-2.17.so]
[snip; to be continued]

I have trimmed the output to bring focus to the most interesting output of all, which is the total cost for each line of my code:

[continued]
---++++++--
-- User-annotated source: play.c
---++++++--
Ir

.  #include <string.h>
.  #include <errno.h>
.  #include <stdio.h>
.  #include <fcntl.h>
.  #include <unistd.h>
.
.  int
.  main (int argc, char **argv)
5  {
.      char path[0xFF];
.      char content[0xFF];
.      int fd;
.      ssize_t written;
.
2      if (argc < 3) {
.     fprintf (stderr, "usage: %s <filename> <content>n", argv[0]);
.     return 1;
.      }
.
7      strcpy (path, argv[1]);
21  => /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/strcpy-sse2-unaligned.S:__strcpy_sse2_unaligned (1x)
799  => /build/eglibc-TepTGA/eglibc-2.17/elf/../sysdeps/x86_64/dl-trampoline.S:_dl_runtime_resolve (1x)
8      sprintf (content, "%sn", argv[2]);
1,188  => /build/eglibc-TepTGA/eglibc-2.17/stdio-common/sprintf.c:sprintf (1x)
805  => /build/eglibc-TepTGA/eglibc-2.17/elf/../sysdeps/x86_64/dl-trampoline.S:_dl_runtime_resolve (1x)
.
5      fd = creat (path, S_IRWXU);
766  => /build/eglibc-TepTGA/eglibc-2.17/elf/../sysdeps/x86_64/dl-trampoline.S:_dl_runtime_resolve (1x)
7  => /build/eglibc-TepTGA/eglibc-2.17/io/../sysdeps/unix/syscall-template.S:creat (1x)
2      if (fd == -1) {
.     fprintf (stderr, "open error: %s ('%s')n", strerror (errno), path);
.     return 1;
.      }
.
10      written = write (fd, content, strlen (content));
7  => /build/eglibc-TepTGA/eglibc-2.17/io/../sysdeps/unix/syscall-template.S:write (1x)
14  => /build/eglibc-TepTGA/eglibc-2.17/string/../sysdeps/x86_64/multiarch/strlen-sse2-pminub.S:__strlen_sse2_pminub (1x)
1,567  => /build/eglibc-TepTGA/eglibc-2.17/elf/../sysdeps/x86_64/dl-trampoline.S:_dl_runtime_resolve (2x)
2      if (written == -1) {
.     fprintf (stderr, "write error: %s ('%s')n", strerror (errno), path);
.     return 1;
.      }
1      return 0;
2  }

---++++++--
Ir
---++++++--
0  percentage of events annotated

As an aside, note that the indentation is messed up a bit.


Since I normally work at too high a level to care about CPU instructions cycles at this detail, I found the exercise eye-opening.