| unix.ba | text • research • links • about |
Profiling is one of the essential techniques for understanding program behaviour and tuning its performance. Recording of profiling information is enabled at compile time, by passing the compiler an option which instructs it to add special profile collection functions to the compiled program. When the program is run, the profiling functions measure execution times of every called function. At program termination, the collected profiling information is stored to a file. The user then runs a special command, such as gprof, to analyze the collected data and generate an execution profile of the program.
Waiting for program termination to collect the profile is reasonable for programs which run to completion in a relatively short time. There are, however, programs with long execution times, for which it is often infeasible to wait until the program terminates for the sake of bare profile collection. This is particularly true of scientific calculations, which may take days or weeks to complete, yet the profiling information from a few minutes of execution could reveal important clues. In such situations, it could be very handy to collect the accumulated profiling information in the middle of program execution. A seemingly obvious way to do this would be to interrupt the program (e.g. by pressing CTRL-C) and then analyze the profiling data that has been collected up to that point. This, however, doesn't work for a simple reason expressed in the following excerpt of the gprof manual:
The profiled program must call exit() or return normally for the profiling information to be saved in the gmon.out file.
In other words, if your program terminates due to a reception of a signal (e.g. user pressing CTRL-C), the profiling information won't be saved to a file and will therefore be lost forever. So, how can we force our program to save the profiling information to a file at any particular time before the program completes?
A simple solution would be to write a signal handler for SIGINT and call exit() when the user interrupts the program with CTRL-C. This is not always trivial, especially if your program is written in a language other than C or C++.
Another approach to this problem, which doesn't require any changes to the program code, is to attach to the program with a debugger while it is running, and then call exit() on behalf of the program from within the debugger.
To show how gdb can be used to generate the execution profile of our program, let us assume we have a program written in FORTRAN, whose source code is contained within a single file named test.f:
$ ls test.f $ █
We first compile our program using the GNU Fortran compiler, passing it the -pg option to enable profiling:
$ gfortran -pg test.f $ ls a.out test.f $ █
To see what happens when a profiled program is terminated by a signal, we execute a.out and let it run for a while, then interrupt it with CTRL-C:
$ ./a.out program is running for some time ^C $ ls a.out test.f $ █
As the output of the ls reveals, interrupting the program didn't result in the generation of the profile file.
Next, we run the program again, leave it to run for some time, and then suspend it by pressing CTRL-Z:
$ ./a.out program is running for some time ^Z [1]+ Stopped ./a.out $ █
While our program is stopped, we want to attach to it with a debugger, so we first find its process ID:
$ ps PID TTY TIME CMD 2729 pts/0 00:00:00 bash 4617 pts/0 00:05:11 a.out 4619 pts/0 00:00:00 ps $ █
Alternatively, the process ID of a.out could have been determined using the jobs shell built-in command with the -l switch:
$ jobs -l [1]+ 4617 Stopped ./a.out $ █
The output of ps shows that a.out has a PID of 4617. Passing this PID to gdb along with the name of the executable makes it attach to the process:
$ gdb a.out 4617
Once in gdb, we can invoke exit() to force a “clean” termination of our program. Then we quit gdb and check from within the shell to confirm the profile file gmon.out has been generated:
(gdb) call exit(0) Program exited normally. The program being debugged exited while in a function called from GDB. Evaluation of the expression containing the function (exit) will be abandoned. (gdb) quit [1]+ Done ./a.out $ ls a.out gmon.out test.f $ █
Now that the profile data has been successfully written to gmon.out, we can run gprof to generate a call graph and proceed with its analysis.
The previous discussion has shown how it is possible to obtain profiling information of a program at any point during its run time. One drawback of the described procedure is that it causes an instant program termination due to a call to exit(). This can sometimes lead to unpredictable results, because the program doesn't get a chance to “clean up”. A more subtle solution would allow us to gather profiling information whenever we want, while leaving our program to continue executing.
To understand how we can achieve this, we should first gain an insight into how profiling information is written. As the gprof manual states, a program must call exit() in order for its profiling information to be recorded to a file. This suggests that the profile is generated from within the exit() function in glibc. Indeed, there is a directory named gmon in the root of the glibc source tree, which contains the code for handling profiling by the GNU C library. A look into the file gmon.c in this directory reveals that profiling information is written to a file from within a function named write_gmon(). Here is the code of write_gmon() from the GNU C library version 2.9 (slightly re-formatted):
1 static void write_gmon(void)
2 {
3 struct gmon_hdr ghdr __attribute__((aligned(__alignof__(int))));
4 int fd = -1;
5 char *env;
6
7 #ifndef O_NOFOLLOW
8 #define O_NOFOLLOW0
9 #endif
10
11 env = getenv("GMON_OUT_PREFIX");
12 if (env != NULL && !__libc_enable_secure) {
13 size_t len = strlen(env);
14 char buf[len + 20];
15 __snprintf(buf, sizeof(buf), "%s.%u", env, __getpid());
16 fd = open_not_cancel(buf,
17 O_CREAT|O_TRUNC|O_WRONLY|O_NOFOLLOW, 0666);
18 }
19
20 if (fd == -1) {
21 fd = open_not_cancel("gmon.out",
22 O_CREAT|O_TRUNC|O_WRONLY|O_NOFOLLOW, 0666);
23 if (fd < 0) {
24 char buf[300];
25 int errnum = errno;
26 __fxprintf(NULL, "_mcleanup: gmon.out: %s\n",
27 __strerror_r(errnum, buf, sizeof buf));
28 return;
29 }
30 }
31
32 /* write gmon.out header: */
33 memset(&ghdr, '\0', sizeof(struct gmon_hdr));
34 memcpy(&ghdr.cookie[0], GMON_MAGIC, sizeof(ghdr.cookie));
35 *(int32_t *) ghdr.version = GMON_VERSION;
36 write_not_cancel(fd, &ghdr, sizeof(struct gmon_hdr));
37
38 /* write PC histogram: */
39 write_hist(fd);
40
41 /* write call-graph: */
42 write_call_graph(fd);
43
44 /* write basic-block execution counts: */
45 write_bb_counts(fd);
46
47 close_not_cancel_no_status(fd);
48 }
As we can see, this function first creates the profiling file, whose name defaults to gmon.out (lines 20 to 30). It is evident from lines 11 to 18 that this name can also take the form of prefix.PID, where prefix is a user-defined string set through the environment variable GMON_OUT_PREFIX, and PID is the process ID of the program being profiled. After opening the file for writing, profiling information is written to it (lines 32 to 45), and the file is eventually closed (line 47).
We can now make use of write_gmon() to generate the profile of our program without causing it to terminate. A quick verification with nm shows that the symbol write_gmon is available in libc.so:
$ nm /lib/libc.so.6 | grep write_gmon 00abb9a0 t write_gmon $ █
Even though the symbol is not exported, it can still be called from within gdb. Now we can repeat the whole procedure described in the previous section, and substitute a call to exit() by a call to write_gmon():
$ rm gmon.out
$ ls
a.out test.f
$ ./a.out
program is running for some time
^Z
[1]+ Stopped ./a.out
$ ps
PID TTY TIME CMD
2729 pts/0 00:00:00 bash
4658 pts/0 00:04:12 a.out
4659 pts/0 00:00:00 ps
$ gdb a.out 4658
many gdb messages removed for brevity
(gdb) call write_gmon()
$1 = 0
(gdb) quit
A debugging session is active.
Inferior 1 [process 4658] will be detached.
Quit anyway? (y or n) y
Detaching from program: /home/kenan/a.out, process 4658
$ █
At this point, gdb detached itself from our program, leaving it to continue executing in the background. Once again, we can verify that the profiling information has been recorded:
$ ls a.out gmon.out test.f $ █
Note that, if we execute our shell's built-in command jobs, it will still show our program in the “stopped” state:
$ jobs [1]+ Stopped ./a.out $ █
This is because we previously suspended our program by pressing CTRL-Z and the shell marked its state as “stopped” at that point. When we subsequently executed gdb, the shell was suspended, while gdb was running (the shell spawned a new process to run gdb and then called wait(), which put it to sleep until gdb finally terminated). While it was sleeping, the shell was unaware of the fact that gdb left our program running after detaching from it, so the job-control subsystem within the shell incorrectly shown a.out in its previous state (i.e. “stopped”).
Although we could ignore this inconsistency without affecting the functionality of our program, it is better to notify the shell of its state change to avoid possible confusion in the future. To do this, we could, for instance, execute fg to move our program into the foreground (where it was originally executing), or simply choose to execute bg and leave it in the background, where it is executing now.
• • •