Skip to main content
1 of 2
davidalger
  • 7.3k
  • 1
  • 30
  • 47

The problem is caused by a lock placed by the PHP session handler. So it's not Magento explicitly locking something and trying to block admin requests, but almost a side-effect per-se of file-based session storage.

A write lock is being placed on the session data file when it is opened by the initial (long-running) request, causing the second request to block until the lock is released when it calls session_start in Mage_Core_Model_Session_Abstract_Varien::start

This is 100% reproducible. I used the same method you did, adding a sleep(30) to the top of Mage_Adminhtml_IndexController::globalSearchAction

Worth noting is that this cannot be reproduced if you are using db session storage. After I found the root cause, I set a sandbox to db session storage and could no longer reproduce the issue. So the db session handlers Magento has seemingly do not use row-level locking to lock session writes. I find this interesting, because it has the potential for session data loss since the application is obviously not accounting for multiple threads writing to the same session. Note for Readers: I would never use db session storage in production to try and solve this, it's only good for overloading your MySql database.

I didn't try reproducing the behavior using memory based session storage systems such as Redis, but my guess is that locking the records in the session store was probably overlooked in these as well.

There are techniques which could be employed to avoid this like using session_write_close to release the lock before you start on a long-running job. But this would also prevent you from writing to the session since you've just closed it. So it's not likely to be readily implemented across the board in Magento, but could potentially be implemented on specific routes/controllers.

My technique for pinning this as the root cause was to enable the Xdebug profiler and exam the "cachegrind" file. Once the second request completed, I loaded the output file (~25 MB log) into MacCallGrind and drilled down into the trace following the path of calls where the inclusive time was 28 seconds or greater. This ultimately led me to the session_start call which took ~28 seconds to run, giving me a great point to research from.

davidalger
  • 7.3k
  • 1
  • 30
  • 47