diff --git a/ydb/core/tx/columnshard/columnshard_schema.cpp b/ydb/core/tx/columnshard/columnshard_schema.cpp index c9a60029a892..b55038d4ed95 100644 --- a/ydb/core/tx/columnshard/columnshard_schema.cpp +++ b/ydb/core/tx/columnshard/columnshard_schema.cpp @@ -6,6 +6,7 @@ namespace NKikimr::NColumnShard { bool Schema::InsertTable_Load(NIceDb::TNiceDb& db, const IBlobGroupSelector* dsGroupSelector, NOlap::TInsertTableAccessor& insertTable, const TInstant& /*loadTime*/) { auto rowset = db.Table().Select(); if (!rowset.IsReady()) { + LOG_S_CRIT("Load: insert table rowset is not ready"); return false; } @@ -25,6 +26,7 @@ bool Schema::InsertTable_Load(NIceDb::TNiceDb& db, const IBlobGroupSelector* dsG break; } if (!rowset.Next()) { + LOG_S_CRIT("Load: insert table next failed"); return false; } } diff --git a/ydb/core/tx/columnshard/columnshard_schema.h b/ydb/core/tx/columnshard/columnshard_schema.h index 373077613751..df583c044260 100644 --- a/ydb/core/tx/columnshard/columnshard_schema.h +++ b/ydb/core/tx/columnshard/columnshard_schema.h @@ -882,8 +882,10 @@ struct Schema : NIceDb::Schema { static bool IndexCounters_Load(NIceDb::TNiceDb& db, const std::function& callback) { auto rowset = db.Table().Prefix(0).Select(); - if (!rowset.IsReady()) + if (!rowset.IsReady()) { + LOG_S_CRIT("Load: index counters rowset is not ready"); return false; + } while (!rowset.EndOfSet()) { ui32 id = rowset.GetValue(); @@ -891,8 +893,10 @@ struct Schema : NIceDb::Schema { callback(id, value); - if (!rowset.Next()) + if (!rowset.Next()) { + LOG_S_CRIT("Load: index counters next failed"); return false; + } } return true; } diff --git a/ydb/core/tx/columnshard/counters/common_data.h b/ydb/core/tx/columnshard/counters/common_data.h index 13c793d36d53..5af3c52e13ba 100644 --- a/ydb/core/tx/columnshard/counters/common_data.h +++ b/ydb/core/tx/columnshard/counters/common_data.h @@ -53,4 +53,66 @@ class TDataOwnerSignals: public TCommonCountersOwner { }; +class TLoadTimeSignals: public TCommonCountersOwner { +private: + using TBase = TCommonCountersOwner; + NMonitoring::TDynamicCounters::TCounterPtr TablesLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr SchemaPresetLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr TableVersionsLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr SchemaPresetVersionsLoadingTimeCounter; + + NMonitoring::TDynamicCounters::TCounterPtr TablesLoadingFailCounter; + NMonitoring::TDynamicCounters::TCounterPtr SchemaPresetLoadingFailCounter; + NMonitoring::TDynamicCounters::TCounterPtr TableVersionsLoadingFailCounter; + NMonitoring::TDynamicCounters::TCounterPtr SchemaPresetVersionsLoadingFailCounter; + + +public: + TLoadTimeSignals() + : TBase("Startup") + { + TablesLoadingTimeCounter = TBase::GetValue("Startup/TablesLoadingTime");; + SchemaPresetLoadingTimeCounter = TBase::GetValue("Startup/SchemaPresetLoadingTime");; + TableVersionsLoadingTimeCounter = TBase::GetValue("Startup/TableVersionsLoadingTime");; + SchemaPresetVersionsLoadingTimeCounter = TBase::GetValue("Startup/SchemaPreseVersionstLoadingTime");; + + TablesLoadingFailCounter = TBase::GetValue("Startup/TablesLoadingFailCount");; + SchemaPresetLoadingFailCounter = TBase::GetValue("Startup/SchemaPresetLoadingFailCount");; + TableVersionsLoadingFailCounter = TBase::GetValue("Startup/TableVersionsLoadingFailCount");; + SchemaPresetVersionsLoadingFailCounter = TBase::GetValue("Startup/SchemaPreseVersionstLoadingFailCount");; + } + + void AddTablesLoadingTime(ui64 microSeconds) { + TablesLoadingTimeCounter->Add(microSeconds); + } + + void AddSchemaPresetLoadingTime(ui64 microSeconds) { + SchemaPresetLoadingTimeCounter->Add(microSeconds); + } + + void AddTableVersionsLoadingTime(ui64 microSeconds) { + TableVersionsLoadingTimeCounter->Add(microSeconds); + } + + void AddSchemaPresetVersionsLoadingTime(ui64 microSeconds) { + SchemaPresetVersionsLoadingTimeCounter->Add(microSeconds); + } + + void AddLoadingTablesFail() { + TablesLoadingFailCounter->Add(1); + } + + void AddLoadingSchemaPresetFail() { + SchemaPresetLoadingFailCounter->Add(1); + } + + void AddLoadingTableVersionsFail() { + TableVersionsLoadingFailCounter->Add(1); + } + + void AddLoadingSchemaPresetVersionsFail() { + SchemaPresetVersionsLoadingFailCounter->Add(1); + } +}; + } diff --git a/ydb/core/tx/columnshard/counters/engine_logs.cpp b/ydb/core/tx/columnshard/counters/engine_logs.cpp index 7a38e052c5ed..0cd261c2f2bd 100644 --- a/ydb/core/tx/columnshard/counters/engine_logs.cpp +++ b/ydb/core/tx/columnshard/counters/engine_logs.cpp @@ -64,6 +64,13 @@ TEngineLogsCounters::TEngineLogsCounters() GranuleOptimizerLocked = TBase::GetDeriviative("Optimizer/Granules/Locked"); + PortionsLoadingTimeCounter = TBase::GetValue("Startup/PortionsLoadingTime"); + ColumnsLoadingTimeCounter = TBase::GetValue("Startup/ColumnsLoadingTime"); + IndexesLoadingTimeCounter = TBase::GetValue("Startup/IndexesLoadingTime"); + LoadPortionsFailCounter = TBase::GetValue("Startup/LoadPortionFailCount"); + LoadColumnsFailCounter = TBase::GetValue("Startup/LoadColumnFailCount"); + LoadIndexFailCounter = TBase::GetValue("Startup/LoadIndexFailCount"); + IndexMetadataUsageBytes = TBase::GetValue("IndexMetadata/Usage/Bytes"); StatUsageForTTLCount = TBase::GetDeriviative("Ttl/StatUsageForTTLCount/Count"); diff --git a/ydb/core/tx/columnshard/counters/engine_logs.h b/ydb/core/tx/columnshard/counters/engine_logs.h index 2cbaf7fa234e..d1a15411e40e 100644 --- a/ydb/core/tx/columnshard/counters/engine_logs.h +++ b/ydb/core/tx/columnshard/counters/engine_logs.h @@ -223,6 +223,13 @@ class TEngineLogsCounters: public TCommonCountersOwner { NMonitoring::TDynamicCounters::TCounterPtr IndexMetadataUsageBytes; + NMonitoring::TDynamicCounters::TCounterPtr PortionsLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr ColumnsLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr IndexesLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr LoadPortionsFailCounter; + NMonitoring::TDynamicCounters::TCounterPtr LoadColumnsFailCounter; + NMonitoring::TDynamicCounters::TCounterPtr LoadIndexFailCounter; + TAgentGranuleDataCounters GranuleDataAgent; std::vector> BlobSizeDistribution; std::vector> PortionSizeDistribution; @@ -329,6 +336,31 @@ class TEngineLogsCounters: public TCommonCountersOwner { GranuleOptimizerLocked->Add(1); } + void AddPortionLoadingTime(ui64 microSeconds) const { + PortionsLoadingTimeCounter->Add(microSeconds); + } + + void AddColumnLoadingTime(ui64 microSeconds) const { + ColumnsLoadingTimeCounter->Add(microSeconds); + } + + void AddIndexesLoadingTime(ui64 microSeconds) const { + IndexesLoadingTimeCounter->Add(microSeconds); + } + + void AddLoadPortionsFail() const { + LoadPortionsFailCounter->Add(1); + } + + void AddLoadColumnsFail() const { + LoadColumnsFailCounter->Add(1); + } + + void AddLoadIndexFail() const { + LoadIndexFailCounter->Add(1); + } + + TEngineLogsCounters(); }; diff --git a/ydb/core/tx/columnshard/counters/insert_table.h b/ydb/core/tx/columnshard/counters/insert_table.h index 52996e190165..f40628a76451 100644 --- a/ydb/core/tx/columnshard/counters/insert_table.h +++ b/ydb/core/tx/columnshard/counters/insert_table.h @@ -68,4 +68,28 @@ class TInsertTableCounters: public TCommonCountersOwner { } }; +class TInsertTableLoadCounters: public TCommonCountersOwner { +private: + using TBase = TCommonCountersOwner; + + NMonitoring::TDynamicCounters::TCounterPtr InsertTableLoadingTimeCounter; + NMonitoring::TDynamicCounters::TCounterPtr InsertTableLoadingFailCounter; + +public: + TInsertTableLoadCounters() + : TBase("InsertTableLoad") + { + InsertTableLoadingTimeCounter = TBase::GetValue("Startup/InsertTableLoadingTime");; + InsertTableLoadingFailCounter = TBase::GetValue("Startup/InsertTableLoadFails");; + } + + void AddInsertTableLoadingTime(ui64 microSeconds) { + InsertTableLoadingTimeCounter->Add(microSeconds); + } + + void AddInsertTableLoadFail() { + InsertTableLoadingFailCounter->Add(1); + } +}; + } diff --git a/ydb/core/tx/columnshard/engines/column_engine_logs.cpp b/ydb/core/tx/columnshard/engines/column_engine_logs.cpp index 07d066b00288..af8c54e4edb8 100644 --- a/ydb/core/tx/columnshard/engines/column_engine_logs.cpp +++ b/ydb/core/tx/columnshard/engines/column_engine_logs.cpp @@ -207,6 +207,7 @@ bool TColumnEngineForLogs::Load(IDbWrapper& db) { bool TColumnEngineForLogs::LoadColumns(IDbWrapper& db) { TPortionConstructors constructors; + TInstant start = TInstant::Now(); { TMemoryProfileGuard g("TTxInit/LoadColumns/Portions"); if (!db.LoadPortions([&](TPortionInfoConstructor&& portion, const NKikimrTxColumnShard::TIndexPortionMeta& metaProto) { @@ -214,10 +215,13 @@ bool TColumnEngineForLogs::LoadColumns(IDbWrapper& db) { AFL_VERIFY(portion.MutableMeta().LoadMetadata(metaProto, indexInfo)); AFL_VERIFY(constructors.AddConstructorVerified(std::move(portion))); })) { + SignalCounters.AddLoadPortionsFail(); return false; } } + TInstant portionsLoaded = TInstant::Now(); + { TMemoryProfileGuard g("TTxInit/LoadColumns/Records"); TPortionInfo::TSchemaCursor schema(VersionedIndex); @@ -226,18 +230,30 @@ bool TColumnEngineForLogs::LoadColumns(IDbWrapper& db) { auto* constructor = constructors.MergeConstructor(std::move(portion)); constructor->LoadRecord(currentSchema->GetIndexInfo(), loadContext); })) { + SignalCounters.AddLoadColumnsFail(); return false; } } + + TInstant columnsLoaded = TInstant::Now(); + { TMemoryProfileGuard g("TTxInit/LoadColumns/Indexes"); if (!db.LoadIndexes([&](const ui64 pathId, const ui64 portionId, const TIndexChunkLoadContext& loadContext) { auto* constructor = constructors.GetConstructorVerified(pathId, portionId); constructor->LoadIndex(loadContext); })) { + SignalCounters.AddLoadIndexFail(); return false; }; } + + TInstant indexesLoaded = TInstant::Now(); + AFL_INFO(NKikimrServices::TX_COLUMNSHARD)("event", "load_columns")("portions_loading_time", portionsLoaded - start)("columns_loading_time", columnsLoaded - portionsLoaded)("indexes_loading_time", indexesLoaded - columnsLoaded); + SignalCounters.AddPortionLoadingTime((portionsLoaded - start).MicroSeconds()); + SignalCounters.AddColumnLoadingTime((columnsLoaded - portionsLoaded).MicroSeconds()); + SignalCounters.AddIndexesLoadingTime((indexesLoaded - columnsLoaded).MicroSeconds()); + { TMemoryProfileGuard g("TTxInit/LoadColumns/Constructors"); for (auto&& [granuleId, pathConstructors] : constructors) { diff --git a/ydb/core/tx/columnshard/engines/db_wrapper.cpp b/ydb/core/tx/columnshard/engines/db_wrapper.cpp index 2f3687563202..158cd19870e7 100644 --- a/ydb/core/tx/columnshard/engines/db_wrapper.cpp +++ b/ydb/core/tx/columnshard/engines/db_wrapper.cpp @@ -103,6 +103,7 @@ bool TDbWrapper::LoadColumns(const std::function().Prefix(0).Select(); if (!rowset.IsReady()) { + LOG_S_CRIT("Load: index columns is not ready"); return false; } @@ -118,6 +119,7 @@ bool TDbWrapper::LoadColumns(const std::function().Select(); if (!rowset.IsReady()) { + LOG_S_CRIT("Load: index portions is not ready"); return false; } @@ -161,6 +164,7 @@ bool TDbWrapper::LoadPortions(const std::function().Select(); if (!rowset.IsReady()) { + LOG_S_CRIT("Load: index indexes is not ready"); return false; } @@ -206,6 +211,7 @@ bool TDbWrapper::LoadIndexes(const std::function(), rowset.GetValue(), chunkLoadContext); if (!rowset.Next()) { + LOG_S_CRIT("Load: index indexes next failed"); return false; } } diff --git a/ydb/core/tx/columnshard/engines/insert_table/insert_table.cpp b/ydb/core/tx/columnshard/engines/insert_table/insert_table.cpp index ebccfed5e3a3..1a1cfe254865 100644 --- a/ydb/core/tx/columnshard/engines/insert_table/insert_table.cpp +++ b/ydb/core/tx/columnshard/engines/insert_table/insert_table.cpp @@ -125,10 +125,18 @@ bool TInsertTable::Load(NIceDb::TNiceDb& db, IDbWrapper& dbTable, const TInstant Loaded = true; LastWriteId = (TInsertWriteId)0; if (!NColumnShard::Schema::GetSpecialValueOpt(db, NColumnShard::Schema::EValueIds::LastWriteId, LastWriteId)) { + LoadCounters.AddInsertTableLoadFail(); return false; } - return dbTable.Load(*this, loadTime); + TInstant start = TInstant::Now(); + bool result = dbTable.Load(*this, loadTime); + TInstant finish = TInstant::Now(); + if (!result) { + LoadCounters.AddInsertTableLoadFail(); + } + LoadCounters.AddInsertTableLoadingTime((finish - start).MicroSeconds()); + return result; } std::vector TInsertTable::Read(ui64 pathId, const std::optional lockId, const TSnapshot& reqSnapshot, diff --git a/ydb/core/tx/columnshard/engines/insert_table/insert_table.h b/ydb/core/tx/columnshard/engines/insert_table/insert_table.h index c05737466839..61b3f1f37c03 100644 --- a/ydb/core/tx/columnshard/engines/insert_table/insert_table.h +++ b/ydb/core/tx/columnshard/engines/insert_table/insert_table.h @@ -16,6 +16,7 @@ class TInsertTableAccessor { protected: TInsertionSummary Summary; THashMap BlobLinks; + NColumnShard::TInsertTableLoadCounters LoadCounters; void AddBlobLink(const TUnifiedBlobId& blobId) { ++BlobLinks[blobId]; diff --git a/ydb/core/tx/columnshard/tables_manager.cpp b/ydb/core/tx/columnshard/tables_manager.cpp index 6d657cebcb6c..b5738a0b4bed 100644 --- a/ydb/core/tx/columnshard/tables_manager.cpp +++ b/ydb/core/tx/columnshard/tables_manager.cpp @@ -45,16 +45,20 @@ bool TTablesManager::FillMonitoringReport(NTabletFlatExecutor::TTransactionConte bool TTablesManager::InitFromDB(NIceDb::TNiceDb& db) { THashMap schemaPresets; + TInstant start = TInstant::Now(); { TMemoryProfileGuard g("TTablesManager/InitFromDB::Tables"); auto rowset = db.Table().Select(); if (!rowset.IsReady()) { + LOG_S_CRIT("Load: tables rowset is not ready"); + LoadTimeCounters->AddLoadingTablesFail(); return false; } while (!rowset.EndOfSet()) { TTableInfo table; if (!table.InitFromDB(rowset)) { + LOG_S_CRIT("Load: can not init table"); return false; } if (table.IsDropped()) { @@ -64,16 +68,22 @@ bool TTablesManager::InitFromDB(NIceDb::TNiceDb& db) { AFL_VERIFY(Tables.emplace(table.GetPathId(), std::move(table)).second); if (!rowset.Next()) { + LoadTimeCounters->AddLoadingTablesFail(); + LOG_S_CRIT("Load: tables next failed"); return false; } } } + TInstant tablesLoaded = TInstant::Now(); + bool isFakePresetOnly = true; { TMemoryProfileGuard g("TTablesManager/InitFromDB::SchemaPresets"); auto rowset = db.Table().Select(); if (!rowset.IsReady()) { + LoadTimeCounters->AddLoadingSchemaPresetFail(); + LOG_S_CRIT("Load: schemapreset rowset is not ready"); return false; } @@ -90,15 +100,21 @@ bool TTablesManager::InitFromDB(NIceDb::TNiceDb& db) { AFL_VERIFY(schemaPresets.emplace(preset.GetId(), preset).second); AFL_VERIFY(SchemaPresetsIds.emplace(preset.GetId()).second); if (!rowset.Next()) { + LoadTimeCounters->AddLoadingSchemaPresetFail(); + LOG_S_CRIT("Load: schemapreset next failed"); return false; } } } + TInstant schemaPresetLoaded = TInstant::Now(); + { TMemoryProfileGuard g("TTablesManager/InitFromDB::Versions"); auto rowset = db.Table().Select(); if (!rowset.IsReady()) { + LoadTimeCounters->AddLoadingTableVersionsFail(); + LOG_S_CRIT("Load: table versions is not ready"); return false; } @@ -132,15 +148,21 @@ bool TTablesManager::InitFromDB(NIceDb::TNiceDb& db) { } table.AddVersion(version); if (!rowset.Next()) { + LoadTimeCounters->AddLoadingTableVersionsFail(); + LOG_S_CRIT("Load: table versions next failed"); return false; } } } + TInstant tableVersionsLoaded = TInstant::Now(); + { TMemoryProfileGuard g("TTablesManager/InitFromDB::PresetVersions"); auto rowset = db.Table().Select(); if (!rowset.IsReady()) { + LoadTimeCounters->AddLoadingSchemaPresetVersionsFail(); + LOG_S_CRIT("Load: schema preset versions is not ready"); return false; } @@ -156,10 +178,19 @@ bool TTablesManager::InitFromDB(NIceDb::TNiceDb& db) { AFL_INFO(NKikimrServices::TX_COLUMNSHARD)("event", "load_preset")("preset_id", id)("snapshot", version)("version", info.HasSchema() ? info.GetSchema().GetVersion() : -1); preset.AddVersion(version, info); if (!rowset.Next()) { + LoadTimeCounters->AddLoadingSchemaPresetVersionsFail(); + LOG_S_CRIT("Load: schema preset next failed"); return false; } } } + TInstant schemaPresetVersionsLoaded = TInstant::Now(); + + AFL_INFO(NKikimrServices::TX_COLUMNSHARD)("event", "init_from_db")("tables_loading_time", tablesLoaded - start)("schema_preset_loading_time", schemaPresetLoaded - tablesLoaded)("table_versions_loading_time", tableVersionsLoaded - schemaPresetLoaded)("schema_preset_versions_loading_time", schemaPresetVersionsLoaded - tableVersionsLoaded); + LoadTimeCounters->AddTablesLoadingTime((tablesLoaded - start).MicroSeconds()); + LoadTimeCounters->AddSchemaPresetLoadingTime((schemaPresetLoaded - tablesLoaded).MicroSeconds()); + LoadTimeCounters->AddTableVersionsLoadingTime((tableVersionsLoaded - schemaPresetLoaded).MicroSeconds()); + LoadTimeCounters->AddSchemaPresetVersionsLoadingTime((schemaPresetVersionsLoaded - tableVersionsLoaded).MicroSeconds()); TMemoryProfileGuard g("TTablesManager/InitFromDB::Other"); for (auto& [id, preset] : schemaPresets) { @@ -340,7 +371,9 @@ void TTablesManager::AddTableVersion(const ui64 pathId, const NOlap::TSnapshot& TTablesManager::TTablesManager(const std::shared_ptr& storagesManager, const ui64 tabletId) : StoragesManager(storagesManager) - , TabletId(tabletId) { + , LoadTimeCounters(std::make_unique()) + , TabletId(tabletId) +{ } bool TTablesManager::TryFinalizeDropPathOnExecute(NTable::TDatabase& dbTable, const ui64 pathId) const { diff --git a/ydb/core/tx/columnshard/tables_manager.h b/ydb/core/tx/columnshard/tables_manager.h index 01643fe8db9a..aeae1318245c 100644 --- a/ydb/core/tx/columnshard/tables_manager.h +++ b/ydb/core/tx/columnshard/tables_manager.h @@ -148,6 +148,7 @@ class TTablesManager { TTtl Ttl; std::unique_ptr PrimaryIndex; std::shared_ptr StoragesManager; + std::unique_ptr LoadTimeCounters; ui64 TabletId = 0; public: TTablesManager(const std::shared_ptr& storagesManager, const ui64 tabletId);