hive-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Dima Machlin <Dima.Mach...@pursway.com>
Subject RE: HiveServer2 VS HiveServer1 Logging
Date Sun, 25 May 2014 10:53:47 GMT
I’ve made some progress in investigating this.
It seems that this behavior happens on certain conditions.

As long as i’m running any query that isn’t “set” or “add” command the logging
is fine.
For example “show table” :

14/05/25 13:47:17 INFO cli.CLIService: SessionHandle [2db07453-2235-4f22-ab72-4a27c1b1457d]:
openSession()
14/05/25 13:47:17 INFO cli.CLIService: SessionHandle [2db07453-2235-4f22-ab72-4a27c1b1457d]:
getInfo()
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=Driver.run>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=TimeToSubmit>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=compile>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=parse>
14/05/25 13:47:18 INFO parse.ParseDriver: Parsing command: show tables
14/05/25 13:47:18 INFO parse.ParseDriver: Parse Completed
14/05/25 13:47:18 INFO ql.Driver: </PERFLOG method=parse start=1401014838047 end=1401014838376
duration=329>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=semanticAnalyze>
14/05/25 13:47:18 INFO ql.Driver: Semantic Analysis Completed
14/05/25 13:47:18 INFO ql.Driver: </PERFLOG method=semanticAnalyze start=1401014838376
end=1401014838453 duration=77>
14/05/25 13:47:18 INFO exec.ListSinkOperator: Initializing Self 0 OP
14/05/25 13:47:18 INFO exec.ListSinkOperator: Operator 0 OP initialized
14/05/25 13:47:18 INFO exec.ListSinkOperator: Initialization Done 0 OP
14/05/25 13:47:18 INFO ql.Driver: Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:tab_name,
type:string, comment:from deserializer)], properties:null)
14/05/25 13:47:18 INFO ql.Driver: </PERFLOG method=compile start=1401014838011 end=1401014838521
duration=510>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=Driver.execute>
14/05/25 13:47:18 INFO ql.Driver: Starting command: show tables
14/05/25 13:47:18 INFO ql.Driver: </PERFLOG method=TimeToSubmit start=1401014838011 end=1401014838531
duration=520>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=runTasks>
14/05/25 13:47:18 INFO ql.Driver: <PERFLOG method=task.DDL.Stage-0>
14/05/25 13:47:18 INFO hive.metastore: Trying to connect to metastore with URI thrift://localhost:9083
14/05/25 13:47:18 INFO hive.metastore: Waiting 1 seconds before next connection attempt.
14/05/25 13:47:19 INFO hive.metastore: Connected to metastore.
14/05/25 13:47:19 INFO ql.Driver: </PERFLOG method=task.DDL.Stage-0 start=1401014838531
end=1401014839627 duration=1096>
14/05/25 13:47:19 INFO ql.Driver: </PERFLOG method=runTasks start=1401014838531 end=1401014839627
duration=1096>
14/05/25 13:47:19 INFO ql.Driver: </PERFLOG method=Driver.execute start=1401014838521 end=1401014839627
duration=1106>
OK
14/05/25 13:47:19 INFO ql.Driver: OK
14/05/25 13:47:19 INFO ql.Driver: <PERFLOG method=releaseLocks>
14/05/25 13:47:19 INFO ql.Driver: </PERFLOG method=releaseLocks start=1401014839627 end=1401014839627
duration=0>
14/05/25 13:47:19 INFO ql.Driver: </PERFLOG method=Driver.run start=1401014838011 end=1401014839627
duration=1616>
14/05/25 13:47:19 INFO cli.CLIService: SessionHandle [2db07453-2235-4f22-ab72-4a27c1b1457d]:
executeStatement()
14/05/25 13:47:19 INFO cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT, getHandleIdentifier()=0628b8f8-01de-4397-8279-a314cf553d7f]:
getResultSetMetadata()
14/05/25 13:47:19 WARN snappy.LoadSnappy: Snappy native library not loaded
14/05/25 13:47:19 INFO mapred.FileInputFormat: Total input paths to process : 1
14/05/25 13:47:19 INFO cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT, getHandleIdentifier()=0628b8f8-01de-4397-8279-a314cf553d7f]:
fetchResults()
14/05/25 13:47:19 INFO cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT, getHandleIdentifier()=0628b8f8-01de-4397-8279-a314cf553d7f]:
fetchResults()
14/05/25 13:47:19 INFO exec.ListSinkOperator: 0 finished. closing...
14/05/25 13:47:19 INFO exec.ListSinkOperator: 0 forwarded 0 rows
14/05/25 13:47:19 INFO ql.Driver: <PERFLOG method=releaseLocks>
14/05/25 13:47:19 INFO ql.Driver: </PERFLOG method=releaseLocks start=1401014839857 end=1401014839857
duration=0>
14/05/25 13:47:19 INFO cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT, getHandleIdentifier()=0628b8f8-01de-4397-8279-a314cf553d7f]:
closeOperation


Now running : “set hive.enforce.bucketing = true;”

14/05/25 13:48:07 INFO operation.Operation: Putting temp output to file /tmp/hadoop/2db07453-2235-4f22-ab72-4a27c1b1457d2566159976359370628.pipeout
14/05/25 13:48:07 INFO cli.CLIService: SessionHandle [2db07453-2235-4f22-ab72-4a27c1b1457d]:
executeStatement()
14/05/25 13:48:07 INFO cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT, getHandleIdentifier()=7b13a3e2-e0ea-4dae-b693-0d456519fc66]:
getOperationStatus()

First thing that happens is : “Putting temp output to file” and from now on, nothing is
shown in the console.

Running again “show tables” generates no logging at all in the console.

The hiveserver is started like this :
/opt/mapr/hive/hive-0.12/bin/hive --service hiveserver2 --hiveconf hive.server2.thrift.port=26006

The connection is made from JDBC.

Executing the same procedure from the CLI generates all the expected logging.


From: Dima Machlin [mailto:Dima.Machlin@pursway.com]
Sent: Wednesday, May 21, 2014 5:06 PM
To: user@hive.apache.org
Subject: HiveServer2 VS HiveServer1 Logging


Hi all,

It seems that for some reason HS2 outputs far less logging than HS1 in hive 0.12 for example,
starting HS1 in the following way : hive --service hiveserver
and executing show tables produces this :

14/04/30 17:14:16 [pool-1-thread-2] INFO service.HiveServer: Running the query: show tables
14/04/30 17:14:16 [pool-1-thread-2] INFO exec.ListSinkOperator: 1 finished. closing...
14/04/30 17:14:16 [pool-1-thread-2] INFO exec.ListSinkOperator: 1 forwarded 0 rows
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=Driver.run>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=TimeToSubmit>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=compile>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=parse>
14/04/30 17:14:16 [pool-1-thread-2] INFO parse.ParseDriver: Parsing command: show tables
14/04/30 17:14:16 [pool-1-thread-2] INFO parse.ParseDriver: Parse Completed
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=parse start=1398867256379
end=1398867256380 duration=1>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=semanticAnalyze>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: Semantic Analysis Completed
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=semanticAnalyze start=1398867256380
end=1398867256381 duration=1>
14/04/30 17:14:16 [pool-1-thread-2] INFO exec.ListSinkOperator: Initializing Self 2 OP
14/04/30 17:14:16 [pool-1-thread-2] INFO exec.ListSinkOperator: Operator 2 OP initialized
14/04/30 17:14:16 [pool-1-thread-2] INFO exec.ListSinkOperator: Initialization Done 2 OP
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:tab_name,
type:string, comment:from deserializer)], properties:null)
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=compile start=1398867256379
end=1398867256384 duration=5>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=Driver.execute>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: Starting command: show tables
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=TimeToSubmit start=1398867256378
end=1398867256384 duration=6>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=runTasks>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=task.DDL.Stage-0>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=task.DDL.Stage-0 start=1398867256384
end=1398867256398 duration=14>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=runTasks start=1398867256384
end=1398867256398 duration=14>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=Driver.execute start=1398867256384
end=1398867256398 duration=14> OK
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: OK
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: <PERFLOG method=releaseLocks>
14/04/30 17:14:16 [pool-1-thread-2] INFO ql.Driver: </PERFLOG method=releaseLocks start=1398867256398
end=1398867256398 duration=0>

while when running on HS2 (hive --service hiveserver2), the only logging data is from the
initialization of the connection:

14/04/30 17:18:54 [pool-2-thread-1] INFO cli.CLIService: SessionHandle [4b0a96cb-626b-45ae-ae0d-6a959e84e5a4]:
openSession()
14/04/30 17:18:55 [pool-2-thread-1] INFO operation.Operation: Putting temp output to file
/tmp/hadoop/4b0a96cb-626b-45ae-ae0d-6a959e84e5a44568051681296760332.pipeout 14/04/30 17:18:55
[pool-2-thread-1] INFO cli.CLIService: SessionHandle [4b0a96cb-626b-45ae-ae0d-6a959e84e5a4]:
executeStatement()
14/04/30 17:18:55 [pool-2-thread-1] INFO cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=01a12804-8f77-4e8f-b17a-de4c39e481c8]: getOperationStatus()

And no sign for the executed query.
The show tables is just an example, it also doesn’t show any queries (both mapreduce and
direct)

Settings :
hive.root.logger in hive-log4j.properties is set to INFO,console

Any reason for this?





************************************************************************************
This footnote confirms that this email message has been scanned by
PineApp Mail-SeCure for the presence of malicious code, vandals & computer viruses.
************************************************************************************
Mime
View raw message