Tracing procedures in your code

To implement the tracing procedures in Fortran, the characteristics of the procedures must be the same as those specified in the following interface:

SUBROUTINE routine_name(procedure_name, file_name, line_number, id)
  USE, INTRINSIC :: iso_c_binding
  CHARACTER(*), INTENT(IN) :: procedure_name
  CHARACTER(*), INTENT(IN) :: file_name
  INTEGER(C_INT), INTENT(IN) :: line_number
  TYPE(C_PTR), INTENT(INOUT) :: id
END SUBROUTINE

where routine_name is the name of an external or module procedure.

You must then tell the compiler to use your subroutine as a tracing procedure in one of the following ways:

• Using the -qfunctrace_xlf_enter, -qfunctrace_xlf_exit, or -qfunctrace_xlf_catch compiler options.
• Using the FUNCTRACE_XLF_ENTER, FUNCTRACE_XLF_EXIT, or FUNCTRACE_XLF_CATCH directives.

Writing the tracing procedures in C or C++ requires that you provide the __func_trace_enter, __func_trace_exit, and __func_trace_catch procedures directly. They must have the following prototypes:

• void __func_trace_enter(const char *const procedure_name, const char *const file_name, int line_number, void **const id);
• void __func_trace_exit(const char *const procedure_name, const char *const file_name, int line_number, void **const id);
• void __func_trace_catch(const char *const procedure_name, const char *const file_name, int line_number, void **const id);

XL Fortran provides sample tracing procedures in the /opt/IBM/xlf/15.1.0/samples/functrace directory. You can use these procedures for simple tracing, or you can modify them for more complex tracing.

• tracing_routines.c: Provides tracing procedures written in C. This file is useful when you do not require access to Fortran modules, and when there is a possibility of recursive input / output.
• tracing_routines.f90: Provides tracing procedures written in Fortran. This file is useful when you need access to Fortran modules or intrinsics in your tracing procedures.

The following example illustrates the use of the samples for simple tracing:

> cat helloworld.f
print *, 'hello world'
end
> cc -c /opt/IBM/xlf/15.1.0/samples/functrace/tracing_routines.c
> xlf95 helloworld.f -qfunctrace tracing_routines.o
** _main   === End of Compilation 1 ===
1501-510  Compilation successful for file helloworld.f.
> ./a.out
{ _main (helloworld.f:1)
 hello world
} _main (helloworld.f:2)

>

The procedure tracing functionality has the following limitations:

• A procedure cannot be traced separately from its ENTRY points. Either all are traced or none are. The name of the procedure is passed to the tracing procedure even when tracing the ENTRY point. The line number helps distinguish what is being traced in this case.
• The Fortran standard requires pure procedures to have no side effects. The compiler uses this assumption when optimizing your program. If you enable tracing of a pure procedure, your tracing procedure must not change the program state in a way that creates a side effect.
• The Fortran standard imposes limits on recursive input/output. If you write your tracing procedures in Fortran, you must be careful not to break these rules.
  The following example has a print statement where an I/O item is the result of a function call (foo). It is illegal for the tracing procedure in this case to have I/O on an external file:

  > cat recursive.f
  integer function test()
    test = 1
  end function
  
  integer test
  print *, test() ! test must not have I/O on external unit
  end
  > xlf95 -c /opt/IBM/xlf/15.1.0/samples/functrace/tracing_routines.f90
  ** my__func_trace_enter   === End of Compilation 1 ===
  ** my__func_trace_exit   === End of Compilation 2 ===
  ** my__func_trace_catch   === End of Compilation 3 ===
  1501-510  Compilation successful for file tracing_routines.f90.
  > xlf95 recursive.f tracing_routines.o -qfunctrace
  ** test   === End of Compilation 1 ===
  ** _main   === End of Compilation 2 ===
  1501-510  Compilation successful for file recursive.f.
  > ./a.out
  { _main (recursive.f:6)
  XL Fortran (I/O initialization): I/O recursion detected.
  IOT/Abort trap
  >

  Note: You can work around this by writing the tracing procedure in C. For an example, see the tracing_routines.c sample file described in section Sample tracing procedures.
• When optimizing your program, the compiler reorders code and removes dead code. As a result, the line number passed to the tracing procedure might not be accurate when optimization is enabled.

In the following example, -qfunctrace is used to measure the time spent in each external procedure. The FUNCTRACE_XLF_ENTER and FUNCTRACE_XLF_EXIT directives are used to specify procedures my_enter and my_exit as the tracing procedures. The NOFUNCTRACE directive is used to disable tracing of main_program:

> cat example.f
! Designate my_enter as a tracing procedure that should be called
! on procedure entry
!ibm* functrace_xlf_enter
subroutine my_enter(procedure_name, file_name, line_number, id)
  use, intrinsic :: iso_c_binding
  use, intrinsic :: xlfutility
  character(*), intent(in) :: procedure_name, file_name
  integer(c_int), intent(in) :: line_number
  type(c_ptr), intent(inout) :: id

  integer(kind=time_size), pointer :: enter_count

  ! Store the time we entered the procedure being traced into id.
  if (.not. c_associated(id)) then
    allocate(enter_count)
    enter_count = time_()
    id = c_loc(enter_count)
  end if

  print *, 'Entered procedure ', procedure_name, ' at ( ',  &
           file_name, ' :', line_number, ').'
end subroutine

! Designate my_exit as a tracing procedure that should be called
! on procedure exit
!ibm* functrace_xlf_exit
subroutine my_exit(procedure_name, file_name, line_number, id)
  use, intrinsic :: iso_c_binding
  use, intrinsic :: xlfutility
  character(*), intent(in) :: procedure_name, file_name
  integer(c_int), intent(in) :: line_number
  type(c_ptr), intent(inout) :: id

  integer(kind=time_size), pointer :: enter_count
  integer(kind=time_size) exit_count, duration

  ! id should have been associated in my_enter with the time we
  ! entered the procedure being traced.  Find the elapsed time.
  if (c_associated(id)) then
    exit_count = time_()
    call c_f_pointer(id, enter_count)
    duration = exit_count - enter_count
  else
    stop "error!"
  endif

  print *, 'Leaving procedure ', procedure_name, ' at ( ',  &
           file_name, ' :', line_number, ').'
  print *, 'Spent', duration, 'seconds in ', procedure_name, '.'
end subroutine

! sub2 will be traced
subroutine sub2
  call sleep_(3)
end subroutine

! sub1 will be traced
subroutine sub1
  call sleep_(5)
  call sub2
end subroutine

! Do not want to trace main_program
!ibm* nofunctrace
program main_program
  call sub1
end program
> xlf95 example.f -qfunctrace
** my_enter   === End of Compilation 1 ===
** my_exit   === End of Compilation 2 ===
** sub2   === End of Compilation 3 ===
** sub1   === End of Compilation 4 ===
** main_program   === End of Compilation 5 ===
1501-510  Compilation successful for file example.f.
> ./a.out
 Entered procedure sub1 at ( example.f : 59 ).
 Entered procedure sub2 at ( example.f : 54 ).
 Leaving procedure sub2 at ( example.f : 55 ).
 Spent 3 seconds in sub2.
 Leaving procedure sub1 at ( example.f : 61 ).
 Spent 8 seconds in sub1.
>