[feat](log) Add more log about cost time for dropTable (#30284)
* In some p0 test cases we have found dropTable cost more than 5 seconds, so add more time cost log
This commit is contained in:
Lei Zhang
@ -40,6 +40,7 @@ import com.google.common.collect.Maps;
|
||||
import com.google.common.collect.Range;
|
||||
import com.google.common.collect.Sets;
|
||||
import com.google.common.collect.Table.Cell;
|
||||
import org.apache.commons.lang3.time.StopWatch;
|
||||
import org.apache.logging.log4j.LogManager;
|
||||
import org.apache.logging.log4j.Logger;
|
||||
|
||||
@ -220,28 +221,36 @@ public class CatalogRecycleBin extends MasterDaemon implements Writable {
|
||||
}
|
||||
|
||||
private synchronized void eraseDatabase(long currentTimeMs, int keepNum) {
|
||||
// 1. erase expired database
|
||||
Iterator<Map.Entry<Long, RecycleDatabaseInfo>> dbIter = idToDatabase.entrySet().iterator();
|
||||
while (dbIter.hasNext()) {
|
||||
Map.Entry<Long, RecycleDatabaseInfo> entry = dbIter.next();
|
||||
RecycleDatabaseInfo dbInfo = entry.getValue();
|
||||
Database db = dbInfo.getDb();
|
||||
if (isExpire(db.getId(), currentTimeMs)) {
|
||||
// erase db
|
||||
dbIter.remove();
|
||||
idToRecycleTime.remove(entry.getKey());
|
||||
Env.getCurrentEnv().eraseDatabase(db.getId(), true);
|
||||
LOG.info("erase db[{}]", db.getId());
|
||||
int eraseNum = 0;
|
||||
StopWatch watch = StopWatch.createStarted();
|
||||
try {
|
||||
// 1. erase expired database
|
||||
Iterator<Map.Entry<Long, RecycleDatabaseInfo>> dbIter = idToDatabase.entrySet().iterator();
|
||||
while (dbIter.hasNext()) {
|
||||
Map.Entry<Long, RecycleDatabaseInfo> entry = dbIter.next();
|
||||
RecycleDatabaseInfo dbInfo = entry.getValue();
|
||||
Database db = dbInfo.getDb();
|
||||
if (isExpire(db.getId(), currentTimeMs)) {
|
||||
// erase db
|
||||
dbIter.remove();
|
||||
idToRecycleTime.remove(entry.getKey());
|
||||
Env.getCurrentEnv().eraseDatabase(db.getId(), true);
|
||||
LOG.info("erase db[{}]", db.getId());
|
||||
eraseNum++;
|
||||
}
|
||||
}
|
||||
}
|
||||
// 2. erase exceed number
|
||||
if (keepNum < 0) {
|
||||
return;
|
||||
}
|
||||
Set<String> dbNames = idToDatabase.values().stream().map(d -> d.getDb().getFullName())
|
||||
.collect(Collectors.toSet());
|
||||
for (String dbName : dbNames) {
|
||||
eraseDatabaseWithSameName(dbName, currentTimeMs, keepNum);
|
||||
// 2. erase exceed number
|
||||
if (keepNum < 0) {
|
||||
return;
|
||||
}
|
||||
Set<String> dbNames = idToDatabase.values().stream().map(d -> d.getDb().getFullName())
|
||||
.collect(Collectors.toSet());
|
||||
for (String dbName : dbNames) {
|
||||
eraseDatabaseWithSameName(dbName, currentTimeMs, keepNum);
|
||||
}
|
||||
} finally {
|
||||
watch.stop();
|
||||
LOG.info("eraseDatabase eraseNum: {} cost: {}ms", eraseNum, watch.getTime());
|
||||
}
|
||||
}
|
||||
|
||||
@ -327,46 +336,54 @@ public class CatalogRecycleBin extends MasterDaemon implements Writable {
|
||||
}
|
||||
|
||||
private synchronized void eraseTable(long currentTimeMs, int keepNum) {
|
||||
// 1. erase expired tables
|
||||
Iterator<Map.Entry<Long, RecycleTableInfo>> tableIter = idToTable.entrySet().iterator();
|
||||
while (tableIter.hasNext()) {
|
||||
Map.Entry<Long, RecycleTableInfo> entry = tableIter.next();
|
||||
RecycleTableInfo tableInfo = entry.getValue();
|
||||
Table table = tableInfo.getTable();
|
||||
long tableId = table.getId();
|
||||
int eraseNum = 0;
|
||||
StopWatch watch = StopWatch.createStarted();
|
||||
try {
|
||||
// 1. erase expired tables
|
||||
Iterator<Map.Entry<Long, RecycleTableInfo>> tableIter = idToTable.entrySet().iterator();
|
||||
while (tableIter.hasNext()) {
|
||||
Map.Entry<Long, RecycleTableInfo> entry = tableIter.next();
|
||||
RecycleTableInfo tableInfo = entry.getValue();
|
||||
Table table = tableInfo.getTable();
|
||||
long tableId = table.getId();
|
||||
|
||||
if (isExpire(tableId, currentTimeMs)) {
|
||||
if (table.getType() == TableType.OLAP) {
|
||||
Env.getCurrentEnv().onEraseOlapTable((OlapTable) table, false);
|
||||
if (isExpire(tableId, currentTimeMs)) {
|
||||
if (table.getType() == TableType.OLAP) {
|
||||
Env.getCurrentEnv().onEraseOlapTable((OlapTable) table, false);
|
||||
}
|
||||
|
||||
// erase table
|
||||
tableIter.remove();
|
||||
idToRecycleTime.remove(tableId);
|
||||
|
||||
// log
|
||||
Env.getCurrentEnv().getEditLog().logEraseTable(tableId);
|
||||
LOG.info("erase table[{}]", tableId);
|
||||
eraseNum++;
|
||||
}
|
||||
} // end for tables
|
||||
|
||||
// erase table
|
||||
tableIter.remove();
|
||||
idToRecycleTime.remove(tableId);
|
||||
|
||||
// log
|
||||
Env.getCurrentEnv().getEditLog().logEraseTable(tableId);
|
||||
LOG.info("erase table[{}]", tableId);
|
||||
// 2. erase exceed num
|
||||
if (keepNum < 0) {
|
||||
return;
|
||||
}
|
||||
} // end for tables
|
||||
|
||||
// 2. erase exceed num
|
||||
if (keepNum < 0) {
|
||||
return;
|
||||
}
|
||||
Map<Long, Set<String>> dbId2TableNames = Maps.newHashMap();
|
||||
for (RecycleTableInfo tableInfo : idToTable.values()) {
|
||||
Set<String> tblNames = dbId2TableNames.get(tableInfo.dbId);
|
||||
if (tblNames == null) {
|
||||
tblNames = Sets.newHashSet();
|
||||
dbId2TableNames.put(tableInfo.dbId, tblNames);
|
||||
Map<Long, Set<String>> dbId2TableNames = Maps.newHashMap();
|
||||
for (RecycleTableInfo tableInfo : idToTable.values()) {
|
||||
Set<String> tblNames = dbId2TableNames.get(tableInfo.dbId);
|
||||
if (tblNames == null) {
|
||||
tblNames = Sets.newHashSet();
|
||||
dbId2TableNames.put(tableInfo.dbId, tblNames);
|
||||
}
|
||||
tblNames.add(tableInfo.getTable().getName());
|
||||
}
|
||||
tblNames.add(tableInfo.getTable().getName());
|
||||
}
|
||||
for (Map.Entry<Long, Set<String>> entry : dbId2TableNames.entrySet()) {
|
||||
for (String tblName : entry.getValue()) {
|
||||
eraseTableWithSameName(entry.getKey(), tblName, currentTimeMs, keepNum);
|
||||
for (Map.Entry<Long, Set<String>> entry : dbId2TableNames.entrySet()) {
|
||||
for (String tblName : entry.getValue()) {
|
||||
eraseTableWithSameName(entry.getKey(), tblName, currentTimeMs, keepNum);
|
||||
}
|
||||
}
|
||||
} finally {
|
||||
watch.stop();
|
||||
LOG.info("eraseTable eraseNum: {} cost: {}ms", eraseNum, watch.getTime());
|
||||
}
|
||||
}
|
||||
|
||||
@ -441,43 +458,51 @@ public class CatalogRecycleBin extends MasterDaemon implements Writable {
|
||||
}
|
||||
|
||||
private synchronized void erasePartition(long currentTimeMs, int keepNum) {
|
||||
// 1. erase expired partitions
|
||||
Iterator<Map.Entry<Long, RecyclePartitionInfo>> iterator = idToPartition.entrySet().iterator();
|
||||
while (iterator.hasNext()) {
|
||||
Map.Entry<Long, RecyclePartitionInfo> entry = iterator.next();
|
||||
RecyclePartitionInfo partitionInfo = entry.getValue();
|
||||
Partition partition = partitionInfo.getPartition();
|
||||
int eraseNum = 0;
|
||||
StopWatch watch = StopWatch.createStarted();
|
||||
try {
|
||||
// 1. erase expired partitions
|
||||
Iterator<Map.Entry<Long, RecyclePartitionInfo>> iterator = idToPartition.entrySet().iterator();
|
||||
while (iterator.hasNext()) {
|
||||
Map.Entry<Long, RecyclePartitionInfo> entry = iterator.next();
|
||||
RecyclePartitionInfo partitionInfo = entry.getValue();
|
||||
Partition partition = partitionInfo.getPartition();
|
||||
|
||||
long partitionId = entry.getKey();
|
||||
if (isExpire(partitionId, currentTimeMs)) {
|
||||
Env.getCurrentEnv().onErasePartition(partition);
|
||||
// erase partition
|
||||
iterator.remove();
|
||||
idToRecycleTime.remove(partitionId);
|
||||
// log
|
||||
Env.getCurrentEnv().getEditLog().logErasePartition(partitionId);
|
||||
LOG.info("erase partition[{}]. reason: expired", partitionId);
|
||||
}
|
||||
} // end for partitions
|
||||
long partitionId = entry.getKey();
|
||||
if (isExpire(partitionId, currentTimeMs)) {
|
||||
Env.getCurrentEnv().onErasePartition(partition);
|
||||
// erase partition
|
||||
iterator.remove();
|
||||
idToRecycleTime.remove(partitionId);
|
||||
// log
|
||||
Env.getCurrentEnv().getEditLog().logErasePartition(partitionId);
|
||||
LOG.info("erase partition[{}]. reason: expired", partitionId);
|
||||
eraseNum++;
|
||||
}
|
||||
} // end for partitions
|
||||
|
||||
// 2. erase exceed number
|
||||
if (keepNum < 0) {
|
||||
return;
|
||||
}
|
||||
com.google.common.collect.Table<Long, Long, Set<String>> dbTblId2PartitionNames = HashBasedTable.create();
|
||||
for (RecyclePartitionInfo partitionInfo : idToPartition.values()) {
|
||||
Set<String> partitionNames = dbTblId2PartitionNames.get(partitionInfo.dbId, partitionInfo.tableId);
|
||||
if (partitionNames == null) {
|
||||
partitionNames = Sets.newHashSet();
|
||||
dbTblId2PartitionNames.put(partitionInfo.dbId, partitionInfo.tableId, partitionNames);
|
||||
// 2. erase exceed number
|
||||
if (keepNum < 0) {
|
||||
return;
|
||||
}
|
||||
partitionNames.add(partitionInfo.getPartition().getName());
|
||||
}
|
||||
for (Cell<Long, Long, Set<String>> cell : dbTblId2PartitionNames.cellSet()) {
|
||||
for (String partitionName : cell.getValue()) {
|
||||
erasePartitionWithSameName(cell.getRowKey(), cell.getColumnKey(), partitionName, currentTimeMs,
|
||||
keepNum);
|
||||
com.google.common.collect.Table<Long, Long, Set<String>> dbTblId2PartitionNames = HashBasedTable.create();
|
||||
for (RecyclePartitionInfo partitionInfo : idToPartition.values()) {
|
||||
Set<String> partitionNames = dbTblId2PartitionNames.get(partitionInfo.dbId, partitionInfo.tableId);
|
||||
if (partitionNames == null) {
|
||||
partitionNames = Sets.newHashSet();
|
||||
dbTblId2PartitionNames.put(partitionInfo.dbId, partitionInfo.tableId, partitionNames);
|
||||
}
|
||||
partitionNames.add(partitionInfo.getPartition().getName());
|
||||
}
|
||||
for (Cell<Long, Long, Set<String>> cell : dbTblId2PartitionNames.cellSet()) {
|
||||
for (String partitionName : cell.getValue()) {
|
||||
erasePartitionWithSameName(cell.getRowKey(), cell.getColumnKey(), partitionName, currentTimeMs,
|
||||
keepNum);
|
||||
}
|
||||
}
|
||||
} finally {
|
||||
watch.stop();
|
||||
LOG.info("erasePartition eraseNum: {} cost: {}ms", eraseNum, watch.getTime());
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -173,6 +173,7 @@ import com.google.common.collect.Sets;
|
||||
import lombok.Getter;
|
||||
import org.apache.commons.collections.CollectionUtils;
|
||||
import org.apache.commons.lang3.StringUtils;
|
||||
import org.apache.commons.lang3.time.StopWatch;
|
||||
import org.apache.hadoop.hive.conf.HiveConf;
|
||||
import org.apache.logging.log4j.LogManager;
|
||||
import org.apache.logging.log4j.Logger;
|
||||
@ -834,6 +835,8 @@ public class InternalCatalog implements CatalogIf<Database> {
|
||||
|
||||
// Drop table
|
||||
public void dropTable(DropTableStmt stmt) throws DdlException {
|
||||
Map<String, Long> costTimes = new TreeMap<String, Long>();
|
||||
StopWatch watch = StopWatch.createStarted();
|
||||
String dbName = stmt.getDbName();
|
||||
String tableName = stmt.getTableName();
|
||||
LOG.info("begin to drop table: {} from db: {}, is force: {}", tableName, dbName, stmt.isForceDrop());
|
||||
@ -845,6 +848,8 @@ public class InternalCatalog implements CatalogIf<Database> {
|
||||
}
|
||||
|
||||
db.writeLockOrDdlException();
|
||||
watch.split();
|
||||
costTimes.put("1:dbWriteLock", watch.getSplitTime());
|
||||
try {
|
||||
Table table = db.getTableNullable(tableName);
|
||||
if (table == null) {
|
||||
@ -880,8 +885,12 @@ public class InternalCatalog implements CatalogIf<Database> {
|
||||
+ "] cannot be dropped. If you want to forcibly drop(cannot be recovered),"
|
||||
+ " please use \"DROP table FORCE\".");
|
||||
}
|
||||
watch.split();
|
||||
costTimes.put("2:existCommittedTxns", watch.getSplitTime());
|
||||
}
|
||||
table.writeLock();
|
||||
watch.split();
|
||||
costTimes.put("3:tableWriteLock", watch.getSplitTime());
|
||||
long recycleTime = 0;
|
||||
try {
|
||||
if (table instanceof OlapTable && !stmt.isForceDrop()) {
|
||||
@ -897,8 +906,12 @@ public class InternalCatalog implements CatalogIf<Database> {
|
||||
Env.getCurrentEnv().getMtmvService().dropMTMV((MTMV) table);
|
||||
}
|
||||
unprotectDropTable(db, table, stmt.isForceDrop(), false, 0);
|
||||
watch.split();
|
||||
costTimes.put("4:unprotectDropTable", watch.getSplitTime());
|
||||
if (!stmt.isForceDrop()) {
|
||||
recycleTime = Env.getCurrentRecycleBin().getRecycleTimeById(table.getId());
|
||||
watch.split();
|
||||
costTimes.put("5:getRecycleTimeById", watch.getSplitTime());
|
||||
}
|
||||
} finally {
|
||||
table.writeUnlock();
|
||||
@ -918,7 +931,10 @@ public class InternalCatalog implements CatalogIf<Database> {
|
||||
} finally {
|
||||
db.writeUnlock();
|
||||
}
|
||||
LOG.info("finished dropping table: {} from db: {}, is force: {}", tableName, dbName, stmt.isForceDrop());
|
||||
watch.stop();
|
||||
costTimes.put("6:total", watch.getTime());
|
||||
LOG.info("finished dropping table: {} from db: {}, is force: {} cost: {}",
|
||||
tableName, dbName, stmt.isForceDrop(), costTimes);
|
||||
}
|
||||
|
||||
public boolean unprotectDropTable(Database db, Table table, boolean isForceDrop, boolean isReplay,
|
||||
@ -934,8 +950,11 @@ public class InternalCatalog implements CatalogIf<Database> {
|
||||
}
|
||||
|
||||
db.dropTable(table.getName());
|
||||
StopWatch watch = StopWatch.createStarted();
|
||||
Env.getCurrentRecycleBin().recycleTable(db.getId(), table, isReplay, isForceDrop, recycleTime);
|
||||
LOG.info("finished dropping table[{}] in db[{}]", table.getName(), db.getFullName());
|
||||
watch.stop();
|
||||
LOG.info("finished dropping table[{}] in db[{}] recycleTable cost: {}ms",
|
||||
table.getName(), db.getFullName(), watch.getTime());
|
||||
return true;
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user