Repository: hive Updated Branches: refs/heads/master d2a14fe28 -> 90f26bb44
HIVE-18426: Memory leak in RoutingAppender for every hive operation (kalyan kumar kalvagadda, reviewed by Aihua Xu) Project: http://git-wip-us.apache.org/repos/asf/hive/repo Commit: http://git-wip-us.apache.org/repos/asf/hive/commit/90f26bb4 Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/90f26bb4 Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/90f26bb4 Branch: refs/heads/master Commit: 90f26bb443176df01a402b80d344b16abfb33eff Parents: d2a14fe Author: Aihua Xu <[email protected]> Authored: Mon Jan 29 15:21:23 2018 -0800 Committer: Aihua Xu <[email protected]> Committed: Mon Jan 29 15:21:23 2018 -0800 ---------------------------------------------------------------------- .../org/apache/hadoop/hive/common/LogUtils.java | 11 +- .../operation/TestOperationLoggingLayout.java | 109 +++++++++++++++---- 2 files changed, 88 insertions(+), 32 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/hive/blob/90f26bb4/common/src/java/org/apache/hadoop/hive/common/LogUtils.java ---------------------------------------------------------------------- diff --git a/common/src/java/org/apache/hadoop/hive/common/LogUtils.java b/common/src/java/org/apache/hadoop/hive/common/LogUtils.java index 5c7ec69..5068eb5 100644 --- a/common/src/java/org/apache/hadoop/hive/common/LogUtils.java +++ b/common/src/java/org/apache/hadoop/hive/common/LogUtils.java @@ -29,10 +29,8 @@ import org.apache.hadoop.hive.conf.HiveConf; import org.apache.hadoop.hive.conf.HiveConf.ConfVars; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.core.Appender; -import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.appender.routing.RoutingAppender; -import org.apache.logging.log4j.core.config.AppenderControl; import org.apache.logging.log4j.core.config.Configurator; import org.apache.logging.log4j.core.config.LoggerConfig; import org.apache.logging.log4j.core.impl.Log4jContextFactory; @@ -248,14 +246,9 @@ public class LogUtils { // The appender is configured to use ${ctx:queryId} by registerRoutingAppender() try { Class<? extends RoutingAppender> clazz = routingAppender.getClass(); - Method method = clazz.getDeclaredMethod("getControl", String.class, LogEvent.class); + Method method = clazz.getDeclaredMethod("deleteAppender", String.class); method.setAccessible(true); - AppenderControl control = (AppenderControl) method.invoke(routingAppender, queryId, null); - Appender subordinateAppender = control.getAppender(); - if (!subordinateAppender.isStopped()) { - // this will cause the subordinate appender to close its output stream. - subordinateAppender.stop(); - } + method.invoke(routingAppender, queryId); } catch (NoSuchMethodException | SecurityException | IllegalAccessException | IllegalArgumentException | InvocationTargetException e) { l4j.warn("Unable to close the operation log appender for query id " + queryId, e); http://git-wip-us.apache.org/repos/asf/hive/blob/90f26bb4/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java ---------------------------------------------------------------------- diff --git a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java index 8febe3e..d90d590 100644 --- a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java +++ b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java @@ -102,14 +102,8 @@ public class TestOperationLoggingLayout { miniHS2.stop(); } - @Test - public void testSwitchLogLayout() throws Exception { - // verify whether the sql operation log is generated and fetch correctly. - OperationHandle operationHandle = client.executeStatement(sessionHandle, sqlCntStar, null); - RowSet rowSetLog = client.fetchResults(operationHandle, FetchOrientation.FETCH_FIRST, 1000, - FetchType.LOG); + private String getQueryId(RowSet rowSetLog) { Iterator<Object[]> iter = rowSetLog.iterator(); - String queryId = null; // non-verbose pattern is %-5p : %m%n. Look for " : " while (iter.hasNext()) { String row = iter.next()[0].toString(); @@ -119,9 +113,32 @@ public class TestOperationLoggingLayout { String queryIdLoggingProbe = "INFO : Query ID = "; int index = row.indexOf(queryIdLoggingProbe); if (index >= 0) { - queryId = row.substring(queryIdLoggingProbe.length()).trim(); + return row.substring(queryIdLoggingProbe.length()).trim(); } } + return null; + } + + private void appendHushableRandomAccessFileAppender(Appender queryAppender) { + HushableRandomAccessFileAppender hushableAppender; + + if((queryAppender!= null) && (queryAppender instanceof HushableRandomAccessFileAppender)) { + hushableAppender = (HushableRandomAccessFileAppender) queryAppender; + try { + hushableAppender.append(new LocalLogEvent()); + } catch (Exception e) { + Assert.fail("Exception is not expected while appending HushableRandomAccessFileAppender"); + } + } + } + + @Test + public void testSwitchLogLayout() throws Exception { + // verify whether the sql operation log is generated and fetch correctly. + OperationHandle operationHandle = client.executeStatement(sessionHandle, sqlCntStar, null); + RowSet rowSetLog = client.fetchResults(operationHandle, FetchOrientation.FETCH_FIRST, 1000, + FetchType.LOG); + String queryId = getQueryId(rowSetLog); Assert.assertNotNull("Could not find query id, perhaps a logging message changed", queryId); checkAppenderState("before operation close ", LogDivertAppender.QUERY_ROUTING_APPENDER, queryId, false); @@ -129,11 +146,35 @@ public class TestOperationLoggingLayout { client.closeOperation(operationHandle); checkAppenderState("after operation close ", LogDivertAppender.QUERY_ROUTING_APPENDER, queryId, true); checkAppenderState("after operation close ", LogDivertAppenderForTest.TEST_QUERY_ROUTING_APPENDER, queryId, true); - } + @Test + /** + * Test to make sure that appending log event to HushableRandomAccessFileAppender even after + * closing the corresponding operation would not throw an exception. + */ + public void testHushableRandomAccessFileAppender() throws Exception { + // verify whether the sql operation log is generated and fetch correctly. + OperationHandle operationHandle = client.executeStatement(sessionHandle, sqlCntStar, null); + RowSet rowSetLog = client.fetchResults(operationHandle, FetchOrientation.FETCH_FIRST, 1000, + FetchType.LOG); + Appender queryAppender; + Appender testQueryAppender; + String queryId = getQueryId(rowSetLog); + + Assert.assertNotNull("Could not find query id, perhaps a logging message changed", queryId); + + checkAppenderState("before operation close ", LogDivertAppender.QUERY_ROUTING_APPENDER, queryId, false); + queryAppender = getAppender(LogDivertAppender.QUERY_ROUTING_APPENDER, queryId); + checkAppenderState("before operation close ", LogDivertAppenderForTest.TEST_QUERY_ROUTING_APPENDER, queryId, false); + testQueryAppender = getAppender(LogDivertAppenderForTest.TEST_QUERY_ROUTING_APPENDER, queryId); + + client.closeOperation(operationHandle); + appendHushableRandomAccessFileAppender(queryAppender); + appendHushableRandomAccessFileAppender(testQueryAppender); + } /** - * assert that the appender for the given queryId is in the expected state + * assert that the appender for the given queryId is in the expected state. * @param msg a diagnostic * @param routingAppenderName name of the RoutingAppender * @param queryId the query id to use as a key @@ -151,19 +192,41 @@ public class TestOperationLoggingLayout { defaultsField.setAccessible(true); ConcurrentHashMap appenders = (ConcurrentHashMap) defaultsField.get(routingAppender); AppenderControl appenderControl = (AppenderControl) appenders.get(queryId); - Assert.assertNotNull(msg + "could not find AppenderControl for query id " + queryId, appenderControl); - Appender appender = appenderControl.getAppender(); - Assert.assertNotNull(msg + "could not find Appender for query id " + queryId + " from AppenderControl " + appenderControl, appender); - Assert.assertEquals(msg + "Appender for query is in unexpected state", expectedStopped, appender.isStopped()); - Assert.assertTrue("Appender should be a HushableMutableRandomAccessAppender", appender instanceof HushableRandomAccessFileAppender); - HushableRandomAccessFileAppender ra = (HushableRandomAccessFileAppender) appender; - // Even if the appender is stopped it should not throw an exception when we log - try { - ra.append(new LocalLogEvent()); - } catch (Exception e) { - e.printStackTrace(); - Assert.fail("Caught exception while logging to an appender of class " + ra.getClass() - + " with stopped=" + ra.isStopped()); + if (!expectedStopped) { + Assert.assertNotNull(msg + "Could not find AppenderControl for query id " + queryId, appenderControl); + Appender appender = appenderControl.getAppender(); + Assert.assertNotNull(msg + "could not find Appender for query id " + queryId + " from AppenderControl " + + appenderControl, appender); + Assert.assertEquals(msg + "Appender for query is in unexpected state", expectedStopped, appender.isStopped()); + } else { + Assert.assertNull(msg + "AppenderControl for query id is not removed" + queryId, appenderControl); + } + } + + /** + * Get the appender associated with a query. + * @param routingAppenderName Routing appender name + * @param queryId Query Id for the operation + * @return Appender if found, else null + * @throws NoSuchFieldException + * @throws IllegalAccessException + */ + private Appender getAppender(String routingAppenderName, String queryId) + throws NoSuchFieldException, IllegalAccessException { + LoggerContext context = (LoggerContext) LogManager.getContext(false); + Configuration configuration = context.getConfiguration(); + LoggerConfig loggerConfig = configuration.getRootLogger(); + Map<String, Appender> appendersMap = loggerConfig.getAppenders(); + RoutingAppender routingAppender = (RoutingAppender) appendersMap.get(routingAppenderName); + Assert.assertNotNull("could not find routingAppender " + routingAppenderName, routingAppender); + Field defaultsField = RoutingAppender.class.getDeclaredField("appenders"); + defaultsField.setAccessible(true); + ConcurrentHashMap appenders = (ConcurrentHashMap) defaultsField.get(routingAppender); + AppenderControl appenderControl = (AppenderControl) appenders.get(queryId); + if(appenderControl != null) { + return appenderControl.getAppender(); + } else { + return null; } }
