Add log timestamps

Author: gurki

include/chia/phase1.hpp

@@ -281,7 +281,7 @@ void compute_f1(const uint8_t* id, 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::cout << get_curr_datetime() << " [P1] Table 1 took " << (get_wall_time_micros() - begin) / 1e6 << " sec" << std::endl;
 }
 
 template<typename T, typename S, typename R, typename DS_L, typename DS_R>
@@ -400,7 +400,7 @@ uint64_t compute_matches(	int R_index, int num_threads,
 		R_sort->finish();
 	}
 	if(num_written < num_found) {
-//		std::cout << "[P1] Lost " << num_found - num_written
+//		std::cout << get_curr_datetime() << " [P1] Lost " << num_found - num_written
 //				<< " matches due to 32-bit overflow." << std::endl;
 	}
 	return num_written;
@@ -443,7 +443,7 @@ uint64_t compute_table(	int R_index, int num_threads,
 	if(R_tmp) {
 		R_tmp->close();
 	}
-	std::cout << "[P1] Table " << R_index << " took " << (get_wall_time_micros() - begin) / 1e6 << " sec"
+	std::cout << get_curr_datetime() << " [P1] Table " << R_index << " took " << (get_wall_time_micros() - begin) / 1e6 << " sec"
 			<< ", found " << num_matches << " matches" << std::endl;
 	return num_matches;
 }
@@ -504,7 +504,7 @@ 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::cout << get_curr_datetime() << " Phase 1 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec" << std::endl;
 }
 
 

include/chia/phase2.hpp

@@ -46,7 +46,7 @@ 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 "
+		std::cout << get_curr_datetime() << " [P2] Table " << R_index << " scan took "
 				<< (get_wall_time_micros() - begin) / 1e6 << " sec" << std::endl;
 	}
 	const auto begin = get_wall_time_micros();
@@ -116,7 +116,7 @@ void compute_table(	int R_index, int num_threads,
 	if(R_file) {
 		R_file->flush();
 	}
-	std::cout << "[P2] Table " << R_index << " rewrite took "
+	std::cout << get_curr_datetime() << " [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;
@@ -138,7 +138,7 @@ 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::cout << get_curr_datetime() << " [P2] max_table_size = " << max_table_size << std::endl;
 
 	auto curr_bitfield = std::make_shared<bitfield>(max_table_size);
 	auto next_bitfield = std::make_shared<bitfield>(max_table_size);
@@ -167,7 +167,7 @@ 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;
+	std::cout << get_curr_datetime() << " Phase 2 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec" << std::endl;
 }
 
 

include/chia/phase3.hpp

@@ -195,7 +195,7 @@ void compute_stage1(int L_index, int num_threads,
 
 	R_sort_2->finish();
 
-	std::cout << "[P3-1] Table " << L_index + 1 << " took "
+	std::cout << get_curr_datetime() << " [P3-1] Table " << L_index + 1 << " took "
 				<< (get_wall_time_micros() - begin) / 1e6 << " sec"
 				<< ", wrote " << R_num_write << " right entries" << std::endl;
 }
@@ -261,7 +261,7 @@ 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::cout << get_curr_datetime() << " Wrote plot header with " << num_bytes << " bytes" << std::endl;
 	return num_bytes;
 }
 
@@ -460,9 +460,9 @@ uint64_t compute_stage2(int L_index, int num_threads,
 	Encoding::ANSFree(kRValues[L_index - 1]);
 
 	if(L_num_write < R_num_read) {
-//		std::cout << "[P3-2] Lost " << R_num_read - L_num_write << " entries due to 32-bit overflow." << std::endl;
+//		std::cout << get_curr_datetime() << " [P3-2] Lost " << R_num_read - L_num_write << " entries due to 32-bit overflow." << std::endl;
 	}
-	std::cout << "[P3-2] Table " << L_index + 1 << " took "
+	std::cout << get_curr_datetime() << " [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;
@@ -559,7 +559,7 @@ 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::cout << get_curr_datetime() << " Phase 3 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec"
 			", wrote " << num_written_final << " entries to final plot" << std::endl;
 }
 

include/chia/phase4.hpp

@@ -79,7 +79,7 @@ uint64_t compute(	FILE* plot_file, const int header_size,
 
     std::vector<uint32_t> C2;
 
-    std::cout << "[P4] Starting to write C1 and C3 tables" << std::endl;
+    std::cout << get_curr_datetime() << " [P4] Starting to write C1 and C3 tables" << std::endl;
 
 	struct park_deltas_t {
 		uint64_t offset = 0;
@@ -215,8 +215,8 @@ uint64_t compute(	FILE* plot_file, const int header_size,
     final_file_writer_1 +=
     		fwrite_at(plot_file, final_file_writer_1, C1_entry_buf, sizeof(C1_entry_buf));
 
-    std::cout << "[P4] Finished writing C1 and C3 tables" << std::endl;
-    std::cout << "[P4] Writing C2 table" << std::endl;
+    std::cout << get_curr_datetime() << " [P4] Finished writing C1 and C3 tables" << std::endl;
+    std::cout << get_curr_datetime() << " [P4] Writing C2 table" << std::endl;
 
     for(const uint64_t C2_entry : C2) {
         Bits(C2_entry, k).ToBytes(C1_entry_buf);
@@ -227,7 +227,7 @@ uint64_t compute(	FILE* plot_file, const int header_size,
     final_file_writer_1 +=
     		fwrite_at(plot_file, final_file_writer_1, C1_entry_buf, sizeof(C1_entry_buf));
 
-    std::cout << "[P4] Finished writing C2 table" << std::endl;
+    std::cout << get_curr_datetime() << " [P4] Finished writing C2 table" << std::endl;
 
     final_file_writer_1 = header_size - 8 * 3;
     uint8_t table_pointer_bytes[8] = {};
@@ -265,7 +265,7 @@ void compute(	const phase3::output_t& input, output_t& out,
 
 	std::rename(input.plot_file_name.c_str(), out.plot_file_name.c_str());
 
-	std::cout << "Phase 4 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec"
+	std::cout << get_curr_datetime() << " Phase 4 took " << (get_wall_time_micros() - total_begin) / 1e6 << " sec"
 			", final plot size is " << out.plot_size << " bytes" << std::endl;
 }
 

include/chia/util.hpp

@@ -375,6 +375,16 @@ namespace Util {
     }
 }
 
+inline
+std::string get_curr_datetime()
+{
+    time_t now;
+    time(&now);
+    char buf[sizeof "YYYY-MM-ddTHH:mm:ssZ"];
+    strftime(buf, sizeof buf, "%FT%TZ", gmtime(&now));
+    return std::string( buf );
+}
+
 inline
 int64_t get_wall_time_micros() {
 	return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch()).count();

src/chia_plot.cpp

@@ -62,27 +62,27 @@ phase4::output_t create_plot(	const int num_threads,
 {
 	const auto total_begin = get_wall_time_micros();
 
-	std::cout << "Process ID: " << GETPID() << std::endl;
-	std::cout << "Number of Threads: " << num_threads << std::endl;
-	std::cout << "Number of Buckets: 2^" << log_num_buckets
+	std::cout << get_curr_datetime() << " Process ID: " << GETPID() << std::endl;
+	std::cout << get_curr_datetime() << " Number of Threads: " << num_threads << std::endl;
+	std::cout << get_curr_datetime() << " Number of Buckets: 2^" << log_num_buckets
 			<< " (" << (1 << log_num_buckets) << ")" << std::endl;
 
 	bls::G1Element pool_key;
 	bls::G1Element farmer_key;
 	try {
 		pool_key = bls::G1Element::FromByteVector(pool_key_bytes);
 	} catch(std::exception& ex) {
-		std::cout << "Invalid poolkey: " << bls::Util::HexStr(pool_key_bytes) << std::endl;
+		std::cout << get_curr_datetime() << " Invalid poolkey: " << bls::Util::HexStr(pool_key_bytes) << std::endl;
 		throw;
 	}
 	try {
 		farmer_key = bls::G1Element::FromByteVector(farmer_key_bytes);
 	} catch(std::exception& ex) {
-		std::cout << "Invalid farmerkey: " << bls::Util::HexStr(farmer_key_bytes) << std::endl;
+		std::cout << get_curr_datetime() << " Invalid farmerkey: " << bls::Util::HexStr(farmer_key_bytes) << std::endl;
 		throw;
 	}
-	std::cout << "Pool Public Key:   " << bls::Util::HexStr(pool_key.Serialize()) << std::endl;
-	std::cout << "Farmer Public Key: " << bls::Util::HexStr(farmer_key.Serialize()) << std::endl;
+	std::cout << get_curr_datetime() << " Pool Public Key:   " << bls::Util::HexStr(pool_key.Serialize()) << std::endl;
+	std::cout << get_curr_datetime() << " Farmer Public Key: " << bls::Util::HexStr(farmer_key.Serialize()) << std::endl;
 
 	vector<uint8_t> seed(32);
 	randombytes_buf(seed.data(), seed.size());
@@ -109,9 +109,9 @@ phase4::output_t create_plot(	const int num_threads,
 	const std::string plot_name = "plot-k32-" + get_date_string_ex("%Y-%m-%d-%H-%M")
 			+ "-" + bls::Util::HexStr(params.id.data(), params.id.size());
 
-	std::cout << "Working Directory:   " << (tmp_dir.empty() ? "$PWD" : tmp_dir) << std::endl;
-	std::cout << "Working Directory 2: " << (tmp_dir_2.empty() ? "$PWD" : tmp_dir_2) << std::endl;
-	std::cout << "Plot Name: " << plot_name << std::endl;
+	std::cout << get_curr_datetime() << " Working Directory:   " << (tmp_dir.empty() ? "$PWD" : tmp_dir) << std::endl;
+	std::cout << get_curr_datetime() << " Working Directory 2: " << (tmp_dir_2.empty() ? "$PWD" : tmp_dir_2) << std::endl;
+	std::cout << get_curr_datetime() << " Plot Name: " << plot_name << std::endl;
 
 	// memo = bytes(pool_public_key) + bytes(farmer_public_key) + bytes(local_master_sk)
 	params.memo.insert(params.memo.end(), pool_key_bytes.begin(), pool_key_bytes.end());
@@ -135,7 +135,7 @@ phase4::output_t create_plot(	const int num_threads,
 	phase4::compute(out_3, out_4, num_threads, log_num_buckets, plot_name, tmp_dir, tmp_dir_2);
 
 	const auto time_secs = (get_wall_time_micros() - total_begin) / 1e6;
-	std::cout << "Total plot creation time was "
+	std::cout << get_curr_datetime() << " Total plot creation time was "
 			<< time_secs << " sec (" << time_secs / 60. << " min)" << std::endl;
 	return out_4;
 }
@@ -312,11 +312,11 @@ int main(int argc, char** argv)
 		std::cout << " - " << GIT_COMMIT_HASH;
 	#endif	
 	std::cout << std::endl;
-	std::cout << "Final Directory: " << final_dir << std::endl;
+	std::cout << get_curr_datetime() << " Final Directory: " << final_dir << std::endl;
 	if(num_plots >= 0) {
-		std::cout << "Number of Plots: " << num_plots << std::endl;
+		std::cout << get_curr_datetime() << " Number of Plots: " << num_plots << std::endl;
 	} else {
-		std::cout << "Number of Plots: infinite" << std::endl;
+		std::cout << get_curr_datetime() << " Number of Plots: infinite" << std::endl;
 	}
 
 	Thread<std::pair<std::string, std::string>> copy_thread(
@@ -327,11 +327,11 @@ int main(int argc, char** argv)
 					const auto bytes = final_copy(from_to.first, from_to.second);
 
 					const auto time = (get_wall_time_micros() - total_begin) / 1e6;
-					std::cout << "Copy to " << from_to.second << " finished, took " << time << " sec, "
+					std::cout << get_curr_datetime() << " Copy to " << from_to.second << " finished, took " << time << " sec, "
 							<< ((bytes / time) / 1024 / 1024) << " MB/s avg." << std::endl;
 					break;
 				} catch(const std::exception& ex) {
-					std::cout << "Copy to " << from_to.second << " failed with: " << ex.what() << std::endl;
+					std::cout << get_curr_datetime() << " Copy to " << from_to.second << " failed with: " << ex.what() << std::endl;
 					std::this_thread::sleep_for(std::chrono::minutes(5));
 				}
 			}
@@ -343,13 +343,13 @@ int main(int argc, char** argv)
 			std::cout << std::endl << "Process has been interrupted, waiting for copy/rename operations to finish ..." << std::endl;
 			break;
 		}
-		std::cout << "Crafting plot " << i+1 << " out of " << num_plots << std::endl;
+		std::cout << get_curr_datetime() << " Crafting plot " << i+1 << " out of " << num_plots << std::endl;
 		const auto out = create_plot(num_threads, log_num_buckets, pool_key, farmer_key, tmp_dir, tmp_dir2);
 
 		if(final_dir != tmp_dir)
 		{
 			const auto dst_path = final_dir + out.params.plot_name + ".plot";
-			std::cout << "Started copy to " << dst_path << std::endl;
+			std::cout << get_curr_datetime() << " Started copy to " << dst_path << std::endl;
 			copy_thread.take_copy(std::make_pair(out.plot_file_name, dst_path));
 		}
 	}