title: What would cause fastcgi_finish_request to take several seconds to execute?
body: <p>I have run into a rather strange issue with a particular part of a large PHP application. The portion of the application in question loads data from MySQL (mostly integer data) and builds a JSON string which gets output to the browser. These requests were taking sevar seconds (8 - 10 seconds each) in Chrome's developer tools as well as via <code>curl</code>. However the PHP shutdown handler I had reported that the requests were executing in less than 1 second.</p>
  
  <p>In order to debug I added a call to <code>fastcgi_finish_request()</code>, and suddenly my shutdown handler reported the same time as Chrome / curl. </p>
  
  <p>With some debugging, I narrowed it down to a particular function. I created the following simple test case:</p>
  
  <pre><code>&lt;?php
  
  $start_time = DFStdLib::exec_time();
  $product = new ApparelQuoteProduct(19);
  $pmatrix = $product-&gt;productMatrix();
  
  // This function call is the problem:
  $ranges = $pmatrix-&gt;ranges();
  
  $end_time = DFStdLib::exec_time();
  $duration =  $end_time - $start_time;
  
  echo "Output generation duration was: $duration sec";
  fastcgi_finish_request();
  $fastcgi_finish_request_duration =  DFStdLib::exec_time() - $end_time;
  DFSkel::log(DFSkel::LOG_INFO,"Output generation duration was: $duration sec; fastcgi_finish_request Duration was: $fastcgi_finish_request_duration sec");
  </code></pre>
  
  <p>If I call <code>$pmatrix-&gt;ranges()</code> (which is a function that executes a number of calls to <code>mysql_query</code> to fetch data and build an in-memory PHP object structure from that data) then I get the output:</p>
  
  <blockquote>
    <p>Output generation duration was: 0.2563910484314 sec; fastcgi_finish_request Duration was: 7.3854329586029 sec</p>
  </blockquote>
  
  <p>in my log file. Note that <strong>the call to <code>$pmatrix-&gt;ranges()</code> does not take long at all</strong>, yet somehow it causes the PHP FastCGI handler to take seven seconds to fihish the request. (This is true even if I don't call <code>fastcgi_finish_request</code> -- the browser takes 7-8 seconds to display the data either way)</p>
  
  <p>If I comment out the call to <code>$pmatrix-&gt;ranges()</code> I get:</p>
  
  <blockquote>
    <p>Output generation duration was: 0.0016419887542725 sec; fastcgi_finish_request Duration was: 0.00035214424133301 sec</p>
  </blockquote>
  
  <p>I can post the entire source for the <code>$pmatrix-&gt;ranges()</code> function, but it's very long. I'd like some advice on where to even start looking.</p>
  
  <p>What is it about the PHP FastCGI request process which would even cause such behavior? Does it call destructor functions / garbage collection? Does it close open resources? How can I troubleshoot this further?</p>
  
  <hr>
  
  <p>EDIT: Here's a larger source sample:</p>
  
  <pre><code>&lt;?php
  
  class ApparelQuote_ProductPricingMatrix_TestCase
  {
      protected $myProductId;
      protected $myQuantityRanges;
  
      private $myProduct;
      protected $myColors;
      protected $mySizes;
  
      protected $myQuantityPricing;
  
      public function __construct($product)
      {
          $this-&gt;myProductId = intval($product);
      }
  
      /**
       * Return an array of all ranges for this matrix.
       *
       * @return array
       */
      public function ranges()
      {
          $this-&gt;myLoadPricing();
          return $this-&gt;myQuantityRanges;
      }
  
      protected function myLoadPricing($force=false)
      {
          if($force || !$this-&gt;myQuantityPricing)
          {
              $this-&gt;myColors = array();
              $this-&gt;mySizes = array();
  
              $priceRec_finder = new ApparelQuote_ProductPricingRecord();
              $priceRec_finder-&gt;_link = Module_ApparelQuote::dbLink();
              $found_recs = $priceRec_finder-&gt;find(_ALL,"`product_id`={$this-&gt;myProductId}","`qtyrange_id`,`color_id`");
  
              $qtyFinder = new ApparelQuote_ProductPricingQtyRange();
              $qtyFinder-&gt;_link = Module_ApparelQuote::dbLink();
              $this-&gt;myQuantityRanges = $qtyFinder-&gt;find(_ALL,"`product_id`=$this-&gt;myProductId");
  
              $this-&gt;myQuantityPricing = array();
  
              foreach ($found_recs as &amp;$r)
              {
                  if(false) $r = new ApparelQuote_ProductPricingRecord();
  
                  if(!isset($this-&gt;myColors[$r-&gt;color_id]))
                      $this-&gt;myColors[$r-&gt;color_id] = true;
  
                  if(!isset($this-&gt;mySizes[$r-&gt;size_id]))
                      $this-&gt;mySizes[$r-&gt;size_id] = true;
  
                  if(!is_array($this-&gt;myQuantityPricing[$r-&gt;qtyrange_id]))
                      $this-&gt;myQuantityPricing[$r-&gt;qtyrange_id] = array();
  
                  if(!is_array($this-&gt;myQuantityPricing[$r-&gt;qtyrange_id][$r-&gt;color_id]))
                      $this-&gt;myQuantityPricing[$r-&gt;qtyrange_id][$r-&gt;color_id] = array();
  
                  $this-&gt;myQuantityPricing[$r-&gt;qtyrange_id][$r-&gt;color_id][$r-&gt;size_id] = &amp;$r;
              }
  
              $this-&gt;myColors = array_keys($this-&gt;myColors);
              $this-&gt;mySizes = array_keys($this-&gt;mySizes);
          }
      }
  }
  
  $start_time = DFStdLib::exec_time();
  $pmatrix = new ApparelQuote_ProductPricingMatrix_TestCase(19);
  $ranges = $pmatrix-&gt;ranges();
  $end_time = DFStdLib::exec_time();
  $duration =  $end_time - $start_time;
  
  echo "Output generation duration was: $duration sec";
  fastcgi_finish_request();
  $fastcgi_finish_request_duration =  DFStdLib::exec_time() - $end_time;
  DFSkel::log(DFSkel::LOG_INFO,"Output generation duration was: $duration sec; fastcgi_finish_request Duration was: $fastcgi_finish_request_duration sec");
  </code></pre>
  
  <p>Upon continued debugging I have narrowed down to the following lines from the above:</p>
  
  <pre><code>                if(!is_array($this-&gt;myQuantityPricing[$r-&gt;qtyrange_id][$r-&gt;color_id]))
                      $this-&gt;myQuantityPricing[$r-&gt;qtyrange_id][$r-&gt;color_id] = array();
  </code></pre>
  
  <p>These statements are building an in-memory array structure of all the data loaded from MySQL. If I comment these out, then  <code>fastcgi_finish_request</code> takes roughly 0.0001 seconds to run. If I do not comment them out, then <code>fastcgi_finish_request</code> takes 7+ seconds to run.</p>
  
  <h1>It's actually the function call to <code>is_array</code> that's the issue here</h1>
  
  <p>Changing to:</p>
  
  <pre><code>                if(!isset($this-&gt;myQuantityPricing[$r-&gt;qtyrange_id][$r-&gt;color_id]))
  </code></pre>
  
  <p>Resolves the problem. Why is this?</p>