Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
73 changes: 37 additions & 36 deletions dspace-api/src/main/java/org/dspace/discovery/SolrServiceImpl.java
Original file line number Diff line number Diff line change
Expand Up @@ -781,19 +781,19 @@ public DiscoverResult search(Context context, DiscoverQuery discoveryQuery)
throws SearchServiceException {
long startTime = System.currentTimeMillis();
log.info("SolrServiceImpl.search - Starting search with query: '{}'", discoveryQuery.getQuery());

try {
if (solrSearchCore.getSolr() == null) {
log.warn("SolrServiceImpl.search - Solr core is null, returning empty result");
return new DiscoverResult();
}

DiscoverResult result = retrieveResult(context, discoveryQuery);

long totalTime = System.currentTimeMillis() - startTime;
log.info("SolrServiceImpl.search - Search completed in {} ms, found {} total results",
log.info("SolrServiceImpl.search - Search completed in {} ms, found {} total results",
totalTime, result.getTotalSearchResults());

return result;

} catch (Exception e) {
Expand Down Expand Up @@ -872,8 +872,9 @@ public Item next() {
protected SolrQuery resolveToSolrQuery(Context context, DiscoverQuery discoveryQuery)
throws SearchServiceException {
long methodStart = System.currentTimeMillis();
log.debug("SolrServiceImpl.resolveToSolrQuery - Starting query resolution for: '{}'", discoveryQuery.getQuery());

log.debug("SolrServiceImpl.resolveToSolrQuery - Starting query resolution for: '{}'",
discoveryQuery.getQuery());

SolrQuery solrQuery = new SolrQuery();

String query = "*:*";
Expand Down Expand Up @@ -1009,67 +1010,67 @@ protected SolrQuery resolveToSolrQuery(Context context, DiscoverQuery discoveryQ
}

long methodTime = System.currentTimeMillis() - methodStart;
log.debug("SolrServiceImpl.resolveToSolrQuery - Query resolution completed in {} ms, final query: '{}'",
log.debug("SolrServiceImpl.resolveToSolrQuery - Query resolution completed in {} ms, final query: '{}'",
methodTime, solrQuery.getQuery());

return solrQuery;
}

protected DiscoverResult retrieveResult(Context context, DiscoverQuery query)
throws SQLException, SolrServerException, IOException, SearchServiceException {
long methodStartTime = System.currentTimeMillis();
log.info("SolrServiceImpl.retrieveResult - Starting result retrieval for query: '{}'", query.getQuery());

// we use valid and executeLimit to decide if the solr query need to be re-run if we found some stale objects
boolean valid = false;
int executionCount = 0;
DiscoverResult result = null;

long solrQueryBuildStart = System.currentTimeMillis();
SolrQuery solrQuery = resolveToSolrQuery(context, query);
long solrQueryBuildTime = System.currentTimeMillis() - solrQueryBuildStart;
log.debug("SolrServiceImpl.retrieveResult - SolrQuery build took {} ms", solrQueryBuildTime);

// how many re-run of the query are allowed other than the first run
int maxAttempts = configurationService.getIntProperty("discovery.removestale.attempts", 3);

do {
long attemptStart = System.currentTimeMillis();
executionCount++;
log.debug("SolrServiceImpl.retrieveResult - Starting attempt {} of {}", executionCount, maxAttempts + 1);

result = new DiscoverResult();
// if we found stale objects we can decide to skip execution of the remaining code to improve performance
boolean skipLoadingResponse = false;
// use zombieDocs to collect stale found objects
List<String> zombieDocs = new ArrayList<>();

long solrExecutionStart = System.currentTimeMillis();
QueryResponse solrQueryResponse = solrSearchCore.getSolr().query(solrQuery,
solrSearchCore.REQUEST_METHOD);
long solrExecutionTime = System.currentTimeMillis() - solrExecutionStart;
log.info("SolrServiceImpl.retrieveResult - Solr query execution took {} ms (attempt {}), QTime: {} ms",
solrExecutionTime, executionCount,
log.info("SolrServiceImpl.retrieveResult - Solr query execution took {} ms (attempt {}), QTime: {} ms",
solrExecutionTime, executionCount,
solrQueryResponse != null ? solrQueryResponse.getQTime() : "null");

if (solrQueryResponse != null) {
long resultProcessingStart = System.currentTimeMillis();

result.setSearchTime(solrQueryResponse.getQTime());
result.setStart(query.getStart());
result.setMaxResults(query.getMaxResults());
result.setTotalSearchResults(solrQueryResponse.getResults().getNumFound());
log.debug("SolrServiceImpl.retrieveResult - Processing {} documents from Solr response",
log.debug("SolrServiceImpl.retrieveResult - Processing {} documents from Solr response",
solrQueryResponse.getResults().size());

List<String> searchFields = query.getSearchFields();
int processedDocs = 0;
int staleDocsFound = 0;

for (SolrDocument doc : solrQueryResponse.getResults()) {
long docProcessingStart = System.currentTimeMillis();
processedDocs++;

IndexableObject indexableObject = findIndexableObject(context, doc);

if (indexableObject != null) {
Expand Down Expand Up @@ -1122,17 +1123,17 @@ protected DiscoverResult retrieveResult(Context context, DiscoverQuery query)
}
}
}

long resultProcessingTime = System.currentTimeMillis() - resultProcessingStart;
log.debug("SolrServiceImpl.retrieveResult - Document processing took {} ms, processed {} docs, found {} stale docs",
resultProcessingTime, processedDocs, staleDocsFound);
log.debug("SolrServiceImpl.retrieveResult - Document processing took {} ms, processed {} docs, "
+ "found {} stale docs", resultProcessingTime, processedDocs, staleDocsFound);

//Resolve our facet field values
long facetFieldsStart = System.currentTimeMillis();
resolveFacetFields(context, query, result, skipLoadingResponse, solrQueryResponse);
long facetFieldsTime = System.currentTimeMillis() - facetFieldsStart;
log.debug("SolrServiceImpl.retrieveResult - Facet fields resolution took {} ms", facetFieldsTime);

//Resolve our json facet field values used for metadata browsing
long jsonFacetStart = System.currentTimeMillis();
resolveJsonFacetFields(context, result, solrQueryResponse);
Expand All @@ -1150,15 +1151,15 @@ protected DiscoverResult retrieveResult(Context context, DiscoverQuery query)
solrSearchCore.getSolr().deleteById(zombieDocs);
solrSearchCore.getSolr().commit();
long staleCleanupTime = System.currentTimeMillis() - staleCleanupStart;
log.info("SolrServiceImpl.retrieveResult - Stale cleanup took {} ms for {} docs",
log.info("SolrServiceImpl.retrieveResult - Stale cleanup took {} ms for {} docs",
staleCleanupTime, zombieDocs.size());
} else {
valid = true;
}

long attemptTime = System.currentTimeMillis() - attemptStart;
log.debug("SolrServiceImpl.retrieveResult - Attempt {} completed in {} ms", executionCount, attemptTime);

} while (!valid && executionCount <= maxAttempts);

if (!valid && executionCount == maxAttempts) {
Expand All @@ -1168,11 +1169,11 @@ protected DiscoverResult retrieveResult(Context context, DiscoverQuery query)
log.fatal(message);
throw new RuntimeException(message);
}

long methodTotalTime = System.currentTimeMillis() - methodStartTime;
log.info("SolrServiceImpl.retrieveResult - Total method execution took {} ms over {} attempts",
log.info("SolrServiceImpl.retrieveResult - Total method execution took {} ms over {} attempts",
methodTotalTime, executionCount);

return result;
}

Expand Down Expand Up @@ -1310,21 +1311,21 @@ protected IndexableObject findIndexableObject(Context context, SolrDocument doc)
long startTime = System.currentTimeMillis();
String type = (String) doc.getFirstValue(SearchUtils.RESOURCE_TYPE_FIELD);
String id = (String) doc.getFirstValue(SearchUtils.RESOURCE_ID_FIELD);

final IndexFactory indexableObjectService = indexObjectServiceFactory.
getIndexFactoryByType(type);
Optional<IndexableObject> indexableObject = indexableObjectService.findIndexableObject(context, id);

if (!indexableObject.isPresent()) {
log.warn("Not able to retrieve object RESOURCE_ID:" + id + " - RESOURCE_TYPE_ID:" + type);
}

long findTime = System.currentTimeMillis() - startTime;
if (findTime > 10) { // Only log if it takes more than 10ms
log.debug("SolrServiceImpl.findIndexableObject - Finding object took {} ms for type: {}, id: {}",
log.debug("SolrServiceImpl.findIndexableObject - Finding object took {} ms for type: {}, id: {}",
findTime, type, id);
}

return indexableObject.orElse(null);
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -135,7 +135,7 @@ public FacetResultsRest getFacetObjects(String facetName, String prefix, String
throws SearchServiceException {

long startTime = System.currentTimeMillis();
log.info("getFacetObjects - Start processing facet '{}' with query '{}' and {} search filters",
log.info("getFacetObjects - Start processing facet '{}' with query '{}' and {} search filters",
facetName, query, searchFilters != null ? searchFilters.size() : 0);

Context context = obtainContext();
Expand All @@ -161,7 +161,7 @@ public FacetResultsRest getFacetObjects(String facetName, String prefix, String
log.info("getFacetObjects - Starting Solr search for facet '{}' with built query", facetName);
DiscoverResult searchResult = searchService.search(context, scopeObject, discoverQuery);
long searchTime = System.currentTimeMillis() - searchStart;
log.info("getFacetObjects - Solr search completed in {} ms for facet '{}', found {} results",
log.info("getFacetObjects - Solr search completed in {} ms for facet '{}', found {} results",
searchTime, facetName, searchResult.getTotalSearchResults());

long conversionStart = System.currentTimeMillis();
Expand All @@ -172,7 +172,8 @@ public FacetResultsRest getFacetObjects(String facetName, String prefix, String
log.debug("getFacetObjects - Result conversion took {} ms", conversionTime);

long totalTime = System.currentTimeMillis() - startTime;
log.info("getFacetObjects - Total processing time: {} ms (scope: {}ms, config: {}ms, query: {}ms, search: {}ms, conversion: {}ms)",
log.info("getFacetObjects - Total processing time: {} ms " +
"(scope: {}ms, config: {}ms, query: {}ms, search: {}ms, conversion: {}ms)",
totalTime, scopeResolveTime, configTime, queryBuildTime, searchTime, conversionTime);

return facetResultsRest;
Expand Down
Loading