[
https://issues.apache.org/jira/browse/HIVE-24590?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17259725#comment-17259725
]
Eugene Chung edited comment on HIVE-24590 at 1/6/21, 1:58 PM:
--------------------------------------------------------------
{noformat}
[2021-01-06T22:35:48,371] INFO [HiveServer2-HttpHandler-Pool: Thread-101]
client.TezClient: Shutting down Tez Session,
sessionName=********og-20210106222500-bc649f09-a16a-4295-ac16-f3e86883364b,
applicationId=application_1591769205146_5391722
2021-01-06 22:35:48,373 HiveServer2-HttpHandler-Pool: Thread-101 WARN
/*******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/****_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
for RandomAccessFileManager is created.
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender$DebugTrace:
/*******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/irteam_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
at
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender.createAppender(HushableRandomAccessFileAppender.java:217)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
at
org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:958)
at
org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:898)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.createAppender(RoutingAppender.java:271)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.getControl(RoutingAppender.java:255)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.append(RoutingAppender.java:225)
at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at
org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:439)
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:434)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
at
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.apache.log4j.Category.forcedLog(Category.java:357)
at org.apache.log4j.Category.log(Category.java:445)
at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
at org.apache.tez.client.TezClient.stop(TezClient.java:737)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionState.closeClient(TezSessionState.java:710)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionState.close(TezSessionState.java:677)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolSession.close(TezSessionPoolSession.java:111)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolManager.closeIfNotDefault(TezSessionPoolManager.java:354)
at
org.apache.hadoop.hive.ql.session.SessionState.close(SessionState.java:1765)
at
org.apache.hive.service.cli.session.HiveSessionImpl.close(HiveSessionImpl.java:761)
at
org.apache.hive.service.cli.session.HiveSessionImplwithUGI.close(HiveSessionImplwithUGI.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:78)
at
org.apache.hive.service.cli.session.HiveSessionProxy.access$000(HiveSessionProxy.java:36)
at
org.apache.hive.service.cli.session.HiveSessionProxy$1.run(HiveSessionProxy.java:63)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1729)
at
org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:59)
at com.sun.proxy.$Proxy63.close(Unknown Source)
at
org.apache.hive.service.cli.session.SessionManager.closeSession(SessionManager.java:553)
at
org.apache.hive.service.cli.CLIService.closeSession(CLIService.java:241)
at
org.apache.hive.service.cli.thrift.ThriftCLIService.CloseSession(ThriftCLIService.java:522)
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1517)
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1502)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at org.apache.thrift.server.TServlet.doPost(TServlet.java:83)
at
org.apache.hive.service.cli.thrift.ThriftHttpServlet.doPost(ThriftHttpServlet.java:207)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at
org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:493)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
at
org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748){noformat}
I think the main cause of the leak is that logging of TezClient.stop() is
logged as the operation log.
At the very beginning of HiveSessionImpl.close(), shouldn't it be cleared for
operation log setting of the log4j context?
Note that my tez client is 0.9.2.
was (Author: euigeun_chung):
{noformat}
[2021-01-06T22:35:48,371] INFO [HiveServer2-HttpHandler-Pool: Thread-101]
client.TezClient: Shutting down Tez Session,
sessionName=********og-20210106222500-bc649f09-a16a-4295-ac16-f3e86883364b,
applicationId=application_1591769205146_5391722
2021-01-06 22:35:48,373 HiveServer2-HttpHandler-Pool: Thread-101 WARN
/*******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/****_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
for RandomAccessFileManager is created.
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender$DebugTrace:
/*******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/irteam_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
at
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender.createAppender(HushableRandomAccessFileAppender.java:217)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
at
org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:958)
at
org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:898)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.createAppender(RoutingAppender.java:271)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.getControl(RoutingAppender.java:255)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.append(RoutingAppender.java:225)
at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at
org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:439)
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:434)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
at
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.apache.log4j.Category.forcedLog(Category.java:357)
at org.apache.log4j.Category.log(Category.java:445)
at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
at org.apache.tez.client.TezClient.stop(TezClient.java:737)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionState.closeClient(TezSessionState.java:710)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionState.close(TezSessionState.java:677)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolSession.close(TezSessionPoolSession.java:111)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolManager.closeIfNotDefault(TezSessionPoolManager.java:354)
at
org.apache.hadoop.hive.ql.session.SessionState.close(SessionState.java:1765)
at
org.apache.hive.service.cli.session.HiveSessionImpl.close(HiveSessionImpl.java:761)
at
org.apache.hive.service.cli.session.HiveSessionImplwithUGI.close(HiveSessionImplwithUGI.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:78)
at
org.apache.hive.service.cli.session.HiveSessionProxy.access$000(HiveSessionProxy.java:36)
at
org.apache.hive.service.cli.session.HiveSessionProxy$1.run(HiveSessionProxy.java:63)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1729)
at
org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:59)
at com.sun.proxy.$Proxy63.close(Unknown Source)
at
org.apache.hive.service.cli.session.SessionManager.closeSession(SessionManager.java:553)
at
org.apache.hive.service.cli.CLIService.closeSession(CLIService.java:241)
at
org.apache.hive.service.cli.thrift.ThriftCLIService.CloseSession(ThriftCLIService.java:522)
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1517)
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1502)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at org.apache.thrift.server.TServlet.doPost(TServlet.java:83)
at
org.apache.hive.service.cli.thrift.ThriftHttpServlet.doPost(ThriftHttpServlet.java:207)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at
org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:493)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
at
org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748){noformat}
I think the main cause of the leak is that logging of TezClient.stop() is
logged as the operation log.
At the very beginning of HiveSessionImpl.close(), shouldn't it be cleared for
operation log setting in the log4j context?
Note that my tez client is 0.9.2.
> Operation Logging still leaks the log4j Appenders
> -------------------------------------------------
>
> Key: HIVE-24590
> URL: https://issues.apache.org/jira/browse/HIVE-24590
> Project: Hive
> Issue Type: Bug
> Components: Logging
> Reporter: Eugene Chung
> Assignee: Stamatis Zampetakis
> Priority: Major
> Attachments: Screen Shot 2021-01-06 at 18.42.05.png, Screen Shot
> 2021-01-06 at 18.42.24.png, Screen Shot 2021-01-06 at 18.42.55.png, Screen
> Shot 2021-01-06 at 21.38.32.png, Screen Shot 2021-01-06 at 21.47.28.png,
> add_debug_log_and_trace.patch
>
>
> I'm using Hive 3.1.2 with options below.
> * hive.server2.logging.operation.enabled=true
> * hive.server2.logging.operation.level=VERBOSE
> * hive.async.log.enabled=false
> I already know the ticket, https://issues.apache.org/jira/browse/HIVE-17128
> but HS2 still leaks log4j RandomAccessFileManager.
> !Screen Shot 2021-01-06 at 18.42.05.png|width=756,height=197!
> I checked the operation log file which is not closed/deleted properly.
> !Screen Shot 2021-01-06 at 18.42.24.png|width=603,height=272!
> Then there's the log,
> {code:java}
> client.TezClient: Shutting down Tez Session, sessionName= ....{code}
> !Screen Shot 2021-01-06 at 18.42.55.png|width=1372,height=26!
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
