001/*-
002 * #%L
003 * HAPI FHIR JPA Server
004 * %%
005 * Copyright (C) 2014 - 2024 Smile CDR, Inc.
006 * %%
007 * Licensed under the Apache License, Version 2.0 (the "License");
008 * you may not use this file except in compliance with the License.
009 * You may obtain a copy of the License at
010 *
011 *      http://www.apache.org/licenses/LICENSE-2.0
012 *
013 * Unless required by applicable law or agreed to in writing, software
014 * distributed under the License is distributed on an "AS IS" BASIS,
015 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
016 * See the License for the specific language governing permissions and
017 * limitations under the License.
018 * #L%
019 */
020package ca.uhn.fhir.jpa.interceptor;
021
022import ca.uhn.fhir.interceptor.api.Hook;
023import ca.uhn.fhir.interceptor.api.Interceptor;
024import ca.uhn.fhir.interceptor.api.Pointcut;
025import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
026import ca.uhn.fhir.jpa.model.search.StorageProcessingMessage;
027import ca.uhn.fhir.util.LogUtil;
028import org.slf4j.Logger;
029import org.slf4j.LoggerFactory;
030import org.slf4j.event.Level;
031
032/**
033 * Logs details about the executed query
034 */
035@Interceptor()
036public class PerformanceTracingLoggingInterceptor {
037        private static final Logger ourLog = LoggerFactory.getLogger(PerformanceTracingLoggingInterceptor.class);
038        private final Logger myLog;
039        private final Level myLevel;
040
041        /**
042         * Constructor that logs to this class with a level of INFO
043         */
044        public PerformanceTracingLoggingInterceptor() {
045                this(Level.INFO);
046        }
047
048        /**
049         * Constructor that logs with a specific level
050         *
051         * @since 5.5.0
052         */
053        public PerformanceTracingLoggingInterceptor(Level theLevel) {
054                this(ourLog, theLevel);
055        }
056
057        /**
058         * Constructor that logs to a custom logger and level
059         */
060        public PerformanceTracingLoggingInterceptor(Logger theLog, Level theLevel) {
061                myLog = theLog;
062                myLevel = theLevel;
063        }
064
065        @Hook(value = Pointcut.JPA_PERFTRACE_SEARCH_FIRST_RESULT_LOADED)
066        public void searchFirstResultLoaded(SearchRuntimeDetails theOutcome) {
067                log(
068                                "Initial query result returned in {} for query {}",
069                                theOutcome.getQueryStopwatch(),
070                                theOutcome.getSearchUuid());
071        }
072
073        @Hook(value = Pointcut.JPA_PERFTRACE_SEARCH_SELECT_COMPLETE)
074        public void searchSelectComplete(SearchRuntimeDetails theOutcome) {
075                log(
076                                "SqlQuery found {} matches in {} for query {}",
077                                theOutcome.getFoundMatchesCount(),
078                                theOutcome.getQueryStopwatch(),
079                                theOutcome.getSearchUuid());
080        }
081
082        @Hook(value = Pointcut.JPA_PERFTRACE_SEARCH_COMPLETE)
083        public void searchComplete(SearchRuntimeDetails theOutcome) {
084                log(
085                                "SqlQuery {} is complete in {} - Found {} matches",
086                                theOutcome.getSearchUuid(),
087                                theOutcome.getQueryStopwatch(),
088                                theOutcome.getFoundMatchesCount());
089        }
090
091        @Hook(value = Pointcut.JPA_PERFTRACE_SEARCH_PASS_COMPLETE)
092        public void searchPassComplete(SearchRuntimeDetails theOutcome) {
093                log(
094                                "SqlQuery {} pass complete and set to status {} in {} - Found {} matches",
095                                theOutcome.getSearchUuid(),
096                                theOutcome.getSearchStatus(),
097                                theOutcome.getQueryStopwatch(),
098                                theOutcome.getFoundMatchesCount());
099        }
100
101        @Hook(value = Pointcut.JPA_PERFTRACE_SEARCH_FAILED)
102        public void searchFailed(SearchRuntimeDetails theOutcome) {
103                log(
104                                "SqlQuery {} failed in {} - Found {} matches",
105                                theOutcome.getSearchUuid(),
106                                theOutcome.getQueryStopwatch(),
107                                theOutcome.getFoundMatchesCount());
108        }
109
110        @Hook(value = Pointcut.JPA_PERFTRACE_INDEXSEARCH_QUERY_COMPLETE)
111        public void indexSearchQueryComplete(SearchRuntimeDetails theOutcome) {
112                log(
113                                "Index query for {} completed in {} - Found {} matches",
114                                theOutcome.getSearchUuid(),
115                                theOutcome.getQueryStopwatch(),
116                                theOutcome.getFoundIndexMatchesCount());
117        }
118
119        @Hook(value = Pointcut.JPA_PERFTRACE_INFO)
120        public void info(StorageProcessingMessage theMessage) {
121                log("[INFO] " + theMessage);
122        }
123
124        @Hook(value = Pointcut.JPA_PERFTRACE_WARNING)
125        public void warning(StorageProcessingMessage theMessage) {
126                log("[WARNING] " + theMessage);
127        }
128
129        private void log(String theMessage, Object... theArgs) {
130                LogUtil.log(myLog, myLevel, theMessage, theArgs);
131        }
132}