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.

Sign up for GitHub

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

SAI-4635 : Log refCount and core name if refCount of SolrCore is > 1 after SolrDispatchFilter finishes processing #145

Closed
wants to merge 1 commit into from
+13 −0
Closed

SAI-4635 : Log refCount and core name if refCount of SolrCore is > 1 after SolrDispatchFilter finishes processing #145

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 13 additions & 0 deletions solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,7 @@
import org.apache.solr.common.util.SuppressForbidden;
import org.apache.solr.core.CoreContainer;
import org.apache.solr.core.NodeRoles;
import org.apache.solr.core.SolrCore;
import org.apache.solr.handler.api.V2ApiUtils;
import org.apache.solr.logging.MDCLoggingContext;
import org.apache.solr.logging.MDCSnapshot;
Expand Down Expand Up @@ -275,6 +276,18 @@ private void dispatch(
}
} finally {
call.destroy();
SolrCore core = call.getCore();
if (core != null) {
int coreRefCount = core.getOpenCount();
if (coreRefCount > 1) {
if (log.isInfoEnabled())
Copy link
Collaborator

Choose a reason for hiding this comment

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

that will log this message whenever core is serving more than one request? if so it might be huge?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Yes, this could happen but I would assume it's still relative rare that a given core is accessed by multiple requests concurrently?

The log line itself is pretty short, so my hope is that it shouldn't burden the log too much.

Copy link
Collaborator Author

@patsonluk patsonluk Sep 19, 2023 •
edited
Loading

Choose a reason for hiding this comment

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

Also crunched some number from BQ on one hour of log in prod fullstoryapp.stackdriver_logs.vm_solr_20230910_H18.

Total log entries: 126,535,028

To roughly estimate the extra entries caused by this, I looked at the number of "Core request" completion message logged by SolrCore#execute : 22,419,120. Every incoming core request should log that completion message exactly once.

It is true that our log added here (SolrDispatcherFilter, which core is non null) has a larger scope than "Core request" handled by SoreCore#execute, for example our change could be reached for admin request (core status?) that uses a core as well, however, I would consider MOST of the requests on prod comes in the form that triggers SoreCore#execute (query etc).

So in the worst case scenario, if all cores have concurrent requests, then it could add around 20% more log lines. However, I see that highly unlikely. I would be surprised if it adds more than 1m+ entry per hour 😓

log.info(
"Core {} has ref count of {} . It's still used by other logic even if the current servlet request {} finishes",
core.getName(),
coreRefCount,
call.getReq().getServletPath());
}
}
ExecutorUtil.setServerThreadFlag(null);
}
}
Expand Down
Loading