feat(search): end-to-end timing instrumentation behind BRAINLAYER_SEARCH_PROFILE flag #325
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,65 @@ | ||
| import Foundation | ||
|
|
||
| enum SearchProfileLogger { | ||
| static var isEnabled: Bool { | ||
| ProcessInfo.processInfo.environment["BRAINLAYER_SEARCH_PROFILE"] == "1" | ||
| } | ||
|
|
||
| static func newQueryID() -> String { | ||
| "q-\(UUID().uuidString.replacingOccurrences(of: "-", with: "").prefix(12))" | ||
| } | ||
|
|
||
| static func now() -> TimeInterval { | ||
| ProcessInfo.processInfo.systemUptime | ||
| } | ||
|
|
||
| static func durationMS(since startedAt: TimeInterval) -> Double { | ||
| ((now() - startedAt) * 1000).rounded(toPlaces: 3) | ||
| } | ||
|
|
||
| static func log( | ||
| scope: String, | ||
| step: String, | ||
| queryID: String?, | ||
| durMS: Double? = nil, | ||
| fields: [String: Any] = [:] | ||
| ) { | ||
| guard isEnabled else { return } | ||
|
|
||
| var event: [String: Any] = [ | ||
| "ts": isoTimestamp(), | ||
| "scope": scope, | ||
| "step": step | ||
| ] | ||
| if let queryID { | ||
| event["query_id"] = queryID | ||
| } | ||
| if let durMS { | ||
| event["dur_ms"] = durMS | ||
| } | ||
| let reservedKeys: Set<String> = ["ts", "scope", "step", "query_id", "dur_ms"] | ||
| for (key, value) in fields where !reservedKeys.contains(key) { | ||
| event[key] = value | ||
| } | ||
|
|
||
| guard JSONSerialization.isValidJSONObject(event), | ||
| let data = try? JSONSerialization.data(withJSONObject: event, options: [.sortedKeys]), | ||
| let line = String(data: data, encoding: .utf8) else { | ||
| return | ||
| } | ||
| NSLog("%@", line) | ||
| } | ||
|
|
||
| private static func isoTimestamp() -> String { | ||
| let formatter = ISO8601DateFormatter() | ||
| formatter.formatOptions = [.withInternetDateTime, .withFractionalSeconds] | ||
| return formatter.string(from: Date()) | ||
| } | ||
| } | ||
|
|
||
| private extension Double { | ||
| func rounded(toPlaces places: Int) -> Double { | ||
| let divisor = pow(10.0, Double(places)) | ||
| return (self * divisor).rounded() / divisor | ||
| } | ||
| } |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,65 @@ | ||
| import Foundation | ||
|
|
||
| enum SearchProfileLogger { | ||
| static var isEnabled: Bool { | ||
| ProcessInfo.processInfo.environment["BRAINLAYER_SEARCH_PROFILE"] == "1" | ||
| } | ||
|
|
||
| static func newQueryID() -> String { | ||
| "q-\(UUID().uuidString.replacingOccurrences(of: "-", with: "").prefix(12))" | ||
| } | ||
|
|
||
| static func now() -> TimeInterval { | ||
| ProcessInfo.processInfo.systemUptime | ||
| } | ||
|
|
||
| static func durationMS(since startedAt: TimeInterval) -> Double { | ||
| ((now() - startedAt) * 1000).rounded(toPlaces: 3) | ||
| } | ||
|
|
||
| static func log( | ||
| scope: String, | ||
| step: String, | ||
| queryID: String?, | ||
| durMS: Double? = nil, | ||
| fields: [String: Any] = [:] | ||
| ) { | ||
| guard isEnabled else { return } | ||
|
|
||
| var event: [String: Any] = [ | ||
| "ts": isoTimestamp(), | ||
| "scope": scope, | ||
| "step": step | ||
| ] | ||
| if let queryID { | ||
| event["query_id"] = queryID | ||
| } | ||
| if let durMS { | ||
| event["dur_ms"] = durMS | ||
| } | ||
| let reservedKeys: Set<String> = ["ts", "scope", "step", "query_id", "dur_ms"] | ||
| for (key, value) in fields where !reservedKeys.contains(key) { | ||
| event[key] = value | ||
| } | ||
|
|
||
| guard JSONSerialization.isValidJSONObject(event), | ||
| let data = try? JSONSerialization.data(withJSONObject: event, options: [.sortedKeys]), | ||
| let line = String(data: data, encoding: .utf8) else { | ||
| return | ||
| } | ||
| NSLog("%@", line) | ||
| } | ||
|
|
||
| private static func isoTimestamp() -> String { | ||
| let formatter = ISO8601DateFormatter() | ||
| formatter.formatOptions = [.withInternetDateTime, .withFractionalSeconds] | ||
| return formatter.string(from: Date()) | ||
| } | ||
| } | ||
|
|
||
| private extension Double { | ||
| func rounded(toPlaces places: Int) -> Double { | ||
| let divisor = pow(10.0, Double(places)) | ||
| return (self * divisor).rounded() / divisor | ||
| } | ||
| } | ||
|
There was a problem hiding this comment. Unused daemon profile loggerLow Severity
  Reviewed by Cursor Bugbot for commit 8c81107. Configure here. |
||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,35 @@ | ||
| # Phase 2.4-G Search Profile Instrumentation Mandate | ||
|
|
||
| Status: instrumentation-only PR. | ||
|
|
||
| Etan reported search latency around 15 seconds after Phase 2.4-F/PR #320 was expected to make warm hybrid search fast. This PR deliberately does not optimize the search path. It adds opt-in timing logs so the next pass can identify the slow segment from data instead of speculation. | ||
|
|
||
| ## Enablement | ||
|
|
||
| Set `BRAINLAYER_SEARCH_PROFILE=1` to emit verbose timing events. With the flag unset, the instrumentation is silent. | ||
|
|
||
| Each event is a single JSON object with: | ||
|
|
||
| - `ts`: UTC ISO timestamp | ||
| - `scope`: `search.brainbar`, `search.helper`, `search.mcp`, or the supplied search scope | ||
| - `step`: measured step name | ||
| - `query_id`: best-effort correlation ID | ||
| - `dur_ms`: duration for completed timed steps, when applicable | ||
| - `error`: exception class for failed timed steps, when applicable | ||
|
|
||
| ## Instrumented Points | ||
|
|
||
| 1. BrainBar command bar keystroke debounce to `submitSearch`: `step=keystroke_submit`. | ||
| 2. BrainBar MCP router dispatch into `handleBrainSearch`: `step=router_dispatch`. | ||
| 3. BrainBar helper RPC start and completion: `step=helper_rpc_start`, `step=helper_rpc_done`. | ||
| 4. Python helper/MCP embedding call: `step=embed`. | ||
| 5. Python hybrid search leg: `step=hybrid_search`. | ||
| 6. Hybrid internals: `step=binary_knn`, `step=float_rerank`, and `step=fts_merge`. | ||
| 7. Helper startup warm state: `step=startup_warm_state`, including `warm_called`, `binary_index_available`, and `binary_knn_mmap_size`. | ||
| 8. BrainBar result rendering completion: `step=render_done`. | ||
|
|
||
| ## Reading Guidance | ||
|
|
||
| Run a real query with the flag enabled and group by `query_id`. Compare `dur_ms` across `embed`, `binary_knn`, `float_rerank`, `fts_merge`, `hybrid_search`, `helper_rpc_done`, and `render_done`. The largest duration is the first candidate for the follow-up performance fix. | ||
|
|
||
| Do not infer a performance fix from this PR alone. Use the captured production log lines first. |
Oops, something went wrong.
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
When
BRAINLAYER_SEARCH_PROFILE=1and the caller omits_profile_query_id, this method generates aprofileQueryIDforhelper_rpc_*logs but sends the originalargumentsunchanged. The Python helper then generates a different ID (HybridSearchHelper._search), so a single request gets split across multiplequery_ids and cannot be reliably correlated end-to-end in profiling logs. This affects any directHybridSearchHelperClient.search(arguments:)caller that doesn’t pre-populate_profile_query_id.Useful? React with 👍 / 👎.