[Webservice] Fix database lock timeouts

Description

We have been seeing errors in the webservice where it tries to write to the database and times out on a lock. I found 12 instances in the log, with tracebacks pointing to 3 different INSERT statements.

Traceback (most recent call last):                                                                                                                                                                        
  File "/home/xcal/deployments/development/git.xfel.eu/detectors/pycalibration/pycalibration-2023-03-22-3.9.2-9e88f31/webservice/webservice.py", line 1034, in _continue
    ret, _ = await self.launch_jobs(                                                                                                                                                                      
  File "/home/xcal/deployments/development/git.xfel.eu/detectors/pycalibration/pycalibration-2023-03-22-3.9.2-9e88f31/webservice/webservice.py", line 1397, in launch_jobs
    cur = self.job_db.execute(                                                                                                                                                                            
sqlite3.OperationalError: database is locked

This indicates that something running concurrently with the webservice is keeping the database locked (i.e. holding a transaction open) for several seconds. The jobs monitor and the web overview (http://max-exfl016.desy.de:8008/) are the only other things that routinely access this database.

I think I've found the culprit in the job monitor code. When updating job statuses, it was issuing SQL updates in a loop which also runs sacct to get job statuses, and then committing (finishing the transaction) outside the loop. If a lot of jobs had finished since the last update, or sacct was slow for some reason, this would mean the database was locked until it finished. I've addressed this by batching the updates needed and writing to the database outside the loop.

I also added some timing code wherever we write to the database, so we can see if it's taking longer than expected.

How Has This Been Tested?

TBD

Types of changes

• Bug fix (non-breaking change which fixes an issue)

Checklist:

• My code follows the code style of this project.

Reviewers

@ahmedk @schmidtp

changed the description

This bit is the fix (I hope) - add the updates to a list, and then make the database changes in one go.

Nice find and fix, LGTM.

Just for my understanding, the exception appears when a timeout is reached while waiting for the lock?

Yup. Read operations need to get a shared lock, and write operations need an exclusive lock. It will wait for 5 seconds (this is a parameter when you open the database) for the lock, and if it takes longer than that, you get this OperationalError.

So we should aim to make database operations, especially writes, as 'point like' as possible. In this example, we could also commit after each update command, to make N very small transactions. This has some upsides, but it's inefficient, because commit is meant to wait until data is fully flushed to disk.

added 1 commit

• fe775397 - Remove unused cursor call

Compare with previous version

Thank you @kluyvert that is a smart way to fix it. I would also suggest adding docstring to the new class.

Besides that, LGTM

added 1 commit

• 59494930 - Add docstring for time_db_transaction

Compare with previous version

Tested on max-exfl017; I see log messages like these:

# Webservice
2023-04-17 15:37:49,774 - root - DEBUG - [webservice.py:330] DB change (Insert execution): 1.5 ms in transaction, 4.1 ms commit
2023-04-17 15:46:58,817 - root - DEBUG - [webservice.py:330] DB change (Insert jobs): 1.0 ms in transaction, 5.3 ms commit

# Job monitor
2023-04-17 15:55:13,280 - root - DEBUG - [webservice.py:330] DB change (Update jobs): 0.8 ms in transaction, 3.6 ms commit
2023-04-17 15:55:13,284 - root - DEBUG - [webservice.py:330] DB change (Update execution): 0.3 ms in transaction, 3.8 ms commit

Calling .commit() to finish the transaction seems to take longer than executing the SQL to insert/update rows. I think this makes sense - commit should flush the changes to disk, which will take time.

If the 'in transaction' time was larger, that might indicate that it's waiting for the lock to modify the database. If the 'commit' time was much longer, that might mean GPFS hiccuped as we were trying to write.

merged

mentioned in commit 9d3bde27

changed milestone to %3.10.0