Skip to content

Commit

Permalink
[feat](log) Add more log about cost time for dropTable
Browse files Browse the repository at this point in the history 
* In some p0 test cases we have found dropTable cost more than
  5 seconds, so add more time cost log
  • Loading branch information
@SWJTU-ZhangLei
SWJTU-ZhangLei committed Jan 24, 2024
1 parent 00283a5 commit 865c8d1
Show file tree
Hide file tree
Showing 2 changed files with 134 additions and 90 deletions.
201 changes: 113 additions & 88 deletions fe/fe-core/src/main/java/org/apache/doris/catalog/CatalogRecycleBin.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@
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;

Expand Down Expand Up @@ -220,28 +221,36 @@ private synchronized boolean isExpire(long id, long currentTimeMs) {
}

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());
}
}

Expand Down Expand Up @@ -327,46 +336,54 @@ public synchronized void replayEraseDatabase(long dbId) {
}

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);

// erase table
tableIter.remove();
idToRecycleTime.remove(tableId);
// log
Env.getCurrentEnv().getEditLog().logEraseTable(tableId);
LOG.info("erase table[{}]", tableId);
eraseNum++;
}
} // end for tables

// 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());
}
}

Expand Down Expand Up @@ -441,43 +458,51 @@ public synchronized void replayEraseTable(long tableId) {
}

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);
eraseNum++;
}
} // 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);
// 2. erase exceed number
if (keepNum < 0) {
return;
}
} // 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);
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());
}
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);
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());
}
}

Expand Down
23 changes: 21 additions & 2 deletions fe/fe-core/src/main/java/org/apache/doris/datasource/InternalCatalog.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -175,6 +175,7 @@
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;
Expand Down Expand Up @@ -836,6 +837,8 @@ public void replayRenameDatabase(String dbName, String newDbName) {

// 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());
Expand All @@ -847,6 +850,8 @@ public void dropTable(DropTableStmt stmt) throws DdlException {
}

db.writeLockOrDdlException();
watch.split();
costTimes.put("1:dbWriteLock", watch.getSplitTime());
try {
Table table = db.getTableNullable(tableName);
if (table == null) {
Expand Down Expand Up @@ -882,8 +887,12 @@ public void dropTable(DropTableStmt stmt) throws DdlException {
+ "] 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()) {
Expand All @@ -899,8 +908,12 @@ public void dropTable(DropTableStmt stmt) throws DdlException {
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();
Expand All @@ -920,7 +933,10 @@ public void dropTable(DropTableStmt stmt) throws DdlException {
} 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,
Expand All @@ -936,8 +952,11 @@ public boolean unprotectDropTable(Database db, Table table, boolean isForceDrop,
}

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;
}

Expand Down

0 comments on commit 865c8d1

Please sign in to comment.