From a6b5d3a2e54a595336447366b9fe5c9da6d968f8 Mon Sep 17 00:00:00 2001 From: Karl Kfoury <76066593+KarlKfoury@users.noreply.github.com> Date: Fri, 30 Aug 2024 02:15:54 +0300 Subject: [PATCH 1/5] logging if NN eval duration > 1s calculating time elapsed before NN eval -> after NN eval and logging a message if time elapsed > 1s --- src/neural/network_tf_cc.cc | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/neural/network_tf_cc.cc b/src/neural/network_tf_cc.cc index f7b5cad65f..93bda011a8 100644 --- a/src/neural/network_tf_cc.cc +++ b/src/neural/network_tf_cc.cc @@ -343,9 +343,15 @@ class TFNetworkComputation : public NetworkComputation { raw_input_.emplace_back(input); } void ComputeBlocking() override { + auto start_time = std::chrono::high_resolution_clock::now(); PrepareInput(); status_ = network_->Compute(input_, &output_); CHECK(status_.ok()) << status_.ToString(); + auto end_time = std::chrono::high_resolution_clock::now(); + std::chrono::duration elapsed = end_time - start_time; + if (elapsed.count() > 1.0) { + std::cerr << "Warning: Computation took " << elapsed.count() << " seconds, which is longer than expected." << std::endl; + } } int GetBatchSize() const override { return raw_input_.size(); } From b12e68bc64b27b6496274b37326b5cf6808b2fb4 Mon Sep 17 00:00:00 2001 From: Karl Kfoury <76066593+KarlKfoury@users.noreply.github.com> Date: Fri, 30 Aug 2024 14:52:53 +0300 Subject: [PATCH 2/5] undoing changes to network_tf_cc.cc that should have been done on search.cc --- src/neural/network_tf_cc.cc | 6 ------ 1 file changed, 6 deletions(-) diff --git a/src/neural/network_tf_cc.cc b/src/neural/network_tf_cc.cc index 93bda011a8..f7b5cad65f 100644 --- a/src/neural/network_tf_cc.cc +++ b/src/neural/network_tf_cc.cc @@ -343,15 +343,9 @@ class TFNetworkComputation : public NetworkComputation { raw_input_.emplace_back(input); } void ComputeBlocking() override { - auto start_time = std::chrono::high_resolution_clock::now(); PrepareInput(); status_ = network_->Compute(input_, &output_); CHECK(status_.ok()) << status_.ToString(); - auto end_time = std::chrono::high_resolution_clock::now(); - std::chrono::duration elapsed = end_time - start_time; - if (elapsed.count() > 1.0) { - std::cerr << "Warning: Computation took " << elapsed.count() << " seconds, which is longer than expected." << std::endl; - } } int GetBatchSize() const override { return raw_input_.size(); } From 4045a1ca7d9bbec166b17fdf3228e21fe8f48928 Mon Sep 17 00:00:00 2001 From: Karl Kfoury <76066593+KarlKfoury@users.noreply.github.com> Date: Fri, 30 Aug 2024 15:08:31 +0300 Subject: [PATCH 3/5] calculating time elapsed from start to end of nn eval + logging if time > 1s fixing issue #1768 --- src/mcts/search.cc | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/src/mcts/search.cc b/src/mcts/search.cc index 71eb543c10..483dff3d30 100644 --- a/src/mcts/search.cc +++ b/src/mcts/search.cc @@ -2189,7 +2189,15 @@ int SearchWorker::PrefetchIntoCache(Node* node, int budget, bool is_odd_depth) { // 4. Run NN computation. // ~~~~~~~~~~~~~~~~~~~~~~ -void SearchWorker::RunNNComputation() { computation_->ComputeBlocking(); } +void SearchWorker::RunNNComputation() { + auto start_time = std::chrono::high_resolution_clock::now(); + computation_->ComputeBlocking(); + auto end_time = std::chrono::high_resolution_clock::now(); + std::chrono::duration elapsed = end_time - start_time; + if (elapsed.count() > 1.0) { + std::cerr << "Warning: Computation took " << elapsed.count() << " seconds, which is longer than expected." << std::endl; + } +} // 5. Retrieve NN computations (and terminal values) into nodes. // ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ From 943ab53138d0bbfebc150d378e3d33d5c0033cfa Mon Sep 17 00:00:00 2001 From: Karl Kfoury <76066593+KarlKfoury@users.noreply.github.com> Date: Fri, 30 Aug 2024 21:06:37 +0300 Subject: [PATCH 4/5] logging if tablebase probing duration > 1s adressing issue #1768 --- src/syzygy/syzygy.cc | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/src/syzygy/syzygy.cc b/src/syzygy/syzygy.cc index 115164b772..856b108eb0 100644 --- a/src/syzygy/syzygy.cc +++ b/src/syzygy/syzygy.cc @@ -1406,9 +1406,13 @@ class SyzygyTablebaseImpl { } idx = type != DTM ? encode_pawn_f(p, ei, be) : encode_pawn_r(p, ei, be); } - + auto start = std::chrono::high_resolution_clock::now(); uint8_t* w = decompress_pairs(ei->precomp, idx); - + auto end = std::chrono::high_resolution_clock::now(); + std::chrono::duration duration = end - start; + if (duration.count() > 1) { + std::cout << "Tablebase probing duration: " << duration.count() << " seconds" << std::endl; + } if (type == WDL) return static_cast(w[0]) - 2; int v = w[0] + ((w[1] & 0x0f) << 8); From b2985a2ddee295bf0475f7c20a826bd92c79b5ee Mon Sep 17 00:00:00 2001 From: Karl Kfoury <76066593+KarlKfoury@users.noreply.github.com> Date: Fri, 30 Aug 2024 21:21:17 +0300 Subject: [PATCH 5/5] including chrono --- src/syzygy/syzygy.cc | 1 + 1 file changed, 1 insertion(+) diff --git a/src/syzygy/syzygy.cc b/src/syzygy/syzygy.cc index 856b108eb0..276879fb5b 100644 --- a/src/syzygy/syzygy.cc +++ b/src/syzygy/syzygy.cc @@ -32,6 +32,7 @@ */ #include +#include #include #include #include