Skip to content

Commit 189a634

Browse files
akokoshnakokoshn
committed
proof-producer: use macroses for timing
1 parent e5afed9 commit 189a634

File tree

7 files changed

+125
-159
lines changed

7 files changed

+125
-159
lines changed

‎crypto3/libs/benchmark_tools/include/nil/crypto3/bench/scoped_profiler.hpp

Lines changed: 102 additions & 76 deletions
Original file line numberDiff line numberDiff line change
@@ -31,82 +31,102 @@
3131
#include <iostream>
3232
#include <iomanip>
3333
#include <unordered_map>
34+
#include <stack>
3435

3536
namespace nil {
3637
namespace crypto3 {
3738
namespace bench {
3839
namespace detail {
39-
40-
// Measures execution time of a given function just once. Prints
41-
// the time when leaving the function in which this class was created.
42-
class scoped_profiler
43-
{
44-
public:
45-
inline scoped_profiler(std::string name)
46-
: start(std::chrono::high_resolution_clock::now())
47-
, name(name) {
48-
}
49-
50-
inline ~scoped_profiler() {
51-
auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(
52-
std::chrono::high_resolution_clock::now() - start);
53-
std::cout << name << ": " << std::fixed << std::setprecision(3)
54-
<< elapsed.count() << " ms" << std::endl;
55-
}
56-
57-
private:
58-
std::chrono::time_point<std::chrono::high_resolution_clock> start;
59-
std::string name;
60-
};
61-
62-
class call_stats {
63-
public:
64-
// Make this class singleton.
65-
static call_stats& get_stats() {
66-
static call_stats instance;
67-
return instance;
68-
}
69-
70-
void add_stat(const std::string& name, uint64_t time_ms) {
71-
call_counts[name]++;
72-
call_miliseconds[name] += time_ms;
73-
}
74-
75-
private:
76-
call_stats() {}
77-
~call_stats() {
78-
for (const auto& [name, count]: call_counts) {
79-
uint64_t miliseconds = call_miliseconds[name] / 1000000;
80-
std::cout << name << ": " << count << " calls "
81-
<< miliseconds / 1000 << " sec "
82-
<< miliseconds % 1000 << " ms" << std::endl;
83-
}
84-
}
85-
86-
std::unordered_map<std::string, uint64_t> call_counts;
87-
std::unordered_map<std::string, uint64_t> call_miliseconds;
88-
};
89-
90-
// Measures the total execution time of the functions it's placed in, and the number of calls.
91-
// Prints the time and number of calls on program exit.
92-
class scoped_aggregate_profiler
93-
{
94-
public:
95-
inline scoped_aggregate_profiler(std::string name)
96-
: start(std::chrono::high_resolution_clock::now())
97-
, name(name) {
98-
}
99-
100-
inline ~scoped_aggregate_profiler() {
101-
auto elapsed = std::chrono::duration_cast<std::chrono::nanoseconds>(
102-
std::chrono::high_resolution_clock::now() - start);
103-
call_stats::get_stats().add_stat(name, elapsed.count());
104-
}
105-
106-
private:
107-
std::chrono::time_point<std::chrono::high_resolution_clock> start;
108-
std::string name;
109-
};
40+
void no_scope_profiling(const std::string& name, bool stop = false) {
41+
static std::stack<std::pair<std::string, std::chrono::time_point<std::chrono::high_resolution_clock>>> points;
42+
if (stop) {
43+
const auto curr = std::chrono::high_resolution_clock::now();
44+
auto start = curr;
45+
if ((points.size() > 0) && (points.top().first == name)) {
46+
start = points.top().second;
47+
points.pop();
48+
}
49+
auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(
50+
curr - start);
51+
std::cout << name << ": " << std::fixed << std::setprecision(3)
52+
<< elapsed.count() << " ms" << std::endl;
53+
} else {
54+
const auto start = std::chrono::high_resolution_clock::now();
55+
const auto point = std::make_pair<>(std::move(name), start);
56+
points.push(point);
57+
}
58+
}
59+
60+
// Measures execution time of a given function just once. Prints
61+
// the time when leaving the function in which this class was created.
62+
class scoped_profiler
63+
{
64+
public:
65+
inline scoped_profiler(std::string name)
66+
: start(std::chrono::high_resolution_clock::now())
67+
, name(name) {
68+
}
69+
70+
inline ~scoped_profiler() {
71+
auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(
72+
std::chrono::high_resolution_clock::now() - start);
73+
std::cout << name << ": " << std::fixed << std::setprecision(3)
74+
<< elapsed.count() << " ms" << std::endl;
75+
}
76+
77+
private:
78+
std::chrono::time_point<std::chrono::high_resolution_clock> start;
79+
std::string name;
80+
};
81+
82+
class call_stats {
83+
public:
84+
// Make this class singleton.
85+
static call_stats& get_stats() {
86+
static call_stats instance;
87+
return instance;
88+
}
89+
90+
void add_stat(const std::string& name, uint64_t time_ms) {
91+
call_counts[name]++;
92+
call_miliseconds[name] += time_ms;
93+
}
94+
95+
private:
96+
call_stats() {}
97+
~call_stats() {
98+
for (const auto& [name, count]: call_counts) {
99+
uint64_t miliseconds = call_miliseconds[name] / 1000000;
100+
std::cout << name << ": " << count << " calls "
101+
<< miliseconds / 1000 << " sec "
102+
<< miliseconds % 1000 << " ms" << std::endl;
103+
}
104+
}
105+
106+
std::unordered_map<std::string, uint64_t> call_counts;
107+
std::unordered_map<std::string, uint64_t> call_miliseconds;
108+
};
109+
110+
// Measures the total execution time of the functions it's placed in, and the number of calls.
111+
// Prints the time and number of calls on program exit.
112+
class scoped_aggregate_profiler
113+
{
114+
public:
115+
inline scoped_aggregate_profiler(std::string name)
116+
: start(std::chrono::high_resolution_clock::now())
117+
, name(name) {
118+
}
119+
120+
inline ~scoped_aggregate_profiler() {
121+
auto elapsed = std::chrono::duration_cast<std::chrono::nanoseconds>(
122+
std::chrono::high_resolution_clock::now() - start);
123+
call_stats::get_stats().add_stat(name, elapsed.count());
124+
}
125+
126+
private:
127+
std::chrono::time_point<std::chrono::high_resolution_clock> start;
128+
std::string name;
129+
};
110130

111131
} // namespace detail
112132
} // namespace bench
@@ -117,14 +137,20 @@ class scoped_aggregate_profiler
117137
#define PROFILE_SCOPE(name) \
118138
nil::crypto3::bench::detail::scoped_profiler profiler(name);
119139
#else
120-
#define PROFILE_SCOPE(name)
140+
#define PROFILE_SCOPE(name)
121141
#endif
122142

123-
#ifdef PROFILING_ENABLED
124-
#define PROFILE_FUNCTION_CALLS() \
125-
nil::crypto3::bench::detail::scoped_aggregate_profiler profiler(__PRETTY_FUNCTION__ );
143+
#ifdef TIME_LOG_ENABLED
144+
#define TIME_LOG_SCOPE(name) \
145+
nil::crypto3::bench::detail::scoped_profiler profiler(name);
146+
#define TIME_LOG_START(name) \
147+
nil::crypto3::bench::detail::no_scope_profiling(name, false);
148+
#define TIME_LOG_END(name) \
149+
nil::crypto3::bench::detail::no_scope_profiling(name, true);
126150
#else
127-
#define PROFILE_FUNCTION_CALLS()
151+
#define TIME_LOG_SCOPE(name)
152+
#define TIME_LOG_START(name)
153+
#define TIME_LOG_END(name)
128154
#endif
129155

130156
#endif // CRYPTO3_SCOPED_PROFILER_HPP

‎proof-producer/bin/proof-producer/include/nil/proof-generator/prover.hpp

Lines changed: 21 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -26,10 +26,14 @@
2626
#include <random>
2727
#include <sstream>
2828
#include <optional>
29-
#include <chrono>
3029

3130
#include <boost/log/trivial.hpp>
3231

32+
#ifndef TIME_LOG_ENABLED
33+
#define TIME_LOG_ENABLED
34+
#include <nil/crypto3/bench/scoped_profiler.hpp>
35+
#endif
36+
3337
#include <nil/marshalling/endianness.hpp>
3438
#include <nil/marshalling/field_type.hpp>
3539
#include <nil/marshalling/status_type.hpp>
@@ -250,7 +254,7 @@ namespace nil {
250254
BOOST_ASSERT(lpc_scheme_);
251255

252256
BOOST_LOG_TRIVIAL(info) << "Generating proof...";
253-
auto start = std::chrono::high_resolution_clock::now();
257+
TIME_LOG_START("Generation Proof")
254258
nil::crypto3::zk::snark::placeholder_prover<BlueprintField, PlaceholderParams> prover(
255259
*public_preprocessed_data_,
256260
*private_preprocessed_data_,
@@ -259,21 +263,21 @@ namespace nil {
259263
std::move(*lpc_scheme_)
260264
);
261265
auto proof = prover.process();
262-
auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::high_resolution_clock::now() - start);
263-
BOOST_LOG_TRIVIAL(info) << "Proof generated: " << duration.count() << "ms";
264266

265-
start = std::chrono::high_resolution_clock::now();
267+
BOOST_LOG_TRIVIAL(info) << "Proof generated";
268+
TIME_LOG_END("Generation Proof")
269+
266270
create_lpc_scheme(); // reset to default scheme to do the verification
267271
bool verify_ok{};
268272
if (skip_verification) {
269273
BOOST_LOG_TRIVIAL(info) << "Skipping proof verification";
270274
verify_ok = true;
271275
} else {
276+
TIME_LOG_SCOPE("Verification Proof")
272277
verify_ok = verify(proof);
273278
}
274279
lpc_scheme_.emplace(std::move(prover.move_commitment_scheme())); // get back the commitment scheme used in prover
275-
duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::high_resolution_clock::now() - start);
276-
BOOST_LOG_TRIVIAL(info) << "Proof verified: " << duration.count() << "ms";
280+
BOOST_LOG_TRIVIAL(info) << "Proof verified";
277281

278282
if (!verify_ok) {
279283
BOOST_LOG_TRIVIAL(error) << "Proof verification failed";
@@ -328,7 +332,7 @@ namespace nil {
328332
BOOST_ASSERT(lpc_scheme_);
329333

330334
BOOST_LOG_TRIVIAL(info) << "Generating proof...";
331-
auto start = std::chrono::high_resolution_clock::now();
335+
TIME_LOG_START("Generation Proof")
332336
auto prover = nil::crypto3::zk::snark::placeholder_prover<BlueprintField, PlaceholderParams>(
333337
*public_preprocessed_data_,
334338
*private_preprocessed_data_,
@@ -337,8 +341,9 @@ namespace nil {
337341
std::move(*lpc_scheme_),
338342
true);
339343
Proof proof = prover.process();
340-
auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::high_resolution_clock::now() - start);
341-
BOOST_LOG_TRIVIAL(info) << "Proof generated: " << duration.count() << "ms";
344+
345+
BOOST_LOG_TRIVIAL(info) << "Proof generated";
346+
TIME_LOG_END("Generation Proof")
342347

343348
lpc_scheme_.emplace(prover.move_commitment_scheme()); // get back the commitment scheme used in prover
344349

@@ -783,7 +788,7 @@ namespace nil {
783788
create_lpc_scheme();
784789

785790
BOOST_LOG_TRIVIAL(info) << "Preprocessing public data";
786-
auto start = std::chrono::high_resolution_clock::now();
791+
TIME_LOG_SCOPE("Preprocess Public Data")
787792
public_preprocessed_data_.emplace(
788793
nil::crypto3::zk::snark::placeholder_public_preprocessor<BlueprintField, PlaceholderParams>::
789794
process(
@@ -794,21 +799,18 @@ namespace nil {
794799
max_quotient_chunks_
795800
)
796801
);
797-
auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::high_resolution_clock::now() - start);
798-
BOOST_LOG_TRIVIAL(info) << "Preprocess: " << duration.count() << "ms";
799802
return true;
800803
}
801804

802805
bool preprocess_private_data() {
803806

804807
BOOST_LOG_TRIVIAL(info) << "Preprocessing private data";
805-
auto start = std::chrono::high_resolution_clock::now();
808+
TIME_LOG_SCOPE("Preprocess Private Data")
806809
private_preprocessed_data_.emplace(
807810
nil::crypto3::zk::snark::placeholder_private_preprocessor<BlueprintField, PlaceholderParams>::
808811
process(*constraint_system_, assignment_table_->move_private_table(), *table_description_)
809812
);
810-
auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::high_resolution_clock::now() - start);
811-
BOOST_LOG_TRIVIAL(info) << "Preprocess private data: " << duration.count() << "ms";
813+
BOOST_LOG_TRIVIAL(info) << "Preprocess private data";
812814

813815
// This is the last stage of preprocessor, and the assignment table is not used after this function call.
814816
assignment_table_.reset();
@@ -894,7 +896,7 @@ namespace nil {
894896
}
895897

896898
BOOST_LOG_TRIVIAL(info) << "Generating combined Q from " << aggregated_challenge_file
897-
<< " to " << output_combined_Q_file << " with satarting_power " << starting_power;
899+
<< " to " << output_combined_Q_file << " with starting_power " << starting_power;
898900

899901
polynomial_type combined_Q = lpc_scheme_->prepare_combined_Q(
900902
challenge.value(), starting_power);
@@ -1126,14 +1128,12 @@ namespace nil {
11261128
}
11271129

11281130
bool setup_prover() {
1129-
auto start = std::chrono::high_resolution_clock::now();
1131+
TIME_LOG_SCOPE("Preset")
11301132
const auto err = CircuitFactory<BlueprintField>::initialize_circuit(circuit_name_, constraint_system_, assignment_table_, table_description_);
11311133
if (err) {
11321134
BOOST_LOG_TRIVIAL(error) << "Can't initialize circuit " << circuit_name_ << ": " << err.value();
11331135
return false;
11341136
}
1135-
auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::high_resolution_clock::now() - start);
1136-
BOOST_LOG_TRIVIAL(info) << "Preset: " << duration.count() << "ms";
11371137
return true;
11381138
}
11391139

@@ -1156,6 +1156,7 @@ namespace nil {
11561156
BOOST_LOG_TRIVIAL(error) << "Assignment table is not initialized";
11571157
return false;
11581158
}
1159+
TIME_LOG_SCOPE("Fill Assignment Table")
11591160
const auto err = fill_assignment_table_single_thread(*assignment_table_, *table_description_, circuit_name_, trace_base_path);
11601161
if (err) {
11611162
BOOST_LOG_TRIVIAL(error) << "Can't fill assignment table from trace " << trace_base_path << ": " << err.value();

‎proof-producer/libs/assigner/include/nil/proof-generator/assigner/add.hpp

Lines changed: 0 additions & 47 deletions
This file was deleted.

0 commit comments

Comments
 (0)