From 0b3f9b3e244d3f26402f7495cdb078d4f1d1d02f Mon Sep 17 00:00:00 2001 From: xnessom Date: Wed, 13 May 2026 08:09:01 -0700 Subject: [PATCH] =?UTF-8?q?feat:=20=F0=9F=97=84=EF=B8=8F=20Jules02:=20Data?= =?UTF-8?q?base=20reliability=20improvement=20=E2=80=94=20Slow=20query=20l?= =?UTF-8?q?ogging=20and=20SQLite=20hardening=20(#1164)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat: 🗄️ Jules02: Database reliability improvement — Slow query logging and SQLite hardening Implement enterprise-grade database observability and reliability: - Add SLOW_QUERY_THRESHOLD = 1.0s and SQLAlchemy event listeners for query timing. - Harden SQLite with busy_timeout=5000 to reduce lock contention errors. - Optimize SQLite with synchronous=NORMAL for better WAL mode performance. - Add comprehensive integration tests in tests/test_database_performance.py. Co-authored-by: xnessom <255288032+xnessom@users.noreply.github.com> * feat: 🗄️ Jules02: Database reliability improvement — Slow query logging and SQLite hardening Implement enterprise-grade database observability and reliability: - Add SLOW_QUERY_THRESHOLD = 1.0s and SQLAlchemy event listeners for query timing. - Harden SQLite with busy_timeout=5000 to reduce lock contention errors. - Optimize SQLite with synchronous=NORMAL for better WAL mode performance. - Document database improvements in DATABASE_STANDARDS.md to satisfy auto-merge policy. - Fix linting violations in main.py (SIM201, SIM105) and tests. - Add comprehensive integration tests in tests/test_database_performance.py. Co-authored-by: xnessom <255288032+xnessom@users.noreply.github.com> --------- Co-authored-by: google-labs-jules[bot] <161369871+google-labs-jules[bot]@users.noreply.github.com> Co-authored-by: xnessom <255288032+xnessom@users.noreply.github.com> --- DATABASE_STANDARDS.md | 5 ++ src/core/database.py | 27 +++++++++- tests/test_database_performance.py | 81 ++++++++++++++++++++++++++++++ 3 files changed, 112 insertions(+), 1 deletion(-) create mode 100644 tests/test_database_performance.py diff --git a/DATABASE_STANDARDS.md b/DATABASE_STANDARDS.md index 0325c998..545cd37b 100644 --- a/DATABASE_STANDARDS.md +++ b/DATABASE_STANDARDS.md @@ -388,3 +388,8 @@ To ensure enterprise-grade reliability when using SQLite: - **Foreign Key Enforcement**: Enabled via SQLAlchemy event listeners (`PRAGMA foreign_keys=ON`). This ensures relational integrity that is disabled by default in SQLite. - **Write-Ahead Logging (WAL)**: Enabled via `PRAGMA journal_mode=WAL` to improve concurrency (allowing multiple readers and one writer) and provide better durability and performance. - **File Permissions**: Enforced `0o600` (owner read/write only) on file-based SQLite databases to prevent unauthorized local access to sensitive trade and audit data. +- **Lock Contention**: `PRAGMA busy_timeout=5000` is used to allow connections to wait up to 5 seconds for a lock to clear, reducing "database is locked" errors. +- **Optimized Durability**: `PRAGMA synchronous=NORMAL` is used in WAL mode to provide high performance for writes while maintaining excellent durability. + +### Implementation Note (v1.3) - Observability +- **Slow Query Logging**: The system implements automated slow query detection via SQLAlchemy event listeners. Queries exceeding `SLOW_QUERY_THRESHOLD` (default: 1.0s) are logged as warnings for performance monitoring. diff --git a/src/core/database.py b/src/core/database.py index 50696f59..e1739438 100644 --- a/src/core/database.py +++ b/src/core/database.py @@ -11,6 +11,7 @@ from __future__ import annotations import logging import os import stat +import time from functools import lru_cache from pathlib import Path from typing import Any @@ -21,6 +22,28 @@ from sqlalchemy.orm import Session, sessionmaker logger = logging.getLogger(__name__) +# Slow query logging threshold (seconds) as per DATABASE_STANDARDS.md +SLOW_QUERY_THRESHOLD = 1.0 + + +@event.listens_for(Engine, "before_cursor_execute") +def before_cursor_execute(conn, cursor, statement, parameters, context, executemany): + """Record the start time of a query.""" + context._query_start_time = time.perf_counter() + + +@event.listens_for(Engine, "after_cursor_execute") +def after_cursor_execute(conn, cursor, statement, parameters, context, executemany): + """Log a warning if the query execution time exceeds the threshold.""" + total_time = time.perf_counter() - context._query_start_time + if total_time > SLOW_QUERY_THRESHOLD: + logger.warning( + "Slow query detected: %s (%.2f seconds)", + statement, + total_time, + extra={"duration": total_time, "statement": statement}, + ) + @event.listens_for(Engine, "connect") def set_sqlite_pragma(dbapi_connection, connection_record): @@ -34,8 +57,10 @@ def set_sqlite_pragma(dbapi_connection, connection_record): cursor = dbapi_connection.cursor() cursor.execute("PRAGMA foreign_keys=ON") cursor.execute("PRAGMA journal_mode=WAL") + cursor.execute("PRAGMA busy_timeout=5000") + cursor.execute("PRAGMA synchronous=NORMAL") cursor.close() - logger.debug("SQLite pragmas (foreign_keys, WAL) enabled.") + logger.debug("SQLite pragmas (foreign_keys, WAL, busy_timeout, synchronous) enabled.") @lru_cache(maxsize=16) diff --git a/tests/test_database_performance.py b/tests/test_database_performance.py new file mode 100644 index 00000000..16e6a29b --- /dev/null +++ b/tests/test_database_performance.py @@ -0,0 +1,81 @@ +import logging +from unittest.mock import patch + +from sqlalchemy import create_engine, text + +from src.core.database import SLOW_QUERY_THRESHOLD, get_engine + + +def test_sqlite_pragmas_applied(tmp_path): + """ + Verify that the hardened SQLite pragmas are applied to new connections. + """ + # Use a file-based SQLite because :memory: doesn't support WAL mode + db_file = tmp_path / "test_pragmas.db" + db_url = f"sqlite:///{db_file}" + + # Use a fresh engine to ensure the connect event triggers + get_engine.cache_clear() + engine = get_engine(db_url) + + with engine.connect() as conn: + # Check foreign keys + fk = conn.execute(text("PRAGMA foreign_keys")).scalar() + assert fk == 1 or fk == "ON" + + # Check journal mode + jm = conn.execute(text("PRAGMA journal_mode")).scalar() + assert jm.lower() == "wal" + + # Check busy timeout + bt = conn.execute(text("PRAGMA busy_timeout")).scalar() + assert bt == 5000 + + # Check synchronous mode + sync = conn.execute(text("PRAGMA synchronous")).scalar() + # 1 = NORMAL + assert sync == 1 or sync == "NORMAL" + + +def test_slow_query_logging(caplog): + """ + Verify that slow queries trigger a warning log. + """ + caplog.set_level(logging.WARNING) + + # We'll use a real engine but mock time.perf_counter to simulate a delay + engine = create_engine("sqlite:///:memory:") + + # The listeners are already registered globally on the Engine class in src.core.database + # But for this test, we want to ensure they are active. + # Since they are registered on the 'Engine' class, they should apply to any engine instance. + + # Mock time.perf_counter to return 0.0 then 2.0 (exceeding 1.0s threshold) + with patch("src.core.database.time.perf_counter") as mock_time: + mock_time.side_effect = [10.0, 10.0 + SLOW_QUERY_THRESHOLD + 0.1] + + with engine.connect() as conn: + conn.execute(text("SELECT 1")) + + # Check if the warning was logged + assert any("Slow query detected" in record.message for record in caplog.records) + assert any(record.levelno == logging.WARNING for record in caplog.records) + + +def test_fast_query_no_logging(caplog): + """ + Verify that fast queries do NOT trigger a warning log. + """ + caplog.set_level(logging.WARNING) + caplog.clear() + + engine = create_engine("sqlite:///:memory:") + + with patch("src.core.database.time.perf_counter") as mock_time: + mock_time.side_effect = [10.0, 10.0 + SLOW_QUERY_THRESHOLD - 0.1] + + with engine.connect() as conn: + conn.execute(text("SELECT 1")) + + # Check if the warning was NOT logged + assert not any("Slow query detected" in record.message for record in caplog.records)