Skip to content

Commit

Permalink
Refine logging
Browse files Browse the repository at this point in the history 
Signed-off-by: JaySon-Huang <[email protected]>
  • Loading branch information
@JaySon-Huang
JaySon-Huang committed Jul 14, 2024
1 parent 2654061 commit a0fc643
Show file tree
Hide file tree
Showing 2 changed files with 55 additions and 44 deletions.
89 changes: 50 additions & 39 deletions dbms/src/TiDB/Schema/SchemaBuilder.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -489,7 +489,7 @@ void SchemaBuilder<Getter, NameMapper>::applyDiff(const SchemaDiff & diff)
auto db_info = getter.getDatabase(opt.schema_id);
if (db_info == nullptr)
throw TiFlashException("miss database: " + std::to_string(diff.schema_id), Errors::DDL::StaleSchema);
applyRenameTable(db_info, opt.table_id);
applyRenameTable(db_info, opt.table_id, "RenameTables");
}
return;
}
Expand Down Expand Up @@ -536,7 +536,7 @@ void SchemaBuilder<Getter, NameMapper>::applyDiff(const SchemaDiff & diff)
}
case SchemaActionType::RenameTable:
{
applyRenameTable(db_info, diff.table_id);
applyRenameTable(db_info, diff.table_id, "RenameTable");
break;
}
case SchemaActionType::AddTablePartition:
Expand Down Expand Up @@ -573,7 +573,8 @@ void SchemaBuilder<Getter, NameMapper>::applyDiff(const SchemaDiff & diff)

if (old_table_id)
{
applyDropTable(db_info, old_table_id);
String action = fmt::format("{}", magic_enum::enum_name(diff.type));
applyDropTable(db_info, old_table_id, action);
}

if (new_table_id)
Expand All @@ -588,19 +589,19 @@ void SchemaBuilder<Getter, NameMapper>::applyPartitionDiff(const TiDB::DBInfoPtr
auto table_info = getter.getTableInfo(db_info->id, table_id);
if (table_info == nullptr)
{
throw TiFlashException(fmt::format("miss old table id in TiKV {}", table_id), Errors::DDL::StaleSchema);
throw TiFlashException(fmt::format("miss old table id in TiKV when applyPartitionDiff, table_id={}", table_id), Errors::DDL::StaleSchema);
}
if (!table_info->isLogicalPartitionTable())
{
throw TiFlashException(fmt::format("new table in TiKV not partition table {}", name_mapper.debugCanonicalName(*db_info, *table_info)),
throw TiFlashException(fmt::format("new table in TiKV not partition table when applyPartitionDiff, {}", name_mapper.debugCanonicalName(*db_info, *table_info)),
Errors::DDL::TableTypeNotMatch);
}

auto & tmt_context = context.getTMTContext();
auto storage = tmt_context.getStorages().get(table_info->id);
if (storage == nullptr)
{
throw TiFlashException(fmt::format("miss table in TiFlash {}", table_id), Errors::DDL::MissingTable);
throw TiFlashException(fmt::format("miss table in TiFlash when applyPartitionDiff, table_id={}", table_id), Errors::DDL::MissingTable);
}

applyPartitionDiff(db_info, table_info, storage, /*drop_part_if_not_exist*/ true);
Expand Down Expand Up @@ -686,10 +687,10 @@ void SchemaBuilder<Getter, NameMapper>::applyPartitionDiff(const TiDB::DBInfoPtr
if (new_part_id_set.count(orig_def.id) == 0)
{
const auto part_table_name = name_mapper.mapTableNameByID(orig_def.id);
// When `tryLoadSchemaDiffs` fails, we may run into `SchemaBuilder::syncAllSchem` -> `applyPartitionDiff` without `applyExchangeTablePartition`
// When `tryLoadSchemaDiffs` fails, we may run into `SchemaBuilder::syncAllSchema` -> `applyPartitionDiff` without `applyExchangeTablePartition`
// The physical table maybe `EXCHANGE` to another database, try to find the partition from all database
auto part_db_info = tryFindDatabaseByPartitionTable(db_info, part_table_name);
applyDropPhysicalTable(name_mapper.mapDatabaseName(*part_db_info), orig_def.id);
applyDropPhysicalTable(name_mapper.mapDatabaseName(*part_db_info), orig_def.id, "exchange partition");
}
}
}
Expand All @@ -700,7 +701,7 @@ void SchemaBuilder<Getter, NameMapper>::applyPartitionDiff(const TiDB::DBInfoPtr
{
auto part_table_info = updated_table_info.producePartitionTableInfo(new_def.id, name_mapper);
const auto part_table_name = name_mapper.mapTableName(*part_table_info);
// When `tryLoadSchemaDiffs` fails, we may run into `SchemaBuilder::syncAllSchem` -> `applyPartitionDiff` without `applyExchangeTablePartition`
// When `tryLoadSchemaDiffs` fails, we may run into `SchemaBuilder::syncAllSchema` -> `applyPartitionDiff` without `applyExchangeTablePartition`
// The physical table maybe `EXCHANGE` from another database, try to find the partition from all database
auto part_db_info = tryFindDatabaseByPartitionTable(db_info, part_table_name);
applyCreatePhysicalTable(part_db_info, part_table_info);
Expand All @@ -715,31 +716,32 @@ void SchemaBuilder<Getter, NameMapper>::applyPartitionDiff(const TiDB::DBInfoPtr
}

template <typename Getter, typename NameMapper>
void SchemaBuilder<Getter, NameMapper>::applyRenameTable(const DBInfoPtr & new_db_info, TableID table_id)
void SchemaBuilder<Getter, NameMapper>::applyRenameTable(const DBInfoPtr & new_db_info, TableID table_id, std::string_view action)
{
auto new_table_info = getter.getTableInfo(new_db_info->id, table_id);
if (new_table_info == nullptr)
{
throw TiFlashException(fmt::format("miss table id in TiKV {}", table_id), Errors::DDL::StaleSchema);
throw TiFlashException(fmt::format("miss table id in TiKV when renameTable, table_id={} action={}", table_id, action), Errors::DDL::StaleSchema);
}

auto & tmt_context = context.getTMTContext();
auto storage = tmt_context.getStorages().get(table_id);
if (storage == nullptr)
{
throw TiFlashException(fmt::format("miss table id in TiFlash {}", table_id), Errors::DDL::MissingTable);
throw TiFlashException(fmt::format("miss table id in TiFlash when renameTable, table_id={} action={}", table_id, action), Errors::DDL::MissingTable);
}

applyRenameLogicalTable(new_db_info, new_table_info, storage);
applyRenameLogicalTable(new_db_info, new_table_info, storage, action);
}

template <typename Getter, typename NameMapper>
void SchemaBuilder<Getter, NameMapper>::applyRenameLogicalTable(
const DBInfoPtr & new_db_info,
const TableInfoPtr & new_table_info,
const ManageableStoragePtr & storage)
const ManageableStoragePtr & storage,
std::string_view action)
{
applyRenamePhysicalTable(new_db_info, *new_table_info, storage);
applyRenamePhysicalTable(new_db_info, *new_table_info, storage, action);

if (new_table_info->isLogicalPartitionTable())
{
Expand All @@ -749,10 +751,16 @@ void SchemaBuilder<Getter, NameMapper>::applyRenameLogicalTable(
auto part_storage = tmt_context.getStorages().get(part_def.id);
if (part_storage == nullptr)
{
throw Exception(fmt::format("miss old table id in Flash {}", part_def.id));
throw Exception( //
ErrorCodes::LOGICAL_ERROR,
"Storage instance is not exist in TiFlash, the partition is not created yet in this TiFlash instance, "
"physical_table_id={} logical_table_id={} action={}",
part_def.id,
new_table_info->id,
action);
}
auto part_table_info = new_table_info->producePartitionTableInfo(part_def.id, name_mapper);
applyRenamePhysicalTable(new_db_info, *part_table_info, part_storage);
applyRenamePhysicalTable(new_db_info, *part_table_info, part_storage, action);
}
}
}
Expand All @@ -761,27 +769,29 @@ template <typename Getter, typename NameMapper>
void SchemaBuilder<Getter, NameMapper>::applyRenamePhysicalTable(
const DBInfoPtr & new_db_info,
const TableInfo & new_table_info,
const ManageableStoragePtr & storage)
const ManageableStoragePtr & storage,
std::string_view action)
{
const auto old_mapped_db_name = storage->getDatabaseName();
const auto new_mapped_db_name = name_mapper.mapDatabaseName(*new_db_info);
const auto old_display_table_name = name_mapper.displayTableName(storage->getTableInfo());
const auto new_display_table_name = name_mapper.displayTableName(new_table_info);
if (old_mapped_db_name == new_mapped_db_name && old_display_table_name == new_display_table_name)
{
LOG_DEBUG(log, "Table {} name identical, not renaming.", name_mapper.debugCanonicalName(*new_db_info, new_table_info));
LOG_DEBUG(log, "Table {} name identical, not renaming, action={}", name_mapper.debugCanonicalName(*new_db_info, new_table_info), action);
return;
}

const auto old_mapped_tbl_name = storage->getTableName();
GET_METRIC(tiflash_schema_internal_ddl_count, type_rename_column).Increment();
LOG_INFO(
log,
"Renaming table {}.{} (display name: {}) to {}.",
"Renaming table {}.{} (display name: {}) to {}, action={}",
old_mapped_db_name,
old_mapped_tbl_name,
old_display_table_name,
name_mapper.debugCanonicalName(*new_db_info, new_table_info));
name_mapper.debugCanonicalName(*new_db_info, new_table_info),
action);

// Note that rename will update table info in table create statement by modifying original table info
// with "tidb_display.table" instead of using new_table_info directly, so that other changes
Expand All @@ -797,11 +807,12 @@ void SchemaBuilder<Getter, NameMapper>::applyRenamePhysicalTable(

LOG_INFO(
log,
"Renamed table {}.{} (display name: {}) to {}",
"Renamed table {}.{} (display name: {}) to {}, action={}",
old_mapped_db_name,
old_mapped_tbl_name,
old_display_table_name,
name_mapper.debugCanonicalName(*new_db_info, new_table_info));
name_mapper.debugCanonicalName(*new_db_info, new_table_info),
action);
}

template <typename Getter, typename NameMapper>
Expand Down Expand Up @@ -897,7 +908,7 @@ void SchemaBuilder<Getter, NameMapper>::applyExchangeTablePartition(const Schema
FAIL_POINT_TRIGGER_EXCEPTION(FailPoints::exception_before_step_2_rename_in_exchange_partition);

if (npt_db_info->id != pt_db_info->id)
applyRenamePhysicalTable(pt_db_info, orig_table_info, storage);
applyRenamePhysicalTable(pt_db_info, orig_table_info, storage, "exchange partition");
FAIL_POINT_TRIGGER_EXCEPTION(FailPoints::exception_after_step_2_in_exchange_partition);

/// step 3 change partition of the partition table to non partition table
Expand Down Expand Up @@ -929,9 +940,9 @@ void SchemaBuilder<Getter, NameMapper>::applyExchangeTablePartition(const Schema
FAIL_POINT_TRIGGER_EXCEPTION(FailPoints::exception_before_step_3_rename_in_exchange_partition);

if (npt_db_info->id != pt_db_info->id)
applyRenamePhysicalTable(npt_db_info, orig_table_info, storage);
applyRenamePhysicalTable(npt_db_info, orig_table_info, storage, "exchange partition");
FAIL_POINT_TRIGGER_EXCEPTION(FailPoints::exception_after_step_3_in_exchange_partition);
LOG_INFO(log, "Execute exchange partition done, npt_table_id={} npt_database_id={} pt_table_id={} pt_partition_id={} pt_database_id={}", npt_table_id, npt_database_id, pt_table_id, pt_partition_id, pt_database_id);
LOG_INFO(log, "Execute exchange partition done, npt_table_id={} npt_database_id={} pt_table_id={} pt_partition_id={} pt_database_id={}", npt_table_id, npt_database_id, pt_table_id, pt_partition_id, pt_database_id);
}

template <typename Getter, typename NameMapper>
Expand Down Expand Up @@ -1026,11 +1037,11 @@ template <typename Getter, typename NameMapper>
void SchemaBuilder<Getter, NameMapper>::applyDropSchema(const String & db_name)
{
GET_METRIC(tiflash_schema_internal_ddl_count, type_drop_db).Increment();
LOG_INFO(log, "Tombstoning database {}", db_name);
LOG_INFO(log, "Tombstone database begin, db_name={}", db_name);
auto db = context.tryGetDatabase(db_name);
if (db == nullptr)
{
LOG_INFO(log, "Database {} does not exists", db_name);
LOG_INFO(log, "Database does not exists, db_name={}", db_name);
return;
}

Expand All @@ -1047,7 +1058,7 @@ void SchemaBuilder<Getter, NameMapper>::applyDropSchema(const String & db_name)
auto tombstone = PDClientHelper::getTSO(tmt_context.getPDClient(), PDClientHelper::get_tso_maxtime);
db->alterTombstone(context, tombstone, /*new_db_info*/ nullptr); // keep the old db_info

LOG_INFO(log, "Tombstoned database {}, tombstone={}", db_name, tombstone);
LOG_INFO(log, "Tombstone database end, db_name={} tombstone={}", db_name, tombstone);
}

template <typename Getter, typename NameMapper>
Expand Down Expand Up @@ -1269,25 +1280,25 @@ void SchemaBuilder<Getter, NameMapper>::applyCreateLogicalTable(const TiDB::DBIn
}

template <typename Getter, typename NameMapper>
void SchemaBuilder<Getter, NameMapper>::applyDropPhysicalTable(const String & db_name, TableID table_id)
void SchemaBuilder<Getter, NameMapper>::applyDropPhysicalTable(const String & db_name, TableID table_id, std::string_view action)
{
auto & tmt_context = context.getTMTContext();
auto storage = tmt_context.getStorages().get(table_id);
if (storage == nullptr)
{
LOG_DEBUG(log, "table {} does not exist.", table_id);
LOG_DEBUG(log, "table does not exist, table_id={} action={}", table_id, action);
return;
}

// Skip updating the tombstone_ts if the table is already tombstone.
if (auto tombstone_ts = storage->getTombstone(); tombstone_ts != 0)
{
LOG_INFO(log, "Tombstone table {}.{} has been done before, tombstone={}", db_name, name_mapper.debugTableName(storage->getTableInfo()), tombstone_ts);
LOG_INFO(log, "Tombstone table {}.{} has been done before, action={} tombstone={}", db_name, name_mapper.debugTableName(storage->getTableInfo()), action, tombstone_ts);
return;
}

GET_METRIC(tiflash_schema_internal_ddl_count, type_drop_table).Increment();
LOG_INFO(log, "Tombstone table {}.{} begin", db_name, name_mapper.debugTableName(storage->getTableInfo()));
LOG_INFO(log, "Tombstone table {}.{} begin, action={}", db_name, name_mapper.debugTableName(storage->getTableInfo()), action);
const auto tombstone_ts = PDClientHelper::getTSO(tmt_context.getPDClient(), PDClientHelper::get_tso_maxtime);
AlterCommands commands;
{
Expand All @@ -1303,11 +1314,11 @@ void SchemaBuilder<Getter, NameMapper>::applyDropPhysicalTable(const String & db
}
auto alter_lock = storage->lockForAlter(getThreadName());
storage->alterFromTiDB(alter_lock, commands, db_name, storage->getTableInfo(), name_mapper, context);
LOG_INFO(log, "Tombstone table {}.{} end, tombstone={}", db_name, name_mapper.debugTableName(storage->getTableInfo()), tombstone_ts);
LOG_INFO(log, "Tombstone table {}.{} end, action={} tombstone={}", db_name, name_mapper.debugTableName(storage->getTableInfo()), action, tombstone_ts);
}

template <typename Getter, typename NameMapper>
void SchemaBuilder<Getter, NameMapper>::applyDropTable(const DBInfoPtr & db_info, TableID table_id)
void SchemaBuilder<Getter, NameMapper>::applyDropTable(const DBInfoPtr & db_info, TableID table_id, std::string_view action)
{
auto & tmt_context = context.getTMTContext();
auto * storage = tmt_context.getStorages().get(table_id).get();
Expand All @@ -1321,13 +1332,13 @@ void SchemaBuilder<Getter, NameMapper>::applyDropTable(const DBInfoPtr & db_info
{
for (const auto & part_def : table_info.partition.definitions)
{
applyDropPhysicalTable(name_mapper.mapDatabaseName(*db_info), part_def.id);
applyDropPhysicalTable(name_mapper.mapDatabaseName(*db_info), part_def.id, action);
}
}

// Drop logical table at last, only logical table drop will be treated as "complete".
// Intermediate failure will hide the logical table drop so that schema syncing when restart will re-drop all (despite some physical tables may have dropped).
applyDropPhysicalTable(name_mapper.mapDatabaseName(*db_info), table_info.id);
applyDropPhysicalTable(name_mapper.mapDatabaseName(*db_info), table_info.id, action);
}

template <typename Getter, typename NameMapper>
Expand Down Expand Up @@ -1463,7 +1474,7 @@ void SchemaBuilder<Getter, NameMapper>::syncAllSchema()
applyPartitionDiff(db, table, storage, /*drop_part_if_not_exist*/ true);
}
/// Rename if needed.
applyRenameLogicalTable(db, table, storage);
applyRenameLogicalTable(db, table, storage, "SyncAllSchema");
/// Update replica info if needed.
applySetTiFlashReplicaOnLogicalTable(db, table, storage);
/// Alter if needed.
Expand All @@ -1479,7 +1490,7 @@ void SchemaBuilder<Getter, NameMapper>::syncAllSchema()
{
if (table_set.count(it->first) == 0)
{
applyDropPhysicalTable(it->second->getDatabaseName(), it->first);
applyDropPhysicalTable(it->second->getDatabaseName(), it->first, "SyncAllSchema");
LOG_INFO(log, "Table {}.{} dropped during sync all schemas", it->second->getDatabaseName(), name_mapper.debugTableName(it->second->getTableInfo()));
}
}
Expand Down
10 changes: 5 additions & 5 deletions dbms/src/TiDB/Schema/SchemaBuilder.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,10 +65,10 @@ struct SchemaBuilder

void applyCreatePhysicalTable(const TiDB::DBInfoPtr & db_info, const TiDB::TableInfoPtr & table_info);

void applyDropTable(const TiDB::DBInfoPtr & db_info, TableID table_id);
void applyDropTable(const TiDB::DBInfoPtr & db_info, TableID table_id, std::string_view action);

/// Parameter schema_name should be mapped.
void applyDropPhysicalTable(const String & db_name, TableID table_id);
void applyDropPhysicalTable(const String & db_name, TableID table_id, std::string_view action);

void applyPartitionDiff(const TiDB::DBInfoPtr & db_info, TableID table_id);

Expand All @@ -81,11 +81,11 @@ struct SchemaBuilder

void applyAlterPhysicalTable(const TiDB::DBInfoPtr & db_info, const TiDB::TableInfoPtr & table_info, const ManageableStoragePtr & storage);

void applyRenameTable(const TiDB::DBInfoPtr & new_db_info, TiDB::TableID table_id);
void applyRenameTable(const TiDB::DBInfoPtr & new_db_info, TiDB::TableID table_id, std::string_view action);

void applyRenameLogicalTable(const TiDB::DBInfoPtr & new_db_info, const TiDB::TableInfoPtr & new_table_info, const ManageableStoragePtr & storage);
void applyRenameLogicalTable(const TiDB::DBInfoPtr & new_db_info, const TiDB::TableInfoPtr & new_table_info, const ManageableStoragePtr & storage, std::string_view action);

void applyRenamePhysicalTable(const TiDB::DBInfoPtr & new_db_info, const TiDB::TableInfo & new_table_info, const ManageableStoragePtr & storage);
void applyRenamePhysicalTable(const TiDB::DBInfoPtr & new_db_info, const TiDB::TableInfo & new_table_info, const ManageableStoragePtr & storage, std::string_view action);

void applyExchangeTablePartition(const SchemaDiff & diff);

Expand Down

0 comments on commit a0fc643

Please sign in to comment.