Perl 5 version 24.3 documentation

perldtrace

NAME

perldtrace - Perl's support for DTrace

SYNOPSIS

  1. # dtrace -Zn 'perl::sub-entry, perl::sub-return { trace(copyinstr(arg0)) }'
  2. dtrace: description 'perl::sub-entry, perl::sub-return ' matched 10 probes
  3. # perl -E 'sub outer { inner(@_) } sub inner { say shift } outer("hello")'
  4. hello
  5. (dtrace output)
  6. CPU ID FUNCTION:NAME
  7. 0 75915 Perl_pp_entersub:sub-entry BEGIN
  8. 0 75915 Perl_pp_entersub:sub-entry import
  9. 0 75922 Perl_pp_leavesub:sub-return import
  10. 0 75922 Perl_pp_leavesub:sub-return BEGIN
  11. 0 75915 Perl_pp_entersub:sub-entry outer
  12. 0 75915 Perl_pp_entersub:sub-entry inner
  13. 0 75922 Perl_pp_leavesub:sub-return inner
  14. 0 75922 Perl_pp_leavesub:sub-return outer

DESCRIPTION

DTrace is a framework for comprehensive system- and application-level tracing. Perl is a DTrace provider, meaning it exposes several probes for instrumentation. You can use these in conjunction with kernel-level probes, as well as probes from other providers such as MySQL, in order to diagnose software defects, or even just your application's bottlenecks.

Perl must be compiled with the -Dusedtrace option in order to make use of the provided probes. While DTrace aims to have no overhead when its instrumentation is not active, Perl's support itself cannot uphold that guarantee, so it is built without DTrace probes under most systems. One notable exception is that Mac OS X ships a /usr/bin/perl with DTrace support enabled.

HISTORY

  • 10.1

    Perl's initial DTrace support was added, providing sub-entry and sub-return probes.

  • 14.0

    The sub-entry and sub-return probes gain a fourth argument: the package name of the function.

  • 16.0

    The phase-change probe was added.

  • 18.0

    The op-entry , loading-file , and loaded-file probes were added.

  • PROBES

    • sub-entry(SUBNAME, FILE, LINE, PACKAGE)

      Traces the entry of any subroutine. Note that all of the variables refer to the subroutine that is being invoked; there is currently no way to get ahold of any information about the subroutine's caller from a DTrace action.

      1. :*perl*::sub-entry {
      2. printf("%s::%s entered at %s line %d\n",
      3. copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2);
      4. }
    • sub-return(SUBNAME, FILE, LINE, PACKAGE)

      Traces the exit of any subroutine. Note that all of the variables refer to the subroutine that is returning; there is currently no way to get ahold of any information about the subroutine's caller from a DTrace action.

      1. :*perl*::sub-return {
      2. printf("%s::%s returned at %s line %d\n",
      3. copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2);
      4. }
    • phase-change(NEWPHASE, OLDPHASE)

      Traces changes to Perl's interpreter state. You can internalize this as tracing changes to Perl's ${^GLOBAL_PHASE} variable, especially since the values for NEWPHASE and OLDPHASE are the strings that ${^GLOBAL_PHASE} reports.

      1. :*perl*::phase-change {
      2. printf("Phase changed from %s to %s\n",
      3. copyinstr(arg1), copyinstr(arg0));
      4. }
    • op-entry(OPNAME)

      Traces the execution of each opcode in the Perl runloop. This probe is fired before the opcode is executed. When the Perl debugger is enabled, the DTrace probe is fired after the debugger hooks (but still before the opcode itself is executed).

      1. :*perl*::op-entry {
      2. printf("About to execute opcode %s\n", copyinstr(arg0));
      3. }
    • loading-file(FILENAME)

      Fires when Perl is about to load an individual file, whether from use, require, or do. This probe fires before the file is read from disk. The filename argument is converted to local filesystem paths instead of providing Module::Name -style names.

      1. :*perl*:loading-file {
      2. printf("About to load %s\n", copyinstr(arg0));
      3. }
    • loaded-file(FILENAME)

      Fires when Perl has successfully loaded an individual file, whether from use, require, or do. This probe fires after the file is read from disk and its contents evaluated. The filename argument is converted to local filesystem paths instead of providing Module::Name -style names.

      1. :*perl*:loaded-file {
      2. printf("Successfully loaded %s\n", copyinstr(arg0));
      3. }

    EXAMPLES

    • Most frequently called functions
      1. # dtrace -qZn 'sub-entry { @[strjoin(strjoin(copyinstr(arg3),"::"),copyinstr(arg0))] = count() } END {trunc(@, 10)}'
      2. Class::MOP::Attribute::slots 400
      3. Try::Tiny::catch 411
      4. Try::Tiny::try 411
      5. Class::MOP::Instance::inline_slot_access 451
      6. Class::MOP::Class::Immutable::Trait:::around 472
      7. Class::MOP::Mixin::AttributeCore::has_initializer 496
      8. Class::MOP::Method::Wrapped::__ANON__ 544
      9. Class::MOP::Package::_package_stash 737
      10. Class::MOP::Class::initialize 1128
      11. Class::MOP::get_metaclass_by_name 1204
    • Trace function calls
      1. # dtrace -qFZn 'sub-entry, sub-return { trace(copyinstr(arg0)) }'
      2. 0 -> Perl_pp_entersub BEGIN
      3. 0 <- Perl_pp_leavesub BEGIN
      4. 0 -> Perl_pp_entersub BEGIN
      5. 0 -> Perl_pp_entersub import
      6. 0 <- Perl_pp_leavesub import
      7. 0 <- Perl_pp_leavesub BEGIN
      8. 0 -> Perl_pp_entersub BEGIN
      9. 0 -> Perl_pp_entersub dress
      10. 0 <- Perl_pp_leavesub dress
      11. 0 -> Perl_pp_entersub dirty
      12. 0 <- Perl_pp_leavesub dirty
      13. 0 -> Perl_pp_entersub whiten
      14. 0 <- Perl_pp_leavesub whiten
      15. 0 <- Perl_dounwind BEGIN
    • Function calls during interpreter cleanup
      1. # dtrace -Zn 'phase-change /copyinstr(arg0) == "END"/ { self->ending = 1 } sub-entry /self->ending/ { trace(copyinstr(arg0)) }'
      2. CPU ID FUNCTION:NAME
      3. 1 77214 Perl_pp_entersub:sub-entry END
      4. 1 77214 Perl_pp_entersub:sub-entry END
      5. 1 77214 Perl_pp_entersub:sub-entry cleanup
      6. 1 77214 Perl_pp_entersub:sub-entry _force_writable
      7. 1 77214 Perl_pp_entersub:sub-entry _force_writable
    • System calls at compile time
      1. # dtrace -qZn 'phase-change /copyinstr(arg0) == "START"/ { self->interesting = 1 } phase-change /copyinstr(arg0) == "RUN"/ { self->interesting = 0 } syscall::: /self->interesting/ { @[probefunc] = count() } END { trunc(@, 3) }'
      2. lseek 310
      3. read 374
      4. stat64 1056
    • Perl functions that execute the most opcodes
      1. # dtrace -qZn 'sub-entry { self->fqn = strjoin(copyinstr(arg3), strjoin("::", copyinstr(arg0))) } op-entry /self->fqn != ""/ { @[self->fqn] = count() } END { trunc(@, 3) }'
      2. warnings::unimport 4589
      3. Exporter::Heavy::_rebuild_cache 5039
      4. Exporter::import 14578

    REFERENCES

    SEE ALSO

    AUTHORS

    Shawn M Moore sartak@gmail.com