Slow transaction on /customer/section/load Magento v2.2.5 CE

Question

I was recently seeing slow response times on our Magento 2.2.5 CE installation, so we installed NewRelic to monitor some site metrics. One thing that instantly stood out to me was the /customer/session/load. It was the the most time-consuming transaction by a huge margin. Under high load it was not unusal to see transactions above 100 second response times (the response times vary from 10-30 seconds under normal load). I opened up all of the traces for this route and they all seemed to hang on Magento\Framework\Session\SaveHandler\Native::read.

I wen around our site and noticed that some pages(category and product) are making 6 called to /customer/section/load. Some of these are from base magento and others are from google tag manager (we are using the magento2-googletagmanager2 module).

Here's what I tried:

1. First I tried disabling the google tag module
2. I changed the session storage to Memcache(we were previously on file storage)
3. I changed the session storage to Redis
4. I also verified on a bare Magento v2.2.5 installation that the base magento calls to /customer/section/load are happening. But even on that installation some of the requests took 1-1.5 seconds. (Although this is subjective because I was using a MAMP server locally)

Specifications

Server specs: We use a hosting service and we have a 32-core server with 128gb of ram and are not experiencing any memory/cpu load issues. We are also using Mysql on the same server and our DB size is around 3.3gb

Magento Specs: We have a Magento v2.2.5 CE installation with around 80,000 Sku's

Additional Info: We are using Varnish and CDN (cloudfront)

Questions:

1. Is this normal for the customer/section/load to be the most time-consuming transaction?
2. Is Magento doing something with the session that is causing a lock? The Redis session storage solution should've eliminated a php lock because it doesn't use a session lock. (unless magento is doing something weird that I have not accounted for)

Additional Diagnostic Information:

command: cat my.cnf link: my.cnf

command: df -h link: df -h

command: iostat -xm 5 3 link: iostat -xm 5 3

command: ulimit -a link: ulimit -a

command: top link: top

command: show global variables link: show global variables

command: show global status link: show global status

Any advice would be greatly appreciated, also if you need me to add more information or clarification please let me know.

Answer 1

It seems it's a M2.1.x / M2.2.x core issue that keeps clearing the intercepted cache following compilation.

This bug will be fixed on M2.3.1.

Source: https://github.com/magento/magento2/pull/18648

Answer 2

Rate Per Second=RPS - Suggestions to consider for your my.cnf [mysqld] section

read_rnd_buffer_size=512K  # from 16M to reduce handler_read_rnd_next RPS of 16,000+
read_buffer_size=512K  # from 8M to reduce handler_read_next RPS of 96
innodb_io_capacity=1600  # from 200 to use more availble IOPS
thread_cache_size=100  # from 100 to reduce threads_created count of 111692 in 3 days
thread_concurrency=30  # from 10 to use more of your 32 available cores

for additional Suggestions and observations (such as why does TOP show php-fpm for multi hours) get in touch preferably by Skype