[FIXED] CakePHP 3 slow json responses, why?

Issue

I have something very simple in an API I've built with CakePHP 3. It's a ping endpoint that just returns a simple little response

{"success":true,"message":"Thanks for saying hello. Everything looks good so far."}

When I use the following code that uses CakePHPs extension parsing for JSON I get the following benchmark.

public function ping(){
    $message = 'Thanks for saying hello. Everything looks good so far.';
    $this->set('message', $message);
    $this->set('success', true);
    $this->set('_serialize', true);
}

Benchmark:

Server Software:        Apache/2.4.18
Server Hostname:        app.local
Server Port:            80

Document Path:          /publisher/v3.0/.json
Document Length:        83 bytes

Concurrency Level:      10
Time taken for tests:   10.034 seconds
Complete requests:      12
Failed requests:        0
Total transferred:      4760 bytes
HTML transferred:       1660 bytes
Requests per second:    1.20 [#/sec] (mean)
Time per request:       8361.339 [ms] (mean)
Time per request:       836.134 [ms] (mean, across all concurrent requests)
Transfer rate:          0.46 [Kbytes/sec] received

And I remove extension parsing and do the following code...

public function ping(){
    $message = 'Thanks for saying hello. Everything looks good so far.';
    echo json_encode(['success'=>true, 'message'=> $message]); 
    exit(0);
}

Benchmark:

Server Software:        Apache/2.4.18
Server Hostname:        app.local
Server Port:            80

Document Path:          /publisher/v3.0/
Document Length:        83 bytes

Concurrency Level:      10
Time taken for tests:   10.000 seconds
Complete requests:      5895
Failed requests:        0
Total transferred:      1733130 bytes
HTML transferred:       489285 bytes
Requests per second:    589.49 [#/sec] (mean)
Time per request:       16.964 [ms] (mean)
Time per request:       1.696 [ms] (mean, across all concurrent requests)
Transfer rate:          169.25 [Kbytes/sec] received

1.2 requests per second is paltry compared to 589 requests per second. How can this be? Have I done something wrong? I used apache benchmark with 10 concurrent requests over 10 seconds. I can't continue with using Cake 3 if its this slow... I'm better off using Phalcon, CI, Slim, or rolling my own at that point. Please tell me I'm doing something wrong...

Solution

8s response times are not normal

I can't continue with using Cake 3 if its this slow

No one in their right mind would use a framework which results in glacial response times for trivial responses; there's something wrong with the application.

Not reproducible

With this set of routes:

<?php

use Cake\Routing\Router;

Router::scope('/extension', function ($routes) {
    $routes->extensions(['json']);
    $routes->connect('/', ['controller' => 'RequestHandler', 'action' => 'ping']);
});

Router::scope('/noextension', function ($routes) {
    $routes->connect('/', ['controller' => 'NoRequestHandler', 'action' => 'ping']);
});

This controller:

<?php
namespace App\Controller;

use App\Controller\AppController;

class RequestHandlerController extends AppController
{
    public function initialize()
    {
        parent::initialize();
        $this->loadComponent('RequestHandler');
    }

    public function ping()
    {
        $message = 'Thanks for saying hello. Everything looks good so far.';
        $this->set('message', $message);
        $this->set('success', true);
        $this->set('_serialize', true);
    }
}

And this controller:

<?php
namespace App\Controller;

use App\Controller\AppController;

class NoRequestHandlerController extends AppController
{
    public function ping()
    {
        $this->viewClass = 'Cake\View\JsonView';
        $message = 'Thanks for saying hello. Everything looks good so far.';
        $this->set('message', $message);
        $this->set('success', true);
        $this->set('_serialize', true);
    }
}

And with debug turned off:

> grep debug config/app.php 
    'debug' => false,

Response times for no extension are some ms:

-> curl -i http://cakephp.dev/noextension # Demonstrate exactly what's being benchmarked
HTTP/1.1 200 OK
Server: nginx/1.8.0
Date: Sat, 06 Aug 2016 09:31:53 GMT
Content-Type: application/json; charset=UTF-8
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding

{"success":true,"message":"Thanks for saying hello. Everything looks good so far."}

Benchmark results:

-> ab -c 10 -t 10 http://cakephp.dev/noextension
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking cakephp.dev (be patient)
Finished 1719 requests


Server Software:        nginx/1.8.0
Server Hostname:        cakephp.dev
Server Port:            80

Document Path:          /noextension
Document Length:        83 bytes

Concurrency Level:      10
Time taken for tests:   10.002 seconds
Complete requests:      1719
Failed requests:        0
Write errors:           0
Total transferred:      428031 bytes
HTML transferred:       142677 bytes
Requests per second:    171.86 [#/sec] (mean)
Time per request:       58.186 [ms] (mean)
Time per request:       5.819 [ms] (mean, across all concurrent requests)
Transfer rate:          41.79 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   1.9      0      41
Processing:    10   58  20.0     57     224
Waiting:       10   58  20.0     57     223
Total:         10   58  20.2     57     224

Percentage of the requests served within a certain time (ms)
  50%     57
  66%     62
  75%     67
  80%     70
  90%     81
  95%     94
  98%    112
  99%    122
 100%    224 (longest request)

Using router extension parsing results are not significantly slower:

-> curl -i http://cakephp.dev/extension.json
HTTP/1.1 200 OK
Server: nginx/1.8.0
Date: Sat, 06 Aug 2016 09:33:25 GMT
Content-Type: application/json; charset=UTF-8
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding

{"success":true,"message":"Thanks for saying hello. Everything looks good so far."}

Benchmark results:

-> ab -c 10 -t 10 http://cakephp.dev/extension.json
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking cakephp.dev (be patient)
Finished 1672 requests


Server Software:        nginx/1.8.0
Server Hostname:        cakephp.dev
Server Port:            80

Document Path:          /extension.json
Document Length:        83 bytes

Concurrency Level:      10
Time taken for tests:   10.012 seconds
Complete requests:      1672
Failed requests:        0
Write errors:           0
Total transferred:      416328 bytes
HTML transferred:       138776 bytes
Requests per second:    166.99 [#/sec] (mean)
Time per request:       59.882 [ms] (mean)
Time per request:       5.988 [ms] (mean, across all concurrent requests)
Transfer rate:          40.61 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.5      0       8
Processing:    10   60  21.8     58     278
Waiting:       10   59  21.8     58     278
Total:         10   60  21.9     58     278

Percentage of the requests served within a certain time (ms)
  50%     58
  66%     63
  75%     67
  80%     71
  90%     80
  95%     94
  98%    111
  99%    134
 100%    278 (longest request)

Absolute numbers in these results are not so important - the lack of significant difference is though. The conclusion here is that the problem is not general, it's somehow specific to the installation in the question.

Identify where those 8 seconds are going

It's not possible to say why the requests are slow in your scenario as it's not reproducible, so you'll need to dig deeper.

A simple first step is to use any url with the same logic that renders html and look at the debug timer waterfall:

(Everything up to "View Render start" is identical to requesting /extension.json)

If any particular timer is significant - look at what that code is doing, and if necessary add some more granular timers to the called code.

If that doesn't help use xdebug and profile a single http request; webgrind is a low effort way to visualize the information of an xdebug profile. Using xdebug profiling aught to be a standard tool in any php dev's toolbelt - if you're not familiar with using xdebug profiles - now's the time to start :).

Answered By - AD7six