Skip to content

Commit fec2fd0

Browse files
SpyCheeseSpyCheese
committed
Add some time stats
1 parent dbde79e commit fec2fd0

File tree

6 files changed

+55
-28
lines changed

6 files changed

+55
-28
lines changed

‎validator/impl/collated-data-merger.cpp‎

Lines changed: 16 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,8 @@ class CollatedDataMergerExtCellLoader {
2929

3030
using CollatedDataMergerExtCell = vm::ExtCell<td::Unit, CollatedDataMergerExtCellLoader>;
3131

32-
void CollatedDataMerger::get_cells(std::vector<vm::CellHash> hashes, td::Promise<td::HashMap<vm::CellHash, Ref<vm::Cell>>> promise) {
32+
void CollatedDataMerger::get_cells(std::vector<vm::CellHash> hashes,
33+
td::Promise<td::HashMap<vm::CellHash, Ref<vm::Cell>>> promise) {
3334
td::HashMap<vm::CellHash, Ref<vm::Cell>> result;
3435
for (const vm::CellHash &hash : hashes) {
3536
auto it = cells_.find(hash);
@@ -101,25 +102,33 @@ void CollatedDataMerger::add_cells(Ref<vm::Cell> cell) {
101102
}
102103

103104
void CollatedDataMerger::add_block_candidate(BlockIdExt block_id, Ref<vm::Cell> root,
104-
std::vector<Ref<vm::Cell>> collated_roots) {
105+
std::vector<Ref<vm::Cell>> collated_roots,
106+
td::Promise<td::RealCpuTimer::Time> promise) {
107+
td::RealCpuTimer timer;
108+
SCOPE_EXIT {
109+
promise.set_value(timer.elapsed_both());
110+
};
105111
if (!blocks_.insert(block_id).second) {
106112
return;
107113
}
108-
td::Timer timer;
109114
add_cells(std::move(root));
110115
for (auto &c : collated_roots) {
111116
add_cells(std::move(c));
112117
}
113-
LOG(INFO) << "Added block " << block_id.to_str() << " in " << timer.elapsed()
118+
LOG(INFO) << "Added block " << block_id.to_str() << " in " << timer.elapsed_real()
114119
<< " s, total cells = " << cells_.size();
115120
}
116121

117122
void CollatedDataMerger::add_block_candidate_data(BlockIdExt block_id, td::BufferSlice data,
118-
td::BufferSlice collated_data) {
123+
td::BufferSlice collated_data,
124+
td::Promise<td::RealCpuTimer::Time> promise) {
125+
td::RealCpuTimer timer;
126+
SCOPE_EXIT {
127+
promise.set_value(timer.elapsed_both());
128+
};
119129
if (!blocks_.insert(block_id).second) {
120130
return;
121131
}
122-
td::Timer timer;
123132
auto r_root = vm::std_boc_deserialize(data);
124133
if (r_root.is_error()) {
125134
LOG(WARNING) << "Failed to deserialize block data for " << block_id.to_str() << " : " << r_root.error();
@@ -135,7 +144,7 @@ void CollatedDataMerger::add_block_candidate_data(BlockIdExt block_id, td::Buffe
135144
for (auto &c : r_collated_roots.move_as_ok()) {
136145
add_cells(std::move(c));
137146
}
138-
LOG(INFO) << "Added block " << block_id.to_str() << " in " << timer.elapsed() << " s";
147+
LOG(INFO) << "Added block " << block_id.to_str() << " in " << timer.elapsed_real() << " s";
139148
}
140149

141150
void CollatedDataMerger::CellInfo::set_cell(const Ref<vm::DataCell> &new_cell) {

‎validator/impl/collated-data-merger.h‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -34,8 +34,10 @@ class CollatedDataMerger : public td::actor::Actor {
3434
public:
3535
void get_cells(std::vector<vm::CellHash> hashes, td::Promise<td::HashMap<vm::CellHash, Ref<vm::Cell>>> promise);
3636
void add_cells(Ref<vm::Cell> cell);
37-
void add_block_candidate(BlockIdExt block_id, Ref<vm::Cell> root, std::vector<Ref<vm::Cell>> collated_roots);
38-
void add_block_candidate_data(BlockIdExt block_id, td::BufferSlice data, td::BufferSlice collated_data);
37+
void add_block_candidate(BlockIdExt block_id, Ref<vm::Cell> root, std::vector<Ref<vm::Cell>> collated_roots,
38+
td::Promise<td::RealCpuTimer::Time> promise);
39+
void add_block_candidate_data(BlockIdExt block_id, td::BufferSlice data, td::BufferSlice collated_data,
40+
td::Promise<td::RealCpuTimer::Time> promise);
3941

4042
private:
4143
struct CellInfo {

‎validator/impl/collator.cpp‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6782,6 +6782,10 @@ void Collator::on_cell_loaded(const vm::LoadedCell& loaded_cell) {
67826782
if (stop_cell_load_processing_) {
67836783
return;
67846784
}
6785+
td::RealCpuTimer timer;
6786+
SCOPE_EXIT {
6787+
stats_.work_time.total_on_cell_loaded += timer.elapsed_both();
6788+
};
67856789
if (merge_collated_data_enabled_) {
67866790
vm::CellHash hash = loaded_cell.data_cell->get_hash(loaded_cell.virt.get_level());
67876791
if (collated_data_deduplicator_ &&

‎validator/impl/validate-query.cpp‎

Lines changed: 22 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -837,28 +837,34 @@ bool ValidateQuery::extract_collated_data() {
837837
}
838838
if (merge_collated_data_enabled_) {
839839
LOG(INFO) << "merge_collated_data = true";
840-
LOG(DEBUG) << "sending add_block_candidate() to CollatedDataMerger";
841-
td::actor::send_closure(collated_data_merger_, &CollatedDataMerger::add_block_candidate, id_, block_root_,
842-
collated_roots_);
843840
if (optimistic_prev_block_.not_null()) {
844841
LOG(DEBUG) << "sending add_block_candidate() for optimistic prev block to CollatedDataMerger";
845842
td::actor::send_closure(collated_data_merger_, &CollatedDataMerger::add_block_candidate_data, id_,
846-
optimistic_prev_block_->data(), optimistic_prev_collated_data_.clone());
843+
optimistic_prev_block_->data(), optimistic_prev_collated_data_.clone(),
844+
[](td::Result<td::RealCpuTimer::Time>) {});
847845
}
846+
LOG(DEBUG) << "sending add_block_candidate() to CollatedDataMerger";
847+
td::actor::send_closure(collated_data_merger_, &CollatedDataMerger::add_block_candidate, id_, block_root_,
848+
collated_roots_, [SelfId = actor_id(this), this](td::Result<td::RealCpuTimer::Time> R) {
849+
if (R.is_error()) {
850+
return;
851+
}
852+
td::actor::send_lambda(SelfId, [this, time = R.move_as_ok()]() {
853+
stats_.work_time.ext_collated_data_merge += time;
854+
});
855+
});
848856
std::vector<vm::CellHash> hashes = collated_data_root_state_hashes_;
849857
hashes.insert(hashes.end(), collated_data_root_dict_hashes_.begin(), collated_data_root_dict_hashes_.end());
850-
if (!hashes.empty()) {
851-
LOG(DEBUG) << "sending get_cells to CollatedDataMerger";
852-
++pending;
853-
td::actor::send_closure_later(
854-
collated_data_merger_, &CollatedDataMerger::get_cells, std::move(hashes),
855-
[self = get_self(), token = perf_log_.start_action("CollatedDataMerger::get_cells")](
856-
td::Result<td::HashMap<vm::CellHash, Ref<vm::Cell>>> res) mutable {
857-
LOG(DEBUG) << "got answer to CollatedDataMerger::get_cells";
858-
td::actor::send_closure_later(std::move(self), &ValidateQuery::process_merged_collated_roots,
859-
std::move(res), std::move(token));
860-
});
861-
}
858+
LOG(DEBUG) << "sending get_cells to CollatedDataMerger";
859+
++pending;
860+
td::actor::send_closure_later(
861+
collated_data_merger_, &CollatedDataMerger::get_cells, std::move(hashes),
862+
[self = get_self(), token = perf_log_.start_action("CollatedDataMerger::get_cells")](
863+
td::Result<td::HashMap<vm::CellHash, Ref<vm::Cell>>> res) mutable {
864+
LOG(DEBUG) << "got answer to CollatedDataMerger::get_cells";
865+
td::actor::send_closure_later(std::move(self), &ValidateQuery::process_merged_collated_roots,
866+
std::move(res), std::move(token));
867+
});
862868
}
863869
return true;
864870
}

‎validator/interfaces/validator-manager.h‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -128,6 +128,8 @@ struct CollationStats {
128128
td::RealCpuTimer::Time create_collated_data;
129129
td::RealCpuTimer::Time create_block_candidate;
130130

131+
td::RealCpuTimer::Time total_on_cell_loaded;
132+
131133
std::string to_str(bool is_cpu) const {
132134
return PSTRING() << "total=" << total.get(is_cpu) << " optimistic_apply=" << optimistic_apply.get(is_cpu)
133135
<< " queue_cleanup=" << queue_cleanup.get(is_cpu)
@@ -137,7 +139,8 @@ struct CollationStats {
137139
<< " final_storage_stat=" << final_storage_stat.get(is_cpu)
138140
<< " create_block=" << create_block.get(is_cpu)
139141
<< " create_collated_data=" << create_collated_data.get(is_cpu)
140-
<< " create_block_candidate=" << create_block_candidate.get(is_cpu);
142+
<< " create_block_candidate=" << create_block_candidate.get(is_cpu)
143+
<< " *total_on_cell_loaded=" << total_on_cell_loaded.get(is_cpu);
141144
}
142145
};
143146
WorkTimeStats work_time;
@@ -187,10 +190,13 @@ struct ValidationStats {
187190
td::RealCpuTimer::Time trx_storage_stat;
188191
td::RealCpuTimer::Time trx_other;
189192

193+
td::RealCpuTimer::Time ext_collated_data_merge;
194+
190195
std::string to_str(bool is_cpu) const {
191196
return PSTRING() << "total=" << total.get(is_cpu) << " optimistic_apply=" << optimistic_apply.get(is_cpu)
192197
<< " trx_tvm=" << trx_tvm.get(is_cpu) << " trx_storage_stat=" << trx_storage_stat.get(is_cpu)
193-
<< " trx_other=" << trx_other.get(is_cpu);
198+
<< " trx_other=" << trx_other.get(is_cpu)
199+
<< " *ext_collated_data_merge=" << ext_collated_data_merge.get(is_cpu);
194200
}
195201
};
196202
WorkTimeStats work_time;

‎validator/validator-group.cpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -800,7 +800,7 @@ void ValidatorGroup::merge_collated_data(PublicKey source, BlockIdExt block_id,
800800
}
801801
if (!o_block_data.empty()) {
802802
td::actor::send_closure(collated_data_merger_, &CollatedDataMerger::add_block_candidate_data, block_id,
803-
o_block_data.clone(), o_collated_data.clone());
803+
o_block_data.clone(), o_collated_data.clone(), [](td::Result<td::RealCpuTimer::Time>) {});
804804
collated_data_deduplicator_->add_block_candidate(block_id.seqno(), o_block_data.clone(), o_collated_data.clone())
805805
.ensure();
806806
collated_data_merged_.insert(block_id.seqno());

0 commit comments

Comments
 (0)