Description
Hello,
We have a multi threaded process.
It happens sometimes (not safely reproduceable, but 1 out of 10 tries fails everytime).
We store database schema information within memcached (which keys in a table exists).
We encounter the issue, that if a too fast parallel execution occures, the readout of key: b returns previously stored a (b was not stored yet).
Here are some debug logs where we track down the issue.
2023-12-14 18:48:53.000000 [723402]:: ################## START ####################
2023-12-14 18:48:53.000000 [723402]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), $cache_str: ':x.x.x.x/x:.energymanager_sensor_measured', $cacheId: 'c1272279f5014ed7894b5c379879c568'
2023-12-14 18:48:53.000000 [723402]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), load cache if available
2023-12-14 18:48:53.000000 [723402]:: Library\Cache\Backend\Memcached->load('c1272279f5014ed7894b5c379879c568') = false
2023-12-14 18:48:53.000000 [723402]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), load cache if available, from cache: $metadata: false
2023-12-14 18:48:53.000000 [723402]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), cache missed, new readout.
2023-12-14 18:48:53.000000 [723403]:: ################## START ####################
2023-12-14 18:48:53.000000 [723403]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), $cache_str: ':x.x.x.x/x:.energymanager_sensor_measured', $cacheId: 'c1272279f5014ed7894b5c379879c568'
2023-12-14 18:48:53.000000 [723403]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), load cache if available
2023-12-14 18:48:53.000000 [723402]:: Library\Cache\Backend\Memcached->save('c1272279f5014ed7894b5c379879c568') with 'a:21:{s:9:"sensor_id";a:15:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:29:"energymanager_sensor_measured";', result: true
2023-12-14 18:48:53.000000 [723402]:: Library\Cache\Backend\Memcached->load('c1272279f5014ed7894b5c379879c568') = array (
0 => 'a:21:{s:9:"sensor_id";a:15:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:29:"energymanager_sensor_measured";',
1 => 1702576133,
2 => 3600,
)
2023-12-14 18:48:53.000000 [723402]:: Model_DbTable_Collection_Object->_setupMetadata(), $cache_str: ':x.x.x.x/x:.object', $cacheId: '57621df1f1be7a77a7033f217865bc4a'
2023-12-14 18:48:53.000000 [723402]:: Model_DbTable_Collection_Object->_setupMetadata(), load cache if available
2023-12-14 18:48:53.000000 [723402]:: Library\Cache\Backend\Memcached->load('57621df1f1be7a77a7033f217865bc4a') = array (
0 => 'a:21:{s:9:"sensor_id";a:15:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:29:"energymanager_sensor_measured"',
1 => 1702576133,
2 => 3600,
)
2023-12-14 18:48:53.000000 [723402]:: ################## END ################
2023-12-14 18:48:53.000000 [723403]:: Library\Cache\Backend\Memcached->load('c1272279f5014ed7894b5c379879c568') = false
2023-12-14 18:48:53.000000 [723403]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), load cache if available, from cache: $metadata: false
2023-12-14 18:48:53.000000 [723403]:: Model_EnergyManager_Sensor_Measured_Collection_Abstract->_setupMetadata(), cache missed, new readout.
2023-12-14 18:48:53.000000 [723403]:: Library\Cache\Backend\Memcached->save('c1272279f5014ed7894b5c379879c568') with 'a:21:{s:9:"sensor_id";a:15:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:29:"energymanager_sensor_measured"', result: true
2023-12-14 18:48:53.000000 [723403]:: Library\Cache\Backend\Memcached->load('c1272279f5014ed7894b5c379879c568') = array (
0 => 'a:21:{s:9:"sensor_id";a:15:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:29:"energymanager_sensor_measured";',
1 => 1702576133,
2 => 3600,
)
2023-12-14 18:48:53.000000 [723403]:: Model_DbTable_Collection_Object->_setupMetadata(), $cache_str: ':x.x.x.x/x:.object', $cacheId: '57621df1f1be7a77a7033f217865bc4a'
2023-12-14 18:48:53.000000 [723403]:: Library\Cache\Backend\Memcached->load('57621df1f1be7a77a7033f217865bc4a') = false
2023-12-14 18:48:53.000000 [723403]:: Model_DbTable_Collection_Object->_setupMetadata(), load cache if available, from cache: $metadata: false
2023-12-14 18:48:53.000000 [723403]:: Model_DbTable_Collection_Object->_setupMetadata(), cache missed, new readout.
2023-12-14 18:48:53.000000 [723403]:: Model_DbTable_Collection_Object->_setupMetadata(), $this->_name: 'object', $check_metadata[TABLE_NAME]: 'object'
The second thread is indented for better readable.
the Memcached->save and Memcached->load are calling the direct library methods.
Before each test, i restart the memcached server completely.
As you can see, within the first thread. it tries to readout key c1272279f5014ed7894b5c379879c568 which is correctly: false
It detects that cache missed, and readout the info from the database. before storing the data into memcached, the second thread also tries to readout the same cache key, which also correctly is still false and it also will load and save it.
but after that, the first thread tries to readout key 57621df1f1be7a77a7033f217865bc4a which never got stored, but it returns the data from first stored key c1272279f5014ed7894b5c379879c568, while the second thread returns correctly false, while getting the data for cache key 57621df1f1be7a77a7033f217865bc4a.
I have stripped down the information which get's stored within the memcached, for better readable and security reasons.
We use
ii php8.0-memcached 3.1.5+2.2.0-9+ubuntu20.04.1+deb.sury.org+1 amd64 memcached extension module for PHP, uses libmemcached
and memcached server:
ii memcached 1.5.22-2ubuntu0.2