Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve query metrics logging #6814

Closed
wants to merge 1 commit into from
Closed

Improve query metrics logging #6814

wants to merge 1 commit into from

Conversation

zkirksey
Copy link
Collaborator

@zkirksey zkirksey commented Nov 12, 2024

What does this PR do?

Adds a few additional metrics to the existing query metric functionality and defines process for logging these metrics. In order to enable metric logging, the metrics-enabled property must be set to true on the query's request or response properties. In addition, additional metrics can be added to the log statement by adding a map to request or response properties via additional-query-metrics.

Who is reviewing it?

Select relevant component teams:

Ask 2 committers to review/merge the PR and tag them here.

How should this be tested?

Any background context you want to provide?

What are the relevant tickets?

Fixes: #____

Screenshots

Checklist:

  • Documentation Updated
  • Update / Add Threat Dragon models
  • Update / Add Unit Tests
  • Update / Add Integration Tests

Notes on Review Process

Please see Notes on Review Process for further guidance on requirements for merging and abbreviated reviews.

Review Comment Legend:

  • ✏️ (Pencil) This comment is a nitpick or style suggestion, no action required for approval. This comment should provide a suggestion either as an in line code snippet or a gist.
  • ❓ (Question Mark) This comment is to gain a clearer understanding of design or code choices, clarification is required but action may not be necessary for approval.
  • ❗ (Exclamation Mark) This comment is critical and requires clarification or action before approval.

@cxbot
Copy link

cxbot commented Nov 12, 2024

Can one of the admins verify this patch?

@zkirksey zkirksey changed the title Improve query metrics logging [2.26.x] Improve query metrics logging Nov 12, 2024
@@ -233,6 +234,8 @@ public QueryResponse federate(List<Source> sources, QueryRequest queryRequest) {
queryResponse = queryResponseQueue;
LOGGER.debug("returning returnResults: {}", queryResponse);
}
Map<String, Serializable> props = queryResponse.getProperties();
props.put("qm.sort.elapsed", endTime - startTime);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't this just the time it takes to submit a task to the executor service? That is, it's not the time to complete the task. Was that the intent?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The intention is to capture the time that the query takes to sort the results. I suppose a more accurate place for this would be in SortedQueryMonitor. Will make that change

@zkirksey
Copy link
Collaborator Author

build now

@cxddfbot
Copy link

Internal build has been started, your results will be available at build completion.

Comment on lines 276 to 277
Long prevSolrTime = (Long) responseProps.get(SQCMB + "solrquery" + QM_ELAPSED);
prevSolrTime = prevSolrTime == null ? 0 : prevSolrTime;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

❓ What is this for? I don't see anywhere in this code where this gets set previously so wouldn't this always be null/0? The responseProps object is created as a new map earlier in this method and that particular key is not added anywhere else.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, where is solrQueries ever being set such that it wouldn't always be null/0?

@@ -235,6 +236,7 @@ public void run() {
returnProperties.put("hitsPerSource", hitsPerSource);
returnProperties.put(
ORIGINAL_SOURCE_PROPERTIES, (Serializable) Collections.unmodifiableMap(sourceProperties));
returnProperties.put("qm.sort.elapsed", System.nanoTime() - startTime);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Either this key is misleading or it isn't measuring what you think it is measuring. By using the start time when the run method is called and then calculating the elapsed time here, that calculates the total search time for all sources, including sorting/trimming as necessary. The for loop above this is going through all of the sources in the query and waiting for them to be complete so that means their search time is included. Sorting happens each time an individual source completes so there is really no way to capture just the "sort" time unless you are going to do that per source, in which case I would expect the name to be different and also calculated in a different spot.

On the other hand, if this is meant to capture the full timing of the sorted query monitor for retrieving all of the source results, sorting them, and trimming to a page size then this is a fine calculation but as stated earlier, I think the name should be something different because just calling it "sort.elapsed" seems misleading if you don't know what it actually represents.

@cxddfbot
Copy link

Build FAILURE See the job results in legacy Jenkins UI or in Blue Ocean UI.

@alexabird
Copy link
Contributor

image

@zkirksey
Copy link
Collaborator Author

build now

@cxddfbot
Copy link

Internal build has been started, your results will be available at build completion.

@cxddfbot
Copy link

Build FAILURE See the job results in legacy Jenkins UI or in Blue Ocean UI.

@zkirksey
Copy link
Collaborator Author

build now

@cxddfbot
Copy link

Internal build has been started, your results will be available at build completion.

@cxddfbot
Copy link

Build FAILURE See the job results in legacy Jenkins UI or in Blue Ocean UI.

@zkirksey
Copy link
Collaborator Author

build now

@cxddfbot
Copy link

Internal build has been started, your results will be available at build completion.

@cxddfbot
Copy link

Build FAILURE See the job results in legacy Jenkins UI or in Blue Ocean UI.

@zkirksey zkirksey changed the title [2.26.x] Improve query metrics logging Improve query metrics logging Dec 11, 2024
@zkirksey zkirksey changed the base branch from 2.26.x to 2.29.x December 11, 2024 18:01
@zkirksey zkirksey changed the base branch from 2.29.x to 2.26.x December 11, 2024 18:01
Added additional query metrics

Small bug fix

Improved query metrics logging

Adding new timing metrics

Addressing comments

Removed unused metrics

Cleaned up more unused code
@zkirksey zkirksey closed this Dec 11, 2024
@zkirksey
Copy link
Collaborator Author

moved to #6822

@zkirksey zkirksey deleted the improve-logging branch December 11, 2024 22:43
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants