• 0 Vote(s) - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
CI runs slow with Nginx + PHP 7.1 + MariaDB

#1
Sad 
Problem

I am running a CentOS 7 machine with Nginx 1.10.2 + PHP 7.1.10 (php-fpm) + MariaDB 10.1.28. Using this machine I am serving the following applications:
  • 4x Laravel 5.x
  • 10x MODx Revo 2.5.8
  • 2x CI 3.1.6
While my Laravel and MODx Revo applications are running super fast without any issues, my status monitors, slow logs (PHP-FPM and MariaDB Slowlog) and manual testing verify that from approx. 10 requests to my  CI applications 3 reqs. are very slow (slowest around 5-7 seconds) while the other 7 reqs. are quick as expected.

Steps to debug/resolve

Activated php-fpm's and mariadb's slowlog (>= 3 seconds): The results confirm that only my CI applications are causing entries in both slowlogs. After analyzing the entries I can group them in two categories:

  1. cron/curl scripts
  2. db transactions
So at first I disabled all cron/curl scripts. But status monitor and manual testing still show slow requests around 5-7 seconds for those applications. This breaks it down to DB transactions. Here are examples:

www-slow.log (PHP-FPM)
Code:
[12-Nov-2017 23:08:02]  [pool www] pid 23991
   script_filename = /usr/share/nginx/www/ci/index.php
   [0x00007ff6f74133c0] query() /usr/share/nginx/www/ci/system/database/drivers/pdo/pdo_driver.php:184
   [0x00007ff6f7413350] _execute() /usr/share/nginx/www/ci/system/database/DB_driver.php:791
   [0x00007ff6f74132e0] simple_query() /usr/share/nginx/www/ci/system/database/DB_driver.php:654
   [0x00007ff6f74131b0] query() /usr/share/nginx/www/ci/system/libraries/Session/drivers/Session_database_driver.php:358
   [0x00007ff6f7413110] _get_lock() /usr/share/nginx/www/ci/system/libraries/Session/drivers/Session_database_driver.php:151
   [0x00007ff6f7413080] read() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
   [0x00007ff6f7413030] session_start() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
   [0x00007ff6f7412f60] __construct() /usr/share/nginx/www/ci/system/core/Loader.php:1279
   [0x00007ff6f7412e40] _ci_init_library() /usr/share/nginx/www/ci/system/core/Loader.php:1172
   [0x00007ff6f7412d20] _ci_load_stock_library() /usr/share/nginx/www/ci/system/core/Loader.php:1037
   [0x00007ff6f7412c10] _ci_load_library() /usr/share/nginx/www/ci/system/core/Loader.php:1083
   [0x00007ff6f7412b00] _ci_load_library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:173
   [0x00007ff6f7412a00] library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:192
   [0x00007ff6f7412950] libraries() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:153
   [0x00007ff6f7412850] library() /usr/share/nginx/www/ci/system/core/Loader.php:1353
   [0x00007ff6f7412790] _ci_autoloader() /usr/share/nginx/www/ci/system/core/Loader.php:157
   [0x00007ff6f7412740] initialize() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:65
   [0x00007ff6f7412690] initialize() /usr/share/nginx/www/ci/system/core/Controller.php:79
   [0x00007ff6f74125f0] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:55
   [0x00007ff6f7412560] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:60


slow.log (MariaDB)

Code:
# Time: 171112 23:08:05
# [email protected]: ci[ci] @ localhost []
# Thread_id: 6445  Schema: pm  QC_hit: No
# Query_time: 16.833340  Lock_time: 0.000049  Rows_sent: 0  Rows_examined: 168
# Rows_affected: 1
#
# explain: id   select_type table   type    possible_keys   key key_len ref rows    r_rows  filtered    r_filtered  Extra
# explain: 1    SIMPLE  ci_un_sessions  ALL NULL    NULL    NULL    NULL    168 168.00  100.00  0.60    Using where
#
use pm;
SET timestamp=1510524485;
UPDATE `ci_un_sessions` SET `timestamp` = 1510524468, `data` = '__ci_last_regenerate|i:1510524343;requested_page|s:41:\"http://example.com/projects/view/19\";user_id|s:1:\"1\";username|s:9:\"admin\";role_id|s:1:\"1\";status|s:1:\"1\";previous_page|s:41:\"http://example.com/projects/view/19\";'
WHERE `id` = '0a75c6tl27pngqnfrh261okdvuotth50';

I also tried to switch the database driver in CI from PDO to Mysqli...this didn't change anything. Also I ran all those slow queries in Phpmyadmin, and they perform super fast...so finally in CI I switched session from DB to Session_files_driver causing the slowlog to print:

Code:
[12-Nov-2017 23:27:00]  [pool www] pid 23991
script_filename = /usr/share/nginx/www/ci/index.php
[0x00007ff6f7413140] flock() /usr/share/nginx/www/ci/system/libraries/Session/drivers/Session_files_driver.php:178
[0x00007ff6f7413080] read() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
[0x00007ff6f7413030] session_start() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
[0x00007ff6f7412f60] __construct() /usr/share/nginx/www/ci/system/core/Loader.php:1279
[0x00007ff6f7412e40] _ci_init_library() /usr/share/nginx/www/ci/system/core/Loader.php:1172
[0x00007ff6f7412d20] _ci_load_stock_library() /usr/share/nginx/www/ci/system/core/Loader.php:1037
[0x00007ff6f7412c10] _ci_load_library() /usr/share/nginx/www/ci/system/core/Loader.php:1083
[0x00007ff6f7412b00] _ci_load_library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:173
[0x00007ff6f7412a00] library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:192
[0x00007ff6f7412950] libraries() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:153
[0x00007ff6f7412850] library() /usr/share/nginx/www/ci/system/core/Loader.php:1353
[0x00007ff6f7412790] _ci_autoloader() /usr/share/nginx/www/ci/system/core/Loader.php:157
[0x00007ff6f7412740] initialize() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:65
[0x00007ff6f7412690] initialize() /usr/share/nginx/www/ci/system/core/Controller.php:79
[0x00007ff6f74125f0] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:55
[0x00007ff6f7412560] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:60
[0x00007ff6f7412500] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/application/third_party/MX/Controller.php:4
[0x00007ff6f74124a0] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/application/third_party/MX/Modules.php:123
[0x00007ff6f7412400] autoload() unknown:0
[0x00007ff6f74123a0] spl_autoload_call() unknown:0

So I am kind of stuck here...I can't really determine the real cause for those slow requests. I first thought it might be related to some slow CURL/CRON requests, after ruling that out I though it is related to DB transactions, but after switching session to Session_files_driver, excluding database, the slow requests still occur.

Any ideas on how to debug this further? I am lost...should I switch back to PHP 7.0 or PHP 5.x?

Thanks in advance!!
Reply

#2
Downgrading PHP can't possibly help, not just with this but with anything.

Looks like you're handling concurrent requests from the same user (AJAX-heavy website?), which when combined with sessions ... Well, it's explained in the manual.

Also, that query explain plan shows that you didn't have an index on the `id` field (which you should, again per the same manual page) and that has slowed it further down.
Reply

#3
@Narf thanks for taking the time to look into this. I will fix those to issues to see if this changes anything!!
Reply

#4
Sad 
I am still stuck here. I altered database table according to man page (added primary key) and also checked for extensive session/ajax use, which is not the case. Especially not on the overview/index page that I am using for reference.

For further testing I copied both CI apps to a PHP 7.0 environment and there I don't have these request delays.

Is it possible that these issues are related to Third Party Add-Ons, or modules that use code that isn't supposed to work well with PHP 7.1+? I am having some slowlog entries without session files as well:


Code:
[14-Nov-2017 08:23:40] WARNING: [pool www] child 25464, script '/usr/share/nginx/www/ci/index.php' (request: "GET /index.php") executing too slow (6.277512 sec), logging


Code:
[14-Nov-2017 08:23:40]  [pool www] pid 25464
script_filename = /usr/share/nginx/www/ci/index.php
[0x00007fda53413f00] query() /usr/share/nginx/www/ci/system/database/drivers/pdo/pdo_driver.php:184
[0x00007fda53413e90] _execute() /usr/share/nginx/www/ci/system/database/DB_driver.php:791
[0x00007fda53413e20] simple_query() /usr/share/nginx/www/ci/system/database/DB_driver.php:654
[0x00007fda53413cf0] query() /usr/share/nginx/www/ci/system/database/DB_query_builder.php:1378
[0x00007fda53413c50] get() /usr/share/nginx/www/ci/application/models/User.php:169
[0x00007fda53413be0] profile_info() /usr/share/nginx/www/ci/application/models/User.php:186
[0x00007fda53413b40] avatar_url() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php(353) : eval()'d code:46
[0x00007fda53413340] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:353
[0x00007fda53413230] _ci_load() /usr/share/nginx/www/ci/application/core/MY_Loader.php:19
[0x00007fda53413160] view() /usr/share/nginx/www/ci/application/modules/sidebar/controllers/Sidebar.php:53
[0x00007fda534130d0] top_header() /usr/share/nginx/www/ci/application/third_party/MX/Modules.php:71
[0x00007fda53412fe0] run() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php(353) : eval()'d code:112
[0x00007fda534127b0] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:353
[0x00007fda534126a0] _ci_load() /usr/share/nginx/www/ci/system/core/Loader.php:503
[0x00007fda53412620] file() /usr/share/nginx/www/ci/application/modules/layouts/libraries/Template.php:701
[0x00007fda534124c0] _load_view() /usr/share/nginx/www/ci/application/modules/layouts/libraries/Template.php:259
[0x00007fda534123d0] build() /usr/share/nginx/www/ci/application/modules/welcome/controllers/Welcome.php:54
[0x00007fda53412340] index() /usr/share/nginx/www/ci/system/core/CodeIgniter.php:532
[0x00007fda534120f0] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/index.php:331
The MariaDB Slowlog doesn't have a related entry to this stack...
Maybe it is a server issues, but the fact that I am running a lot of other applications on this PHP 7.1 server as well without any issues I assume it is related to CI in some way.
Reply

#5
Any third-party extensions can certainly slow the app down. These logs even show eval() usage, which should be avoided for other reasons, but it's also a particularly slow function.
Reply

#6
Okay...and is it possible that these third-party extensions/bad coding style (eval()) are having such a huge effect on PHP 7.1 while PHP 7.0 isn't complaining?
Reply

#7
No difference between PHP 7.0 and 7.1 can cause such a regression. In fact, as far as I know, 7.1 should be even faster than 7.0. It must be some difference in the environments, such as extra or missing extensions.

In any case, asking more and more questions here won't get you anywhere. You need to follow that stack trace, dig through the code and find the bottleneck.
Reply

#8
Turn on CodeIgniter's Profiler and see what is going on...
What did you Try? What did you Get? What did you Expect?

Joined the CodeIgniter Community in 2009.          ( Skype: insitfx )
Reply


Digg   Delicious   Reddit   Facebook   Twitter   StumbleUpon  


Users browsing this thread:
1 Guest(s)


  Theme © 2014 iAndrew  
Powered By MyBB, © 2002-2017 MyBB Group.