[HIVE-16037] with fetch optimization, the query runs after locks are released

• Type: Bug
• Status: Open
• Priority: Critical
• Resolution: Unresolved
• Component/s: Locking, Transactions
• Assignee: Unassigned
• Reporter: Sergey Shelukhin
• Created: 24/Feb/17 22:50
• Updated: 03/Mar/17 00:28

Description

Other assumptions may also be broken.
FetchTask.execute implementation is very curious - it does nothing, and the FetchTask that actually runs the query is put in the same place as the one that normally fetches the results; that is to say, the whole pipeline is run after Driver has "shut down" the query. That releases locks before the query runs, and may also have other implications (for transactions, etc.? I don't think simple fetch can be run for updates)
Adding a log line to TSOP process method, and running encrypted_table_insert from EncryptedHDFS cli driver, I get:

2017-02-24T14:41:24,521 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] log.PerfLogger: <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
[no lines here]
2017-02-24T14:41:24,521 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] log.PerfLogger: </PERFLOG method=runTasks start=1487976084521 end=1487976084521 duration=0 from=org.apache.hadoop.hive.ql.Driver>
...
2017-02-24T14:41:24,521 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] log.PerfLogger: <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2017-02-24T14:41:24,521 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] ZooKeeperHiveLockManager: About to release lock for default/encrypted_table
2017-02-24T14:41:24,523 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] ZooKeeperHiveLockManager: About to release lock for default
2017-02-24T14:41:24,525 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] log.PerfLogger: </PERFLOG method=releaseLocks start=1487976084521 end=1487976084525 duration=4 from=org.apache.hadoop.hive.ql.Driver>
2017-02-24T14:41:24,525 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] log.PerfLogger: </PERFLOG method=Driver.run start=1487976084394 end=1487976084525 duration=131 from=org.apache.hadoop.hive.ql.Driver>
2017-02-24T14:41:24,525 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] ql.Driver: Shutting down query 
...
2017-02-24T14:41:24,532 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] mapred.FileInputFormat: Total # of splits generated by getSplits: 1, TimeTaken: 4
2017-02-24T14:41:24,532 DEBUG [50cde691-3602-4273-a4d9-e35f0c8b6001 main] exec.FetchOperator: Creating fetchTask ...
...
2017-02-24T14:41:24,541  INFO [50cde691-3602-4273-a4d9-e35f0c8b6001 main] exec.TableScanOperator: TODO# calling process
2017-02-24T14:41:24,543  INFO [50cde691-3602-4273-a4d9-e35f0c8b6001 main] exec.TableScanOperator: TODO# calling process
2017-02-24T14:41:24,543  INFO [50cde691-3602-4273-a4d9-e35f0c8b6001 main] exec.TableScanOperator: Closing operator TS[0]
...