[HIVE-13037] Query with UDF never terminate - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Open
Priority: Major
Resolution: Unresolved
Affects Version/s: 1.0.0
Fix Version/s: None
Component/s: HiveServer2
Labels:
None

Description

I am writing a client for HS2 that uses the JDBC interface. I can execute a simple select query. When I add a UDF to the query, the client hangs. I looked at the logs (larger excerpt below) and there is this bit that looks suspect, and repeats ad infinitum

2016-02-10 20:26:49,571 INFO  [hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]: queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down. sleeping for 30000 milli seconds. indexQueue=0, queueName=hiveServer2.async.multi_dest.batch, consumer=hiveServer2.async.multi_dest.batch.db

No tez dag is ever submitted or executed, per log and web UI. The only special thing about this UDF may be that it accesses a file that has been added with ADD FILE from hdfs.

Log from query submission to infinite loop first few iterations:

2016-02-10 20:24:32,695 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.ParseDriver (ParseDriver.java:parse(185)) - Parsing command: SELECT count(*) FROM (SELECT `mpg`, `cyl`, 
`disp`, `hp`, `drat`, `wt`, `qsec`, `vs`, `am`, `gear`, `carb`, rudfdouble('/tmp/8d4a5fc1-a5d1-4048-81dc-e1e3b86b3074_resources/squareudf', `carb`) AS `sq`
FROM `mtcars`) AS `master`
2016-02-10 20:24:32,698 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.ParseDriver (ParseDriver.java:parse(209)) - Parse Completed
2016-02-10 20:24:32,699 INFO  [HiveServer2-Handler-Pool: Thread-4907]: log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=parse start=1455135872695 end=145513587269
9 duration=4 from=org.apache.hadoop.hive.ql.Driver>
2016-02-10 20:24:32,704 INFO  [HiveServer2-Handler-Pool: Thread-4907]: log.PerfLogger (PerfLogger.java:PerfLogBegin(121)) - <PERFLOG method=semanticAnalyze from=org.apache.hadoop.hi
ve.ql.Driver>
2016-02-10 20:24:32,704 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:analyzeInternal(10105)) - Starting Semantic Analysis
2016-02-10 20:24:32,704 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:genResolvedParseTree(10052)) - Completed phase 1 of Semantic Analy
sis
2016-02-10 20:24:32,705 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1534)) - Get metadata for source tables
2016-02-10 20:24:32,705 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1686)) - Get metadata for subqueries
2016-02-10 20:24:32,705 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1534)) - Get metadata for source tables
2016-02-10 20:24:32,706 INFO  [HiveServer2-Handler-Pool: Thread-4907]: metastore.ObjectStore (ObjectStore.java:initialize(290)) - ObjectStore, initialize called
2016-02-10 20:24:32,708 WARN  [HiveServer2-Handler-Pool: Thread-4907]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:determineDbType(160)) - DB Product name[MySQL] obtained,
 but not used to determine db type. Falling back to using SQL to determine which db we're using
2016-02-10 20:24:32,713 INFO  [HiveServer2-Handler-Pool: Thread-4907]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(140)) - Using direct SQL, underlying DB is MYSQL
2016-02-10 20:24:32,713 INFO  [HiveServer2-Handler-Pool: Thread-4907]: metastore.ObjectStore (ObjectStore.java:setConf(273)) - Initialized ObjectStore
2016-02-10 20:24:32,714 INFO  [HiveServer2-Handler-Pool: Thread-4907]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(747)) - 213: get_table : db=default tbl=mtcars
2016-02-10 20:24:32,714 INFO  [HiveServer2-Handler-Pool: Thread-4907]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(372)) - ugi=hive   ip=unknown-ip-addr      cmd=get_table
 : db=default tbl=mtcars   
2016-02-10 20:24:32,753 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1686)) - Get metadata for subqueries
2016-02-10 20:24:32,753 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1710)) - Get metadata for destination tables
2016-02-10 20:24:32,753 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1710)) - Get metadata for destination tables
2016-02-10 20:24:32,772 INFO  [HiveServer2-Handler-Pool: Thread-4907]: ql.Context (Context.java:getMRScratchDir(330)) - New scratch dir is hdfs://sandbox.hortonworks.com:8020/tmp/hi
ve/hive/8d4a5fc1-a5d1-4048-81dc-e1e3b86b3074/hive_2016-02-10_20-24-32_695_972448943093277787-40
2016-02-10 20:24:32,772 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.CalcitePlanner (SemanticAnalyzer.java:genResolvedParseTree(10056)) - Completed getting MetaData in Seman
tic Analysis
2016-02-10 20:24:32,772 INFO  [HiveServer2-Handler-Pool: Thread-4907]: parse.BaseSemanticAnalyzer (CalcitePlanner.java:canCBOHandleAst(392)) - Not invoking CBO because the statement
 has too few joins
2016-02-10 20:24:33,382 INFO  [HiveServer2-Handler-Pool: Thread-4907]: log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=compile start=1455135872694 end=1455135873382 duration=688 from=org.apache.hadoop.hive.ql.Driver>
2016-02-10 20:24:49,568 INFO  [hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]: queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down. sleeping for 30000 milli seconds. indexQueue=0, queueName=hiveServer2.async.multi_dest.batch, consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:24:52,083 INFO  [org.apache.ranger.audit.queue.AuditBatchQueue1]: provider.BaseAuditHandler (BaseAuditHandler.java:logStatus(301)) - Audit Status Log: name=hiveServer2.async.multi_dest.batch, finalDestination=hiveServer2.async.multi_dest.batch.hdfs, interval=01:00.009 minutes, events=14, succcessCount=5, totalEvents=420, totalSuccessCount=111, totalStashedCount=184
2016-02-10 20:25:03,352 INFO  [org.apache.ranger.audit.queue.AuditBatchQueue0]: provider.BaseAuditHandler (BaseAuditHandler.java:logStatus(301)) - Audit Status Log: name=hiveServer2.async.multi_dest.batch, finalDestination=hiveServer2.async.multi_dest.batch.db, interval=01:02.999 minutes, events=5, succcessCount=2, totalEvents=717, totalSuccessCount=295
2016-02-10 20:25:31,635 INFO  [HiveServer2-Handler-Pool: Thread-5400]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
2016-02-10 20:25:31,653 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created local directory: /tmp/47f78843-0f14-4db5-ad7c-318b37ac44c9_resources
2016-02-10 20:25:31,662 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created HDFS directory: /tmp/hive/hive/47f78843-0f14-4db5-ad7c-318b37ac44c9
2016-02-10 20:25:31,665 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created local directory: /tmp/hive/47f78843-0f14-4db5-ad7c-318b37ac44c9
2016-02-10 20:25:31,672 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created HDFS directory: /tmp/hive/hive/47f78843-0f14-4db5-ad7c-318b37ac44c9/_tmp_space.db
2016-02-10 20:25:31,675 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(236)) - Operation log session directory is created: /home/hive/${system:java.io.tmpdir}/${system:user.name}/operation_logs/47f78843-0f14-4db5-ad7c-318b37ac44c9
2016-02-10 20:25:49,569 INFO  [hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]: queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down. sleeping for 30000 milli seconds. indexQueue=0, queueName=hiveServer2.async.multi_dest.batch, consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:26:30,890 INFO  [HiveServer2-Handler-Pool: Thread-5400]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
2016-02-10 20:26:30,902 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created local directory: /tmp/2ca839b8-f6e5-465d-9ae7-3cbe5418be64_resources
2016-02-10 20:26:30,910 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created HDFS directory: /tmp/hive/hive/2ca839b8-f6e5-465d-9ae7-3cbe5418be64
2016-02-10 20:26:30,914 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created local directory: /tmp/hive/2ca839b8-f6e5-465d-9ae7-3cbe5418be64
2016-02-10 20:26:30,922 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created HDFS directory: /tmp/hive/hive/2ca839b8-f6e5-465d-9ae7-3cbe5418be64/_tmp_space.db
2016-02-10 20:26:30,926 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(236)) - Operation log session directory is created: /home/hive/${system:java.io.tmpdir}/${system:user.name}/operation_logs/2ca839b8-f6e5-465d-9ae7-3cbe5418be64
2016-02-10 20:26:49,571 INFO  [hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]: queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down. sleeping for 30000 milli seconds. indexQueue=0, queueName=hiveServer2.async.multi_dest.batch, consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:27:31,748 INFO  [HiveServer2-Handler-Pool: Thread-5400]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
2016-02-10 20:27:31,763 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created local directory: /tmp/701b1cef-63c4-4c13-a275-fe28469eccc8_resources
2016-02-10 20:27:31,771 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created HDFS directory: /tmp/hive/hive/701b1cef-63c4-4c13-a275-fe28469eccc8
2016-02-10 20:27:31,776 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created local directory: /tmp/hive/701b1cef-63c4-4c13-a275-fe28469eccc8
2016-02-10 20:27:31,783 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.SessionState (SessionState.java:createPath(641)) - Created HDFS directory: /tmp/hive/hive/701b1cef-63c4-4c13-a275-fe28469eccc8/_tmp_space.db
2016-02-10 20:27:31,787 INFO  [HiveServer2-Handler-Pool: Thread-5400]: session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(236)) - Operation log session directory is created: /home/hive/${system:java.io.tmpdir}/${system:user.name}/operation_logs/701b1cef-63c4-4c13-a275-fe28469eccc8
2016-02-10 20:27:49,572 INFO  [hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]: queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down. sleeping for 30000 milli seconds. indexQueue=0, queueName=hiveServer2.async.multi_dest.batch, consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:28:31,397 INFO  [HiveServer2-Handler-Pool: Thread-5400]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: Antonio Piccolboni

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 10/Feb/16 20:51

Updated:: 05/May/16 22:24