Pods page times out when GravityForms plugin is enabled

Hi @awakensolutions,

Since the core issue is a timeout, here are some thoughts and things to check:

• Perhaps easiest to test in a development environment — but both WPEngine and Cloudflare will terminate a process if it takes too long. Both platforms are tuned to be maximally responsive, which involves turning off anything that runs too long. Cloudflare will timeout at 100 seconds if no output is sent, but WPEngine does not allow any PHP request to take more than 60 seconds.
• Without knowing what is on the specific Reservations admin page, I would take a guess that there might be a field which queries user accounts. The health check says the site has 2,658 user accounts. If that many users, especially with their profile information, is queried all at once, rather than with a page-limited AJAX search, it could cause such a timeout.
• If there is not a user field, consider any other fields, such as content generated by those users, which might be even more processor intensive. The thing to look for and consider is if any menu item is loading hundreds or thousands of content items up-front; anything that might take longer than 60 seconds for a typical single-threaded database request to get through.

That is a bit puzzling, but it sounds like somewhere in Gravity Forms or perhaps the Gravity Forms Pods Integration, there may be a query which is attempting to get all users or content of another type. This could be various things, as even the database has memory and time limits of its own which vary by each installation.

WP.org forum policies recommend avoiding sharing credentials. There are other Pods support venues on the plugin site, but here’s something that may point to what might be causing the issue on a test instance without anyone logging in:

<?php
/**
 * Plugin Name: Log Long Actions
 * Description: When active, write log files to <code>wp-content/uploads/action-logs/<code> which contain timestamped files of every action taking more than <code>0.5 seconds</code>. Also logs WPDB SQL queries nearby relevant actions.
 * Version: 1
 */

class Log_Long_Actions {

  /**
   * In a default Pods + Gravity Forms install, 0.001 will log around 16 actions.
   * In a situation where something is awry or timing out, 0.5 might log a few.
   * In a default install, 0.5 will log nothing.
   */
  private $minimum_time_to_log = 0.5; // seconds.
  private $actions = [];
  private $counter = 0;
  private $log_dir = '';
  private $debug_backtrace_lookback = 10; // Maximum files to look back for where the action came from.

  private $actions_to_ignore = [
    // These actions will not be logged.
    // If the logging does not get to the action causing the timeout,
    // Add some actions associated with log files that do show up to skip them,
    // Then delete the logs and try again.

    'plugins_loaded',           // Starting here.
    'load_textdomain_mofile',
    'sanitize_file_name_chars',
    'mime_types',
    'sanitize_file_name',
    'attribute_escape',
    'posts_pre_query',
  ];
  private $action_patterns_to_ignore = [
    // Happens a lot in various forms.
    'gettext',
    'esc_',
    'clean_',
    'wp_kses',
  ];
  // Additionally do not log anything which is not in a file or directory containing 'gravity'.
  // This makes an assumption that we are looking in plugins/gravityforms/ or plugins/pods-gravity-forms/
  private $logged_action_file_path_must_contain = 'gravity';

  /**
   * Add a timer to the beginning and end of every action and filter.
   */
  public function __construct() {
    // If filters and ignores above are turned off,
    // This might take some memory!
    @ini_set( 'memory_limit', '4G' );

    /**
     * Define and possibly create a directory for logs in wp-content/uploads/action-logs.
     */
    $this->log_dir = sprintf( '%s/action-logs', wp_get_upload_dir()['basedir'] );
    if ( ! is_dir( $this->log_dir ) ) {
      wp_mkdir_p( $this->log_dir );
    }

    add_action( 'all', [ $this, 'action_start' ], PHP_INT_MIN );
    add_action( 'all', [ $this, 'action_end' ], PHP_INT_MAX );

    add_action( 'posts_pre_query', [ $this, 'posts_pre_query' ], PHP_INT_MAX, 2 );
  }

  private function maybe_ignore( $action = '' ) {
    foreach( $this->action_patterns_to_ignore as $nope ) {
      if ( false !== strpos( $action, $nope ) ) {
        return true;
      }
    }
    return ( in_array( $action, $this->actions_to_ignore ) );
  }

  /**
   * Note the most recent query in a log file prefix with a counter close to the most recent action.
   */
  public function posts_pre_query( $maybe_null, $wp_query ) {
    file_put_contents(
      sprintf(
        '%s/%s-query-%s.log',
        $this->log_dir,
        str_pad(
          (string) $counter,
          6,
          '0',
          STR_PAD_LEFT
        ),
        md5( $wp_query->request )
      ),
      (string) $wp_query->request
    );
    return $maybe_null;
  }

  public function action_start() {
    $this->counter++;
    $current_action = current_action();

    if ( $this->maybe_ignore( $current_action ) ) {
      return;
    }

    // Optional verbose PHP error log of current action.
    // error_log( $current_action );

    $counter                   = $this->counter;
    $start_time                = microtime( true );
    $this->actions[ $counter ] = $start_time;
    // Replacing DEBUG_BACKTRACE_IGNORE_ARGS with 0 or increasing $this->debug_backtrace_lookback will provide more information,
    // but will require more memory.
    $debug_backtrace           = debug_backtrace( DEBUG_BACKTRACE_IGNORE_ARGS, $this->debug_backtrace_lookback );
    $file_chain                = implode( ',', wp_list_pluck( $debug_backtrace, 'file' ) );
    $line_chain                = implode( ',', wp_list_pluck( $debug_backtrace, 'line' ) );

    // Optional very verbose PHP error log of current backtrace.
    // error_log( print_r( $debug_backtrace, true ) );

    // Save some time by only looking at Gravity Forms.
    // Commenting this out will write an enormous amount of files.
    if ( false === strpos( $file_chain, $this->logged_action_file_path_must_contain ) ) {
      return;
    }

    // Optional filtered verbose PHP error log of current backtrace.
    // error_log( print_r( $debug_backtrace, true ) );

    $file_path      = sprintf(
      '%s/%s-%s-at.%s.%s.log',
      $this->log_dir,
      str_pad(
        (string) $counter,
        6,
        '0',
        STR_PAD_LEFT
      ),
      str_replace( '/', '_slash_', $current_action ),
      (string) $start_time,
      md5( $file_chain . $line_chain . $_SERVER['REQUEST_URI'] )
    );

    file_put_contents(
      $file_path,
      sprintf(
        'Action "%s" from %s :%s%s',
        $current_action,
        $_SERVER['REQUEST_URI'],
        PHP_EOL . PHP_EOL,
        print_r( $debug_backtrace, true )
      )
    );

    unset( $debug_backtrace );
  }

  /**
   * Remove the log files if the action took less than 2 seconds.
   * 
   * This may not work perfectly if actions call themselves recursively or in similarly complex counting/timing situations.
   */
  public function action_end() {
    $current_action = current_action();

    if ( $this->maybe_ignore( $current_action ) ) {
      return;
    }

    $now = microtime( true );

    // For each log file associated with this action...
    foreach(
      glob( sprintf( '%s/*-%s-*.log', $this->log_dir, str_replace( '/', '_slash_', $current_action ) ) )
      as $log_file
    ) {
      // Get the counter from the file name.
      $counter = intval( explode( '-', basename( $log_file ) )[0] );
      $time_it_took = ( array_key_exists( $counter, $this->actions ) )
        ? ( $now - $this->actions[ $counter ] )
        : false;

      // Check if a start time still exists for that action call.
      if ( $time_it_took ) {
        // If it's been less than max seconds since the action started...
        if ( $this->minimum_time_to_log >= $time_it_took ) {
          // Delete the file.
          unlink( $log_file );
        }else {
          // Note how long it took.
          file_put_contents(
            $log_file,
            sprintf(
              '%sTook %s seconds.',
              PHP_EOL . PHP_EOL,
              number_format( $time_it_took, 4 )
            ),
            FILE_APPEND
          );
        } 
      }

      // Clear the start time, as we have either removed the file or logged the execution time.
      unset( $this->actions[ $counter ] );
    }

    /**
     * The only remaining log files should be actions which either:
     *   - Took longer than the minimum time.
     *   - Did not complete due to timeout.
     */
  }
}

add_action(
  'plugins_loaded',
  function() {
    new Log_Long_Actions();
  }
);

The above plugin is a bit complex, as it is constructed in such a way that logs will be written for any filter or action in a file path containing gravity if it takes longer than 0.5 seconds to run all associated functions, or if it times out and fails completely.

Completed actions/filters will log total run time if over the 0.5 setting. Actions/filters which fail to complete or timeout will still log a file saying what it was and where to find it, but will not contain a completion timer at the end.

There are lots of comments in there are some optional verbose logs. I tested on Pods + Gravity Forms; it should log a file to wp-content/uploads/action-logs/xxx.log for any action or filter with gravity anywhere in the path.

It can be installed as a plugin or mu-plugin… Don’t install it on production! It ended up being very efficient in testing, only taking 58 MB of memory, but removing any of the filters or ignores can result in much more memory and disk input/output being consumed.

The idea is to load the plugin, then directly load the URL of the problematic page. Any long-running action or filter that does not complete within 0.5 seconds will show up in the log directory in uploads. They will be numbered in order of execution, and will contain a full execution path that led there, as well as the calling URL for cases such as background processes / AJAX calls.

A critical look at the resulting files may have a good chance of leading to a file and line number in GF or GFPI very close to a point where a query is not completing.

Edit: The above plugin is now marked Version: 1. In this revision, I added functionality similar to Query Monitor, in that all SQL queries going through WPDB will be logged in files prefixed by a counter associating it closely with related long-running actions. Unlike query monitor, it will not say how long the query took, but the last query to be logged will likely be the one too complex to complete, verifiable by either running it manually or considering its “weight” relative to the amount of content of various types found in the database.

• This reply was modified 1 year, 1 month ago by Paul Clark. Reason: Add query log