/* $PostgreSQL:$ */

<chapter id="trace">
 <title>Diagnostic Trace Facilities</title>

 <para>
  Various facilities are available for tracing internal database server 
  activity. These are primarily intended for use by database developers
  to diagnose undesirable dynamic behaviour. Some of these facilities
  have been advocated for wider use, though such use is not yet common.
  You should start by referring to the production monitoring facilities 
  in <xref linkend="monitoring">.
 </para>

 <para>
  Note that all of the features described here require special source
  compilation flags to work at all, so they may not be available to you
  if you are using installed binary programs.
 </para>

   <sect1 id="trace-config-developer">
    <title>Developer Trace and Debug Parameters</title>

    <para>
     The following parameters are intended for work on the
     <productname>PostgreSQL</productname> source. There
     should be no reason to use them in a production database setup.
     As such, they have been excluded from the sample
     <filename>postgresql.conf</> file.  
    </para>

     <varlistentry id="guc-debug-assertions" xreflabel="debug_assertions">
      <term><varname>debug_assertions</varname> (<type>boolean</type>)</term>
      <indexterm>
       <primary><varname>debug_assertions</> configuration parameter</primary>
      </indexterm>
      <listitem>
       <para>
        Turns on various assertion checks. This is a debugging aid. If
        you are experiencing strange problems or crashes you might want
        to turn this on, as it might expose programming mistakes. To use
        this parameter, the macro <symbol>USE_ASSERT_CHECKING</symbol>
        must be defined when <productname>PostgreSQL</productname> is
        built (accomplished by the <command>configure</command> option
        <option>--enable-cassert</option>). Note that
        <varname>debug_assertions</varname> defaults to <literal>on</>
        if <productname>PostgreSQL</productname> has been built with
        assertions enabled.
       </para>
      </listitem>
     </varlistentry>

     <varlistentry id="guc-post-auth-delay" xreflabel="post_auth_delay">
      <term><varname>post_auth_delay</varname> (<type>integer</type>)</term>
      <indexterm>
       <primary><varname>post_auth_delay</> configuration parameter</primary>
      </indexterm>
      <listitem>
       <para>
        If nonzero, a delay of this many seconds occurs when a new
        server process is started, after it conducts the
        authentication procedure.  This is intended to give an
        opportunity to attach to the server process with a debugger.
        This parameter cannot be changed after session start.
       </para>
      </listitem>
     </varlistentry>

     <varlistentry id="guc-pre-auth-delay" xreflabel="pre_auth_delay">
      <term><varname>pre_auth_delay</varname> (<type>integer</type>)</term>
      <indexterm>
       <primary><varname>pre_auth_delay</> configuration parameter</primary>
      </indexterm>
      <listitem>
       <para>
        If nonzero, a delay of this many seconds occurs just after a
        new server process is forked, before it conducts the
        authentication procedure.  This is intended to give an
        opportunity to attach to the server process with a debugger to
        trace down misbehavior in authentication.
        This parameter can only be set in the <filename>postgresql.conf</>
        file or on the server command line.
       </para>
      </listitem>
     </varlistentry>

     <varlistentry id="guc-trace-notify" xreflabel="trace_notify">
      <term><varname>trace_notify</varname> (<type>boolean</type>)</term>
      <indexterm>
       <primary><varname>trace_notify</> configuration parameter</primary>
      </indexterm>
      <listitem>
       <para>
        Generates a great amount of debugging output for the
        <command>LISTEN</command> and <command>NOTIFY</command>
        commands.  <xref linkend="guc-client-min-messages"> or
        <xref linkend="guc-log-min-messages"> must be
        <literal>DEBUG1</literal> or lower to send this output to the
        client or server log, respectively.
       </para>
      </listitem>
     </varlistentry>

     <varlistentry id="guc-trace-sort" xreflabel="trace_sort">
      <term><varname>trace_sort</varname> (<type>boolean</type>)</term>
      <indexterm>
       <primary><varname>trace_sort</> configuration parameter</primary>
      </indexterm>
      <listitem>
       <para>
        If on, emit information about resource usage during sort operations.
        This parameter is only available if the <symbol>TRACE_SORT</symbol> macro
        was defined when <productname>PostgreSQL</productname> was compiled.
        (However, <symbol>TRACE_SORT</symbol> is currently defined by default.)
       </para>
      </listitem>
     </varlistentry>

     <varlistentry>
      <term><varname>trace_locks</varname> (<type>boolean</type>)</term>
      <term><varname>trace_lwlocks</varname> (<type>boolean</type>)</term>
      <term><varname>trace_userlocks</varname> (<type>boolean</type>)</term>
      <term><varname>trace_lock_oidmin</varname> (<type>boolean</type>)</term>
      <term><varname>trace_lock_table</varname> (<type>boolean</type>)</term>
      <term><varname>debug_deadlocks</varname> (<type>boolean</type>)</term>
      <term><varname>log_btree_build_stats</varname> (<type>boolean</type>)</term>
      <listitem>
       <para>
        Various other code tracing and debugging options.
        Only superusers can change these settings.
       </para>
      </listitem>
     </varlistentry>

     <varlistentry id="guc-wal-debug" xreflabel="wal_debug">
      <term><varname>wal_debug</varname> (<type>boolean</type>)</term>
      <indexterm>
       <primary><varname>wal_debug</> configuration parameter</primary>
      </indexterm>
      <listitem>
       <para>
        If on, emit WAL-related debugging output. This parameter is
        only available if the <symbol>WAL_DEBUG</symbol> macro was
        defined when <productname>PostgreSQL</productname> was
        compiled. Only superusers can change this setting.
       </para>
      </listitem>
     </varlistentry>

   </variablelist>
  </sect1>

   <sect1 id="dynamic-trace">
    <title>Dynamic Tracing</title>

    <para>
     PostgreSQL provides facilities to enable dynamic tracing utilities
     on the database server. This allows an external utility to be called
     at specific points in the code and thereby trace execution.
    </para>

    <para>
     A number of trace points, often called probes, are already inserted
     into the source code.  By default PG_TRACE probes are disabled, and
     the user needs to explicitly tell the configure script to make the
     probes available in PostgreSQL.
    </para>

    <para> 
     Currently, probes are only defined when using the DTrace utility, so enabling
     DTrace only makes sense on certain Operating Systems. Currently DTrace
     works with both Solaris Express and Solaris 10+, though the above probes
     do not yet work with Solaris 10+. It is expected that DTrace will be 
     available in the future on FreeBSD and Mac OS X.
    </para>

    <sect2 id="trace-points">
     <title>Well-known Trace Points</title>

    <para>
     The following trace points are placed within the code to allow dynamic tracing
     of certain events related to locking and performance. These are:
    </para>

   <table id="trace-point-table">
    <title></title>
    <tgroup cols="3">
     <thead>
      <row>
       <entry>Trace Point</entry>
       <entry>Definition</entry>
       <entry>Overview</entry>
      </row>
     </thead>

     <tbody>
      <row>
       <entry>transaction__start</entry>
       <entry>(int transactionId)</entry>
       <entry>The start of a new transaction.</entry>
      </row>
      <row>
       <entry>transaction__commit</entry>
       <entry>(int transactionId)</entry>
       <entry>The successful completion of a transaction.</entry>
      </row>
      <row>
       <entry>transaction__abort</entry>
       <entry>(int transactionId)</entry>
       <entry>The unsuccessful completion of a transaction.</entry>
      </row>
               
      <row>
       <entry>lwlock__acquire</entry>
       <entry>(int lockid, int mode)</entry>
       <entry>An shared resource has been locked.</entry>
      </row>
      <row>
       <entry>lwlock__release</entry>
       <entry>(int lockid, int mode)</entry>
       <entry>An shared resource has been released.</entry>
      </row>
      <row>
       <entry>lwlock__startwait</entry>
       <entry>(int lockid, int mode)</entry>
       <entry>An shared resource was not immediately available and a backend
         has begun to wait in a queue for the resource to become available.
       </entry>
      </row>    
      <row>
       <entry>lwlock__endwait</entry>
       <entry>(int lockid, int mode)</entry>
       <entry>A backend has reached the head of the queue and the resource
        is now available.
       </entry>
      </row>
      <row>
       <entry>lwlock__condacquire</entry>
       <entry>(int lockid, int mode)</entry>
       <entry>A resource was requested only on condition that no wait was 
        required. The resource has now been successfully locked.
       </entry>
      </row> 
      <row>
       <entry>lwlock__condacquire__fail</entry>
       <entry>(int lockid, int mode)</entry>
       <entry>A resource was requested only on condition that no wait was 
        required. The resource was busy, so has not been locked.
       </entry>
      </row>
      <row>
       <entry>lock__startwait</entry>
       <entry>(int locktag_field2, int lockmode)</entry>
       <entry>A request for a lock on user data has started to wait in 
        a priority queue for access to that data. Meaning
        of the locktag varies according to the lock type requested. 
       </entry>
      </row>
      <row>
       <entry>lock__endwait</entry>
       <entry>(int locktag_field2, int lockmode)</entry>
       <entry>A request for a lock on user data has now reached the
        head of the priority queue for access to that data. Meaning
        of the locktag varies according to the lock type requested. 
       </entry>
      </row>
     </tbody>
    </sect2>

    <sect2 id="compiling-for-trace">
     <title>Compiling for Dynamic Trace</title>

    <para>
     By default, trace points are disabled, so you will need to
     explicitly tell the configure script to make the probes available
     in <productname>PostgreSQL</productname>. To include trace points
     in a 32 bit binary, specify --enable-dtrace to configure. For example:
<programlisting>
        $ configure --enable-dtrace ...
<programlisting>
     To include DTrace probes in a 64 bit binary, specify --enable-dtrace
     and DTRACEFLAGS="-64" to configure. For example:
    </para>

    <para>
     Using gcc compiler:
<programlisting>
        $ configure CC='gcc -m64' --enable-dtrace DTRACEFLAGS='-64' ...
</programlisting>            
     Using Sun compiler:
<programlisting>            
        $ configure CC='/path_to_sun_compiler/cc -xtarget=native64' --enable-dtrace DTRACEFLAGS='-64' ...
</programlisting>
    </para>
    </sect2>

    <sect2 id="using-trace-points">
     <title>Using Trace Points</title>

    <para>
     Existing trace points can be utilised by the dynamic tracing utility.
     The example below shows a DTrace script for analyzing transaction
     counts on the system, as an alternative to snapshotting 
     <structname>pg_stat_database</> before and after a performance test.
<programlisting>
#!/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();
        @commit["Abort"] = count();
        @time["Total time (ns)"] = sum(timestamp - self->ts);
        self->ts=0;
}
</programlisting>
     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 the following output:
<programlisting>
# ./txn_count.d `pgrep -n postgres`
^C

  Start                                          71
  Commit                                         70
  Abort                                           1
  Total time (ns)                        2312105013
</programlisting>
    </para>
    <para>
     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.
    </para>
    </sect2>

    <sect2 id="defining-trace-points">
     <title>Defining Trace Points</title>

    <para>
     New trace points can be defined within the code wherever the developer
     desires, though this will require a re-compile.
    </para>

    <para>
     A trace point can be inserted in a single line 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.
<programlisting>
        PG_TRACE (my__new__trace__point);
</programlisting>
     More complex trace points can be provided with one or more variables
     for inspection by the dynamic tracing utility by using the PG_TRACE
     macro that corresponds to the number of parameters after the trace
     point name.
<programlisting>
        PG_TRACE3 (my__complex__event, varX, varY, varZ);
</programlisting>
     The definition of the transaction__start trace point is shown below:
<programlisting>
static void
   StartTransaction(void)
   {
        ...

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

        XactLockTableInsert(s->transactionId);

        PG_TRACE1(transaction__start, s->transactionId);

        ...
   }    
</programlisting>
     Note how the variable is made available to the dynamic tracing utility.
    </para>

    <para>
     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
     <filename>src/backend/utils/probes.d</> as shown here:
<programlisting>
provider postgresql {
        ...
        probe transaction__start(int);
        ...
   };
</programlisting>
     You should take care that the datatype of the probe arguments match the datatypes
     of the variables defined in the PG_TRACE macro. This is not checked at compile
     time of the source. You can check that your newly added trace point is available
     by recompiling, then run the new binary, and as root, execute a DTrace command
     such as:
<programlisting>
    dtrace -l -n transaction-start
</programlisting>
    </para>

    <para>
     Supporting new dynamic tracing utilities is possible by changing the definitions
     for the PG_TRACE macros in <filename>src/include/pg_trace.h</>
    </para>
    </sect2>

  </sect1>
</chapter>