Welcome Guest, Not a member yet? Register   Sign In
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
# User@Host: 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 
(This post was last modified: 11-14-2017, 01:43 AM by travisbotello.)

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 CodeIgniter Community 2009.  ( Skype: insitfx )
Reply
#9

(11-14-2017, 10:55 AM)InsiteFX Wrote: Turn on CodeIgniter's Profiler and see what is going on...

Thanks. This is pretty helpful...
Reply
#10

If someone is interested in the solution/cause of the issue:

After some more debugging I was able to identify the problem to be related to MySQL. CI and Wordpress are using InnoDB Engine while MODx and my other applications were using MyISAM. I converted one MODx installation to InnoDB and suddenly it started having exactly the same issues:

[Image: jBd7X.png]
As I mentioned earlier most slowlog entries were related to sessions, so I digged in a bit deeper, and I think the problem is InnoDB clustered indexes

In CI the PK of the default CI session table is likely to cause those issues when used in certain setups with InnoDB. Let me sum up the following post which explains it in more detail:

From MySQL Docs:

Quote:Every InnoDB table has a special index called the clustered index where the data for the rows is stored. Typically, the clustered index is synonymous with the primary key. To get the best performance from queries, inserts, and other database operations, you must understand how InnoDB uses the clustered index to optimize the most common lookup and DML operations for each table.


From this SO answer:


Quote:According to The Queen Of Indexing - Kimberly Tripp - what she looks for in a clustered index is primarily:
  • Unique

  • Narrow

  • Static
And if you can also guarantee:
  • Ever-increasing pattern
then you're pretty close to having your ideal clustering key!

In the case of CI session table this is not really the case:
  • Unique => yes
  • Narrow => yes
  • Static => yes
  • Ever-increasing pattern => no

Here's what can happen when a non-ever-increasing clustered index is used. Source

Quote:If the clustering key is ever-increasing then new rows have a specific location where they can be placed. If that location is at the end of the table then the new row needs space allocated to it but it doesn't have to make space in the middle of the table. If a row is inserted to a location that doesn't have any room then room needs to be made (e.g. you insert based on last name then as rows come in space will need to be made where that name should be placed). If room needs to be made, it's made by SQL Server doing something called a split. Splits in SQL Server are 50/50 splits - simply put - 50% of the data stays and 50% of the data is moved. This keeps the index logically intact (the lowest level of an index - called the leaf level - is a douly-linked list) but not physically intact. When an index has a lot of splits then the index is said to be fragmented. Good examples of an index that is ever-increasing are IDENTITY columns (and they're also naturally unique, natural static and naturally narrow) or something that follows as many of these things as possible - like a datetime column (or since that's NOT very likely to be unique by itself datetime, identity).


In my case with CI and other applications this lead to the following issue:

Quote:When you are inserting a new row (the "random" hash guarantees that) it gets inserted in a random location of the index. This means that it sometimes will find no space there available to be inserted (note that InnoDB always leaves some space free in the index but when that free-available space is filled) there has to be some rearrangement of the index - and that takes time.

What the rearrangement is also causing over time is fragmentation of the index. Which will eventually make other queries and statements slower.

The solutions for me is to either use a different session driver, or switch the session table to MyISAM.
Reply




Theme © iAndrew 2016 - Forum software by © MyBB