Better SchemeShard split logs (#17158)

3 files changed, 117 insertions, 63 deletions

diff --git a/ydb/core/tx/schemeshard/schemeshard__operation_split_merge.cpp b/ydb/core/tx/schemeshard/schemeshard__operation_split_merge.cpp
index 25e08ad235f..83e876b011b 100644
--- a/ydb/core/tx/schemeshard/schemeshard__operation_split_merge.cpp
+++ b/ydb/core/tx/schemeshard/schemeshard__operation_split_merge.cpp
@@ -721,18 +721,31 @@ public:
         }
 
         LOG_NOTICE_S(context.Ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-                     "TSplitMerge Propose"
-                         << ", tableStr: " << info.GetTablePath()
-                         << ", tableId: " << pathId
-                         << ", opId: " << OperationId
-                         << ", at schemeshard: " << ssId);
-
+            "TSplitMerge Propose"
+            << ", tableStr: " << info.GetTablePath()
+            << ", tableId: " << pathId
+            << ", opId: " << OperationId
+            << ", at schemeshard: " << ssId
+            << ", request: " << info.ShortDebugString());
+        
         auto result = MakeHolder<TProposeResponse>(NKikimrScheme::StatusAccepted, ui64(OperationId.GetTxId()), ui64(ssId));
+
+        auto setResultError = [&](NKikimrScheme::EStatus status, const TString& error) {
+            result->SetError(status, error);
+            LOG_WARN_S(context.Ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+                "TSplitMerge Propose failed " << status << " " << error
+                << ", tableStr: " << info.GetTablePath()
+                << ", tableId: " << pathId
+                << ", opId: " << OperationId
+                << ", at schemeshard: " << ssId
+                << ", request: " << info.ShortDebugString());
+        };
+
         TString errStr;
 
         if (!info.HasTablePath() && !info.HasTableLocalId()) {
             errStr = "Neither table name nor pathId in SplitMergeInfo";
-            result->SetError(NKikimrScheme::StatusInvalidParameter, errStr);
+            setResultError(NKikimrScheme::StatusInvalidParameter, errStr);
             return result;
         }
 
@@ -759,18 +772,18 @@ public:
             }
 
             if (!checks) {
-                result->SetError(checks.GetStatus(), checks.GetError());
+                setResultError(checks.GetStatus(), checks.GetError());
                 return result;
             }
         }
 
         if (!context.SS->CheckApplyIf(Transaction, errStr)) {
-            result->SetError(NKikimrScheme::StatusPreconditionFailed, errStr);
+            setResultError(NKikimrScheme::StatusPreconditionFailed, errStr);
             return result;
         }
 
         if (!context.SS->CheckLocks(path.Base()->PathId, Transaction, errStr)) {
-            result->SetError(NKikimrScheme::StatusMultipleModifications, errStr);
+            setResultError(NKikimrScheme::StatusMultipleModifications, errStr);
             return result;
         }
 
@@ -781,14 +794,14 @@ public:
         if (tableInfo->IsBackup) {
             TString errMsg = TStringBuilder()
                 << "cannot split/merge backup table " << info.GetTablePath();
-            result->SetError(NKikimrScheme::StatusInvalidParameter, errMsg);
+            setResultError(NKikimrScheme::StatusInvalidParameter, errMsg);
             return result;
         }
 
         if (tableInfo->IsRestore) {
             TString errMsg = TStringBuilder()
                 << "cannot split/merge restore table " << info.GetTablePath();
-            result->SetError(NKikimrScheme::StatusInvalidParameter, errMsg);
+            setResultError(NKikimrScheme::StatusInvalidParameter, errMsg);
             return result;
         }
 
@@ -801,7 +814,7 @@ public:
             auto srcShardIdx = context.SS->GetShardIdx(srcTabletId);
             if (!srcShardIdx) {
                 TString errMsg = TStringBuilder() << "Unknown SourceTabletId: " << srcTabletId;
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errMsg);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errMsg);
                 return result;
             }
 
@@ -811,7 +824,7 @@ public:
                     << ", tablet: " << srcTabletId
                     << ", srcShardIdx: " << srcShardIdx
                     << ", pathId: " << path.Base()->PathId;
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errMsg);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errMsg);
                 return result;
             }
 
@@ -821,20 +834,20 @@ public:
                     << ", tablet: " << srcTabletId
                     << ", srcShardIdx: " << srcShardIdx
                     << ", pathId: " << path.Base()->PathId;
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errMsg);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errMsg);
                 return result;
             }
 
             if (context.SS->ShardInfos.FindPtr(srcShardIdx)->PathId != path.Base()->PathId || !shardIdx2partition.contains(srcShardIdx)) {
                 TString errMsg = TStringBuilder() << "TabletId " << srcTabletId << " is not a partition of table " << info.GetTablePath();
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errMsg);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errMsg);
                 return result;
             }
 
 
             if (context.SS->ShardIsUnderSplitMergeOp(srcShardIdx)) {
                 TString errMsg = TStringBuilder() << "TabletId " << srcTabletId << " is already in process of split";
-                result->SetError(NKikimrScheme::StatusMultipleModifications, errMsg);
+                setResultError(NKikimrScheme::StatusMultipleModifications, errMsg);
                 return result;
             }
 
@@ -842,7 +855,7 @@ public:
                 const auto* stats = tableInfo->GetStats().PartitionStats.FindPtr(srcShardIdx);
                 if (!stats || stats->ShardState != NKikimrTxDataShard::Ready) {
                     TString errMsg = TStringBuilder() << "Src TabletId " << srcTabletId << " is not in Ready state";
-                    result->SetError(NKikimrScheme::StatusNotAvailable, errMsg);
+                    setResultError(NKikimrScheme::StatusNotAvailable, errMsg);
                     return result;
                 }
 
@@ -857,7 +870,7 @@ public:
         if (context.SS->SplitSettings.SplitMergePartCountLimit != -1 &&
             totalSrcPartCount >= context.SS->SplitSettings.SplitMergePartCountLimit)
         {
-            result->SetError(NKikimrScheme::StatusNotAvailable,
+            setResultError(NKikimrScheme::StatusNotAvailable,
                              Sprintf("Split/Merge operation involves too many parts: %" PRIu64, totalSrcPartCount));
 
             LOG_CRIT_S(context.Ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
@@ -869,7 +882,7 @@ public:
         }
 
         if (srcPartitionIdxs.empty()) {
-            result->SetError(NKikimrScheme::StatusInvalidParameter, TStringBuilder() << "No source partitions specified for split/merge TxId " << OperationId.GetTxId());
+            setResultError(NKikimrScheme::StatusInvalidParameter, TStringBuilder() << "No source partitions specified for split/merge TxId " << OperationId.GetTxId());
             return result;
         }
 
@@ -885,7 +898,7 @@ public:
 
             if (!context.SS->GetBindingsRooms(path.GetPathIdForDomain(), tableInfo->PartitionConfig(), storageRooms, familyRooms, channelsBinding, errStr)) {
                 errStr = TString("database doesn't have required storage pools to create tablet with storage config, details: ") + errStr;
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errStr);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errStr);
                 return result;
             }
 
@@ -900,7 +913,7 @@ public:
             }
         } else if (context.SS->IsCompatibleChannelProfileLogic(path.GetPathIdForDomain(), tableInfo)) {
             if (!context.SS->GetChannelsBindings(path.GetPathIdForDomain(), tableInfo, channelsBinding, errStr)) {
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errStr);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errStr);
                 return result;
             }
         }
@@ -920,17 +933,17 @@ public:
         if (srcPartitionIdxs.size() == 1 && dstCount > 1) {
             // This is Split operation, allocate new shards for split Dsts
             if (!AllocateDstForSplit(info, OperationId.GetTxId(), path.Base()->PathId, srcPartitionIdxs[0], tableInfo, op, channelsBinding, errStr, context)) {
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errStr);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errStr);
                 return result;
             }
         } else if (dstCount == 1 && srcPartitionIdxs.size() > 1) {
             // This is merge, allocate 1 Dst shard
             if (!AllocateDstForMerge(info, OperationId.GetTxId(), path.Base()->PathId, srcPartitionIdxs, tableInfo, op, channelsBinding, errStr, context)) {
-                result->SetError(NKikimrScheme::StatusInvalidParameter, errStr);
+                setResultError(NKikimrScheme::StatusInvalidParameter, errStr);
                 return result;
             }
         } else {
-            result->SetError(NKikimrScheme::StatusInvalidParameter, "Invalid request: only 1->N or N->1 are supported");
+            setResultError(NKikimrScheme::StatusInvalidParameter, "Invalid request: only 1->N or N->1 are supported");
             return result;
         }
 
@@ -978,6 +991,16 @@ public:
         path->IncShardsInside(dstCount);
 
         SetState(NextState());
+
+        LOG_NOTICE_S(context.Ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TSplitMerge Propose accepted"
+            << ", tableStr: " << info.GetTablePath()
+            << ", tableId: " << pathId
+            << ", opId: " << OperationId
+            << ", at schemeshard: " << ssId
+            << ", op: " << op.SplitDescription->ShortDebugString()
+            << ", request: " << info.ShortDebugString());
+
         return result;
     }
 
diff --git a/ydb/core/tx/schemeshard/schemeshard__table_stats.cpp b/ydb/core/tx/schemeshard/schemeshard__table_stats.cpp
index c8013bc57d3..9dfaac17560 100644
--- a/ydb/core/tx/schemeshard/schemeshard__table_stats.cpp
+++ b/ydb/core/tx/schemeshard/schemeshard__table_stats.cpp
@@ -466,12 +466,21 @@ bool TTxStoreTableStats::PersistSingleStats(const TPathId& pathId,
     TString reason;
     if (table->ShouldSplitBySize(dataSize, forceShardSplitSettings, reason)) {
         // We would like to split by size and do this no matter how many partitions there are
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "Want to split tablet " << datashardId << " by size " << reason);
     } else if (table->GetPartitions().size() >= table->GetMaxPartitionsCount()) {
         // We cannot split as there are max partitions already
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "Do not want to split tablet " << datashardId << " by size,"
+            << " its table already has "<< table->GetPartitions().size() << " out of " << table->GetMaxPartitionsCount() << " partitions");
         return true;
     } else if (table->CheckSplitByLoad(Self->SplitSettings, shardIdx, dataSize, rowCount, mainTableForIndex, reason)) {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "Want to split tablet " << datashardId << " by load " << reason);
         collectKeySample = true;
     } else {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "Do not want to split tablet " << datashardId);
         return true;
     }
 
@@ -494,15 +503,15 @@ bool TTxStoreTableStats::PersistSingleStats(const TPathId& pathId,
     }
 
     if (newStats.HasBorrowedData) {
-        // We don't want to split shards that have borrow parts
-        // We must ask them to compact first
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "Postpone split tablet " << datashardId << " because it has borrow parts, enqueue compact them first");
         Self->EnqueueBorrowedCompaction(shardIdx);
         return true;
     }
 
     // Request histograms from the datashard
-    LOG_DEBUG(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-             "Requesting full stats from datashard %" PRIu64, rec.GetDatashardId());
+    LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+        "Requesting full tablet stats " << datashardId << " to split it");
     auto request = new TEvDataShard::TEvGetTableStats(pathId.LocalPathId);
     request->Record.SetCollectKeySample(collectKeySample);
     PendingMessages.emplace_back(item.Ev->Sender, request);
diff --git a/ydb/core/tx/schemeshard/schemeshard__table_stats_histogram.cpp b/ydb/core/tx/schemeshard/schemeshard__table_stats_histogram.cpp
index 11ff0e42979..f78ff977165 100644
--- a/ydb/core/tx/schemeshard/schemeshard__table_stats_histogram.cpp
+++ b/ydb/core/tx/schemeshard/schemeshard__table_stats_histogram.cpp
@@ -222,7 +222,6 @@ TSerializedCellVec ChooseSplitKeyByKeySample(const NKikimrTableStats::THistogram
 
 enum struct ESplitReason {
     NO_SPLIT = 0,
-    FAST_SPLIT_INDEX,
     SPLIT_BY_SIZE,
     SPLIT_BY_LOAD
 };
@@ -231,8 +230,6 @@ const char* ToString(ESplitReason splitReason) {
     switch (splitReason) {
     case ESplitReason::NO_SPLIT:
         return "No split";
-    case ESplitReason::FAST_SPLIT_INDEX:
-        return "Fast split index table";
     case ESplitReason::SPLIT_BY_SIZE:
         return "Split by size";
     case ESplitReason::SPLIT_BY_LOAD:
@@ -277,9 +274,9 @@ void TSchemeShard::Handle(TEvDataShard::TEvGetTableStatsResult::TPtr& ev, const
     LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
                "Got partition histogram at tablet " << TabletID()
                <<" from datashard " << datashardId
-               << " state: '" << DatashardStateName(rec.GetShardState()) << "'"
-               << " data size: " << dataSize
-               << " row count: " << rowCount
+               << " state " << DatashardStateName(rec.GetShardState())
+               << " data size " << dataSize
+               << " row count " << rowCount
     );
 
     Execute(new TTxPartitionHistogram(this, ev), ctx);
@@ -313,14 +310,14 @@ THolder<TProposeRequest> SplitRequest(
 bool TTxPartitionHistogram::Execute(TTransactionContext& txc, const TActorContext& ctx) {
     const auto& rec = Ev->Get()->Record;
 
-    if (!rec.GetFullStatsReady())
+    if (!rec.GetFullStatsReady()) {
         return true;
+    }
 
     auto datashardId = TTabletId(rec.GetDatashardId());
     TPathId tableId = InvalidPathId;
     if (rec.HasTableOwnerId()) {
-        tableId = TPathId(TOwnerId(rec.GetTableOwnerId()),
-                          TLocalPathId(rec.GetTableLocalId()));
+        tableId = TPathId(TOwnerId(rec.GetTableOwnerId()), TLocalPathId(rec.GetTableLocalId()));
     } else {
         tableId = Self->MakeLocalId(TLocalPathId(rec.GetTableLocalId()));
     }
@@ -328,26 +325,35 @@ bool TTxPartitionHistogram::Execute(TTransactionContext& txc, const TActorContex
     ui64 rowCount = rec.GetTableStats().GetRowCount();
 
     LOG_INFO_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-                "TTxPartitionHistogram::Execute partition histogram"
-                    << " at tablet " << Self->SelfTabletId()
-                    << " from datashard " << datashardId
-                    << " for pathId " << tableId
-                    << " state '" << DatashardStateName(rec.GetShardState()).data() << "'"
-                    << " dataSize " << dataSize
-                    << " rowCount " << rowCount
-                    << " dataSizeHistogram buckets " << rec.GetTableStats().GetDataSizeHistogram().BucketsSize());
+        "TTxPartitionHistogram Execute partition histogram"
+            << " at tablet " << Self->SelfTabletId()
+            << " from datashard " << datashardId
+            << " for pathId " << tableId
+            << " state '" << DatashardStateName(rec.GetShardState()).data() << "'"
+            << " dataSize " << dataSize
+            << " rowCount " << rowCount
+            << " dataSizeHistogram buckets " << rec.GetTableStats().GetDataSizeHistogram().BucketsSize());
 
-    if (!Self->Tables.contains(tableId))
+    if (!Self->Tables.contains(tableId)) {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TTxPartitionHistogram Unknown table " << tableId << " tablet " << datashardId);
         return true;
+    }
 
     TTableInfo::TPtr table = Self->Tables[tableId];
 
-    if (!Self->TabletIdToShardIdx.contains(datashardId))
+    if (!Self->TabletIdToShardIdx.contains(datashardId)) {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TTxPartitionHistogram Unknown tablet " << datashardId);
         return true;
+    }
 
     // Don't split/merge backup tables
-    if (table->IsBackup)
+    if (table->IsBackup) {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TTxPartitionHistogram Skip backup table tablet " << datashardId);
         return true;
+    }
 
     auto shardIdx = Self->TabletIdToShardIdx[datashardId];
     const auto forceShardSplitSettings = Self->SplitSettings.GetForceShardSplitSettings();
@@ -365,13 +371,23 @@ bool TTxPartitionHistogram::Execute(TTransactionContext& txc, const TActorContex
     }
 
     if (splitReason == ESplitReason::NO_SPLIT) {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TTxPartitionHistogram Do not want to split tablet " << datashardId);
         return true;
     }
 
     if (splitReason != ESplitReason::SPLIT_BY_SIZE && table->GetPartitions().size() >= table->GetMaxPartitionsCount()) {
+        LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TTxPartitionHistogram Do not want to split tablet " << datashardId << " by size,"
+            << " its table already has "<< table->GetPartitions().size() << " out of " << table->GetMaxPartitionsCount() << " partitions");
         return true;
     }
 
+    LOG_DEBUG_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+        "TTxPartitionHistogram Want to"
+        << " " << ToString(splitReason) << " " << splitReasonMsg
+        << " tablet " << datashardId);
+
     TSmallVec<NScheme::TTypeInfo> keyColumnTypes(table->KeyColumnIds.size());
     for (size_t ki = 0; ki < table->KeyColumnIds.size(); ++ki) {
         keyColumnTypes[ki] = table->Columns.FindPtr(table->KeyColumnIds[ki])->PType;
@@ -390,9 +406,10 @@ bool TTxPartitionHistogram::Execute(TTransactionContext& txc, const TActorContex
 
         splitKey = ChooseSplitKeyByHistogram(histogram, dataSize, keyColumnTypes);
         if (splitKey.GetBuffer().empty()) {
-            LOG_WARN(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-                "Failed to find proper split key (initially) for '%s' of datashard %" PRIu64,
-                ToString(splitReason), datashardId);
+            LOG_WARN_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+                "TTxPartitionHistogram Failed to find proper split key (initially) for"
+                << " " << ToString(splitReason) << " " << splitReasonMsg
+                << " tablet " << datashardId);
             return true;
         }
 
@@ -402,17 +419,19 @@ bool TTxPartitionHistogram::Execute(TTransactionContext& txc, const TActorContex
                                     keyColumnTypes.data(),
                                     lowestKey.GetCells().size(), splitKey.GetCells().size()))
         {
-            LOG_WARN(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-                     "Failed to find proper split key (less than first) for '%s' of datashard %" PRIu64,
-                      ToString(splitReason), datashardId);
+            LOG_WARN_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+                "TTxPartitionHistogram Failed to find proper split key (less than first) for"
+                << " " << ToString(splitReason) << " " << splitReasonMsg
+                << " tablet " << datashardId);
             return true;
         }
     }
 
     if (splitKey.GetBuffer().empty()) {
-        LOG_WARN(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-                 "Failed to find proper split key for '%s' of datashard %" PRIu64,
-                  ToString(splitReason), datashardId);
+        LOG_WARN_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
+            "TTxPartitionHistogram Failed to find proper split key for"
+            << " " << ToString(splitReason) << " " << splitReasonMsg
+            << " tablet " << datashardId);
         return true;
     }
 
@@ -420,17 +439,20 @@ bool TTxPartitionHistogram::Execute(TTransactionContext& txc, const TActorContex
 
     if (!txId) {
         LOG_WARN_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-                   "Do not request split op"
-                   << ", reason: no cached tx ids for internal operation"
-                   << ", shardIdx: " << shardIdx);
+            "TTxPartitionHistogram Do not request split: no cached tx ids for internal operation"
+            << " " << ToString(splitReason) << " " << splitReasonMsg
+            << " tablet " << datashardId
+            << " shardIdx " << shardIdx);
         return true;
     }
 
     auto request = SplitRequest(Self, txId, tableId, datashardId, splitKey.GetBuffer());
 
     LOG_INFO_S(ctx, NKikimrServices::FLAT_TX_SCHEMESHARD,
-        "Propose split request : " << request->Record.ShortDebugString()
-        << ", reason: " << splitReasonMsg);
+        "TTxPartitionHistogram Propose"
+        << " " << ToString(splitReason) << " " << splitReasonMsg
+        << " tablet " << datashardId
+        << " request " << request->Record.ShortDebugString());
 
     TMemoryChanges memChanges;
     TStorageChanges dbChanges;