Support Questions
Find answers, ask questions, and share your expertise

Processing simple 1 line insert hive jobs extremely slow

Explorer

Caveat: I'm a newbie HDP user experimenting with a small cluster at work.

I have HDP 2.4 stack deployed using Ambari on a three node cluster (master = 32gb ram 4 vcores; slaves (x2) = 9gb ram 2 vcores) for my own sandbox. I also installed Hue on top of it. I created a table called test_table with two columns. Whenever I do a simple insert (e.g. insert into test_table values (1, 'abc')), the job is submitted but sits in running for about 15 minutes before it completes.

I've tried setting up a separate queue for Tez and Hive as well as increasing the vcores and memory allocated to it all to no avail. I've pretty much exhausted google as well.

Is this normal behavior? Or is there something that I missed?

4 REPLIES 4

Rising Star

@Rey L

No this is not a normal behaviour and further analysis is require for this issue.

A.) Are you running this query from the "hive cli" or "Hue" ?

B.) Can you try to run the query from the "hive cli" and check the performance?

For further troubleshooting, following should be checked:

1. explain plan i.e

explain insert into test_table values (1, 'abc'));

explain formatted insert into test_table values (1, 'abc'));

2. describe table i.e.

describe test_table;

describe formatted test_table;

3. analyze table i.e.

analyze test_table

4. Also, to understand the Root Cause of the issue, it would be great to look into:

Yarn Logs - for the job id of hive query

HiveMetastore logs

HiveServer2 logs

Explorer

@Ravi

A) Running from Hue.

B) When I run in hive, it takes 7.31 seconds

1. Stage-3 Stats-Aggr Operator Stage-0 Move Operator table:{"serde:":"org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe","name:":"default.test_table","input format:":"org.apache.hadoop.mapred.TextInputFormat","output format:":"org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat"} Stage-2 Dependency Collection{} Stage-1 Map 1 File Output Operator [FS_3] compressed:false Statistics:Num rows: 1 Data size: 15 Basic stats: COMPLETE Column stats: NONE table:{"serde:":"org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe","name:":"default.test_table","input format:":"org.apache.hadoop.mapred.TextInputFormat","output format:":"org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat"} Select Operator [SEL_1] outputColumnNames:["_col0","_col1"] Statistics:Num rows: 1 Data size: 15 Basic stats: COMPLETE Column stats: NONE TableScan [TS_0] alias:values__tmp__table__2 Statistics:Num rows: 1 Data size: 15 Basic stats: COMPLETE Column stats: NONE Time taken: 0.19 seconds, Fetched: 22 row(s) Formatted {"STAGE PLANS":{"Stage-2":{"Dependency Collection":{}},"Stage-1":{"Tez":{"DagId:":"admin_20160716151415_b4943414-7f29-4422-8c54-ae43720fee45:3","DagName:":"","Vertices:":{"Map 1":{"Map Operator Tree:":[{"TableScan":{"alias:":"values__tmp__table__3","children":{"Select Operator":{"expressions:":"UDFToInteger(tmp_values_col1) (type: int), tmp_values_col2 (type: string)","outputColumnNames:":["_col0","_col1"],"children":{"File Output Operator":{"Statistics:":"Num rows: 1 Data size: 15 Basic stats: COMPLETE Column stats: NONE","compressed:":"false","table:":{"serde:":"org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe","name:":"default.test_table","input format:":"org.apache.hadoop.mapred.TextInputFormat","output format:":"org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat"}}},"Statistics:":"Num rows: 1 Data size: 15 Basic stats: COMPLETE Column stats: NONE"}},"Statistics:":"Num rows: 1 Data size: 15 Basic stats: COMPLETE Column stats: NONE"}}]}}}},"Stage-0":{"Move Operator":{"tables:":{"replace:":"false","table:":{"serde:":"org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe","name:":"default.test_table","input format:":"org.apache.hadoop.mapred.TextInputFormat","output format:":"org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat"}}}},"Stage-3":{"Stats-Aggr Operator":{}}},"STAGE DEPENDENCIES":{"Stage-2":{"DEPENDENT STAGES":"Stage-1"},"Stage-1":{"ROOT STAGE":"TRUE"},"Stage-0":{"DEPENDENT STAGES":"Stage-2"},"Stage-3":{"DEPENDENT STAGES":"Stage-0"}}} Time taken: 0.179 seconds, Fetched: 1 row(s) 2. id int name string Time taken: 0.409 seconds, Fetched: 2 row(s) Formatted: # col_name data_type comment id int name string # Detailed Table Information Database: default Owner: hive CreateTime: Thu Jul 14 11:56:31 PDT 2016 LastAccessTime: UNKNOWN Protect Mode: None Retention: 0 Location: hdfs://vdchdpdata1:8020/apps/hive/warehouse/test_table Table Type: MANAGED_TABLE Table Parameters: COLUMN_STATS_ACCURATE true numFiles 7 numRows 7 rawDataSize 84 totalSize 91 transient_lastDdlTime 1468707179 # Storage Information SerDe Library: org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe InputFormat: org.apache.hadoop.mapred.TextInputFormat OutputFormat: org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat Compressed: No Num Buckets: -1 Bucket Columns: [] Sort Columns: [] Storage Desc Params: serialization.format 1 Time taken: 0.401 seconds, Fetched: 32 row(s)

Explorer

The logs don't show anything out of the ordinary either.

hivemetastore.log

2016-07-16 15:41:47,522 INFO [pool-3-thread-79]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 79: source:172.23.100.211 get_all_databases 2016-07-16 15:41:47,522 INFO [pool-3-thread-79]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_all_databases 2016-07-16 15:41:47,522 INFO [pool-3-thread-79]: metastore.HiveMetaStore (HiveMetaStore.java:newRawStore(599)) - 79: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore 2016-07-16 15:41:47,523 INFO [pool-3-thread-79]: metastore.ObjectStore (ObjectStore.java:initialize(294)) - ObjectStore, initialize called 2016-07-16 15:41:47,529 INFO [pool-3-thread-79]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(140)) - Using direct SQL, underlying DB is MYSQL 2016-07-16 15:41:47,529 INFO [pool-3-thread-79]: metastore.ObjectStore (ObjectStore.java:setConf(277)) - Initialized ObjectStore 2016-07-16 15:41:47,536 INFO [pool-3-thread-79]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 79: source:172.23.100.211 get_functions: db=default pat=* 2016-07-16 15:41:47,536 INFO [pool-3-thread-79]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_functions: db=default pat=* 2016-07-16 15:41:50,050 INFO [pool-3-thread-79]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 79: source:172.23.100.211 get_all_databases 2016-07-16 15:41:50,051 INFO [pool-3-thread-79]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_all_databases 2016-07-16 15:44:46,625 INFO [pool-3-thread-80]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 80: source:172.23.100.211 get_all_databases 2016-07-16 15:44:46,626 INFO [pool-3-thread-80]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_all_databases 2016-07-16 15:44:46,626 INFO [pool-3-thread-80]: metastore.HiveMetaStore (HiveMetaStore.java:newRawStore(599)) - 80: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore 2016-07-16 15:44:46,627 INFO [pool-3-thread-80]: metastore.ObjectStore (ObjectStore.java:initialize(294)) - ObjectStore, initialize called 2016-07-16 15:44:46,632 INFO [pool-3-thread-80]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(140)) - Using direct SQL, underlying DB is MYSQL 2016-07-16 15:44:46,632 INFO [pool-3-thread-80]: metastore.ObjectStore (ObjectStore.java:setConf(277)) - Initialized ObjectStore 2016-07-16 15:44:46,639 INFO [pool-3-thread-80]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 80: source:172.23.100.211 get_functions: db=default pat=* 2016-07-16 15:44:46,639 INFO [pool-3-thread-80]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_functions: db=default pat=* 2016-07-16 15:44:49,113 INFO [pool-3-thread-80]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 80: source:172.23.100.211 get_all_databases 2016-07-16 15:44:49,114 INFO [pool-3-thread-80]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_all_databases 2016-07-16 15:47:46,887 INFO [pool-3-thread-81]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 81: source:172.23.100.211 get_all_databases 2016-07-16 15:47:46,887 INFO [pool-3-thread-81]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_all_databases 2016-07-16 15:47:46,887 INFO [pool-3-thread-81]: metastore.HiveMetaStore (HiveMetaStore.java:newRawStore(599)) - 81: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore 2016-07-16 15:47:46,888 INFO [pool-3-thread-81]: metastore.ObjectStore (ObjectStore.java:initialize(294)) - ObjectStore, initialize called 2016-07-16 15:47:46,894 INFO [pool-3-thread-81]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(140)) - Using direct SQL, underlying DB is MYSQL 2016-07-16 15:47:46,894 INFO [pool-3-thread-81]: metastore.ObjectStore (ObjectStore.java:setConf(277)) - Initialized ObjectStore 2016-07-16 15:47:46,903 INFO [pool-3-thread-81]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 81: source:172.23.100.211 get_functions: db=default pat=* 2016-07-16 15:47:46,904 INFO [pool-3-thread-81]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_functions: db=default pat=* 2016-07-16 15:47:49,560 INFO [pool-3-thread-81]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(756)) - 81: source:172.23.100.211 get_all_databases 2016-07-16 15:47:49,560 INFO [pool-3-thread-81]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(367)) - ugi=ambari-qaip=172.23.100.211cmd=source:172.23.100.211 get_all_databases

hiveserver2.log

2016-07-16 15:41:46,216 INFO [HiveServer2-Handler-Pool: Thread-106]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8 2016-07-16 15:41:46,231 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created local directory: /tmp/3cb802d1-08cf-44e0-8fd6-ae0c664996b6_resources 2016-07-16 15:41:46,235 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created HDFS directory: /tmp/hive/anonymous/3cb802d1-08cf-44e0-8fd6-ae0c664996b6 2016-07-16 15:41:46,236 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created local directory: /tmp/hive/3cb802d1-08cf-44e0-8fd6-ae0c664996b6 2016-07-16 15:41:46,239 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created HDFS directory: /tmp/hive/anonymous/3cb802d1-08cf-44e0-8fd6-ae0c664996b6/_tmp_space.db 2016-07-16 15:41:46,240 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(257)) - Operation log session directory is created: /tmp/hive/operation_logs/3cb802d1-08cf-44e0-8fd6-ae0c664996b6 2016-07-16 15:41:46,326 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 3cb802d1-08cf-44e0-8fd6-ae0c664996b6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:41:46,326 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:41:46,336 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 3cb802d1-08cf-44e0-8fd6-ae0c664996b6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:41:46,337 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:41:46,368 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 3cb802d1-08cf-44e0-8fd6-ae0c664996b6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:41:46,369 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 3cb802d1-08cf-44e0-8fd6-ae0c664996b6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:41:46,373 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,136 INFO [HiveServer2-Handler-Pool: Thread-106]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8 2016-07-16 15:44:45,148 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created local directory: /tmp/2c0c6deb-3fa0-4221-9236-ae527c9a5ba3_resources 2016-07-16 15:44:45,151 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created HDFS directory: /tmp/hive/anonymous/2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 2016-07-16 15:44:45,152 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created local directory: /tmp/hive/2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 2016-07-16 15:44:45,155 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created HDFS directory: /tmp/hive/anonymous/2c0c6deb-3fa0-4221-9236-ae527c9a5ba3/_tmp_space.db 2016-07-16 15:44:45,156 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(257)) - Operation log session directory is created: /tmp/hive/operation_logs/2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 2016-07-16 15:44:45,247 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,247 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,257 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,257 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,281 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,281 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 2c0c6deb-3fa0-4221-9236-ae527c9a5ba3 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:44:45,284 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,380 INFO [HiveServer2-Handler-Pool: Thread-106]: thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8 2016-07-16 15:47:45,389 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created local directory: /tmp/9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6_resources 2016-07-16 15:47:45,393 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created HDFS directory: /tmp/hive/anonymous/9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 2016-07-16 15:47:45,394 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created local directory: /tmp/hive/9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 2016-07-16 15:47:45,398 INFO [HiveServer2-Handler-Pool: Thread-106]: session.SessionState (SessionState.java:createPath(633)) - Created HDFS directory: /tmp/hive/anonymous/9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6/_tmp_space.db 2016-07-16 15:47:45,399 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(257)) - Operation log session directory is created: /tmp/hive/operation_logs/9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 2016-07-16 15:47:45,488 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,489 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,501 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,502 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,530 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,530 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:acquire(304)) - We are setting the hadoop caller context to 9fe745d7-cdc7-4a61-a2e1-21d9aee26ab6 for thread HiveServer2-Handler-Pool: Thread-106 2016-07-16 15:47:45,534 INFO [HiveServer2-Handler-Pool: Thread-106]: session.HiveSessionImpl (HiveSessionImpl.java:release(318)) - We are resetting the hadoop caller context for thread HiveServer2-Handler-Pool: Thread-106

Explorer

@Ravi

Found something in the yard-resource manager log. 2016-07-16 16:03:43,108 INFO capacity.ParentQueue (ParentQueue.java:completedContainer(623)) - completedContainer queue=root usedCapacity=0.41666666 absoluteUsedCapacity=0.41666666 used=<memory:5120, vCores:4> cluster=<memory:12288, vCores:12> 2016-07-16 16:03:43,108 INFO capacity.ParentQueue (ParentQueue.java:completedContainer(640)) - Re-sorting completed queue: root.hive stats: hive: capacity=0.5, absoluteCapacity=0.5, usedResources=<memory:2048, vCores:1>, usedCapacity=0.33333334, absoluteUsedCapacity=0.16666667, numApps=1, numContainers=1 2016-07-16 16:03:43,108 INFO capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1562)) - Application attempt appattempt_1468709627607_0001_000001 released container container_e11_1468709627607_0001_01_000002 on node: host: vdchdpdata3:45454 #containers=1 available=<memory:2048, vCores:3> used=<memory:2048, vCores:1> with event: FINISHED 2016-07-16 16:03:43,110 INFO capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1536)) - Container container_e11_1468709627607_0001_01_000002 completed with event RELEASED 2016-07-16 16:03:46,877 WARN resourcemanager.RMAuditLogger (RMAuditLogger.java:logFailure(267)) - USER=hueOPERATION=AM Released ContainerTARGET=SchedulerRESULT=FAILUREDESCRIPTION=Trying to release container not owned by app or with invalid id.PERMISSIONS=Unauthorized access or invalid containerAPPID=application_1468709627607_0001CONTAINERID=container_e11_1468709627607_0001_01_000002 2016-07-16 16:03:46,909 INFO scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:run(470)) - Release request cache is cleaned up 2016-07-16 16:14:23,358 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:rememberTargetTransitionsAndStoreState(1200)) - Updating application attempt appattempt_1468709627607_0001_000001 with final state: FINISHING, and exit status: -1000 2016-07-16 16:14:23,358 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(807)) - appattempt_1468709627607_0001_000001 State change from RUNNING to FINAL_SAVING 2016-07-16 16:14:23,359 INFO integration.RMRegistryOperationsService (RMRegistryOperationsService.java:onApplicationAttemptUnregistered(107)) - Application attempt appattempt_1468709627607_0001_000001 unregistered, purging app attempt records 2016-07-16 16:14:23,359 INFO integration.RMRegistryOperationsService (RMRegistryOperationsService.java:purgeRecordsAsync(198)) - records under / with ID appattempt_1468709627607_0001_000001 and policy application-attempt: {} 2016-07-16 16:14:23,359 INFO rmapp.RMAppImpl (RMAppImpl.java:rememberTargetTransitionsAndStoreState(1080)) - Updating application application_1468709627607_0001 with final state: FINISHING notice the time jump from 16:03 to 16:14. That's the only clue/failure I can see from the logs. Not sure if related.