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

HiveServer2 LogDivertAppender should be more selective for beeline getLogs

Log workAgile BoardRank to TopRank to BottomBulk Copy AttachmentsBulk Move AttachmentsVotersWatch issueWatchersCreate sub-taskConvert to sub-taskMoveLinkCloneLabelsUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • None
    • 0.14.0
    • None

    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.5.patch
          17 kB
          Thejas Nair
        2. HIVE-8785.4.patch
          16 kB
          Thejas Nair
        3. HIVE-8785.4.patch
          17 kB
          Gunther Hagleitner
        4. HIVE-8785.3.patch
          16 kB
          Thejas Nair
        5. HIVE-8785.2.patch
          16 kB
          Thejas Nair
        6. HIVE-8785.1.patch
          14 kB
          Thejas Nair

        Issue Links

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            thejas Thejas Nair Assign to me
            gopalv Gopal Vijayaraghavan
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment