Description
Describe the bug
While flamegraphing a test query in OSB on nyc_taxis, I saw a large chunk of time was spent on ProfileScorer.score(). This is strange since "profile":true is not in the query. I also checked the incoming queries using slow logs to confirm OSB wasn't somehow enabling profiling, which it wasn't.
Query:
"bool" : {
"must": {"match" : {"vendor_id" : "1"}},
"filter": {"range" : {"dropoff_datetime" : {"gte": "01/01/2015", "lte": "01/09/2015", "format": "dd/MM/yyyy"}}}
}
I'm unsure if all of this 36% is really just spent on ProfileScorer.score() (presumably starting and stopping the timer?) or if it's also calling another wrapped scorer which the flamegraph isn't picking up. When I ran this again, ProfileScorer was still present but it took 3% instead of 36%, so maybe something like this is happening.
Weirdly the same query with both clauses as must
never showed ProfileScorer in its flamegraph.
I wasn't always able to reproduce this. When I tried using a new tar install with extra logging, the problem stopped happening. I was also unable to attach arthas because of security manager issues.
It's very possible this is somehow due to my setup and not actually happening within OpenSearch, but I'm not sure how and was curious if others had seen this.
Related component
Search
To Reproduce
Use OSB to index nyc_taxis in a single-node tar install domain. I ran mine in EC2. Run the above query through OSB and take a flamegraph.
Expected behavior
ProfileScorer.score() shouldn't be run at all for non profiled queries.
Additional Details
No plugins are used. This is the main branch as of 3/24 (last commit).
From looking at the code ProfileScorer
should only ever be constructed when ContextIndexSearcher
, which uses a new instance for each search, has profiler != null
. This can only happen if the check if (source.profile())
at line 1544 of SearchService.parseSource()
returns true.
Metadata
Metadata
Assignees
Type
Projects
Status