Tracing rule execution in GNU Make

Who hasn't wondered what exactly Make's log file output means.

This article is about Makefile tracing. Back in October 2004 I wrote about tracing GNU Make macro values; here I cover tracing the execution of Makefile rules.

An Example

Throughout the this article I'll use the follow example. It builds to files: foo.o and bar. foo.o is created using a built-in rule from foo.c (which is assumed to exist) and bar has a simple rule that just touches $@.

If you run make for the first time with this Makefile you'd see the following output:

There's no sign of the rule for bar being run (that's because the touch $@ was hidden using GNU Make's @ modifier so that the command was printed). There's no indication that it was the rule for foo.o that generated the compilation line. And there's no indication that the all rule was used.

You could, of course, use make -n to take look at the work that GNU Make would perform. In this case, it's practical, but in general make -n's output can be just as cryptic as a normal lo g file, and it doesn't provide any way of matching lines in ! the log with lines in the Makefile:

The SHELL hack

One simple way to enhance the output of GNU Make is to redefine SHELL. SHELL is a GNU Make built-in variable that contains the name of the shell to use when GNU Make executes commands.

Since most shells have a -x option that causes them to print out each command they are about to execute modifying SHELL in a Makefile by appendin -x causes every command to be printed (usually preceded by +) as the Makefile is run.

Here's the example Makefile modified using GNU Make's += operator to append -x to SHELL:

Now when the Makefile is run with GNU Make the output reveals the touch bar generated by the rule for bar:

The SHELL technique has one disadvantage: it slows GNU Make down. If SHELL is left untouched GNU Make will sometimes avoid using the shell entirely if it knows it can execute the command directly (which is the case for simple operations like compilation and links). Once SHELL is redefined in a Makefile GNU Make will always use the shell slowing down exection.

Of course, that doesn't make this a bad debugging trick: getting additional information for a small slow down is a very small price to pay. But this redefinition of SHELL doesn't help track the relationship between the lines in a log file and the Makefile. Luckily, it's possible to do that with an even smarter redefinition of SHELL

Even smarter SHELL hack

If SHELL has been redefined GNU Make will expand its value before it runs each line of each rule. This means that if the expansion of SHELL were to output information it would be possible to print out information before each rule runs.

GNU Make has a $(warning) function the helpfully outputs a string of our choosing and the name of the Makefile and line number at which the $(warning) was written. It turns out that when SHELL is expanded it's possible to use $(warning) to print detailed information about the rule that's about to run.

To make this work I first capture the normal value of SHELL in a variable called OLD_SHELL (notice below that I use := to get SHELL's value and not its definition) and then I define SHELL to include the real shell value and a $(warning) that will print out the name of the target being built.

Running GNU Make now produces really useful information:

The first line is the output of the $(warning) produced when the pattern rule to build foo.o is about to be executed. Since there's no Makefile and line number information we know that a built-in rule was used. The $(warning) shows us that foo.o was about to be built. That's because the $(warning) was able to use the GNU Make automatic variable $@ and hence we know which rule was about to run.

Then you see the actual output of the built-in rule (the cc comma! nd) foll owed by another piece of output from the $(warning). This time there's detailed information: bar is about to be built using the rule in Makefile at line 7.

Since it was possible to use $@ nothing stops us using other automatic variables. For example, we could find out the value of $< (the first prerequisite from which the target is being built) or the list of prerequisites that are newer than the target (which tells us why the target was built and is stored in $?).

Here SHELL has been redefined to output three pieces of information: the name of the target being built (from $@), the name of the first prerequi site (from $< and wrapped in a $(if) so that nothing is printed if there is no prerequisite) and the names of any newer prerequisites.

Running GNU Make now shows that foo.o was built from foo.c because foo.c was newer.

There's nothing to stop us combining this $(warning) trick with the -x to get output showing which rules ran and what commands were executed:

Here's the full output with warnings and echoing of commands :

In October 2005 I talked about the GNU Make Debugger which uses a SHELL definition trick to prompt the user for input each time a rule is run. Take a look at its code if you are interested in other things you can do by redefining SHELL.

Conclusion

With just a small redefinition of SHELL GNU Make can be coaxed into outputting detailed information about the rules that it is executing.

Next month I'll return with a look at what's new in GNU Make 3.81 including the new .SECONDEXPANSION feature, some backward incompatibilities, an explanation of order-only prerequisites, and all the new GNU Make functions.