6

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.

enter image description here

enter image description here

enter image description here

enter image description here

7
  • Additional information request. Post on pastebin.com or here. A) complete (not edited) my.cnf or my.ini Text results of: B) SHOW GLOBAL STATUS; after minimum 24 hours UPTIME C) SHOW GLOBAL VARIABLES; D) complete MySQLTuner report AND Optional very helpful information, if available includes - htop OR top OR mytop for most active apps, ulimit -a for a linux/unix list of limits, iostat -xm 5 3 when system is busy for an idea of IOPS by device, df -h for a linux/unix free space list by device, for server tuning analysis. Dec 15, 2018 at 17:24
  • 1
    @WilsonHauck, I do not have mysql tuner installed on the server but I have added links to pastebin for the other requested information. Please let me know if that is sufficient, thanks for the help.
    – Cskip
    Dec 17, 2018 at 15:39
  • 1
    Please run iostat -xm 5 3 from your Linux command prompt and post the results. The result should include cpu/core count, please. Thanks for the other info posted. Analysis is in process. Please view my profile, Network profile, and download FREE Utility Scripts to use in a couple of days. Do you have any SSD devices or all rotating media? Dec 17, 2018 at 18:52
  • 1
    I added the iostat -xm 5 3 command to the post and the server is on a hosted VPC. I will look into those scripts now thanks!
    – Cskip
    Dec 17, 2018 at 20:23
  • 1
    No there is not.
    – Cskip
    Dec 18, 2018 at 1:37

2 Answers 2

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

2
  • Thank you, thats an interesting bug. I had a question, what do you mean when you say compilation? like when the page is loading? What if the page is served from cache, it wouldn't need to be compiled then, correct? Thank you for your comment, I am just trying to understand how this is affecting the site better.
    – Cskip
    Feb 13, 2019 at 15:43
  • Please check code changes for further details: github.com/magento/magento2/pull/18648/files Feb 14, 2019 at 19:34
0

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

10
  • 1
    Thanks for the suggestions! but I'm under the impression that the issue is not a MySQL concern. Mainly because the issue seems to happen on the session file read which wouldn't have any load on the DB because the session files are not stored there. Furthermore if there was a DB issue I would expect that I would have multiple slow routes not just this one. A side note I'm not sure if I mentioned this clearly but everything on this server is running in one box so they are all competing for the same resources. I'm not sure if that changes your suggestion or not.
    – Cskip
    Dec 18, 2018 at 14:43
  • @Cskip When we Skype TALK? When you are reading anything 16,000+ times per SECOND, it is likely a throttle, preventing completion of the request. All the suggestions provided could be SET GLOBAL variable_name=number (512000 would be close enough for the first two suggestions). Dec 18, 2018 at 16:21
  • Please monitor CPU busy prior to each of the SET GLOBAL and have a PAPER TRAIL. Five minutes between each SET GLOBAL, please. In 30 minutes you will be able to decide clearly if any of these changes are positive. Thanks Dec 18, 2018 at 16:24
  • 1
    Thanks for the input I will try those settings tonight/tomorrow and then reach out to you on skype.
    – Cskip
    Dec 18, 2018 at 19:09
  • 1
    I was not able to apply your changes yet because I was waiting until I had access to a more powerful server to test it against before I change the production site (which could take months). Our hosting provider advised us that there was a clock source configuration issue and since it has been fixed I have not seen any issues on the server and the long transaction is limited to 15 seconds. Which is still bad but probably due to something within magento because the base install transaction times are very high for that route.
    – Cskip
    Jan 8, 2019 at 14:42

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.