Log SQL Queries based on execution time threshold

application/src/main/resources/thingsboard.yml

@@ -273,7 +273,8 @@ sql:
     # Specify whether to remove null characters from strValue of attributes and timeseries before insert
     remove_null_chars: "${SQL_REMOVE_NULL_CHARS:true}"
   # Specify whether to log database queries and their parameters generated by entity query repository
-    log_entity_queries: "${SQL_LOG_ENTITY_QUERIES:false}"
+    log_queries: "${SQL_LOG_QUERIES:false}"
+    log_queries_threshold: "${SQL_LOG_QUERIES_THRESHOLD:5000}"
     postgres:
       # Specify partitioning size for timestamp key-value storage. Example: DAYS, MONTHS, YEARS, INDEFINITE.
       ts_key_value_partitioning: "${SQL_POSTGRES_TS_KV_PARTITIONING:MONTHS}"

dao/src/main/java/org/thingsboard/server/dao/sql/query/DefaultAlarmQueryRepository.java

@@ -43,6 +43,7 @@ import org.thingsboard.server.dao.model.ModelConstants;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collection;
+import java.util.Collections;
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.List;
@@ -114,12 +115,12 @@ public class DefaultAlarmQueryRepository implements AlarmQueryRepository {
     protected final NamedParameterJdbcTemplate jdbcTemplate;
     private final TransactionTemplate transactionTemplate;
 
-    @Value("${sql.log_entity_queries:false}")
+    private final DefaultQueryLogComponent queryLog;
-    private boolean logSqlQueries;
 
-    public DefaultAlarmQueryRepository(NamedParameterJdbcTemplate jdbcTemplate, TransactionTemplate transactionTemplate) {
+    public DefaultAlarmQueryRepository(NamedParameterJdbcTemplate jdbcTemplate, TransactionTemplate transactionTemplate, DefaultQueryLogComponent queryLog) {
         this.jdbcTemplate = jdbcTemplate;
         this.transactionTemplate = transactionTemplate;
+        this.queryLog = queryLog;
     }
 
     @Override
@@ -230,8 +231,17 @@ public class DefaultAlarmQueryRepository implements AlarmQueryRepository {
             if (!textSearchQuery.isEmpty()) {
                 mainQuery = String.format("select * from (%s) a WHERE %s", mainQuery, textSearchQuery);
             }
-            String countQuery = mainQuery;
+            String countQuery = String.format("select count(*) from (%s) result", mainQuery);
-            int totalElements = jdbcTemplate.queryForObject(String.format("select count(*) from (%s) result", countQuery), ctx, Integer.class);
+            long queryTs = System.currentTimeMillis();
+            int totalElements;
+            try {
+                totalElements = jdbcTemplate.queryForObject(countQuery, ctx, Integer.class);
+            } finally {
+                queryLog.logQuery(ctx, countQuery, System.currentTimeMillis() - queryTs);
+            }
+            if (totalElements == 0) {
+                return AlarmDataAdapter.createAlarmData(pageLink, Collections.emptyList(), totalElements, orderedEntityIds);
+            }
 
             String dataQuery = mainQuery + sortPart;
 
@@ -239,10 +249,12 @@ public class DefaultAlarmQueryRepository implements AlarmQueryRepository {
             if (pageLink.getPageSize() > 0) {
                 dataQuery = String.format("%s limit %s offset %s", dataQuery, pageLink.getPageSize(), startIndex);
             }
-            List<Map<String, Object>> rows = jdbcTemplate.queryForList(dataQuery, ctx);
+            queryTs = System.currentTimeMillis();
-            if (logSqlQueries) {
+            List<Map<String, Object>> rows;
-                log.info("QUERY: {}", dataQuery);
+            try {
-                Arrays.asList(ctx.getParameterNames()).forEach(param -> log.info("QUERY PARAM: {}->{}", param, ctx.getValue(param)));
+                rows = jdbcTemplate.queryForList(dataQuery, ctx);
+            } finally {
+                queryLog.logQuery(ctx, dataQuery, System.currentTimeMillis() - queryTs);
             }
             return AlarmDataAdapter.createAlarmData(pageLink, rows, totalElements, orderedEntityIds);
         });

dao/src/main/java/org/thingsboard/server/dao/sql/query/DefaultEntityQueryRepository.java

@@ -17,12 +17,8 @@ package org.thingsboard.server.dao.sql.query;
 
 import lombok.extern.slf4j.Slf4j;
 import org.apache.commons.lang3.StringUtils;
-import org.springframework.beans.factory.annotation.Autowired;
-import org.springframework.beans.factory.annotation.Value;
 import org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate;
 import org.springframework.stereotype.Repository;
-import org.springframework.transaction.TransactionStatus;
-import org.springframework.transaction.support.TransactionCallback;
 import org.springframework.transaction.support.TransactionTemplate;
 import org.thingsboard.server.common.data.EntityType;
 import org.thingsboard.server.common.data.id.CustomerId;
@@ -237,13 +233,12 @@ public class DefaultEntityQueryRepository implements EntityQueryRepository {
 
     private final NamedParameterJdbcTemplate jdbcTemplate;
     private final TransactionTemplate transactionTemplate;
+    private final DefaultQueryLogComponent queryLog;
 
-    @Value("${sql.log_entity_queries:false}")
+    public DefaultEntityQueryRepository(NamedParameterJdbcTemplate jdbcTemplate, TransactionTemplate transactionTemplate, DefaultQueryLogComponent queryLog) {
-    private boolean logSqlQueries;
-
-    public DefaultEntityQueryRepository(NamedParameterJdbcTemplate jdbcTemplate, TransactionTemplate transactionTemplate) {
         this.jdbcTemplate = jdbcTemplate;
         this.transactionTemplate = transactionTemplate;
+        this.queryLog = queryLog;
     }
 
     @Override
@@ -254,11 +249,14 @@ public class DefaultEntityQueryRepository implements EntityQueryRepository {
         ctx.append(addEntityTableQuery(ctx, query.getEntityFilter()));
         ctx.append(" e where ");
         ctx.append(buildEntityWhere(ctx, query.getEntityFilter(), Collections.emptyList()));
-        if (logSqlQueries) {
+        return transactionTemplate.execute(status -> {
-            log.info("QUERY: {}", ctx.getQuery());
+            long startTs = System.currentTimeMillis();
-            Arrays.asList(ctx.getParameterNames()).forEach(param -> log.info("QUERY PARAM: {}->{}", param, ctx.getValue(param)));
+            try {
-        }
+                return jdbcTemplate.queryForObject(ctx.getQuery(), ctx, Long.class);
-        return transactionTemplate.execute(status -> jdbcTemplate.queryForObject(ctx.getQuery(), ctx, Long.class));
+            } finally {
+                queryLog.logQuery(ctx, ctx.getQuery(), System.currentTimeMillis() - startTs);
+            }
+        });
     }
 
     @Override
@@ -329,7 +327,14 @@ public class DefaultEntityQueryRepository implements EntityQueryRepository {
                 fromClauseCount = fromClauseData;
             }
             String countQuery = String.format("select count(id) %s", fromClauseCount);
-            int totalElements = jdbcTemplate.queryForObject(countQuery, ctx, Integer.class);
+
+            long startTs = System.currentTimeMillis();
+            int totalElements;
+            try {
+                totalElements = jdbcTemplate.queryForObject(countQuery, ctx, Integer.class);
+            } finally {
+                queryLog.logQuery(ctx, countQuery, System.currentTimeMillis() - startTs);
+            }
 
             if (totalElements == 0) {
                 return new PageData<>();
@@ -354,11 +359,13 @@ public class DefaultEntityQueryRepository implements EntityQueryRepository {
             if (pageLink.getPageSize() > 0) {
                 dataQuery = String.format("%s limit %s offset %s", dataQuery, pageLink.getPageSize(), startIndex);
             }
-            if (logSqlQueries) {
+            startTs = System.currentTimeMillis();
-                log.info("QUERY: {}", dataQuery);
+            List<Map<String, Object>> rows;
-                Arrays.asList(ctx.getParameterNames()).forEach(param -> log.info("QUERY PARAM: {}->{}", param, ctx.getValue(param)));
+            try {
+                rows = jdbcTemplate.queryForList(dataQuery, ctx);
+            } finally {
+                queryLog.logQuery(ctx, countQuery, System.currentTimeMillis() - startTs);
             }
-            List<Map<String, Object>> rows = jdbcTemplate.queryForList(dataQuery, ctx);
             return EntityDataAdapter.createEntityData(pageLink, selectionMapping, rows, totalElements);
         });
     }
@@ -486,7 +493,7 @@ public class DefaultEntityQueryRepository implements EntityQueryRepository {
                 + SELECT_TYPE + ", " + SELECT_NAME + ", " + SELECT_LABEL + ", " +
                 SELECT_FIRST_NAME + ", " + SELECT_LAST_NAME + ", " + SELECT_EMAIL + ", " + SELECT_REGION + ", " +
                 SELECT_TITLE + ", " + SELECT_COUNTRY + ", " + SELECT_STATE + ", " + SELECT_CITY + ", " +
-                SELECT_ADDRESS + ", " + SELECT_ADDRESS_2 + ", " + SELECT_ZIP + ", " + SELECT_PHONE + ", "  + SELECT_ADDITIONAL_INFO +
+                SELECT_ADDRESS + ", " + SELECT_ADDRESS_2 + ", " + SELECT_ZIP + ", " + SELECT_PHONE + ", " + SELECT_ADDITIONAL_INFO +
                 ", entity.entity_type as entity_type";
         String from = getQueryTemplate(entityFilter.getDirection());
         ctx.addUuidParameter("relation_root_id", rootId.getId());

dao/src/main/java/org/thingsboard/server/dao/sql/query/DefaultQueryLogComponent.java

@@ -0,0 +1,40 @@
+/**
+ * Copyright © 2016-2020 The Thingsboard Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.thingsboard.server.dao.sql.query;
+
+import lombok.extern.slf4j.Slf4j;
+import org.springframework.beans.factory.annotation.Value;
+import org.springframework.stereotype.Component;
+
+import java.util.Arrays;
+
+@Component
+@Slf4j
+public class DefaultQueryLogComponent implements QueryLogComponent {
+
+    @Value("${sql.log_queries:false}")
+    private boolean logSqlQueries;
+    @Value("${sql.log_queries_threshold:5000}")
+    private long logQueriesThreshold;
+
+    @Override
+    public void logQuery(QueryContext ctx, String query, long duration) {
+        if (logSqlQueries && duration > logQueriesThreshold) {
+            log.info("QUERY: {} took {}ms", query, duration);
+            Arrays.asList(ctx.getParameterNames()).forEach(param -> log.info("QUERY PARAM: {} -> {}", param, ctx.getValue(param)));
+        }
+    }
+}

dao/src/main/java/org/thingsboard/server/dao/sql/query/QueryLogComponent.java

@@ -0,0 +1,21 @@
+/**
+ * Copyright © 2016-2020 The Thingsboard Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.thingsboard.server.dao.sql.query;
+
+public interface QueryLogComponent {
+
+    void logQuery(QueryContext ctx, String query, long duration);
+}