In a Magento 2 project we monitor with Tideways, we noticed a recurring bottleneck at session_start(), especially in the AJAX requests that load customer data.

The issue is that simultaneous requests that use the same session will block each other, causing them to wait for each request to finish and unlock the session. This default behavior prevents race conditions (more on that later), so disabling the locking entirely is not desired. But we should be able to write and close the session early to release the lock, if we know that we do not need to write to the session later in the process.

We published our current solution on Github and plan to extend it over time: integer-net/magento2-session-unblocker.

Below is a detailed description of the way my colleague Willem and I debugged and solved this issue. There also was a discussion on Twitter you may find interesting:

Read the whole thread

It started with this warning in Tideways:

Session Bottleneck Report

Screenshot of Tideways showing bottleneck

Click for text version

Session

This trace has a Session bottleneck with 2.01 s to start a session. This can happen for two reasons:

  1. The contents of the session are very large.
  2. Concurrent requests to the same session id block each other.

When you make concurrent AJAX requests from the browser of a user, each of them will try to acquire a lock to the session data.

PHP prevents concurrent write access to the session data, even if you use non-file based session drivers such as Memcache.

You can unblock the sessions by calling the methodsession_write_close();. This will write the current session data to storage and all changes to the$_SESSION data afterwards are ignored/lost.

So the question arised: is it possible in Magento to close the session early instead of keeping it open for the whole request? What side effects will it have?

Disable locking?

Another possible approach is to disable locking in Redis entirely, and people have reported huge performance gains from it. But this comes at a cost of potential data loss from parallel requests, and may lead to annoying, hard to reproduce bugs. Also, that’s a Redis specific configuration, and the locking issue exists for all kinds of session storages.

Race condition example

  1. Request 1 opens session
  2. Request 2 opens session
  3. Request 1 changes data in session
  4. Request 1 closes session and writes updated data
  5. Request 2 closes session and writes old data

This is a risk we were not willing to take.

I’m going into detail of our analysis now. If you are only interested in our solution, scroll down to The Solution.

Finding out when session is opened

The debugging commenced. We choose the customer/section/load AJAX controller because it was one of the routes that caused most session locking trouble, and we were sure that it only needs to read from the session, never write to it. This controller loads updated customer data (like cart contents for the mini cart) into the browsers localstorage.

So theoretically we should be able to close the session right after opening it. In plain PHP it would look like this:

The first test was to add session_write_close() right at the top of the execute() method of the controller. Due to Magento’s dependency injection strategy, all services, including session should be instantiated at that point, right? Well, no. First, session models are often injected as proxy, so that they are not instantiated before they are actually used. And second, the customer section controller uses a SectionPool class which acts as a factory for different data sources (i.e. it uses the object manager directly).

Watch session access

To understand what is happening, we used file based sessions and the Linux tool inotifywait that watches file system events:

The output looks like this
Setting up watches.
Watches established.
10:22:17 OPEN
10:22:17 ACCESS
10:22:19 MODIFY
10:22:19 CLOSE_WRITE,CLOSE

OPEN tells us that the file has been opened, MODIFY means content has been modified and CLOSE_WRITE,CLOSE indicate that changes have been written and the file is now closed. Because sessions are always opened for writing, it is locked between OPEN and CLOSE_WRITE,CLOSE events.

Now something interesting happened when we opened and closed the session early. Instead of just calling session_start, we instantiated a Magento session class, which implicitly starts the session with the correct name, etc.:

The session was opened again by the same request! It turns out that all the different session classes (customer session, catalog session, message session etc.) start the session if it is not open yet when they are instantiated, even if session data is loaded and present via $_SESSION superglobal.

So what if we explicitly instantiate all the session models at the beginning?

Poor man’s debugger: echo + browser console

The quickest way to find out which sessions are instantiated was to add echo get_class($this), "\n"; in the SessionManager::start() method and repeat the AJAX requests via browser console. Chrome has a nice feature in the Network tab, “Copy as fetch”, which copies a JS fetch() call to the clipboard that can be executed in the console.

For a request that updates all sections, we found:

  • Magento\Framework\Session\Generic
  • Magento\Framework\Message\Session
  • Magento\Customer\Model\Session
  • Magento\Catalog\Model\Session
  • Magento\Framework\Session\Generic

And instantiated all of them before the \session_write_close() call. Still, the session was being reopened, and it was Magento\Framework\Session\Generic again. Why would this class be instantiated twice?

This was tough to find, but in the end we spotted it by “logging” the namespaces of the sessions in the Session\Storage class. The Magento_Review module uses a virtual type for its session:

Virtual Types

For the object manager of Magento, virtual types can be used in the same way as normal types, but Magento\Review\Model\Session is not actually a PHP class, not even generated, so in the code it will always be Magento\Framework\Session\Generic. But it has different default constructor arguments and a separate shared instance (“singleton”).

Magento used the virtual type here because the review session does not have own custom behavior, so a real class was not necessary. The session namespace can be configured by constructor argument of the session storage, which is configured via another virtual type.

A solution in our test was:

Note that this works because the ::class constant does not require the class to exist, it only resolves namespace and alias to a fully qualified class name.

With inotifywait we could now see that the session was opened once and immediatetly closed, not blocking other requests. When adding a \sleep(5) right after \session_write_close(), the effect was obvious: multiple requests could be executed in parallel without blocking. Without closing the session and three requests issued at once, we would see one 5 second request, one 10 second request and one 15 second request.

Turn the hack into a clean solution

Of course, changing the execute() method of a core controller is not an option. The preferred way to add behavior to existing methods are plugins. A “beforeExecute” plugin for the controller could run before the execute method is called. But instead of instantiating the sessions there manually, we declared them as constructor dependencies in the plugin class. This way there are instantiated as soon as the plugin is instantiated, which is as soon as the controller itself is instantiated. Now the earliest time to close the session again is in the constructor of the plugin.

(but an unconventional one)

Here’s the code (with explanatory comments removed)

$genericSession->writeClose() calls \session_write_close(), we use the core method to maintain the extensibility and flexibility of Magento. $additionalSessions is an array of session instances, configured via di.xml. This way, custom modules can add sessions if needed, without touching the code of this base module.

Here’s the di.xml:

It should be noted that we violated several Magento coding standards on purpose:

  • Unused arguments: we only added the sessions as constructor argument to make sure they are instantiated, not to do anything with them
  • Logic in constructor: usually, the constructor should not contain any logic, especially no conditions and no side effects. This is because Magento instantiates a graph of objects quite early, many that may not be actually used. So instantiating should be cheap. But in our case, priority was to close the session at the earliest moment and that’s in the constructor that triggered session instantiation through its dependencies.
  • Empty method: There needs to be an actual plugin method, beforeExecute(), so that the plugin class is instantiated, but there is nothing to do there.
  • Session not as proxy: Since instantiating sessions is costly and this is usually not desired (see “logic in constructor”), it is advised to inject them as proxy. A proxy is a generated class that extends the original one but only instantiates the real class with its dependencies when a method is called upon it. In this case we want the opposite: instantiate all the sessions immediately.

Adding automated tests

I would not be quite myself if I would not think of a way how to automate the testing that we have done earlier manually. Why now, when it seems done, you may ask?

  1. In future Magento releases, new session classes may be introduced that are instantiated during customer section load
  2. We want to repeat the tests for more controllers that may benefit from the same optimization
  3. We want to repeat the tests in projects where extensions and custom modules may instantiate additional session classes

The goal of the tests was to inspect the order of relevant method calls to sessions for a given controller execution, especially when sessions are started. The best choice for this was using high level integration tests: The complete application is in place, but the tests have access to the code (whitebox tests).

So how exactly would we inspect what happens with the sessions? Replacing sessions with mocks was not an option because instantiating them from the test would tamper with the initialization. An idea was to use spies, test doubles that maintain the original behavior but add logging facilities.

The problem is that we don’t know which session classes may exist and need to know all instantiations (or start() calls in the abstract base class). Luckily, Magento provides us with a perfect mechanism for spies, namely plugins. A plugin on the abstract base class could catch all those start() calls.

But this was harder than expected: Apparently it is not possible to dynamically add plugins at runtime, at least without affecting the config cache. PluginList::merge() does not have any effect because plugins from the loaded cache take precedence.

So it had to be a “real” plugin, i.e. configured via di.xml. It would do nothing in production but logging “init” and “setData” calls to any Magento\Framework\Session\StorageInterface instances in tests. Test logic in production is a test smell, but a compromise had to be made.

Additionally, we created spies for Magento\Framework\Session\Generic to log when our call to writeClose() happens, and for Magento\Customer\Controller\Section\Load to log when its execute() method is called. For these, no plugins were needed because the constraints above do not apply. We extended the classes to add logging and configured them as preferences in the test setup:

The method log

Now where do the spies report to? A logger that collects the different types of events we are interested in:

  • logSessionStart()
  • logSessionModify()
  • logControllerAction()
  • logWriteClose()

And provides methods to make assertions on the order of operations:

  • hasSessionStartAfterAction()
  • hasSessionStartBeforeAction()
  • hasSessionWriteCloseBeforeAction
  • hasModifyAfterSessionWriteClose()

The careful reader may notice that we test something that was not part of the manual tests before: if session data is modified after the session has been closed. This should not happen because that data would be lost. By testing it, we make sure that our assumption holds true, that controller data is only read and not written. It will be especially useful to test new candidates.

We were in for a little surprise: Session data was modified in the section load controller! While debugging this, we found that some values were initialized with empty arrays or 0 (e.g. recently viewed products). Of course, this is something we can afford to lose, but how do we tell this to our tests? The solution: initialize the session before (we did this by dispatching an arbitrary controller).

The high level test method for session modifications looks like this:

The Solution

We published the solution as a little extension on Github: integer-net/magento2-session-unblocker.

To install it, run the following in your Magento installation:

composer require integer-net/magento2-session-unblocker
bin/magento setup:upgrade

The result can be observed in a fresh Magento installation with sample data, e.g. when working with the wishlist. There, multiple AJAX calls to the customer section load controller can happen:

Without the session unblocker

With the session unblocker

The second call does not need to wait for the first call to be finished, so it is noticeably faster. With a greater number or more expensive AJAX calls than these, as we had it in our project, the effect was even more visible.

And this is just the beginning. If you want to help adding more optimizations to the extension, feel free to play around with the test suite and other controllers!

Fabian Schmengler

Author: Fabian Schmengler

Fabian Schmengler is Magento developer and trainer at integer_net. His focus lies in backend development, conceptual design and test automation.

Fabian was repeatedly selected as a Magento Master in 2017 and 2018 based on his engagements, active participation on StackExchange and contributions to the Magento 2 core.

More Information · Twitter · GitHub