Stamatis Zampetakis created HIVE-26404:
--
Summary: HMS memory leak when compaction cleaner fails to remove
obsolete files
Key: HIVE-26404
URL: https://issues.apache.org/jira/browse/HIVE-26404
Project: Hive
Issue Type: Bug
Components: Metastore
Affects Versions: 4.0.0-alpha-1
Reporter: Stamatis Zampetakis
Assignee: Stamatis Zampetakis
While investigating an issue where HMS becomes unresponsive we noticed a lot of
failed attempts from the compaction Cleaner thread to remove obsolete
directories with exceptions similar to the one below.
{noformat}
2022-06-16 05:48:24,819 ERROR org.apache.hadoop.hive.ql.txn.compactor.Cleaner:
[Cleaner-executor-thread-0]: Caught exception when cleaning, unable to complete
cleaning of
id:4410976,dbname:my_database,tableName:my_table,partName:day=20220502,state:,type:MAJOR,enqueueTime:0,start:0,properties:null,runAs:some_user,tooManyAborts:false,hasOldAbort:false,highestWriteId:187502,errorMessage:null
java.io.IOException: Not enough history available for (187502,x). Oldest
available base:
hdfs://nameservice1/warehouse/tablespace/managed/hive/my_database.db/my_table/day=20220502/base_0188687_v4297872
at
org.apache.hadoop.hive.ql.io.AcidUtils.getAcidState(AcidUtils.java:1432)
at
org.apache.hadoop.hive.ql.txn.compactor.Cleaner.removeFiles(Cleaner.java:261)
at
org.apache.hadoop.hive.ql.txn.compactor.Cleaner.access$000(Cleaner.java:71)
at
org.apache.hadoop.hive.ql.txn.compactor.Cleaner$1.run(Cleaner.java:203)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1898)
at
org.apache.hadoop.hive.ql.txn.compactor.Cleaner.clean(Cleaner.java:200)
at
org.apache.hadoop.hive.ql.txn.compactor.Cleaner.lambda$run$0(Cleaner.java:105)
at
org.apache.hadoop.hive.ql.txn.compactor.CompactorUtil$ThrowingRunnable.lambda$unchecked$0(CompactorUtil.java:54)
at
java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1640)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
{noformat}
In addition the logs contained a large number of long JVM pauses as shown below
and the HMS (RSZ) memory kept increasing at rate of 90MB per hour.
{noformat}
2022-06-16 16:17:17,805 WARN
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 34346ms
2022-06-16 16:17:21,497 INFO
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 1690ms
2022-06-16 16:17:57,696 WARN
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 34697ms
2022-06-16 16:18:01,326 INFO
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 1628ms
2022-06-16 16:18:37,280 WARN
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 34453ms
2022-06-16 16:18:40,927 INFO
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 1646ms
2022-06-16 16:19:16,929 WARN
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 33997ms
2022-06-16 16:19:20,572 INFO
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 1637ms
2022-06-16 16:20:01,643 WARN
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor$Monitor@5b022296]:
Detected pause in JVM or host machine (eg GC): pause of approximately 39329ms
2022-06-16 16:20:05,572 INFO
org.apache.hadoop.hive.metastore.metrics.JvmPauseMonitor:
[org.apache.hadoop.h