Uploaded image for project: 'Hive'
  1. Hive
  2. HIVE-8785

HiveServer2 LogDivertAppender should be more selective for beeline getLogs

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.14.0
    • Component/s: None
    • Labels:

      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.

        Attachments

        1. HIVE-8785.1.patch
          14 kB
          Thejas M Nair
        2. HIVE-8785.2.patch
          16 kB
          Thejas M Nair
        3. HIVE-8785.3.patch
          16 kB
          Thejas M Nair
        4. HIVE-8785.4.patch
          16 kB
          Thejas M Nair
        5. HIVE-8785.4.patch
          17 kB
          Gunther Hagleitner
        6. HIVE-8785.5.patch
          17 kB
          Thejas M Nair

          Issue Links

            Activity

              People

              • Assignee:
                thejas Thejas M Nair
                Reporter:
                gopalv Gopal V
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: