This is an automated email from the ASF dual-hosted git repository.
yiguolei pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/master by this push:
new c9969587457 [feat](log) Add more log about cost time for `dropTable`
(#30284)
c9969587457 is described below
commit c996958745787fed489a8b9b43e22fe8385fc5e8
Author: Lei Zhang <[email protected]>
AuthorDate: Thu Jan 25 13:41:27 2024 +0800
[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
---
.../apache/doris/catalog/CatalogRecycleBin.java | 201 ++++++++++++---------
.../apache/doris/datasource/InternalCatalog.java | 23 ++-
2 files changed, 134 insertions(+), 90 deletions(-)
diff --git
a/fe/fe-core/src/main/java/org/apache/doris/catalog/CatalogRecycleBin.java
b/fe/fe-core/src/main/java/org/apache/doris/catalog/CatalogRecycleBin.java
index ac66dc6dd36..5eaa18f2bf8 100644
--- a/fe/fe-core/src/main/java/org/apache/doris/catalog/CatalogRecycleBin.java
+++ b/fe/fe-core/src/main/java/org/apache/doris/catalog/CatalogRecycleBin.java
@@ -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);
- // 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());
}
}
@@ -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);
+ 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());
}
}
diff --git
a/fe/fe-core/src/main/java/org/apache/doris/datasource/InternalCatalog.java
b/fe/fe-core/src/main/java/org/apache/doris/datasource/InternalCatalog.java
index 51787b66353..9f7d60cdc8f 100644
--- a/fe/fe-core/src/main/java/org/apache/doris/datasource/InternalCatalog.java
+++ b/fe/fe-core/src/main/java/org/apache/doris/datasource/InternalCatalog.java
@@ -175,6 +175,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;
@@ -836,6 +837,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());
@@ -847,6 +850,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) {
@@ -882,8 +887,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()) {
@@ -899,8 +908,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();
@@ -920,7 +933,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,
@@ -936,8 +952,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;
}
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
