9

I'm currently facing a slow page load with the checkout being the slowest of all with:

  • 28 requests
  • 18.5 KB transferred (rest cached from disk or memory)
  • Finish: 15.24s (loader disappears and the user can do something)
  • DOMContentLoaded: 6.45s
  • Load: 10.28s

Loading checkout/cart ends with:

  • 29 requests
  • 28.5 KB transferred (rest cached from disk or memory)
  • Finish: 6.35s
  • DOMContentLoaded: 1.9s
  • Load: 3.79s

whilst an empty cart has this:

  • 22 requests
  • 8.2 KB transferred (rest cached from disk or memory)
  • Finish: 2.78s
  • DOMContentLoaded: 1.22s
  • Load: 2.65s

I'm using redis for caching and all caches are active. Javascript is minified, merged and bundled as well as css and html. The server is pretty well situated with 8 CPUs, 16GB RAM and an SSD. Load etc. is never high enough to be even mentioned. Basically the server is sleeping...

There are just ~80 products and one store. We don't use the content part of Magento. Just product detail pages, checkout and customer area (as well as backend) is served by Magento. There is a CMS system "in front" of Magento which serves pages in less than a second total including media.

I see that TTFB for the checkout document is already 5.66s. With the Magento profiler enabled I can find that magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body causes most of that time. Although it is pretty unclear what exactly causes it. Here the profiler can not help much (me at least).

magento->routers_match                                                                                                                                                                                                                                                                                            5.347600 5.347600 1  42,063,304 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index                                                                                                                                                                                                                                                    5.143997 5.143997 1  15,976,176 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body                                                                                                                                                                                                                                       5.143980 5.143980 1  15,975,304 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->EVENT:checkout_allow_guest                                                                                                                                                                                                           0.000609 0.000609 1  82.464     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->EVENT:checkout_allow_guest->OBSERVER:checkout_allow_guest                                                                                                                                                                            0.000592 0.000592 1  80.944     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT                                                                                                                                                                                                                               0.106220 0.035407 3  13,085,544 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_load                                                                                                                                                                                                                  0.000666 0.000666 1  136.56     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_xml                                                                                                                                                                                                          0.005658 0.005658 1  174.632    0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_blocks                                                                                                                                                                                                       0.099472 0.099472 1  12,755,648 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_blocks->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements                                                                                                                       0.099462 0.099462 1  12,902,296 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_blocks->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements->generate_elements                                                                                                    0.091426 0.091426 1  11,885,184 10,485,760
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_blocks->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements->generate_elements->EVENT:core_layout_block_create_after                                                              0.000169 0.000003 51 -16.128    0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_blocks->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements->generate_elements->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements                    0.000609 0.000609 1  52.76      0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->layout_generate_blocks->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements->generate_elements->Magento\Framework\View\Layout::Magento\Framework\View\Layout::generateElements->generate_elements 0.000455 0.000455 1  26.952     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->EVENT:layout_generate_blocks_after                                                                                                                                                                                           0.000297 0.000297 1  16.32      0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->LAYOUT->EVENT:layout_generate_blocks_after->OBSERVER:persistent                                                                                                                                                                      0.000279 0.000279 1  14.776     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->postdispatch                                                                                                                                                                                                                         0.002972 0.002972 1  116.752    0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->postdispatch->EVENT:controller_action_postdispatch                                                                                                                                                                                   0.002913 0.002913 1  110.192    0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->postdispatch->EVENT:controller_action_postdispatch->OBSERVER:customer_visitor                                                                                                                                                        0.002900 0.002900 1  108.656    0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->postdispatch->EVENT:controller_action_postdispatch->OBSERVER:customer_visitor->EVENT:clean_cache_by_tags                                                                                                                             0.001175 0.001175 1  77.784     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->postdispatch->EVENT:controller_action_postdispatch->OBSERVER:customer_visitor->EVENT:clean_cache_by_tags->OBSERVER:invalidate_varnish                                                                                                0.000516 0.000516 1  35.056     0         
magento->routers_match->CONTROLLER_ACTION:checkout_index_index->action_body->postdispatch->EVENT:controller_action_postdispatch->OBSERVER:customer_visitor->EVENT:clean_cache_by_tags->OBSERVER:invalidate_builtin                                                                                                0.000629 0.000629 1  41.08      0

I also enabled the database profiler but no query takes more than 1ms even though there are almost 120 calls. But that adds up to just 120ms then.

I generated an xdebug profile locally and can see that most of time is wasted in autoloading. But I'm not sure if that's "normal". I just wonder why file_exists is called so often. As I was under the impression everything is precompiled and cached. I use composer dump-autoload -o --apcu after compiling di. And of course apc is up and running.

enter image description here

enter image description here

enter image description here

enter image description here

Yet I'm stuck here for now. I don't seem to be able to figure why TTFB is 5 secs already. And even if I solved that there is still 10 more seconds to explain and fix. My main guess currently is that these are some xhr requests in the background blocking. Ie. I see estimate-shipping-methods only starts after an intensly long gap of about 7 seconds at 13 seconds and takes about 647ms. Why does it wait so long to trigger that? Until that finishes the loader animation is displayed making the page seem to "hang".

estimate-shipping-methods "delay"

checkout page load

Any input is highly welcome! I hope for a page load of 2 - 4 secs max. as that's what I started with.

Edit: I fixed the high TTFB. As said I'm using Redis for caching. Also for session caching but it leads to a lockup between two concurring sessions. Actually being the checkout request and the estimate-shipping-request leading to a 5 second timeout. I switched sessions back to normal file mode. Unfortunately this did not fix the long load time at all! My current best guess is that something makes estimate-shipping-methods wait before being called resulting in a blocking of the page. Additionally I tried to defer all JS with no change whatsoever.

Edit2: As @peter-ocallaghan notes the problem with the checkout loading so slow (+10 secs) is actually just a chrome specific problem having the dev-console opened. Checkout/cart does not seem to be affected.

Improve this question
11
  • i dont know much more about it. i have facing this issue when i was calling third party api or plugin. This was occurred when I haven't received any response from it.
    – Mahendra
    Aug 21, 2018 at 7:47
  • I'm currently trying to eliminate all that might interfere. I'm also calling a 3rd party api so I turned that off for a test. No change. So far I couldn't manage to rule out what makes the page load so slow.
    – steros
    Aug 21, 2018 at 7:50
  • I'm going to go out on a limb and guess that if you close the Chrome debugger the time will "magically" drop into (or at least significantly closer to) the 2-4 second load time. During investigations of live M2 sites, I couldn't understand how merchants would accept 15 second load times. I finaly realised that by using the chrome debugger as the timing mechanism, I was inadvertently slowing the request by an order of magnitude.
    – Peter O'Callaghan
    Aug 21, 2018 at 8:02
  • I was just testing this. Most pages take still at least ~4 seconds and cart up to 7 secs. But at least the checkout doesn't load in 15 seconds in all other browsers, more like 5 seconds. Seems this is something with chrome.
    – steros
    Aug 21, 2018 at 8:07
  • I managed to bring down the time some more by using memcached for session cache. As mentioned I used redis but that led to locking so I switched back to files but seems that locks too. So I switched to memcached and now the cart loads in ~2secs on the second load and 5-7sec on the first. It seems estimate-shipping-methods and totals-information are the blocker here. If I just reload the cart without any change, it's that 2 seconds. If I add a product or just change the amount and refresh the cart -> 5-7 secs.
    – steros
    Aug 21, 2018 at 8:36

3 Answers 3

Reset to default
4

It seems my main problem is session concurrency happening for whatever reason. I tried to use session caching with Redis as proposed in the documentation.

'session' =>
array (
  'save' => 'redis',
  'redis' =>
  array (
    'host' => '127.0.0.1',
    'port' => '6379',
    'password' => '',
    'timeout' => '2.5',
    'persistent_identifier' => '',
    'database' => '2',
    'compression_threshold' => '2048',
    'compression_library' => 'gzip',
    'log_level' => '1',
    'max_concurrency' => '6',
    'break_after_frontend' => '5',
    'break_after_adminhtml' => '30',
    'first_lifetime' => '600',
    'bot_first_lifetime' => '60',
    'bot_lifetime' => '7200',
    'disable_locking' => '0',
    'min_lifetime' => '60',
    'max_lifetime' => '2592000'
  )
),

But as I have the session locking problem I think this comes into account:

break_after_frontend

Number of seconds to wait before trying to break the lock for frontend (that is, storefront) session.

Meaning there is always a delay of max. 5 seconds. When I switched to memcached session it got slightly better because the wait was lower. It defaults to these settings:

memcached.sess_lock_wait_min => 1000
memcached.sess_lock_wait_max => 2000
memcached.sess_lock_retries => 5

These are the defaults from some older php-memcached version. The newest version proposes these defaults:

memcached.sess_lock_wait_min => 150
memcached.sess_lock_wait_max => 150
memcached.sess_lock_retries => 200

After reading these two: https://github.com/php-memcached-dev/php-memcached/pull/350 https://github.com/php-memcached-dev/php-memcached/issues/269

I tried with:

ini_set('memcached.sess_lock_wait_min', 150);
ini_set('memcached.sess_lock_wait_max', 150);
ini_set('memcached.sess_lock_retries', ini_get('max_execution_time') * 1000 / 150);

in Magento's index.php and this again speeds up the process. I now get a load of the checkout in roughly 4 seconds. The cart is a bit slower with ~5 secs because of the loading of totals-information. (all first try no browser caching)

I suppose fixing the session locking problem would again speed up the loading times as looking at the profiles reveals there is still a wait for session_start() from 300 to 800 ms for several calls.

Improve this answer
1
  • I am also stuck on this Sateros. I am using varnish with a workaround for https and Redis. Site is slow. Have been looking through newrelic and cannot find the conclusive answer. Is it the Redis issue?
    – Adarsh Khatri
    Feb 25, 2020 at 12:13
1

Possible Optimisations:

Profiler

Improve this answer
0

By using Solar or Memcache or Varnish , you can speed up your magento site.

Improve this answer
2
  • I'm using Redis and memcached. I can't use Varnish as it does not support https and I don't want to use one of the workarounds.
    – steros
    Aug 23, 2018 at 6:41
  • @steros Please view my profile, Network profile for contact info and get in touch with me by Skype for assistance.
    – Wilson Hauck
    Aug 23, 2018 at 12:11

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.