PHOENIX-2715 Query Log (Ankit Singhal)
[phoenix.git] / phoenix-core / src / it / java / org / apache / phoenix / end2end / QueryLoggerIT.java
1 /*
2 * Licensed to the Apache Software Foundation (ASF) under one
3 * or more contributor license agreements. See the NOTICE file
4 * distributed with this work for additional information
5 * regarding copyright ownership. The ASF licenses this file
6 * to you under the Apache License, Version 2.0 (the
7 * "License"); you may not use this file except in compliance
8 * with the License. You may obtain a copy of the License at
9 *
10 * http://www.apache.org/licenses/LICENSE-2.0
11 *
12 * Unless required by applicable law or agreed to in writing, software
13 * distributed under the License is distributed on an "AS IS" BASIS,
14 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15 * See the License for the specific language governing permissions and
16 * limitations under the License.
17 */
18 package org.apache.phoenix.end2end;
19
20 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.BIND_PARAMETERS;
21 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.CLIENT_IP;
22 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.EXCEPTION_TRACE;
23 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.EXPLAIN_PLAN;
24 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.GLOBAL_SCAN_DETAILS;
25 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.NO_OF_RESULTS_ITERATED;
26 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.QUERY;
27 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.QUERY_ID;
28 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.QUERY_STATUS;
29 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.SCAN_METRICS_JSON;
30 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.START_TIME;
31 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.SYSTEM_CATALOG_SCHEMA;
32 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.SYSTEM_LOG_TABLE;
33 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.TENANT_ID;
34 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.TOTAL_EXECUTION_TIME;
35 import static org.apache.phoenix.jdbc.PhoenixDatabaseMetaData.USER;
36 import static org.junit.Assert.assertEquals;
37 import static org.junit.Assert.assertFalse;
38 import static org.junit.Assert.assertTrue;
39 import static org.junit.Assert.fail;
40
41 import java.net.InetAddress;
42 import java.sql.Connection;
43 import java.sql.DriverManager;
44 import java.sql.PreparedStatement;
45 import java.sql.ResultSet;
46 import java.sql.SQLException;
47 import java.util.Map;
48 import java.util.Properties;
49
50 import org.apache.phoenix.compile.StatementContext;
51 import org.apache.phoenix.exception.SQLExceptionCode;
52 import org.apache.phoenix.jdbc.PhoenixConnection;
53 import org.apache.phoenix.jdbc.PhoenixDriver;
54 import org.apache.phoenix.jdbc.PhoenixResultSet;
55 import org.apache.phoenix.log.LogLevel;
56 import org.apache.phoenix.log.QueryLogState;
57 import org.apache.phoenix.query.QueryServices;
58 import org.apache.phoenix.util.QueryUtil;
59 import org.apache.phoenix.util.ReadOnlyProps;
60 import org.junit.BeforeClass;
61 import org.junit.Test;
62
63 import com.google.common.collect.Maps;
64
65 public class QueryLoggerIT extends BaseUniqueNamesOwnClusterIT {
66
67
68 @BeforeClass
69 public static void doSetup() throws Exception {
70 Map<String, String> props = Maps.newHashMapWithExpectedSize(1);
71 // Enable request metric collection at the driver level
72 props.put(QueryServices.COLLECT_REQUEST_LEVEL_METRICS, String.valueOf(true));
73 // disable renewing leases as this will force spooling to happen.
74 props.put(QueryServices.RENEW_LEASE_ENABLED, String.valueOf(false));
75 setUpTestDriver(new ReadOnlyProps(props.entrySet().iterator()));
76 // need the non-test driver for some tests that check number of hconnections, etc.
77 DriverManager.registerDriver(PhoenixDriver.INSTANCE);
78 }
79
80
81 @Test
82 public void testDebugLogs() throws Exception {
83 String tableName = generateUniqueName();
84 createTableAndInsertValues(tableName, true);
85 Properties props= new Properties();
86 props.setProperty(QueryServices.LOG_LEVEL, LogLevel.DEBUG.name());
87 Connection conn = DriverManager.getConnection(getUrl(),props);
88 assertEquals(conn.unwrap(PhoenixConnection.class).getLogLevel(),LogLevel.DEBUG);
89 String query = "SELECT * FROM " + tableName;
90 ResultSet rs = conn.createStatement().executeQuery(query);
91 StatementContext context = ((PhoenixResultSet)rs).getContext();
92 String queryId = context.getQueryLogger().getQueryId();
93 while (rs.next()) {
94 rs.getString(1);
95 rs.getString(2);
96 }
97 ResultSet explainRS = conn.createStatement().executeQuery("Explain " + query);
98
99 String logQuery = "SELECT * FROM " + SYSTEM_CATALOG_SCHEMA + ".\"" + SYSTEM_LOG_TABLE + "\"";
100 rs = conn.createStatement().executeQuery(logQuery);
101 boolean foundQueryLog = false;
102 int delay = 5000;
103
104 // sleep for sometime to let query log committed
105 Thread.sleep(delay);
106 while (rs.next()) {
107 if (rs.getString(QUERY_ID).equals(queryId)) {
108 foundQueryLog = true;
109 assertEquals(rs.getString(BIND_PARAMETERS), null);
110 assertEquals(rs.getString(USER), System.getProperty("user.name"));
111 assertEquals(rs.getString(CLIENT_IP), InetAddress.getLocalHost().getHostAddress());
112 assertEquals(rs.getString(EXPLAIN_PLAN), QueryUtil.getExplainPlan(explainRS));
113 assertEquals(rs.getString(GLOBAL_SCAN_DETAILS), context.getScan().toJSON());
114 assertEquals(rs.getLong(NO_OF_RESULTS_ITERATED), 10);
115 assertEquals(rs.getString(QUERY), query);
116 assertEquals(rs.getString(QUERY_STATUS), QueryLogState.COMPLETED.toString());
117 assertTrue(System.currentTimeMillis() - rs.getTimestamp(START_TIME).getTime() > delay);
118 assertEquals(rs.getString(TENANT_ID), null);
119 assertTrue(rs.getString(TOTAL_EXECUTION_TIME) != null);
120 assertTrue(rs.getString(SCAN_METRICS_JSON).contains("scanMetrics"));
121 assertEquals(rs.getString(EXCEPTION_TRACE),null);
122 }else{
123 //confirm we are not logging system queries
124 assertFalse(rs.getString(QUERY).toString().contains(SYSTEM_CATALOG_SCHEMA));
125 }
126 }
127 assertTrue(foundQueryLog);
128 conn.close();
129 }
130
131 @Test
132 public void testLogSampling() throws Exception {
133 String tableName = generateUniqueName();
134 createTableAndInsertValues(tableName, true);
135 Properties props= new Properties();
136 props.setProperty(QueryServices.LOG_LEVEL, LogLevel.DEBUG.name());
137 props.setProperty(QueryServices.LOG_SAMPLE_RATE, "0.5");
138 Connection conn = DriverManager.getConnection(getUrl(),props);
139 assertEquals(conn.unwrap(PhoenixConnection.class).getLogLevel(),LogLevel.DEBUG);
140 String query = "SELECT * FROM " + tableName;
141 int count=100;
142 for (int i = 0; i < count; i++) {
143 conn.createStatement().executeQuery(query);
144 }
145
146 String logQuery = "SELECT * FROM " + SYSTEM_CATALOG_SCHEMA + ".\"" + SYSTEM_LOG_TABLE + "\"";
147 ResultSet rs = conn.createStatement().executeQuery(logQuery);
148 int delay = 5000;
149
150 // sleep for sometime to let query log committed
151 Thread.sleep(delay);
152 int logCount=0;
153 while (rs.next()) {
154 logCount++;
155 }
156
157 //sampling rate is 0.5 , but with lesser count, uniformity of thread random may not be perfect, so taking 0.75 for comparison
158 assertTrue(logCount != 0 && logCount < count * 0.75);
159 conn.close();
160 }
161
162 @Test
163 public void testInfoLogs() throws Exception{
164 String tableName = generateUniqueName();
165 createTableAndInsertValues(tableName, true);
166 Properties props= new Properties();
167 props.setProperty(QueryServices.LOG_LEVEL, LogLevel.INFO.name());
168 Connection conn = DriverManager.getConnection(getUrl(),props);
169 assertEquals(conn.unwrap(PhoenixConnection.class).getLogLevel(),LogLevel.INFO);
170 String query = "SELECT * FROM " + tableName;
171
172 ResultSet rs = conn.createStatement().executeQuery(query);
173 StatementContext context = ((PhoenixResultSet)rs).getContext();
174 String queryId = context.getQueryLogger().getQueryId();
175 while (rs.next()) {
176 rs.getString(1);
177 rs.getString(2);
178 }
179
180 String logQuery = "SELECT * FROM " + SYSTEM_CATALOG_SCHEMA + ".\"" + SYSTEM_LOG_TABLE + "\"";
181 rs = conn.createStatement().executeQuery(logQuery);
182 boolean foundQueryLog = false;
183 int delay = 5000;
184
185 // sleep for sometime to let query log committed
186 Thread.sleep(delay);
187 while (rs.next()) {
188 if (rs.getString(QUERY_ID).equals(queryId)) {
189 foundQueryLog = true;
190 assertEquals(rs.getString(USER), System.getProperty("user.name"));
191 assertEquals(rs.getString(CLIENT_IP), InetAddress.getLocalHost().getHostAddress());
192 assertEquals(rs.getString(EXPLAIN_PLAN), null);
193 assertEquals(rs.getString(GLOBAL_SCAN_DETAILS),null);
194 assertEquals(rs.getLong(NO_OF_RESULTS_ITERATED), 0);
195 assertEquals(rs.getString(QUERY), query);
196 assertEquals(rs.getString(QUERY_STATUS),null);
197 assertTrue(System.currentTimeMillis() - rs.getTimestamp(START_TIME).getTime() > delay);
198 assertEquals(rs.getString(TENANT_ID), null);
199 assertTrue(rs.getString(TOTAL_EXECUTION_TIME) == null);
200 }
201 }
202 assertTrue(foundQueryLog);
203 conn.close();
204 }
205
206 @Test
207 public void testWithLoggingOFF() throws Exception{
208 String tableName = generateUniqueName();
209 createTableAndInsertValues(tableName, true);
210 Properties props= new Properties();
211 props.setProperty(QueryServices.LOG_LEVEL, LogLevel.OFF.name());
212 Connection conn = DriverManager.getConnection(getUrl(),props);
213 assertEquals(conn.unwrap(PhoenixConnection.class).getLogLevel(),LogLevel.OFF);
214 String query = "SELECT * FROM " + tableName;
215
216 ResultSet rs = conn.createStatement().executeQuery(query);
217 StatementContext context = ((PhoenixResultSet)rs).getContext();
218 String queryId = context.getQueryLogger().getQueryId();
219 while (rs.next()) {
220 rs.getString(1);
221 rs.getString(2);
222 }
223
224 String logQuery = "SELECT * FROM " + SYSTEM_CATALOG_SCHEMA + ".\"" + SYSTEM_LOG_TABLE + "\"";
225 rs = conn.createStatement().executeQuery(logQuery);
226 boolean foundQueryLog = false;
227 int delay = 5000;
228
229 // sleep for sometime to let query log committed
230 Thread.sleep(delay);
231 while (rs.next()) {
232 if (rs.getString(QUERY_ID).equals(queryId)) {
233 foundQueryLog = true;
234 }
235 }
236 assertFalse(foundQueryLog);
237 conn.close();
238 }
239
240
241 @Test
242 public void testPreparedStatementWithTrace() throws Exception{
243 testPreparedStatement(LogLevel.TRACE);
244 }
245
246 @Test
247 public void testPreparedStatementWithDebug() throws Exception{
248 testPreparedStatement(LogLevel.DEBUG);
249 }
250
251 private void testPreparedStatement(LogLevel loglevel) throws Exception{
252 String tableName = generateUniqueName();
253 createTableAndInsertValues(tableName, true);
254 Properties props= new Properties();
255 props.setProperty(QueryServices.LOG_LEVEL, loglevel.name());
256 Connection conn = DriverManager.getConnection(getUrl(),props);
257 assertEquals(conn.unwrap(PhoenixConnection.class).getLogLevel(),loglevel);
258
259 String query = "SELECT * FROM " + tableName +" where V = ?";
260
261 PreparedStatement pstmt = conn.prepareStatement(query);
262 pstmt.setString(1, "value5");
263 ResultSet rs = pstmt.executeQuery();
264 StatementContext context = ((PhoenixResultSet)rs).getContext();
265 String queryId = context.getQueryLogger().getQueryId();
266 while (rs.next()) {
267 rs.getString(1);
268 rs.getString(2);
269 }
270 ResultSet explainRS = conn.createStatement()
271 .executeQuery("Explain " + "SELECT * FROM " + tableName + " where V = 'value5'");
272 String logQuery = "SELECT * FROM " + SYSTEM_CATALOG_SCHEMA + ".\"" + SYSTEM_LOG_TABLE + "\"";
273 rs = conn.createStatement().executeQuery(logQuery);
274 boolean foundQueryLog = false;
275 int delay = 5000;
276
277 // sleep for sometime to let query log committed
278 Thread.sleep(delay);
279 while (rs.next()) {
280 if (rs.getString(QUERY_ID).equals(queryId)) {
281 foundQueryLog = true;
282 assertEquals(rs.getString(BIND_PARAMETERS), loglevel == LogLevel.TRACE ? "value5" : null);
283 assertEquals(rs.getString(USER), System.getProperty("user.name"));
284 assertEquals(rs.getString(CLIENT_IP), InetAddress.getLocalHost().getHostAddress());
285 assertEquals(rs.getString(EXPLAIN_PLAN), QueryUtil.getExplainPlan(explainRS));
286 assertEquals(rs.getString(GLOBAL_SCAN_DETAILS), context.getScan().toJSON());
287 assertEquals(rs.getLong(NO_OF_RESULTS_ITERATED), 1);
288 assertEquals(rs.getString(QUERY), query);
289 assertEquals(rs.getString(QUERY_STATUS), QueryLogState.COMPLETED.toString());
290 assertTrue(System.currentTimeMillis() - rs.getTimestamp(START_TIME).getTime() > delay);
291 assertEquals(rs.getString(TENANT_ID), null);
292 assertTrue(rs.getString(TOTAL_EXECUTION_TIME) != null);
293 }
294 }
295 assertTrue(foundQueryLog);
296 conn.close();
297 }
298
299
300
301 @Test
302 public void testFailedQuery() throws Exception {
303 String tableName = generateUniqueName();
304 Properties props = new Properties();
305 props.setProperty(QueryServices.LOG_LEVEL, LogLevel.DEBUG.name());
306 Connection conn = DriverManager.getConnection(getUrl(), props);
307 assertEquals(conn.unwrap(PhoenixConnection.class).getLogLevel(), LogLevel.DEBUG);
308 // Table does not exists
309 String query = "SELECT * FROM " + tableName;
310
311 try {
312 conn.createStatement().executeQuery(query);
313 fail();
314 } catch (SQLException e) {
315 assertEquals(e.getErrorCode(), SQLExceptionCode.TABLE_UNDEFINED.getErrorCode());
316 }
317 String logQuery = "SELECT * FROM " + SYSTEM_CATALOG_SCHEMA + ".\"" + SYSTEM_LOG_TABLE + "\"";
318 ResultSet rs = conn.createStatement().executeQuery(logQuery);
319 boolean foundQueryLog = false;
320 int delay = 5000;
321
322 // sleep for sometime to let query log committed
323 Thread.sleep(delay);
324 while (rs.next()) {
325 if (QueryLogState.FAILED.name().equals(rs.getString(QUERY_STATUS))) {
326 foundQueryLog = true;
327 assertEquals(rs.getString(USER), System.getProperty("user.name"));
328 assertEquals(rs.getString(CLIENT_IP), InetAddress.getLocalHost().getHostAddress());
329 assertEquals(rs.getString(EXPLAIN_PLAN), null);
330 assertEquals(rs.getString(GLOBAL_SCAN_DETAILS), null);
331 assertEquals(rs.getLong(NO_OF_RESULTS_ITERATED), 0);
332 assertEquals(rs.getString(QUERY), query);
333 assertTrue(rs.getString(EXCEPTION_TRACE).contains(SQLExceptionCode.TABLE_UNDEFINED.getMessage()));
334 assertTrue(System.currentTimeMillis() - rs.getTimestamp(START_TIME).getTime() > delay);
335 assertTrue(rs.getString(TOTAL_EXECUTION_TIME) != null);
336 }
337 }
338 assertTrue(foundQueryLog);
339 conn.close();
340 }
341
342 private static void createTableAndInsertValues(String tableName, boolean resetGlobalMetricsAfterTableCreate)
343 throws Exception {
344 String ddl = "CREATE TABLE " + tableName + " (K VARCHAR NOT NULL PRIMARY KEY, V VARCHAR)";
345 Connection conn = DriverManager.getConnection(getUrl());
346 conn.createStatement().execute(ddl);
347 // executing 10 upserts/mutations.
348 String dml = "UPSERT INTO " + tableName + " VALUES (?, ?)";
349 PreparedStatement stmt = conn.prepareStatement(dml);
350 for (int i = 1; i <= 10; i++) {
351 stmt.setString(1, "key" + i);
352 stmt.setString(2, "value" + i);
353 stmt.executeUpdate();
354 }
355 conn.commit();
356 }
357
358 }