|
| 1 | +import cProfile |
| 2 | +import time |
| 3 | +from collections import Counter |
| 4 | + |
| 5 | +from django.conf import settings |
| 6 | +from django.db import connection, reset_queries |
| 7 | +from django.test.utils import CaptureQueriesContext |
| 8 | + |
| 9 | +from .utils import clean_sql, extract_tables, fingerprint_sql |
| 10 | + |
| 11 | +SLOW_QUERY_THRESHOLD = 0.04 |
| 12 | +N_PLUS_ONE_THRESHOLD = 3 |
| 13 | + |
| 14 | + |
| 15 | +class PerformanceAuditor: |
| 16 | + """ |
| 17 | + Context manager for comprehensive performance auditing. |
| 18 | +
|
| 19 | + Tracks: |
| 20 | + - Database queries (count, duplicates, N+1 patterns, slow queries, mutations) |
| 21 | + - Execution time (total, Python, database) |
| 22 | + - CPU Profiling |
| 23 | + """ |
| 24 | + |
| 25 | + def __init__(self, enable_profiling=True): |
| 26 | + self.total_time = 0 |
| 27 | + self.db_time = 0 |
| 28 | + self.exact_duplicates = [] |
| 29 | + self.query_map = {} |
| 30 | + self.n_plus_one_suspects = [] |
| 31 | + self.writes_detected = [] |
| 32 | + self.table_counts = Counter() |
| 33 | + self.slow_query_plans = [] |
| 34 | + |
| 35 | + self.profiler = cProfile.Profile() if enable_profiling else None |
| 36 | + |
| 37 | + def __enter__(self): |
| 38 | + # Ensure DEBUG is disabled to mimic a production environment |
| 39 | + self.old_debug = settings.DEBUG |
| 40 | + settings.DEBUG = False |
| 41 | + |
| 42 | + # Reset query count and enable capture |
| 43 | + reset_queries() |
| 44 | + self.queries_ctx = CaptureQueriesContext(connection).__enter__() |
| 45 | + |
| 46 | + self.start_time = time.perf_counter() |
| 47 | + self.start_cpu = time.process_time() |
| 48 | + |
| 49 | + if self.profiler: |
| 50 | + self.profiler.enable() |
| 51 | + |
| 52 | + return self |
| 53 | + |
| 54 | + def __exit__(self, exc_type, exc_value, traceback): |
| 55 | + if self.profiler: |
| 56 | + self.profiler.disable() |
| 57 | + |
| 58 | + # Calculate times |
| 59 | + self.end_time = time.perf_counter() |
| 60 | + self.end_cpu = time.process_time() |
| 61 | + self.total_time = self.end_time - self.start_time |
| 62 | + self.cpu_time = self.end_cpu - self.start_cpu |
| 63 | + |
| 64 | + # Restore DEBUG |
| 65 | + settings.DEBUG = self.old_debug |
| 66 | + |
| 67 | + # Stop query capture |
| 68 | + self.queries_ctx.__exit__(exc_type, exc_value, traceback) |
| 69 | + self.queries = self.queries_ctx.captured_queries |
| 70 | + |
| 71 | + self._analyze_results() |
| 72 | + |
| 73 | + def _analyze_results(self): |
| 74 | + """ |
| 75 | + Process the raw data into more meaningful stats. |
| 76 | + """ |
| 77 | + |
| 78 | + for query in self.queries: |
| 79 | + sql = clean_sql(query["sql"]) |
| 80 | + |
| 81 | + # Calculate DB time (Django stores it as string seconds) |
| 82 | + duration = float(query["time"]) |
| 83 | + self.db_time += duration |
| 84 | + |
| 85 | + # Detect mutations |
| 86 | + if any(x in sql for x in ["INSERT INTO", "UPDATE ", "DELETE FROM"]): |
| 87 | + # Ignore savepoints/transaction management |
| 88 | + if "django_session" not in sql: # ignore session updates |
| 89 | + self.writes_detected.append(sql) |
| 90 | + |
| 91 | + # Extract tables accessed |
| 92 | + tables = extract_tables(sql) |
| 93 | + for table in tables: |
| 94 | + self.table_counts[table] += 1 |
| 95 | + |
| 96 | + # Fingerprint query shape |
| 97 | + fp = fingerprint_sql(sql) |
| 98 | + if fp not in self.query_map: |
| 99 | + self.query_map[fp] = { |
| 100 | + "durations": [], |
| 101 | + "sql": sql, # Capture the First raw SQL with this shape |
| 102 | + } |
| 103 | + self.query_map[fp]["durations"].append(duration) |
| 104 | + |
| 105 | + # Analyze slow queries |
| 106 | + if duration > SLOW_QUERY_THRESHOLD: |
| 107 | + self._run_explain(sql, duration) |
| 108 | + |
| 109 | + # Detect duplicated queries |
| 110 | + raw_sql_counts = Counter([clean_sql(q["sql"]) for q in self.queries]) |
| 111 | + for sql, count in raw_sql_counts.items(): |
| 112 | + if count > 1 and "SAVEPOINT" not in sql: |
| 113 | + self.exact_duplicates.append({"sql": sql, "count": count}) |
| 114 | + |
| 115 | + # Detect N+1 |
| 116 | + # If the same query structure runs > N_PLUS_ONE_THRESHOLD times, flag it |
| 117 | + for fp, data in self.query_map.items(): |
| 118 | + durations = data["durations"] |
| 119 | + count = len(durations) |
| 120 | + if count > N_PLUS_ONE_THRESHOLD: |
| 121 | + self.n_plus_one_suspects.append( |
| 122 | + { |
| 123 | + "fingerprint": fp, |
| 124 | + "sql": data["sql"], |
| 125 | + "count": count, |
| 126 | + "avg_time": sum(durations) / count, |
| 127 | + "total_time": sum(durations), |
| 128 | + } |
| 129 | + ) |
| 130 | + |
| 131 | + def _run_explain(self, sql, duration): |
| 132 | + # We need to be careful not to break the transaction state |
| 133 | + # Usually safe for SELECTs in tests |
| 134 | + try: |
| 135 | + with connection.cursor() as cursor: |
| 136 | + cursor.execute(f"EXPLAIN ANALYZE {sql}") |
| 137 | + plan = cursor.fetchall() |
| 138 | + # Flatten the result into a single string |
| 139 | + plan_text = "\n".join([row[0] for row in plan]) |
| 140 | + |
| 141 | + self.slow_query_plans.append( |
| 142 | + {"sql": sql, "duration": duration, "plan": plan_text} |
| 143 | + ) |
| 144 | + except Exception as e: |
| 145 | + # Don't crash the test if EXPLAIN fails (syntax errors, etc) |
| 146 | + print(f"Could not explain query: {e}") |
| 147 | + |
| 148 | + def get_summary(self): |
| 149 | + """Returns a dictionary summary for the report generator.""" |
| 150 | + |
| 151 | + return { |
| 152 | + "total_duration": self.total_time, |
| 153 | + "cpu_duration": self.cpu_time, |
| 154 | + "db_duration": self.db_time, |
| 155 | + "query_count": len(self.queries), |
| 156 | + "exact_duplicates": self.exact_duplicates, |
| 157 | + "n_plus_one_suspects": self.n_plus_one_suspects, |
| 158 | + "writes_detected": self.writes_detected, |
| 159 | + "table_breakdown": dict( |
| 160 | + self.table_counts.most_common() |
| 161 | + ), # Sorts by most accessed |
| 162 | + "slow_query_plans": self.slow_query_plans, |
| 163 | + } |
0 commit comments