Skip to content

background logging with stats #990

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

background logging with stats #990

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
3085026
background logging with stats
risner Jan 24, 2022
30de55d
Merge branch 'master' into bg_log+stats
risner Feb 27, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
35 changes: 22 additions & 13 deletions include/chia/phase1.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -258,7 +258,7 @@ class FxMatcher {
* id = 32 bytes
*/
template<typename DS>
void compute_f1(const uint8_t* id, int k, int num_threads, DS* T1_sort)
void compute_f1(const uint8_t* id, int k, int num_threads, DS* T1_sort, std::ofstream* log_file = nullptr)
{
static constexpr size_t M = 4096; // F1 block size

Expand Down Expand Up @@ -292,7 +292,9 @@ void compute_f1(const uint8_t* id, int k, int num_threads, DS* T1_sort)
output.close();
T1_sort->finish();

std::cout << "[P1] Table 1 took " << (get_wall_time_micros() - begin) / 1e6 << " sec" << std::endl;
std::ostringstream temp_buff;
temp_buff << "[P1] Table 1 took " << (get_wall_time_micros() - begin) / 1e6 << " sec" << std::endl;
show_message(&temp_buff, log_file);
}

template<typename T, typename S, typename R, typename DS_L, typename DS_R>
Expand Down Expand Up @@ -420,7 +422,8 @@ uint64_t compute_matches( int R_index, int k, int num_threads,
template<typename T, typename S, typename R, typename DS_L, typename DS_R>
uint64_t compute_table( int R_index, int k, int num_threads,
DS_L* L_sort, DS_R* R_sort,
DiskTable<R>* L_tmp, DiskTable<S>* R_tmp = nullptr)
DiskTable<R>* L_tmp, DiskTable<S>* R_tmp = nullptr,
std::ofstream* log_file = nullptr)
{
Thread<std::vector<T>> L_write(
[L_tmp](std::vector<T>& input) {
Expand Down Expand Up @@ -454,8 +457,10 @@ uint64_t compute_table( int R_index, int k, int num_threads,
if(R_tmp) {
R_tmp->close();
}
std::cout << "[P1] Table " << R_index << " took " << (get_wall_time_micros() - begin) / 1e6 << " sec"
std::ostringstream temp_buff;
temp_buff << "[P1] Table " << R_index << " took " << (get_wall_time_micros() - begin) / 1e6 << " sec"
<< ", found " << num_matches << " matches" << std::endl;
show_message(&temp_buff, log_file);
return num_matches;
}

Expand All @@ -464,7 +469,8 @@ void compute( const input_t& input, output_t& out,
const int num_threads, const int log_num_buckets,
const std::string plot_name,
const std::string tmp_dir,
const std::string tmp_dir_2)
const std::string tmp_dir_2,
std::ofstream* log_file = nullptr)
{
const auto total_begin = get_wall_time_micros();

Expand All @@ -475,37 +481,37 @@ void compute( const input_t& input, output_t& out,
const std::string prefix_2 = tmp_dir_2 + plot_name + ".p1.";

DiskSort1 sort_1(k + kExtraBits, log_num_buckets, prefix_2 + "t1");
compute_f1(input.id.data(), k, num_threads, &sort_1);
compute_f1(input.id.data(), k, num_threads, &sort_1, log_file);

DiskTable<tmp_entry_1> tmp_1(prefix + "table1.tmp");
DiskSort2 sort_2(k + kExtraBits, log_num_buckets, prefix_2 + "t2");
compute_table<entry_1, entry_2, tmp_entry_1>(
2, k, num_threads, &sort_1, &sort_2, &tmp_1);
2, k, num_threads, &sort_1, &sort_2, &tmp_1, nullptr, log_file);

DiskTable<tmp_entry_x> tmp_2(prefix + "table2.tmp");
DiskSort3 sort_3(k + kExtraBits, log_num_buckets, prefix_2 + "t3");
compute_table<entry_2, entry_3, tmp_entry_x>(
3, k, num_threads, &sort_2, &sort_3, &tmp_2);
3, k, num_threads, &sort_2, &sort_3, &tmp_2, nullptr, log_file);

DiskTable<tmp_entry_x> tmp_3(prefix + "table3.tmp");
DiskSort4 sort_4(k + kExtraBits, log_num_buckets, prefix_2 + "t4");
compute_table<entry_3, entry_4, tmp_entry_x>(
4, k, num_threads, &sort_3, &sort_4, &tmp_3);
4, k, num_threads, &sort_3, &sort_4, &tmp_3, nullptr, log_file);

DiskTable<tmp_entry_x> tmp_4(prefix + "table4.tmp");
DiskSort5 sort_5(k + kExtraBits, log_num_buckets, prefix_2 + "t5");
compute_table<entry_4, entry_5, tmp_entry_x>(
5, k, num_threads, &sort_4, &sort_5, &tmp_4);
5, k, num_threads, &sort_4, &sort_5, &tmp_4, nullptr, log_file);

DiskTable<tmp_entry_x> tmp_5(prefix + "table5.tmp");
DiskSort6 sort_6(k + kExtraBits, log_num_buckets, prefix_2 + "t6");
compute_table<entry_5, entry_6, tmp_entry_x>(
6, k, num_threads, &sort_5, &sort_6, &tmp_5);
6, k, num_threads, &sort_5, &sort_6, &tmp_5, nullptr, log_file);

DiskTable<tmp_entry_x> tmp_6(prefix + "table6.tmp");
DiskTable<entry_7> tmp_7(prefix_2 + "table7.tmp");
compute_table<entry_6, entry_7, tmp_entry_x, DiskSort6, DiskSort7>(
7, k, num_threads, &sort_6, nullptr, &tmp_6, &tmp_7);
7, k, num_threads, &sort_6, nullptr, &tmp_6, &tmp_7, log_file);

out.params = input;
out.table[0] = tmp_1.get_info();
Expand All @@ -516,7 +522,10 @@ void compute( const input_t& input, output_t& out,
out.table[5] = tmp_6.get_info();
out.table[6] = tmp_7.get_info();

std::cout << "Phase 1 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec" << std::endl;
std::ostringstream temp_buff;
temp_buff << "Phase 1 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec" << std::endl;
temp_buff << "Timestamp: " << get_date_string_ex("%Y/%m/%d %H:%M:%S") << std::endl;
show_message(&temp_buff, log_file);
}


Expand Down
25 changes: 17 additions & 8 deletions include/chia/phase2.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,9 +22,11 @@ void compute_table( int R_index, int num_threads,
DS* R_sort, DiskTable<S>* R_file,
const table_t& R_table,
bitfield* L_used,
const bitfield* R_used)
const bitfield* R_used,
std::ofstream* log_file = nullptr)
{
const int num_threads_read = std::max(num_threads / 4, 2);
std::ostringstream temp_buff;

DiskTable<T> R_input(R_table);
{
Expand All @@ -46,8 +48,9 @@ void compute_table( int R_index, int num_threads,
R_input.read(&pool, num_threads_read);
pool.close();

std::cout << "[P2] Table " << R_index << " scan took "
temp_buff << "[P2] Table " << R_index << " scan took "
<< (get_wall_time_micros() - begin) / 1e6 << " sec" << std::endl;
show_message(&temp_buff, log_file);
}
const auto begin = get_wall_time_micros();

Expand Down Expand Up @@ -116,18 +119,20 @@ void compute_table( int R_index, int num_threads,
if(R_file) {
R_file->flush();
}
std::cout << "[P2] Table " << R_index << " rewrite took "
temp_buff << "[P2] Table " << R_index << " rewrite took "
<< (get_wall_time_micros() - begin) / 1e6 << " sec"
<< ", dropped " << R_table.num_entries - num_written << " entries"
<< " (" << 100 * (1 - double(num_written) / R_table.num_entries) << " %)" << std::endl;
show_message(&temp_buff, log_file);
}

inline
void compute( const phase1::output_t& input, output_t& out,
const int num_threads, const int log_num_buckets,
const std::string plot_name,
const std::string tmp_dir,
const std::string tmp_dir_2)
const std::string tmp_dir_2,
std::ofstream* log_file = nullptr)
{
const auto total_begin = get_wall_time_micros();

Expand All @@ -139,15 +144,17 @@ void compute( const phase1::output_t& input, output_t& out,
for(const auto& table : input.table) {
max_table_size = std::max(max_table_size, table.num_entries);
}
std::cout << "[P2] max_table_size = " << max_table_size << std::endl;
std::ostringstream temp_buff;
temp_buff << "[P2] max_table_size = " << max_table_size << std::endl;
show_message(&temp_buff, log_file);

auto curr_bitfield = std::make_shared<bitfield>(max_table_size);
auto next_bitfield = std::make_shared<bitfield>(max_table_size);

DiskTable<entry_7> table_7(prefix_2 + "table7.tmp");

compute_table<entry_7, entry_7, DiskSort7>(
7, num_threads, nullptr, &table_7, input.table[6], next_bitfield.get(), nullptr);
7, num_threads, nullptr, &table_7, input.table[6], next_bitfield.get(), nullptr, log_file);

table_7.close();
remove(input.table[6].file_name);
Expand All @@ -158,7 +165,7 @@ void compute( const phase1::output_t& input, output_t& out,
out.sort[i] = std::make_shared<DiskSortT>(k, log_num_buckets, (i == 1 ? prefix_2 : prefix) + "t" + std::to_string(i + 1));

compute_table<phase1::tmp_entry_x, entry_x, DiskSortT>(
i + 1, num_threads, out.sort[i].get(), nullptr, input.table[i], next_bitfield.get(), curr_bitfield.get());
i + 1, num_threads, out.sort[i].get(), nullptr, input.table[i], next_bitfield.get(), curr_bitfield.get(), log_file);

remove(input.table[i].file_name);
}
Expand All @@ -168,7 +175,9 @@ void compute( const phase1::output_t& input, output_t& out,
out.table_7 = table_7.get_info();
out.bitfield_1 = next_bitfield;

std::cout << "Phase 2 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec" << std::endl;
temp_buff << "Phase 2 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec" << std::endl;
temp_buff << "Timestamp: " << get_date_string_ex("%Y/%m/%d %H:%M:%S") << std::endl;
show_message(&temp_buff, log_file);
}


Expand Down
44 changes: 29 additions & 15 deletions include/chia/phase3.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ template<typename T, typename S, typename DS_L, typename DS_R>
void compute_stage1(int L_index, int num_threads,
DS_L* L_sort, DS_R* R_sort, DiskSortLP* R_sort_2,
DiskTable<T>* L_table = nullptr, bitfield const* L_used = nullptr,
DiskTable<S>* R_table = nullptr)
DiskTable<S>* R_table = nullptr, std::ofstream* log_file = nullptr)
{
const auto begin = get_wall_time_micros();
const int num_threads_merge = std::max(num_threads / 4, 1);
Expand Down Expand Up @@ -195,9 +195,11 @@ void compute_stage1(int L_index, int num_threads,

R_sort_2->finish();

std::cout << "[P3-1] Table " << L_index + 1 << " took "
std::ostringstream temp_buff;
temp_buff << "[P3-1] Table " << L_index + 1 << " took "
<< (get_wall_time_micros() - begin) / 1e6 << " sec"
<< ", wrote " << R_num_write << " right entries" << std::endl;
show_message(&temp_buff, log_file);
}

static uint32_t CalculateLinePointSize(uint8_t k) {
Expand Down Expand Up @@ -229,7 +231,8 @@ uint32_t WriteHeader(
uint8_t k,
const uint8_t* id,
const uint8_t* memo,
uint32_t memo_len)
uint32_t memo_len,
std::ofstream* log_file = nullptr)
{
// 19 bytes - "Proof of Space Plot" (utf-8)
// 32 bytes - unique plot id
Expand Down Expand Up @@ -261,7 +264,9 @@ uint32_t WriteHeader(
num_bytes += fwrite((pointers), 8, 10, file) * 8;

fflush(file);
std::cout << "Wrote plot header with " << num_bytes << " bytes" << std::endl;
std::ostringstream temp_buff;
temp_buff << "Wrote plot header with " << num_bytes << " bytes" << std::endl;
show_message(&temp_buff, log_file);
return num_bytes;
}

Expand Down Expand Up @@ -329,7 +334,8 @@ void WritePark(
inline
uint64_t compute_stage2(int L_index, int k, int num_threads,
DiskSortLP* R_sort, DiskSortNP* L_sort,
FILE* plot_file, uint64_t L_final_begin, uint64_t* R_final_begin)
FILE* plot_file, uint64_t L_final_begin, uint64_t* R_final_begin,
std::ofstream* log_file = nullptr)
{
const auto begin = get_wall_time_micros();

Expand Down Expand Up @@ -462,10 +468,12 @@ uint64_t compute_stage2(int L_index, int k, int num_threads,
if(L_num_write < R_num_read) {
// std::cout << "[P3-2] Lost " << R_num_read - L_num_write << " entries due to PMAX-bit overflow." << std::endl;
}
std::cout << "[P3-2] Table " << L_index + 1 << " took "
std::ostringstream temp_buff;
temp_buff << "[P3-2] Table " << L_index + 1 << " took "
<< (get_wall_time_micros() - begin) / 1e6 << " sec"
<< ", wrote " << L_num_write << " left entries"
<< ", " << num_written_final << " final" << std::endl;
show_message(&temp_buff, log_file);
return num_written_final;
}

Expand All @@ -475,7 +483,8 @@ void compute( phase2::output_t& input, output_t& out,
const std::string plot_name,
const std::string tmp_dir,
const std::string tmp_dir_2,
const std::string plot_dir)
const std::string plot_dir,
std::ofstream* log_file = nullptr)
{
const auto total_begin = get_wall_time_micros();

Expand All @@ -490,7 +499,7 @@ void compute( phase2::output_t& input, output_t& out,
throw std::runtime_error("fopen() failed with: " + std::string(std::strerror(errno)));
}
out.header_size = WriteHeader( plot_file, k, input.params.id.data(),
input.params.memo.data(), input.params.memo.size());
input.params.memo.data(), input.params.memo.size(), log_file);

std::vector<uint64_t> final_pointers(8, 0);
final_pointers[1] = out.header_size;
Expand All @@ -503,7 +512,8 @@ void compute( phase2::output_t& input, output_t& out,
2 * k - 1, log_num_buckets, prefix_2 + "p3s1.t2");

compute_stage1<phase2::entry_1, phase2::entry_x, DiskSortNP, phase2::DiskSortT>(
1, num_threads, nullptr, input.sort[1].get(), R_sort_lp.get(), &L_table_1, input.bitfield_1.get());
1, num_threads, nullptr, input.sort[1].get(), R_sort_lp.get(),
&L_table_1, input.bitfield_1.get(), nullptr, log_file);

input.bitfield_1 = nullptr;
remove(input.table_1.file_name);
Expand All @@ -513,7 +523,7 @@ void compute( phase2::output_t& input, output_t& out,

num_written_final += compute_stage2(
1, k, num_threads, R_sort_lp.get(), L_sort_np.get(),
plot_file, final_pointers[1], &final_pointers[2]);
plot_file, final_pointers[1], &final_pointers[2], log_file);

for(int L_index = 2; L_index < 6; ++L_index)
{
Expand All @@ -523,30 +533,31 @@ void compute( phase2::output_t& input, output_t& out,
2 * k - 1, log_num_buckets, prefix_2 + "p3s1." + R_t);

compute_stage1<entry_np, phase2::entry_x, DiskSortNP, phase2::DiskSortT>(
L_index, num_threads, L_sort_np.get(), input.sort[L_index].get(), R_sort_lp.get());
L_index, num_threads, L_sort_np.get(), input.sort[L_index].get(),
R_sort_lp.get(), nullptr, nullptr, nullptr, log_file);

L_sort_np = std::make_shared<DiskSortNP>(
k, log_num_buckets, prefix_2 + "p3s2." + R_t);

num_written_final += compute_stage2(
L_index, k, num_threads, R_sort_lp.get(), L_sort_np.get(),
plot_file, final_pointers[L_index], &final_pointers[L_index + 1]);
plot_file, final_pointers[L_index], &final_pointers[L_index + 1], log_file);
}

DiskTable<phase2::entry_7> R_table_7(input.table_7);

R_sort_lp = std::make_shared<DiskSortLP>(2 * k - 1, log_num_buckets, prefix_2 + "p3s1.t7");

compute_stage1<entry_np, phase2::entry_7, DiskSortNP, phase2::DiskSort7>(
6, num_threads, L_sort_np.get(), nullptr, R_sort_lp.get(), nullptr, nullptr, &R_table_7);
6, num_threads, L_sort_np.get(), nullptr, R_sort_lp.get(), nullptr, nullptr, &R_table_7, log_file);

remove(input.table_7.file_name);

L_sort_np = std::make_shared<DiskSortNP>(k, log_num_buckets, prefix_2 + "p3s2.t7");

const auto num_written_final_7 = compute_stage2(
6, k, num_threads, R_sort_lp.get(), L_sort_np.get(),
plot_file, final_pointers[6], &final_pointers[7]);
plot_file, final_pointers[6], &final_pointers[7], log_file);
num_written_final += num_written_final_7;

fseek_set(plot_file, out.header_size - 10 * 8);
Expand All @@ -564,8 +575,11 @@ void compute( phase2::output_t& input, output_t& out,
out.num_written_7 = num_written_final_7;
out.final_pointer_7 = final_pointers[7];

std::cout << "Phase 3 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec"
std::ostringstream temp_buff;
temp_buff << "Phase 3 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec"
", wrote " << num_written_final << " entries to final plot" << std::endl;
temp_buff << "Timestamp: " << get_date_string_ex("%Y/%m/%d %H:%M:%S") << std::endl;
show_message(&temp_buff, log_file);
}


Expand Down
Loading