Hive
  1. Hive
  2. HIVE-7445

Improve LOGS for Hive when a query is not able to acquire locks

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 0.13.1
    • Fix Version/s: 0.14.0
    • Component/s: Diagnosability, Logging
    • Labels:
      None

      Description

      Currently the error thrown when you cannot acquire a lock is:
      Error in acquireLocks...
      FAILED: Error in acquiring locks: Locks on the underlying objects cannot be acquired. retry after some time
      This error is insufficient if the user would like to understand what is blocking them and insufficient from a diagnosability perspective because it is difficult to know what query is blocking the lock acquisition.

      1. HIVE-7445.patch
        4 kB
        Chaoyu Tang
      2. HIVE-7445.1.patch
        12 kB
        Chaoyu Tang
      3. HIVE-7445.2.patch
        12 kB
        Chaoyu Tang
      4. HIVE-7445.3.patch
        12 kB
        Chaoyu Tang

        Activity

        Hide
        Chaoyu Tang added a comment -

        With this patch, when in debug mode, ZooKeeperHiveLockManager logs out all conflicting locks to a lock which it fails to acquire for a query. The logging looks like:
        {code
        14/07/18 09:43:08 ERROR ZooKeeperHiveLockManager: Unable to acquire lock for default@sample_07 mode IMPLICIT
        14/07/18 09:43:08 DEBUG ZooKeeperHiveLockManager: Requested lock default@sample_07:: mode:IMPLICIT; query:insert into table sample_07 select * from sample_08
        14/07/18 09:43:08 DEBUG ZooKeeperHiveLockManager: Conflicting lock to default@sample_07:: mode:IMPLICIT;query:select * from sample_07;queryId:root_20140718064141_439583f9-f281-4d01-ba0c-616523685124;clientIp:10.20.92.233

        
        
        Show
        Chaoyu Tang added a comment - With this patch, when in debug mode, ZooKeeperHiveLockManager logs out all conflicting locks to a lock which it fails to acquire for a query. The logging looks like: {code 14/07/18 09:43:08 ERROR ZooKeeperHiveLockManager: Unable to acquire lock for default@sample_07 mode IMPLICIT 14/07/18 09:43:08 DEBUG ZooKeeperHiveLockManager: Requested lock default@sample_07:: mode:IMPLICIT; query:insert into table sample_07 select * from sample_08 14/07/18 09:43:08 DEBUG ZooKeeperHiveLockManager: Conflicting lock to default@sample_07:: mode:IMPLICIT;query:select * from sample_07;queryId:root_20140718064141_439583f9-f281-4d01-ba0c-616523685124;clientIp:10.20.92.233
        Hide
        Hive QA added a comment -

        Overall: -1 at least one tests failed

        Here are the results of testing the latest attachment:
        https://issues.apache.org/jira/secure/attachment/12656516/HIVE-7445.patch

        ERROR: -1 due to 9 failed/errored test(s), 5725 tests executed
        Failed tests:

        org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into1
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into2
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into3
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into4
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg1
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg_try_db_lock_conflict
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg_try_drop_locked_db
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg_try_lock_db_in_use
        

        Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-Build/855/testReport
        Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-Build/855/console
        Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-Build-855/

        Messages:

        Executing org.apache.hive.ptest.execution.PrepPhase
        Executing org.apache.hive.ptest.execution.ExecutionPhase
        Executing org.apache.hive.ptest.execution.ReportingPhase
        Tests exited with: TestsFailedException: 9 tests failed
        

        This message is automatically generated.

        ATTACHMENT ID: 12656516

        Show
        Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12656516/HIVE-7445.patch ERROR: -1 due to 9 failed/errored test(s), 5725 tests executed Failed tests: org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into1 org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into2 org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into3 org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_insert_into4 org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg1 org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg_try_db_lock_conflict org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg_try_drop_locked_db org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_lockneg_try_lock_db_in_use Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-Build/855/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-Build/855/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-Build-855/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 9 tests failed This message is automatically generated. ATTACHMENT ID: 12656516
        Hide
        Szehon Ho added a comment -

        Hi Chaoyu this is a great idea.

        Thought I'm a little concerned that 'conflictingLocks' is a member variable of the shared ZKLockManager instance. Would that be an issue with different threads calling lock() at same time, as they are sharing access on the variable? Can it be done differently, for example if lock() method passed in a flag to lockPrimitive() telling it whether to print the log? Then it can just make the 'conflictingLock' list locally in the method and print it. Also appreciate a RB for easier viewing

        Show
        Szehon Ho added a comment - Hi Chaoyu this is a great idea. Thought I'm a little concerned that 'conflictingLocks' is a member variable of the shared ZKLockManager instance. Would that be an issue with different threads calling lock() at same time, as they are sharing access on the variable? Can it be done differently, for example if lock() method passed in a flag to lockPrimitive() telling it whether to print the log? Then it can just make the 'conflictingLock' list locally in the method and print it. Also appreciate a RB for easier viewing
        Hide
        Chaoyu Tang added a comment -

        Hi Szehon Ho, thanks for review and comments. I will look into the change based on your comments and also the failed tests.

        Show
        Chaoyu Tang added a comment - Hi Szehon Ho , thanks for review and comments. I will look into the change based on your comments and also the failed tests.
        Hide
        Chaoyu Tang added a comment -

        Hi @Szehon, I made the changes based on your comments (see attached HIVE-7445.1.patch) and also posted it in RB https://reviews.apache.org/r/23820/. Please review it and let me know if there is any problem. Thanks

        Show
        Chaoyu Tang added a comment - Hi @Szehon, I made the changes based on your comments (see attached HIVE-7445 .1.patch) and also posted it in RB https://reviews.apache.org/r/23820/ . Please review it and let me know if there is any problem. Thanks
        Hide
        Hive QA added a comment -

        Overall: -1 at least one tests failed

        Here are the results of testing the latest attachment:
        https://issues.apache.org/jira/secure/attachment/12657166/HIVE-7445.1.patch

        ERROR: -1 due to 3 failed/errored test(s), 5736 tests executed
        Failed tests:

        org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_authorization_fail_8
        org.apache.hive.jdbc.TestJdbcDriver2.testParentReferences
        

        Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/8/testReport
        Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/8/console
        Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-8/

        Messages:

        Executing org.apache.hive.ptest.execution.PrepPhase
        Executing org.apache.hive.ptest.execution.ExecutionPhase
        Executing org.apache.hive.ptest.execution.ReportingPhase
        Tests exited with: TestsFailedException: 3 tests failed
        

        This message is automatically generated.

        ATTACHMENT ID: 12657166

        Show
        Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12657166/HIVE-7445.1.patch ERROR: -1 due to 3 failed/errored test(s), 5736 tests executed Failed tests: org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_authorization_fail_8 org.apache.hive.jdbc.TestJdbcDriver2.testParentReferences Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/8/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/8/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-8/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 3 tests failed This message is automatically generated. ATTACHMENT ID: 12657166
        Hide
        Chaoyu Tang added a comment -

        Changed format based on the review comments and make the indention two empty space.

        Show
        Chaoyu Tang added a comment - Changed format based on the review comments and make the indention two empty space.
        Hide
        Hive QA added a comment -

        Overall: -1 at least one tests failed

        Here are the results of testing the latest attachment:
        https://issues.apache.org/jira/secure/attachment/12657260/HIVE-7445.2.patch

        ERROR: -1 due to 4 failed/errored test(s), 5736 tests executed
        Failed tests:

        org.apache.hadoop.hive.cli.TestMiniTezCliDriver.testCliDriver_tez_join_hash
        org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx
        org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_authorization_fail_8
        org.apache.hive.jdbc.TestJdbcDriver2.testParentReferences
        

        Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/19/testReport
        Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/19/console
        Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-19/

        Messages:

        Executing org.apache.hive.ptest.execution.PrepPhase
        Executing org.apache.hive.ptest.execution.ExecutionPhase
        Executing org.apache.hive.ptest.execution.ReportingPhase
        Tests exited with: TestsFailedException: 4 tests failed
        

        This message is automatically generated.

        ATTACHMENT ID: 12657260

        Show
        Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12657260/HIVE-7445.2.patch ERROR: -1 due to 4 failed/errored test(s), 5736 tests executed Failed tests: org.apache.hadoop.hive.cli.TestMiniTezCliDriver.testCliDriver_tez_join_hash org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx org.apache.hadoop.hive.cli.TestNegativeCliDriver.testNegativeCliDriver_authorization_fail_8 org.apache.hive.jdbc.TestJdbcDriver2.testParentReferences Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/19/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/19/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-19/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 4 tests failed This message is automatically generated. ATTACHMENT ID: 12657260
        Hide
        Hive QA added a comment -

        Overall: -1 at least one tests failed

        Here are the results of testing the latest attachment:
        https://issues.apache.org/jira/secure/attachment/12657343/HIVE-7445.3.patch

        ERROR: -1 due to 2 failed/errored test(s), 5751 tests executed
        Failed tests:

        org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx
        org.apache.hive.jdbc.miniHS2.TestHiveServer2.testConnection
        

        Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/24/testReport
        Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/24/console
        Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-24/

        Messages:

        Executing org.apache.hive.ptest.execution.PrepPhase
        Executing org.apache.hive.ptest.execution.ExecutionPhase
        Executing org.apache.hive.ptest.execution.ReportingPhase
        Tests exited with: TestsFailedException: 2 tests failed
        

        This message is automatically generated.

        ATTACHMENT ID: 12657343

        Show
        Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12657343/HIVE-7445.3.patch ERROR: -1 due to 2 failed/errored test(s), 5751 tests executed Failed tests: org.apache.hadoop.hive.cli.TestMinimrCliDriver.testCliDriver_ql_rewrite_gbtoidx org.apache.hive.jdbc.miniHS2.TestHiveServer2.testConnection Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/24/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/24/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-24/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 2 tests failed This message is automatically generated. ATTACHMENT ID: 12657343
        Hide
        Szehon Ho added a comment -

        Thanks Chaoyu for taking care of review comments. +1

        Show
        Szehon Ho added a comment - Thanks Chaoyu for taking care of review comments. +1
        Hide
        Szehon Ho added a comment -

        Committed to trunk. Thanks Chaoyu for the contribution!

        Show
        Szehon Ho added a comment - Committed to trunk. Thanks Chaoyu for the contribution!
        Hide
        Thejas M Nair added a comment -

        This has been fixed in 0.14 release. Please open new jira if you see any issues.

        Show
        Thejas M Nair added a comment - This has been fixed in 0.14 release. Please open new jira if you see any issues.

          People

          • Assignee:
            Chaoyu Tang
            Reporter:
            Chaoyu Tang
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development