OPcache diagnostic instrumentation

Debugging support

All versions of OPcache within this fork add some built-in debug logging when configured with --enable-opcache-debug. If not configured the DEBUGn() and ENTER() macros in the source code generate null text, and these source lines are effectively ignored.

When this configuration option is used the DEBUGn() and ENTER() then generate extra logging during the build that can be enabled at runtime on a category basis by using the INI parameter opcache.debug_flags for the purpose of debugging. This parameter is a bit mask with the following debug categories.

  0001  ACCEL_DBG_ALLOC          SMA Storage Allocation
  0002  ACCEL_DBG_KEY            SMA Key resolution
  0004  ACCEL_DBG_HASH           SMA Hash Functions
  0008  ACCEL_DBG_RELR           Missed relocation report
  0010  ACCEL_DBG_LOAD           Load/Unload Info
  0020  ACCEL_DBG_ENTER          Print out function entry audit
  0040  ACCEL_DBG_COUNTS         Print out function summary counts
  0080  ACCEL_DBG_INDEX          Print out cache index save and load
  0100  ACCEL_DBG_INTERN         Intern allocation
  0200  ACCEL_DBG_TIMIMG         Time tracking (see next section)

So for example, -d opcache.debugs_flags=0x0007 turns on tracing of storage allocation, key and hash operations relating to SMA storage.

All generated debug code is predicated by an inline test of the appropriate flag bit, so the runtime overhead of -d opcache.debugs_flags=0 as compared to debugging disabled run is minimal, and hence it is entirely feasible to configure debug logging for testing and validation in an otherwise production build (e.g. with -O3 or -Ofast build and direct execution rather than through gdb in a *nix environment).

Any debug log records are issued to STDERR if the INI paramter opcache.log_verbosity_level=4

Timing support

The ACCEL_DBG_TIMING feature is available as an option when debugging is configured on POSIX builds, this collects timing data on the following categories during execution to microsecond resolution and presents a single information message summarising these counts on the PHP error log during request rundown (to avoid the logging overhead contaminating the timings). The purpose of this function is to enable the collection of accurate timing statistics on the various aspect of the OPcache processing.

 0001 ACCEL_TIMING_REQUEST      Total to execute the request including user processing
 0002 ACCEL_TIMING_NDXLOAD      To open the cache and load the index
 0003 ACCEL_TIMING_STDCOMP      To execute non-cached compiles
 0004 ACCEL_TIMING_CACHECOMP    To execute cached compiles (that is when priming the SMA)
 0005 ACCEL_TIMING_PERSIST      To execute the compiler O/P to SMA copies
 0006 ACCEL_TIMING_PREPSAVE     To copy content from SMA to temp file cache
 0007 ACCEL_TIMING_CACHEWRITE   To create O/P cache including index and module copies from temp cache
 0008 ACCEL_TIMING_CACHEREAD    To read in the compiled module from the file cache 
 0009 ACCEL_TIMING_PREPEXEC     To copy content from SMA to local memory for execution
 0010 ACCEL_TIMING_DEFLATE      To deflate the index & compiled module to compressed form
 0011 ACCEL_TIMING_INFLATE      To inflate the index & compiled modules to uncompressed form

If OPcache is configured with --enable-opcache-timing the timing support is available whether or not the remaining debug categories have been configured.

Note:

1. Times are collected using the gettimeofday function with a resolution of 1 uSec.
2. The gettimeofday-based timing overhead (roughly 0.06 uSec on the test system) is much smaller that the 1 uSec resolution.