[HIVE-8785] HiveServer2 LogDivertAppender should be more selective for beeline getLogs

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 0.14.0
• Labels: TODOC14
• Assignee: Thejas Nair
• Reporter: Gopal Vijayaraghavan
• Created: 07/Nov/14 22:06
• Updated: 17/Feb/15 08:55
• Resolved: 08/Nov/14 18:37

Description

A simple query run via beeline JDBC like explain select count(1) from testing.foo; produces 50 lines of output which looks like

0: jdbc:hive2://localhost:10002> explain select count(1) from testing.foo;
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=compile from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=parse from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO parse.ParseDriver: Parsing command: explain select count(1) from testing.foo
14/11/06 00:35:59 INFO parse.ParseDriver: Parse Completed
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=parse start=1415262959379 end=1415262959380 duration=1 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=semanticAnalyze from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Starting Semantic Analysis
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Completed phase 1 of Semantic Analysis
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Get metadata for source tables
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Get metadata for subqueries
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Get metadata for destination tables
14/11/06 00:35:59 INFO ql.Context: New scratch dir is hdfs://cn041-10.l42scl.hortonworks.com:8020/tmp/hive/gopal/6b3980f6-3238-4e91-ae53-cb3f54092dab/hive_2014-11-06_00-35-59_379_317426424610374080-1
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Completed getting MetaData in Semantic Analysis
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Set stats collection dir : hdfs://cn041-10.l42scl.hortonworks.com:8020/tmp/hive/gopal/6b3980f6-3238-4e91-ae53-cb3f54092dab/hive_2014-11-06_00-35-59_379_317426424610374080-1/-ext-10002
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for FS(16)
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for SEL(15)
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for GBY(14)
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for RS(13)
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for GBY(12)
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for SEL(11)
14/11/06 00:35:59 INFO ppd.OpProcFactory: Processing for TS(10)
14/11/06 00:35:59 INFO optimizer.ColumnPrunerProcFactory: RS 13 oldColExprMap: {VALUE._col0=Column[_col0]}
14/11/06 00:35:59 INFO optimizer.ColumnPrunerProcFactory: RS 13 newColExprMap: {VALUE._col0=Column[_col0]}
14/11/06 00:35:59 INFO parse.SemanticAnalyzer: Completed plan generation
14/11/06 00:35:59 INFO ql.Driver: Semantic Analysis Completed
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=semanticAnalyze start=1415262959381 end=1415262959401 duration=20 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO ql.Driver: Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:Explain, type:string, comment:null)], properties:null)
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=compile start=1415262959378 end=1415262959402 duration=24 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=Driver.run from=org.apache.hadoop.hive.ql.Driver>
+----------------------------+--+
|          Explain           |
+----------------------------+--+
| STAGE DEPENDENCIES:        |
|   Stage-0 is a root stage  |
|                            |
| STAGE PLANS:               |
|   Stage: Stage-0           |
|     Fetch Operator         |
|       limit: 1             |
|       Processor Tree:      |
|         ListSink           |
|                            |
+----------------------------+--+
10 rows selected (0.1 seconds)
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=TimeToSubmit from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO ql.Driver: Concurrency mode is disabled, not creating a lock manager
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=Driver.execute from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO ql.Driver: Starting command: explain select count(1) from testing.foo
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=TimeToSubmit start=1415262959403 end=1415262959405 duration=2 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=task.EXPLAIN.Stage-1 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO ql.Driver: Starting task [Stage-1:EXPLAIN] in serial mode
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=runTasks start=1415262959405 end=1415262959408 duration=3 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=Driver.execute start=1415262959404 end=1415262959408 duration=4 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO ql.Driver: OK
14/11/06 00:35:59 INFO log.PerfLogger: <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=releaseLocks start=1415262959408 end=1415262959409 duration=1 from=org.apache.hadoop.hive.ql.Driver>
14/11/06 00:35:59 INFO log.PerfLogger: </PERFLOG method=Driver.run start=1415262959403 end=1415262959409 duration=6 from=org.apache.hadoop.hive.ql.Driver>

A more complex query like Query27 produces 800+ lines of unnecessary logging.

This is unreadable and in-fact slows down the beeline JDBC client.

Issue Links

• relates to: HIVE-4629 HS2 should support an API to retrieve query logs
• links to: Review Board