25.4. Dynamic Tracing

25.4.1. Compiling for Dynamic Tracing

By default, trace points are disabled, so you will need to explicitly tell the configure script to make the probes available in PostgreSQL. To include DTrace support specify --enable-dtrace to configure. See Section 14.5 for further information.

25.4.2. Built-in Trace Points

A few standard trace points are provided in the source code (of course, more can be added as needed for a particular problem). These are shown in Table 25-3.

25.4.3. Using Trace Points

The example below shows a DTrace script for analyzing transaction counts on the system, as an alternative to snapshotting pg_stat_database before and after a performance test.

#!/usr/sbin/dtrace -qs 

postgresql$1:::transaction-start
{
      @start["Start"] = count();
      self->ts  = timestamp;
}

postgresql$1:::transaction-abort
{
      @abort["Abort"] = count();
}

postgresql$1:::transaction-commit
/self->ts/
{
      @commit["Commit"] = count();
      @time["Total time (ns)"] = sum(timestamp - self->ts);
      self->ts=0;
}

Note how the double underline in trace point names needs to be replaced by a hyphen when using D script. When executed, the example D script gives output such as:

# ./txn_count.d `pgrep -n postgres`
^C

Start                                          71
Commit                                         70
Total time (ns)                        2312105013

You should remember that trace programs need to be carefully written and debugged prior to their use, otherwise the trace information collected may be meaningless. In most cases where problems are found it is the instrumentation that is at fault, not the underlying system. When discussing information found using dynamic tracing, be sure to enclose the script used to allow that too to be checked and discussed.

25.4.4. Defining Trace Points

New trace points can be defined within the code wherever the developer desires, though this will require a recompilation.

A trace point can be inserted by using one of the trace macros. These are chosen according to how many variables will be made available for inspection at that trace point. Tracing the occurrence of an event can be achieved with a single line, using just the trace point name, e.g.

PG_TRACE (my__new__trace__point);

More complex trace points can be provided with one or more variables for inspection by the dynamic tracing utility by using the PG_TRACEn macro that corresponds to the number of parameters after the trace point name:

PG_TRACE3 (my__complex__event, varX, varY, varZ);

The definition of the transaction__start trace point is shown below:

static void
StartTransaction(void)
{
    ...

    /*
     * generate a new transaction id
     */
    s->transactionId = GetNewTransactionId(false);

    XactLockTableInsert(s->transactionId);

    PG_TRACE1(transaction__start, s->transactionId);

    ...
}    

Note how the transaction ID is made available to the dynamic tracing utility.

The dynamic tracing utility may require you to further define these trace points. For example, DTrace requires you to add new probes to the file src/backend/utils/probes.d as shown here:

provider postgresql {
      ...
      probe transaction__start(int);
      ...
 };

You should take care that the data types specified for the probe arguments match the datatypes of the variables used in the PG_TRACE macro. This is not checked at compile time. You can check that your newly added trace point is available by recompiling, then running the new binary, and as root, executing a DTrace command such as:

dtrace -l -n transaction-start