Issue: test_multiple_writers failing with database is locked on ppc64le arch
Author: vkrizan
State: closed
Created: 2023-04-03 13:34:00

Hello,

The `tests.db_tests.TestThreadSafety.test_multiple_writers` test is failing on ppc64le architecture with:
```
peewee.OperationalError: database is locked
```

```
+ createdb peewee_test
+ psql -c 'CREATE EXTENSION hstore' peewee_test
CREATE EXTENSION
+ /usr/bin/python3 runtests.py
...................................................................................s................ssssssssssssssssssssssssssssssssss...................s..........................sss............................................s.......ss............................s.................s........ssss..................................................................................s..........................................................................ssssss...........................ss..............................................s...................................................................................................................................................s.ss.................ssss............................................ss...............................s..................s...........ss...............................s....ss......s..............s..............................................................ss...............................................................Exception in thread Thread-47 (create_users):
Traceback (most recent call last):
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3236, in execute_sql
Exception in thread Thread-46 (create_users):
Traceback (most recent call last):
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3236, in execute_sql
    cursor.execute(sql, params or ())
    cursor.execute(sql, params or ())
sqlite3.OperationalError: database is locked
During handling of the above exception, another exception occurred:
sqlite3.OperationalError: database is locked
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/lib64/python3.11/threading.py", line 1038, in _bootstrap_inner
Traceback (most recent call last):
  File "/usr/lib64/python3.11/threading.py", line 1038, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.11/threading.py", line 975, in run
    self._target(*self._args, **self._kwargs)
  File "/builddir/build/BUILD/peewee-3.16.0/tests/db_tests.py", line 358, in create_users
    self.run()
  File "/usr/lib64/python3.11/threading.py", line 975, in run
    User.create(username='u%d' % i)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 6537, in create
    self._target(*self._args, **self._kwargs)
  File "/builddir/build/BUILD/peewee-3.16.0/tests/db_tests.py", line 358, in create_users
    User.create(username='u%d' % i)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 6537, in create
    inst.save(force_insert=True)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 6747, in save
    inst.save(force_insert=True)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 6747, in save
    pk = self.insert(**field_dict).execute()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 1962, in inner
    return method(self, database, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 2033, in execute
    return self._execute(database)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 2838, in _execute
    return super(Insert, self)._execute(database)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 2551, in _execute
    pk = self.insert(**field_dict).execute()
    cursor = database.execute(self)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 1962, in inner
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3244, in execute
    return method(self, database, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 2033, in execute
    return self._execute(database)
    return self.execute_sql(sql, params)
           ^^^^^^^^^^^^^^^^^^^^^^^
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3234, in execute_sql
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 2838, in _execute
    with __exception_wrapper__:
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3010, in __exit__
    reraise(new_type, new_type(exc_value, *exc_args), traceback)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 192, in reraise
    return super(Insert, self)._execute(database)
    raise value.with_traceback(tb)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3236, in execute_sql
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 2551, in _execute
    cursor.execute(sql, params or ())
peewee.OperationalError: database is locked
    cursor = database.execute(self)
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3244, in execute
    return self.execute_sql(sql, params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3234, in execute_sql
    with __exception_wrapper__:
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3010, in __exit__
    reraise(new_type, new_type(exc_value, *exc_args), traceback)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 192, in reraise
    raise value.with_traceback(tb)
  File "/builddir/build/BUILD/peewee-3.16.0/peewee.py", line 3236, in execute_sql
    cursor.execute(sql, params or ())
peewee.OperationalError: database is locked
Fssssssss..............................sssssss........sss.......ssssssssssssss.....s........................s..................................
======================================================================
FAIL: test_multiple_writers (tests.db_tests.TestThreadSafety.test_multiple_writers)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/peewee-3.16.0/tests/db_tests.py", line 367, in test_multiple_writers
    self.assertEqual(User.select().count(), self.nrows * self.nthreads)
AssertionError: 20 != 40
```

Full log: https://kojipkgs.fedoraproject.org//work/tasks/6601/99476601/build.log
Failing build: https://koji.fedoraproject.org/koji/taskinfo?taskID=99476601

Thank you.


Thanks for the report. That timing for the tests (500+ seconds) is unreal, for comparison they run in less than 4 seconds on my workstation:

```
Ran 1154 tests in 3.359s
```

So I wonder if you are hitting the sqlite busy timeout on that particular test-case. Is there a particular test that is slowing things down? Even on a small, lightly provisioned VM I'd expect them to run much more quickly than your timing.

You can also try this patch or one like it to see if eliminates the failure:

```diff
diff --git a/tests/db_tests.py b/tests/db_tests.py
index 593abe40..f38d14e0 100644
--- a/tests/db_tests.py
+++ b/tests/db_tests.py
@@ -23,6 +23,7 @@ from .base import TestModel
 from .base import db
 from .base import db_loader
 from .base import get_in_memory_db
+from .base import new_connection
 from .base import requires_models
 from .base import requires_postgresql
 from .base_models import Category
@@ -348,6 +349,8 @@ class TestDatabase(DatabaseTestCase):
 
 
 class TestThreadSafety(ModelTestCase):
+    if IS_SQLITE:
+        database = new_connection(timeout=30)
     nthreads = 4
     nrows = 10
     requires = [User]
```

Here is the full build: https://koji.fedoraproject.org/koji/taskinfo?taskID=99476458

Interestingly other archs are running slow as well:
* x86_64 -- Ran 1147 tests in 16.497s
* aarch64 (ARM64) -- Ran 1147 tests in 11.318s
* s390x (IBM System/390) -- Ran 1147 tests in 22.812s

This runs on build system ([Koji](https://fedoraproject.org/wiki/Koji)). I think build nodes should have enough resources to complete a build.

I can try to apply the suggested fix and do a scratch build. However, the test run seems a bit off based on your comment.

Build of 3.15.4 was slow as well https://koji.fedoraproject.org/koji/buildinfo?buildID=2128823 (16s on x86_64).

Test runs on the order of 10's of seconds is definitely no problem and nothing to worry about, even 100-200s is likely just indicative of a slow machine and/or disk and no real problem.

On my workstation I used the above patch with the timeout set to `0.001` and was able to replicate this type of failure -- so my guess is that the ppc64le arch is just performing terribly on our testcases (for whatever reason). By default we give Sqlite 5s to acquire that lock in the multiple writers tests which is ordinarily orders of magnitude more than necessary (for comparison setting it to `0.01` was still plenty of time and did not replicate the issue).

Do you all maintain any patches for peewee? If so you can try adding the above patch I shared or just marking the test as allowed failure.

Currently there are no patches applied, but we can create any that would be necessary. I'll try that...
Having patches in the upstream (this repository) would be the best option.

Here is the packaging repository https://src.fedoraproject.org/rpms/python-peewee/tree/rawhide (build is defined within an [RPM spec](https://rpm-packaging-guide.github.io/)) 
Here's where test run is defined https://src.fedoraproject.org/rpms/python-peewee/blob/rawhide/f/python-peewee.spec#_90

@vkrizan - try the above commit, https://github.com/coleifer/peewee/commit/027eccff176bf458972900d6a329e05d5b969eb4 and let's see if that addresses the issue.

@coleifer I'll try to apply it as a patch and see (tomorrow). Unfortunately the [build spec follows git version tags](https://src.fedoraproject.org/rpms/python-peewee/blob/rawhide/f/python-peewee.spec#_16) for me to test it quickly (without applying a patch).

If this were a legit issue I'd be more concerned, but this seems to be a confluence of some kind of build environment issues manifesting as a test-only failure, so take heart: all is well.

I've tried the patch and this time 3 tests have failed and it got deadlocked :slightly_frowning_face: .
* 2x tests.pool.TestPooledDatabaseIntegration.test_pool_with_models
* tests.pool.TestPooledDatabaseIntegration.test_pooled_database_integration

```
peewee.OperationalError: database is locked
----------------------------------------------------------------------
Ran 1147 tests in 484.713s
FAILED (errors=3, skipped=112)
Unable to import SQLCipher extension tests, skipping.
```
That was the last log message. It never exited, I had to cancel the build job today.

The version of sqlite is: `sqlite-libs-3.40.1-2.fc38.ppc64le`.
(It succeeded on Fedora in development F39. That one has `sqlite-libs-3.41.2-1.fc39.ppc64le`.)

https://koji.fedoraproject.org/koji/taskinfo?taskID=99517867

On second try it went through -- build succeeded. The behavior seems a bit non-deterministic. 

Id suggest looking into why the performance on ppc64le is so abysmal. I think you mentioned most other architectures finished in 10-15s, so 400-500+ seems unreasonably slow.

3.16.1 released.