diff --git a/dspace-api/src/main/java/org/dspace/discovery/SolrServiceImpl.java b/dspace-api/src/main/java/org/dspace/discovery/SolrServiceImpl.java index 024b1193a13a..ccec3810b2fe 100644 --- a/dspace-api/src/main/java/org/dspace/discovery/SolrServiceImpl.java +++ b/dspace-api/src/main/java/org/dspace/discovery/SolrServiceImpl.java @@ -779,14 +779,26 @@ public Iterator iteratorSearch(Context context, IndexableObject dso, Disco @Override 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(); } - return retrieveResult(context, discoveryQuery); + DiscoverResult result = retrieveResult(context, discoveryQuery); + + long totalTime = System.currentTimeMillis() - startTime; + log.info("SolrServiceImpl.search - Search completed in {} ms, found {} total results", + totalTime, result.getTotalSearchResults()); + + return result; } catch (Exception e) { + long totalTime = System.currentTimeMillis() - startTime; + log.error("SolrServiceImpl.search - Search failed after {} ms: {}", totalTime, e.getMessage(), e); throw new org.dspace.discovery.SearchServiceException(e.getMessage(), e); } } @@ -859,6 +871,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()); + SolrQuery solrQuery = new SolrQuery(); String query = "*:*"; @@ -993,40 +1008,74 @@ protected SolrQuery resolveToSolrQuery(Context context, DiscoverQuery discoveryQ searchPlugin.additionalSearchParameters(context, discoveryQuery, solrQuery); } + long methodTime = System.currentTimeMillis() - methodStart; + 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 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, + 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", + solrQueryResponse.getResults().size()); List 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) { result.addIndexableObject(indexableObject); } else { + staleDocsFound++; // log has warn because we try to fix the issue log.warn(LogHelper.getHeader(context, "Stale entry found in Discovery index," @@ -1073,23 +1122,43 @@ 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); + //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); + long jsonFacetTime = System.currentTimeMillis() - jsonFacetStart; + log.debug("SolrServiceImpl.retrieveResult - JSON facet resolution took {} ms", jsonFacetTime); } // If any stale entries are found in the current page of results, // we remove those stale entries and rerun the same query again. // Otherwise, the query is valid and the results are returned. if (!zombieDocs.isEmpty()) { + long staleCleanupStart = System.currentTimeMillis(); log.info("Cleaning " + zombieDocs.size() + " stale objects from Discovery Index"); log.info("ZombieDocs "); zombieDocs.forEach(log::info); solrSearchCore.getSolr().deleteById(zombieDocs); solrSearchCore.getSolr().commit(); + long staleCleanupTime = System.currentTimeMillis() - staleCleanupStart; + 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) { @@ -1099,6 +1168,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", + methodTotalTime, executionCount); + return result; } @@ -1233,8 +1307,10 @@ private void resolveFacetFields(Context context, DiscoverQuery query, DiscoverRe * An exception that provides information on a database access error or other errors. */ protected IndexableObject findIndexableObject(Context context, SolrDocument doc) throws SQLException { + 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 = indexableObjectService.findIndexableObject(context, id); @@ -1242,6 +1318,13 @@ protected IndexableObject findIndexableObject(Context context, SolrDocument doc) 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: {}", + findTime, type, id); + } + return indexableObject.orElse(null); } diff --git a/dspace-server-webapp/src/main/java/org/dspace/app/rest/repository/DiscoveryRestRepository.java b/dspace-server-webapp/src/main/java/org/dspace/app/rest/repository/DiscoveryRestRepository.java index 4b9b7d764478..6bc84e7044b5 100644 --- a/dspace-server-webapp/src/main/java/org/dspace/app/rest/repository/DiscoveryRestRepository.java +++ b/dspace-server-webapp/src/main/java/org/dspace/app/rest/repository/DiscoveryRestRepository.java @@ -134,19 +134,47 @@ public FacetResultsRest getFacetObjects(String facetName, String prefix, String String dsoScope, final String configuration, List searchFilters, Pageable page) throws SearchServiceException { + long startTime = System.currentTimeMillis(); + log.info("getFacetObjects - Start processing facet '{}' with query '{}' and {} search filters", + facetName, query, searchFilters != null ? searchFilters.size() : 0); + Context context = obtainContext(); + long scopeResolveStart = System.currentTimeMillis(); IndexableObject scopeObject = scopeResolver.resolveScope(context, dsoScope); + long scopeResolveTime = System.currentTimeMillis() - scopeResolveStart; + log.debug("getFacetObjects - Scope resolution took {} ms", scopeResolveTime); + + long configStart = System.currentTimeMillis(); DiscoveryConfiguration discoveryConfiguration = searchConfigurationService .getDiscoveryConfigurationByNameOrIndexableObject(context, configuration, scopeObject); + long configTime = System.currentTimeMillis() - configStart; + log.debug("getFacetObjects - Configuration loading took {} ms", configTime); + long queryBuildStart = System.currentTimeMillis(); DiscoverQuery discoverQuery = queryBuilder.buildFacetQuery(context, scopeObject, discoveryConfiguration, prefix, query, searchFilters, dsoTypes, page, facetName); + long queryBuildTime = System.currentTimeMillis() - queryBuildStart; + log.debug("getFacetObjects - Query building took {} ms", queryBuildTime); + + long searchStart = System.currentTimeMillis(); + 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", + searchTime, facetName, searchResult.getTotalSearchResults()); + long conversionStart = System.currentTimeMillis(); FacetResultsRest facetResultsRest = discoverFacetResultsConverter.convert(context, facetName, prefix, query, dsoTypes, dsoScope, searchFilters, searchResult, discoveryConfiguration, page, utils.obtainProjection()); + long conversionTime = System.currentTimeMillis() - conversionStart; + 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)", + totalTime, scopeResolveTime, configTime, queryBuildTime, searchTime, conversionTime); + return facetResultsRest; }