Any change somebody has a clue about this? From: Dima Machlin [mailto:dima.mach...@pursway.com] Sent: Sunday, May 25, 2014 1:54 PM To: u...@hive.apache.org Subject: RE: HiveServer2 VS HiveServer1 Logging
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.mach...@pursway.com] Sent: Wednesday, May 21, 2014 5:06 PM To: u...@hive.apache.org<mailto:u...@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. ************************************************************************************ ************************************************************************************ This footnote confirms that this email message has been scanned by PineApp Mail-SeCure for the presence of malicious code, vandals & computer viruses. ************************************************************************************
