2

I'm confused about how Civi::lockManager is supposed to be used in handling sql-level locks on certain processes.

I'm looking at a few existing code usages (as in Omnipay here and in civicrm core here). These are all using essentially this logic:

Listing 1:

  $lock = Civi::lockManager()->acquire($PROPERLY_FORMATTED_LOCK_NAME);
  if (!$lock->isAcquired()) {
    // This entity is locked, so don't do anything
  }
  else {
    // This entity is not locked, so go ahead and do that thing.
  }

However, my rather naive testing shows that $lock>isAcquired($ANYTHING) will always return TRUE. Consider this simple test script and its output:

Listing 2:

$ cat /tmp/locktest.php
<?php
$lockName = 'data.contribute.contribution.1';

$lock = Civi::lockManager()->acquire($lockName);
echo("lock is acquired:" . $lock->isAcquired()) . "\n";

$lock = Civi::lockManager()->acquire($lockName);
echo("lock is acquired:" . $lock->isAcquired()) . "\n";

$ cv scr /tmp/locktest.php
lock is acquired:1
lock is acquired:1

(From my reading, this seems reasonable, considering that mysql GET_LOCK() (which is always called by acquire()) is designed to allow multiple simultaneous locks of the same name. (Reference mysql docs). I.e., if you ask to acquire a lock of name 'x', mysql will always give it to you. The important step would be using IS_FREE_LOCK() to test whether the lock is actually free.)

Given the output in Listing 2, how is it possible that the code in Listing 1 is actually testing for the pre-existence of a named lock and avoiding repeat action if that lock is in place?

5
  • 2
    So listing 2 is not 'real' because you are doing both within the same process / mysql connection If I open 2 separate mysql sessions & in one put get_lock('bambi', 100) Then I can run that over & over in that session and I will get the lock (result = 1) . In the other session I keep running it and get a result of 0 - because the other session has the lock. One thing I noticed in the code is that the timeout seems to be only 3 seconds - which might be enough but is less than I expected I then run it
    – eileen
    Nov 2 '21 at 19:23
  • 1
    @eileen OK, I see. You're right: if I put a sleep() in there long enough to keep locktest.php running in one terminal, and then run locktest.php in another terminal, that second instance will pause at Civi::lockManager()->acquire() until the first process's lock is released. If you'd like, please make an answer, because I think you've answered it. Else I will at some point.
    – TwoMice
    Nov 2 '21 at 20:11
  • +1 - you need two separate processes to demonstrate the locking. Re:3 seconds -- it's subjective. For background tasks, I could see a longer wait. For foreground tasks, you have a user waiting for feedback. In either case, a long wait may be a code-smell (the critical-section is too heavy).
    – Tim Otten
    Nov 2 '21 at 20:38
  • 1
    Maybe related? github.com/civicrm/civicrm-core/pull/22013
    – Demerit
    Nov 9 '21 at 15:27
  • 1
    @twomice I've observed on a live site using ACLs heavily that the locks DO get allocated multiple times which causes duplicate DB errors on ACL cache rebuild. That would appear to match scenario 2 above and that's what my PR fixes. Nov 9 '21 at 16:44
2

To answer my own question:

Civi::lockManager is expected to be used in a way that will allow one process to acquire a lock (with Civi::lockManager()->acquire()) such that any other process will be made to wait until the first process has released the lock (either explicitly with Civi::lockManager()->release(), or simply by completing script execution and ending the mysql connection).

To demonstrate this, we can run this script in two separate sessions (i.e., two separate cli terminals):

<?php

$connection_id = CRM_Core_DAO::singleValueQuery('SELECT connection_id()');
echo "connection id:                  {$connection_id}\n";

$startTime = time();
echo "Attempting to acquire lock at:  ". date('c', $startTime) . "\n";
$lock = Civi::lockManager()->acquire('data.contribute.contribution.1', 100);

$lockAcquireTime = time();
echo "Lock acquired at:               ". date('c', $lockAcquireTime) . "\n";
echo "Time elapsed waiting for lock:  ". ($lockAcquireTime - $startTime) . " seconds\n";
echo "Lock is acquired:               ". $lock->isAcquired() . "\n";

$timeout = 10;
echo "Sleeping $timeout...\n";
sleep($timeout);
echo "Script ended at:                " . date('c') ."\n";

Run this script in terminal 1 and observe this output:

$ cv scr /tmp/locktest.php
connection id:                  23757
Attempting to acquire lock at:  2021-11-03T10:41:01-05:00
Lock acquired at:               2021-11-03T10:41:01-05:00
Time elapsed waiting for lock:  0 seconds
Lock is acquired:               1
Sleeping 10...
Script ended at:                2021-11-03T10:41:11-05:00

Before that script completes, run it separately in terminal 2, and observe this output:

$ cv scr /tmp/locktest.php 
connection id:                  23759
Attempting to acquire lock at:  2021-11-03T10:41:05-05:00
Lock acquired at:               2021-11-03T10:41:11-05:00
Time elapsed waiting for lock:  6 seconds
Lock is acquired:               1
Sleeping 10...
Script ended at:                2021-11-03T10:41:21-05:00

Specifically, compare the output lines labeled "Time elapsed waiting for lock". In Terminal 1, the lock was acquired instantly. Meanwhile in Terminal 2, execution paused for 6 seconds waiting for Civi::lockManager()->acquire() to acquire the lock. This demonstrates that lock acquisition will wait (up to the timeout value of 100 seconds, as defined in the second parameter to Civi::lockManager()->acquire()) until the named lock is free; it then acquires that named lock, which will cause any other processes to pause similarly when they try to acquire a lock of the same name.

Thanks to @eileen and @Tim Otten for the helpful comments.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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