Coverage for src/asgi_profiler/detectors/n_plus_one.py: 98%

1"""The same statement, over and over, from the same line.""" 

2 

3from __future__ import annotations 

4 

5from collections.abc import Iterator 

6 

7from ..models import Problem, Profile, Query 

8from .settings import Settings 

9from .utils import common_frames, fingerprint, total_span_ms 

10 

11TYPE = "n_plus_one_db" 

12 

13#: Offender lists are stored with the profile and rendered into the page. A 

14#: 500-row N+1 does not need 500 indices to make its point. 

15_MAX_OFFENDERS = 50 

16 

17#: Transaction and session bookkeeping, which is repetitive by nature and 

18#: never an N+1. `SAVEPOINT sa_1` and `SAVEPOINT sa_2` normalise to the same 

19#: statement -- correctly, they *are* the same statement -- so without this 

20#: five nested `begin_nested()` blocks would be reported as a loop issuing 

21#: the same query five times. Which is true, and is not a finding. 

22_BOOKKEEPING = frozenset( 

23 {"BEGIN", "COMMIT", "ROLLBACK", "SAVEPOINT", "RELEASE", "SET", "PRAGMA", "USE"} 

24) 

25 

26 

27def detect(profile: Profile, settings: Settings) -> Iterator[Problem]: 

28 """Repeated identical statements sharing a call site. 

29 

30 `Profile.duplicate_count` already counts repeats, and counting is not the 

31 same as concluding: two identical `SELECT`s are a coincidence, and five 

32 hundred from inside one loop are a bug. Three conditions separate them. 

33 

34 **Enough of them.** `n_plus_one_count` repeats, default five, matching the 

35 threshold Sentry settled on. 

36 

37 **Costing enough.** `n_plus_one_ms` of *non-overlapping* time, default 

38 fifty. The union rather than the sum, so a deliberate `asyncio.gather` 

39 fan-out is not reported as a problem for being fast. 

40 

41 **From one place.** Every execution must share a stack prefix, and the 

42 deepest shared frame is what the problem is named after. This is the test 

43 Sentry cannot make -- its database spans carry no Python stack, so it 

44 falls back to the parent span and reports the query. Here the finding can 

45 name the line, which is the difference between "you have an N+1" and 

46 "line 20 of repository.py is your N+1". 

47 

48 When stacks are off (`capture_stacks=False`) the shared-call-site test is 

49 skipped rather than failed, and the problem is fingerprinted on the route 

50 instead. Less precise, still true. 

51 """ 

52 groups: dict[str, list[int]] = {} 

53 for index, query in enumerate(profile.queries): 

54 if not query.truncated and query.operation not in _BOOKKEEPING: 

55 groups.setdefault(query.sql_hash, []).append(index) 

56 

57 for key, indices in groups.items(): 

58 if len(indices) < settings.n_plus_one_count: 

59 continue 

60 queries = [profile.queries[i] for i in indices] 

61 span_ms = total_span_ms(queries) 

62 if span_ms < settings.n_plus_one_ms: 

63 continue 

64 

65 frame = _call_site(queries) 

66 if settings.stacks and not frame: 

67 # Stacks were being captured and these executions share no 

68 # application frame -- either they came from unrelated places (a 

69 # serialiser and a permission check that happen to ask the same 

70 # question are not a loop) or from inside a library, where there 

71 # is no line of the user's to change. Reporting either would send 

72 # someone looking for a loop that does not exist. 

73 continue 

74 

75 source = _source_query(profile, indices[0], key) 

76 total_ms = sum(q.duration_ms for q in queries) 

77 yield Problem( 

78 type=TYPE, 

79 fingerprint=fingerprint( 

80 TYPE, 

81 profile.group, 

82 frame, 

83 source.sql_hash if source else "", 

84 key, 

85 ), 

86 title=f"N+1 query: {len(indices)} identical statements", 

87 detail=_detail(len(indices), span_ms, total_ms, frame), 

88 evidence={ 

89 "sql": queries[0].sql, 

90 "count": len(indices), 

91 "span_ms": round(span_ms, 3), 

92 "total_ms": round(total_ms, 3), 

93 "avg_ms": round(total_ms / len(queries), 3), 

94 "frame": frame, 

95 "source_sql": source.sql if source else "", 

96 "source_frame": source.stack[-1] if source and source.stack else "", 

97 }, 

98 offenders=indices[:_MAX_OFFENDERS], 

99 time_ms=span_ms, 

100 ) 

101 

102 

103def _call_site(queries: list[Query]) -> str: 

104 """The deepest frame every one of these executions came through. 

105 

106 Empty when they do not all have stacks, or share no frame at all. The 

107 caller decides what that means: with stacks off it is expected, and with 

108 stacks on it is a reason not to report. 

109 """ 

110 stacks = [q.stack for q in queries if q.stack] 

111 if len(stacks) != len(queries): 

112 return "" 

113 shared = common_frames(stacks) 

114 return shared[-1] if shared else "" 

115 

116 

117def _source_query(profile: Profile, first: int, key: str) -> Query | None: 

118 """The last different statement before the repeats began. 

119 

120 Almost always the query that loaded the rows being looped over, which is 

121 the other half of the story: these five hundred statements exist because 

122 that one returned five hundred rows. 

123 """ 

124 for index in range(first - 1, -1, -1): 

125 candidate = profile.queries[index] 

126 if candidate.sql_hash != key: 126 ↛ 124line 126 didn't jump to line 124 because the condition on line 126 was always true

127 return candidate 

128 return None 

129 

130 

131def _detail(count: int, span_ms: float, total_ms: float, frame: str) -> str: 

132 where = f" issued from {frame}" if frame else "" 

133 return ( 

134 f"The same statement ran {count} times{where}, taking {span_ms:.1f} ms " 

135 f"of wall time ({total_ms:.1f} ms summed). Load the relationship in one " 

136 f"query -- `selectinload`/`joinedload` for a read, a bulk insert for a write." 

137 )