Profile some of the CLE report's methods #35830

Charl1996 · 2025-02-24T10:11:50Z

Note: This PR is the second in a series to capture timing information around the CLE processing.

Technical Summary

This ticket makes use of the ESQueryProfilerMixin by adding it to the CaseListMixin and augmenting some methods of the CaseListExplorer to capture timing information around the processing of report rows.

A new decorator, profile, has been created to make it easier (and less verbose) to make use of the profiler for capturing a report method's timing information.

Below is a screenshot of the raw json of what the profiling data looks like (example taken from running on local machine). Pay attention to the nesting and what each nested block reports.

Safety Assurance

Safety story

Tested locally

Automated test coverage

Appended one-liner to test. Don't think much more is really required at this stage.

QA Plan

QA to commence as part of this PR

Rollback instructions

This PR can be reverted after deploy with no further considerations

Labels & Review

Risk label is set correctly
The set of people pinged as reviewers is appropriate for the level of risk of the change

Charl1996 · 2025-02-24T13:06:52Z

@CodeRabbit please review

coderabbitai

Actionable comments posted: 1

🧹 Nitpick comments (2)

corehq/apps/reports/tests/test_case_list_explorer_report.py (2)
87-108: Improve property access and approve test implementation.

The test implementation correctly verifies the profiling functionality. However, there's a minor improvement needed in how the property is accessed.

Apply this diff to improve the property access:
-        cle.json_response
+        _ = cle.json_response
This change explicitly shows that we're intentionally accessing the property for its side effects.

🧰 Tools

🪛 Ruff (0.8.2)

106-106: Found useless expression. Either assign it to a variable or remove it.

(B018)

102-107: Enhance test assertions and fix property access.

The assertions verify the profiler state correctly, but there are a few improvements to consider:

Add descriptive messages to assertions for better test failure diagnostics

Fix the property access on line 106 which is currently not assigned or used

Apply this diff to improve the test:
-        assert cle.profiler_enabled
-        assert cle.profiler.timing_context.to_dict()['percent_total'] is None
+        assert cle.profiler_enabled, "Profiler should be enabled for CaseListExplorer"
+        assert cle.profiler.timing_context.to_dict()['percent_total'] is None, "Initial percent_total should be None"

         # Run the CLE
-        cle.json_response
-        assert cle.profiler.timing_context.to_dict()['percent_total'] == 100.0
+        _ = cle.json_response  # Access the property to trigger profiling
+        assert cle.profiler.timing_context.to_dict()['percent_total'] == 100.0, "Final percent_total should be 100.0"
🧰 Tools

🪛 Ruff (0.8.2)

106-106: Found useless expression. Either assign it to a variable or remove it.

(B018)

📜 Review details

Configuration used: .coderabbit.yaml
Review profile: CHILL
Plan: Pro

📥 Commits

Reviewing files that changed from the base of the PR and between e1fac07 and e680cf0.

📒 Files selected for processing (4)

corehq/apps/reports/standard/__init__.py (3 hunks)
corehq/apps/reports/standard/cases/basic.py (5 hunks)
corehq/apps/reports/standard/cases/case_list_explorer.py (6 hunks)
corehq/apps/reports/tests/test_case_list_explorer_report.py (1 hunks)

🧰 Additional context used

📓 Path-based instructions (1)

`**/*.py`: - Review the code following best practises and st...

**/*.py: - Review the code following best practises and standards

corehq/apps/reports/tests/test_case_list_explorer_report.py
corehq/apps/reports/standard/__init__.py
corehq/apps/reports/standard/cases/basic.py
corehq/apps/reports/standard/cases/case_list_explorer.py

🪛 Ruff (0.8.2)

corehq/apps/reports/tests/test_case_list_explorer_report.py

106-106: Found useless expression. Either assign it to a variable or remove it.

(B018)

🔇 Additional comments (4)

corehq/apps/reports/standard/__init__.py (1)

313-377: Well-implemented profiling decorator with comprehensive documentation!

The implementation is clean and follows best practices:

Proper use of wraps to preserve function metadata

Elegant fallback to nullcontext() for when profiling is disabled

Clear and detailed documentation with usage examples

corehq/apps/reports/standard/cases/case_list_explorer.py (2)

66-67: Profiler configuration looks good!

The profiler is properly configured with appropriate values for profiler_enabled and profiler_name.

127-130: Good separation of concerns for profiling!

Extracting _apply_xpath_case_search_filter into a separate method allows for more granular profiling of the XPath case filter application.

corehq/apps/reports/tests/test_case_list_explorer_report.py (1)

87-101: LGTM! Well-structured test setup.

The test setup follows consistent patterns with other test methods in the class and properly sets up the required test data.

corehq/apps/reports/standard/cases/basic.py

Charl1996 · 2025-02-24T15:10:12Z

@CodeRabbit resolve

corehq/apps/reports/standard/__init__.py

mkangia · 2025-02-27T08:43:26Z

corehq/apps/reports/standard/cases/case_list_explorer.py

-        return self._get_rows(data)
+
+        with self.profiler.timing_context("Retrieving rows"):
+            data = (wrap_case_search_hit(row) for row in self.es_results['hits'].get('hits', []))


you could consider tracking "Fetching results from ES" and "Wrapping result" as two different metrics, just to be very specific about how long ES took.

mkangia · 2025-02-27T08:45:00Z

corehq/apps/reports/standard/cases/case_list_explorer.py

+
+        with self.profiler.timing_context("Retrieving rows"):
+            data = (wrap_case_search_hit(row) for row in self.es_results['hits'].get('hits', []))
+            with self.profiler.timing_context("Parsing rows"):


nit: preparing data for display?

I like that. I'll update.

mkangia · 2025-02-27T08:46:39Z

corehq/apps/reports/standard/__init__.py

@@ -334,3 +336,18 @@ def _get_search_class(self):
        if not self.search_class:
            raise NotImplementedError("You must define a search_class attribute.")
        return self.search_class
+
+
+def profile(name=None):


ooo very nice!

mkangia · 2025-02-27T08:47:25Z

corehq/apps/reports/standard/cases/case_list_explorer.py

-            with self.profiler.timing_context("Parsing rows"):
-                return self._get_rows(data)
+        data = (wrap_case_search_hit(row) for row in self.es_results['hits'].get('hits', []))
+        return self._get_rows(data)


nit: I liked the specific tracking before. There is a lot happening here to put under one metric.

I'll add a screenshot so you can see how the different timings are being reported.

so, the "wrap_case_search_hit" and the time taken by ES to get the data is clubbed into "Retrieving rows" right?

Yes. Feel free to suggest different wording if you think it's necessary.

Feel free to ignore this is this is drilling to deep for metrics.
I was just thinking of

@profile("Retrieving rows") def rows(self): self.track_search() es_hits = self.es_results() data = self._wrap_results(es_hits) return self._get_rows(data) @profile("Fetching Elasticsearch hits") def es_results(self): #... @profile("Wrap Elasticsearch hits") def _wrap_results(es_hits): return [wrap_case_search_hit(row) for row in es_hits] def _get_rows(): #...

mkangia

Looking good.

Can you share a screenshot or two in the description on how this would look?

Charl1996 · 2025-02-27T13:45:43Z

Can you share a screenshot or two in the description on how this would look?

@mkangia See updated description.

Charl1996 · 2025-02-27T14:35:21Z

Now that I'm looking at the timings again more closely I think there's still some room to add more profiling, since the "ES Query" part only makes up about 15% of the "Retrieving rows", which in turn makes up 96% of the total (for that test run). Maybe I'll run it a couple of times more and see if I can capture the other parts.

Charl1996 · 2025-03-03T09:30:10Z

Actually, on a bunch of subsequent runs locally it seem like the execution of the query takes the majority of the time of the "ES query" block, which in turn makes up > 80% of the "Retrieving rows" block, so I think the current profiling "checkpoints" is good enough.

mkangia · 2025-03-04T12:09:57Z

corehq/apps/reports/standard/cases/basic.py

@@ -13,7 +15,7 @@
 from corehq.apps.reports.generic import ElasticProjectInspectionReport
 from corehq.apps.reports.standard import (
    ProjectReport,
-    ProjectReportParametersMixin,
+    ProjectReportParametersMixin, ESQueryProfilerMixin,


nit: isort.

mkangia · 2025-03-04T12:14:26Z

corehq/apps/reports/standard/__init__.py

+        def wrapper(obj, *args, **kwargs):
+            with obj.profiler.timing_context(name) if obj.profiler_enabled else contextlib.nullcontext():
+                result = func(obj, *args, **kwargs)
+            return result


nit: is it simpler with?

if obj.profiler_enabled: with obj.profiler.timing_context(name): return func(obj, *args, **kwargs) else: return func(obj, *args, **kwargs)

mkangia · 2025-03-04T12:16:00Z

corehq/apps/reports/standard/cases/basic.py

@@ -107,7 +109,8 @@ def _build_query(self):
    @memoized
    def es_results(self):
        try:
-            return self._build_query().run().raw
+            with self.profiler.timing_context("ES query") if self.profiler_enabled else contextlib.nullcontext():
+                return self._build_query().run().raw


nit: for sake of code clarity can this be extracted in a method and decorated with profile as well?

mkangia

Looks good to me.

As a follow up, you could consider how the metrics how up on admin restore page. just a better UI experience than a JSON.

Charl1996 requested review from esoergel and removed request for esoergel February 24, 2025 10:11

This comment was marked as resolved.

Sign in to view

coderabbitai bot reviewed Feb 24, 2025

View reviewed changes

corehq/apps/reports/standard/cases/basic.py Show resolved Hide resolved

esoergel reviewed Feb 25, 2025

View reviewed changes

corehq/apps/reports/standard/__init__.py Show resolved Hide resolved

Charl1996 added 5 commits February 26, 2025 13:45

Use ESQueryProfilerMixin on CaseListExplorer

a0aa999

Add timing_context to various parts

92b14d2

Create decorator for profiling

02311af

Update documentation

e478a93

Append test

0ab5c4f

Charl1996 force-pushed the cs/SC-4180-add-profiling-to-cle branch from 9decda0 to 0ab5c4f Compare February 26, 2025 11:48

Charl1996 marked this pull request as ready for review February 26, 2025 12:09

Charl1996 requested review from mkangia, zandre-eng and ajeety4 February 26, 2025 12:10

mkangia reviewed Feb 27, 2025

View reviewed changes

Update name

8451b53

Merge branch 'master' into cs/SC-4180-add-profiling-to-cle

5d5c8d6

zandre-eng approved these changes Mar 4, 2025

View reviewed changes

mkangia reviewed Mar 4, 2025

View reviewed changes

isort

988e047

mkangia reviewed Mar 4, 2025

View reviewed changes

mkangia approved these changes Mar 4, 2025

View reviewed changes

Charl1996 added 3 commits March 4, 2025 14:36

Refactor for better reading

b262916

Add method for decorating @Profile

58576de

Merge branch 'master' into cs/SC-4180-add-profiling-to-cle

c5ef2d1

mkangia approved these changes Mar 4, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Profile some of the CLE report's methods #35830

Profile some of the CLE report's methods #35830

Charl1996 commented Feb 24, 2025 •

edited

Loading

Charl1996 commented Feb 24, 2025

This comment was marked as resolved.

This comment was marked as resolved.

coderabbitai bot left a comment

Charl1996 commented Feb 24, 2025

mkangia Feb 27, 2025

mkangia Feb 27, 2025

Charl1996 Feb 27, 2025

Charl1996 Feb 27, 2025

mkangia Feb 27, 2025

mkangia Feb 27, 2025

Charl1996 Feb 27, 2025

mkangia Mar 4, 2025

Charl1996 Mar 4, 2025

mkangia Mar 4, 2025

mkangia left a comment

Charl1996 commented Feb 27, 2025

Charl1996 commented Feb 27, 2025 •

edited

Loading

Charl1996 commented Mar 3, 2025 •

edited

Loading

mkangia Mar 4, 2025

Charl1996 Mar 4, 2025

mkangia Mar 4, 2025

Charl1996 Mar 4, 2025

mkangia Mar 4, 2025

Charl1996 Mar 4, 2025

mkangia left a comment

Profile some of the CLE report's methods #35830

Are you sure you want to change the base?

Profile some of the CLE report's methods #35830

Conversation

Charl1996 commented Feb 24, 2025 • edited Loading

Technical Summary

Safety Assurance

Safety story

Automated test coverage

QA Plan

Rollback instructions

Labels & Review

Charl1996 commented Feb 24, 2025

This comment was marked as resolved.

This comment was marked as resolved.

coderabbitai bot left a comment

Choose a reason for hiding this comment

Charl1996 commented Feb 24, 2025

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mkangia left a comment

Choose a reason for hiding this comment

Charl1996 commented Feb 27, 2025

Charl1996 commented Feb 27, 2025 • edited Loading

Charl1996 commented Mar 3, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mkangia left a comment

Choose a reason for hiding this comment

Charl1996 commented Feb 24, 2025 •

edited

Loading

Charl1996 commented Feb 27, 2025 •

edited

Loading

Charl1996 commented Mar 3, 2025 •

edited

Loading