[debug][don't merge] add debug logs for DORIS-14951

be/src/common/config.cpp

@@ -211,7 +211,7 @@ DEFINE_mString(sys_log_level, "INFO");
 // TIME-DAY, TIME-HOUR, SIZE-MB-nnn
 DEFINE_String(sys_log_roll_mode, "SIZE-MB-1024");
 // log roll num
-DEFINE_Int32(sys_log_roll_num, "10");
+DEFINE_Int32(sys_log_roll_num, "50");
 // verbose log
 DEFINE_Strings(sys_log_verbose_modules, "");
 // verbose log level

be/src/runtime/load_stream.cpp

@@ -403,6 +403,11 @@ Status LoadStream::close(int64_t src_id, const std::vector<PTabletID>& tablets_t
  LOG(INFO) << "received CLOSE_LOAD from sender " << src_id << ", remaining "
  << _total_streams - _close_load_cnt << " senders, " << *this;
 
+ for (const auto& tablet : tablets_to_commit) {
+ LOG(INFO) << "received tablets commit info from src_id=" << src_id
+ << ", load_id=" << print_id(_load_id) << " tablet_id=" << tablet.tablet_id()
+ << ", num_segments=" << tablet.num_segments();
+ }
  _tablets_to_commit.insert(_tablets_to_commit.end(), tablets_to_commit.begin(),
  tablets_to_commit.end());
 

be/src/runtime/load_stream.h

@@ -52,7 +52,11 @@ class TabletStream {
 
  Status append_data(const PStreamHeader& header, butil::IOBuf* data);
  Status add_segment(const PStreamHeader& header, butil::IOBuf* data);
- void add_num_segments(int64_t num_segments) { _num_segments += num_segments; }
+ void add_num_segments(int64_t num_segments) {
+ _num_segments += num_segments;
+ LOG(INFO) << "adding num segments, load_id=" << print_id(_load_id) << ", tablet_id=" << _id
+ << ", num_segments=" << num_segments << ", total_segments=" << _num_segments;
+ }
  Status close();
  int64_t id() const { return _id; }
 

be/src/runtime/load_stream_writer.cpp

@@ -155,7 +155,7 @@ Status LoadStreamWriter::close_segment(uint32_t segid) {
  }
  g_load_stream_file_writer_cnt << -1;
  LOG(INFO) << "segment " << segid << " path " << file_writer->path().native()
- << "closed, written " << file_writer->bytes_appended() << " bytes";
+ << " closed, written " << file_writer->bytes_appended() << " bytes";
  if (file_writer->bytes_appended() == 0) {
  return Status::Corruption("segment {} closed with 0 bytes", file_writer->path().native());
  }

be/src/vec/sink/load_stream_map_pool.cpp

@@ -118,9 +118,15 @@ Status LoadStreamMap::close_load(bool incremental) {
  continue;
  }
  if (first) {
+ LOG(INFO) << "sending CLOSE_LOAD with tablets to commit, load_id=" << _load_id
+ << ", dst_id=" << stream->dst_id()
+ << ", stream_id=" << stream->stream_id();
  RETURN_IF_ERROR(stream->close_load(tablets_to_commit));
  first = false;
  } else {
+ LOG(INFO) << "sending CLOSE_LOAD without tablets to commit, load_id=" << _load_id
+ << ", dst_id=" << stream->dst_id()
+ << ", stream_id=" << stream->stream_id();
  RETURN_IF_ERROR(stream->close_load({}));
  }
  }

be/src/vec/sink/load_stream_map_pool.h

@@ -91,6 +91,10 @@ class LoadStreamMap {
  void save_tablets_to_commit(int64_t dst_id, const std::vector<PTabletID>& tablets_to_commit);
 
  void save_segments_for_tablet(const std::unordered_map<int64_t, int32_t>& segments_for_tablet) {
+ for (auto [k, v] : segments_for_tablet) {
+ LOG(INFO) << "saving segments for tablet, load_id=" << _load_id << " tablet_id=" << k
+ << ", segments=" << v;
+ }
  _segments_for_tablet.insert(segments_for_tablet.cbegin(), segments_for_tablet.cend());
  }
 

be/src/vec/sink/load_stream_stub.cpp

@@ -256,6 +256,10 @@ Status LoadStreamStub::close_load(const std::vector<PTabletID>& tablets_to_commi
  header.set_opcode(doris::PStreamHeader::CLOSE_LOAD);
  for (const auto& tablet : tablets_to_commit) {
  *header.add_tablets() = tablet;
+ LOG(INFO) << "reporting num segments, load_id=" << print_id(_load_id)
+ << ", tablet_id=" << tablet.tablet_id()
+ << ", num_segments=" << tablet.num_segments()
+ << ", dst_id=" << _dst_id << ", stream_id=" << _stream_id;
  }
  return _encode_and_send(header);
 }

be/src/vec/sink/load_stream_stub.h

@@ -209,6 +209,8 @@ class LoadStreamStub : public std::enable_shared_from_this<LoadStreamStub> {
 
  void add_failed_tablet(int64_t tablet_id, Status reason) {
  std::lock_guard<bthread::Mutex> lock(_failed_tablets_mutex);
+ LOG(INFO) << "load_id=" << print_id(_load_id) << ", stream_id=" << _stream_id
+ << " add failed tablet " << tablet_id << ": " << reason;
  _failed_tablets[tablet_id] = reason;
  }
 

be/src/vec/sink/vrow_distribution.cpp

@@ -93,7 +93,7 @@ Status VRowDistribution::automatic_create_partition() {
  request.__set_table_id(_vpartition->table_id());
  request.__set_partitionValues(_partitions_need_create);
 
- VLOG_NOTICE << "automatic partition rpc begin request " << request;
+ LOG(INFO) << "automatic partition rpc begin request " << request;
  TNetworkAddress master_addr = ExecEnv::GetInstance()->master_info()->network_address;
  int time_out = _state->execution_timeout() * 1000;
  RETURN_IF_ERROR(ThriftRpcHelper::rpc<FrontendServiceClient>(
@@ -104,7 +104,7 @@ Status VRowDistribution::automatic_create_partition() {
  time_out));
 
  Status status(Status::create(result.status));
- VLOG_NOTICE << "automatic partition rpc end response " << result;
+ LOG(INFO) << "automatic partition rpc end response " << result;
  if (result.status.status_code == TStatusCode::OK) {
  // add new created partitions
  RETURN_IF_ERROR(_vpartition->add_partitions(result.partitions));

be/src/vec/sink/writer/vtablet_writer_v2.cpp

@@ -64,7 +64,23 @@ VTabletWriterV2::~VTabletWriterV2() = default;
 Status VTabletWriterV2::on_partitions_created(TCreatePartitionResult* result) {
  // add new tablet locations. it will use by address. so add to pool
  auto* new_locations = _pool->add(new std::vector<TTabletLocation>(result->tablets));
+ for (auto loc : result->tablets) {
+ std::stringstream ss;
+ loc.printTo(ss);
+ LOG(INFO) << "add location " << ss.str() << " load_id=" << print_id(_load_id);
+ }
  _location->add_locations(*new_locations);
+ for (auto loc : result->tablets) {
+ const auto* location = _location->find_tablet(loc.tablet_id);
+ if (location->node_ids.size() > 3) {
+ std::stringstream ss;
+ for (const auto& node_id : location->node_ids) {
+ ss << node_id << " ";
+ }
+ LOG(WARNING) << "tablet location > 3, load_id=" << print_id(_load_id)
+ << ", tablet_id=" << loc.tablet_id << ", dst_id=[" << ss.str() << "]";
+ }
+ }
 
  // update new node info
  _nodes_info->add_nodes(result->nodes);
@@ -98,6 +114,7 @@ Status VTabletWriterV2::_incremental_open_streams(
  if (!_load_stream_map->contains(node)) {
  new_backends.insert(node);
  }
+ LOG(INFO) << "incremental add tablets_for_node node=" << node << ", tablet_id=" << tablet_id;
  _tablets_for_node[node].emplace(tablet_id, tablet);
  if (known_indexes.contains(index.index_id)) [[likely]] {
  continue;
@@ -317,6 +334,7 @@ Status VTabletWriterV2::_build_tablet_node_mapping() {
  tablet.set_partition_id(partition->id);
  tablet.set_index_id(index.index_id);
  tablet.set_tablet_id(tablet_id);
+ LOG(INFO) << "build_tablets_for_node node=" << node << ", tablet_id=" << tablet_id;
  _tablets_for_node[node].emplace(tablet_id, tablet);
  constexpr int64_t DUMMY_TABLET_ID = 0;
  if (tablet_id == DUMMY_TABLET_ID) [[unlikely]] {
@@ -366,6 +384,14 @@ Status VTabletWriterV2::_select_streams(int64_t tablet_id, int64_t partition_id,
  if (location == nullptr) {
  return Status::InternalError("unknown tablet location, tablet id = {}", tablet_id);
  }
+ if (location->node_ids.size() > 3) {
+ std::stringstream ss;
+ for (const auto& node_id : location->node_ids) {
+ ss << node_id << " ";
+ }
+ LOG(WARNING) << "tablet location > 3, load_id=" << print_id(_load_id)
+ << ", tablet_id=" << tablet_id << ", dst_id=[" << ss.str() << "]";
+ }
  for (const auto& node_id : location->node_ids) {
  PTabletID tablet;
  tablet.set_partition_id(partition_id);
@@ -700,6 +726,8 @@ Status VTabletWriterV2::_create_commit_info(std::vector<TTabletCommitInfo>& tabl
  if (known_tablets.contains(tablet_id)) {
  continue;
  }
+ LOG(INFO) << "tablet " << tablet_id << " failed on backend " << dst_id
+ << ": " << failed_reason[tablet_id];
  known_tablets.insert(tablet_id);
  failed_tablets[tablet_id]++;
  failed_reason[tablet_id] = reason;

fe/fe-common/src/main/java/org/apache/doris/common/Config.java

@@ -81,7 +81,7 @@ public class Config extends ConfigBase {
 
  @ConfField(description = {"FE 日志文件的最大数量。超过这个数量后，最老的日志文件会被删除",
  "The maximum number of FE log files. After exceeding this number, the oldest log file will be deleted"})
- public static int sys_log_roll_num = 10;
+ public static int sys_log_roll_num = 50;
 
  @ConfField(description = {
  "Verbose 模块。VERBOSE 级别的日志是通过 log4j 的 DEBUG 级别实现的。"

fe/fe-core/src/main/java/org/apache/doris/service/FrontendServiceImpl.java

@@ -3562,6 +3562,7 @@ public TCreatePartitionResult createPartition(TCreatePartitionRequest request) t
  if (bePathsMap.keySet().size() < quorum) {
  LOG.warn("auto go quorum exception");
  }
+ LOG.info("add tablet partitionName={}, partitionID={}, tabletID={}", partitionName, partition.getId(), tablet.getId());
  tablets.add(new TTabletLocation(tablet.getId(), Lists.newArrayList(bePathsMap.keySet())));
  }
  }