Merge pull request #1203

4038e86 Add performance timers for ringct tx verification (moneromooo-monero)
74dfdb0 perf_timer: new class and macros to make performance logs easier (moneromooo-monero)

6 files changed, 154 insertions, 1 deletions

diff --git a/src/common/CMakeLists.txt b/src/common/CMakeLists.txt
index 6bf8b1777..4b6149cbd 100644
--- a/src/common/CMakeLists.txt
+++ b/src/common/CMakeLists.txt
@@ -31,7 +31,8 @@ set(common_sources
   command_line.cpp
   dns_utils.cpp
   util.cpp
-  i18n.cpp)
+  i18n.cpp
+  perf_timer.cpp)
 
 if (STACK_TRACE)
   list(APPEND common_sources stack_trace.cpp)
@@ -53,6 +54,7 @@ set(common_private_headers
   util.h
   varint.h
   i18n.h
+  perf_timer.h
   stack_trace.h)
 
 monero_private_headers(common
diff --git a/src/common/perf_timer.cpp b/src/common/perf_timer.cpp
new file mode 100644
index 000000000..d23c9f11d
--- /dev/null
+++ b/src/common/perf_timer.cpp
@@ -0,0 +1,47 @@
+// Copyright (c) 2016, The Monero Project
+// 
+// All rights reserved.
+// 
+// Redistribution and use in source and binary forms, with or without modification, are
+// permitted provided that the following conditions are met:
+// 
+// 1. Redistributions of source code must retain the above copyright notice, this list of
+//    conditions and the following disclaimer.
+// 
+// 2. Redistributions in binary form must reproduce the above copyright notice, this list
+//    of conditions and the following disclaimer in the documentation and/or other
+//    materials provided with the distribution.
+// 
+// 3. Neither the name of the copyright holder nor the names of its contributors may be
+//    used to endorse or promote products derived from this software without specific
+//    prior written permission.
+// 
+// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND ANY
+// EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF
+// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL
+// THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
+// PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
+// INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT,
+// STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF
+// THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+
+#include "perf_timer.h"
+
+namespace tools
+{
+
+int performance_timer_log_level = 2;
+__thread std::vector<PerformanceTimer*> *performance_timers = NULL;
+
+void set_performance_timer_log_level(int level)
+{
+  if (level < LOG_LEVEL_MIN || level > LOG_LEVEL_MAX)
+  {
+    LOG_PRINT_L0("Wrong log level: " << level << ", using 2");
+    level = 2;
+  }
+  performance_timer_log_level = level;
+}
+
+}
diff --git a/src/common/perf_timer.h b/src/common/perf_timer.h
new file mode 100644
index 000000000..3d732012d
--- /dev/null
+++ b/src/common/perf_timer.h
@@ -0,0 +1,92 @@
+// Copyright (c) 2016, The Monero Project
+// 
+// All rights reserved.
+// 
+// Redistribution and use in source and binary forms, with or without modification, are
+// permitted provided that the following conditions are met:
+// 
+// 1. Redistributions of source code must retain the above copyright notice, this list of
+//    conditions and the following disclaimer.
+// 
+// 2. Redistributions in binary form must reproduce the above copyright notice, this list
+//    of conditions and the following disclaimer in the documentation and/or other
+//    materials provided with the distribution.
+// 
+// 3. Neither the name of the copyright holder nor the names of its contributors may be
+//    used to endorse or promote products derived from this software without specific
+//    prior written permission.
+// 
+// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND ANY
+// EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF
+// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL
+// THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
+// PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
+// INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT,
+// STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF
+// THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+
+#pragma once
+
+#include <string>
+#include <stdio.h>
+#include "misc_log_ex.h"
+
+namespace tools
+{
+
+class PerformanceTimer;
+
+extern int performance_timer_log_level;
+extern __thread std::vector<PerformanceTimer*> *performance_timers;
+
+class PerformanceTimer
+{
+public:
+  PerformanceTimer(const std::string &s, int l = LOG_LEVEL_2): name(s), level(l), started(false)
+  {
+    ticks = epee::misc_utils::get_tick_count();
+    if (!performance_timers)
+    {
+      LOG_PRINT("PERF             ----------", level);
+      performance_timers = new std::vector<PerformanceTimer*>();
+    }
+    else
+    {
+      PerformanceTimer *pt = performance_timers->back();
+      if (!pt->started)
+      {
+        LOG_PRINT("PERF           " << std::string((performance_timers->size()-1) * 2, ' ') << "  " << pt->name, pt->level);
+        pt->started = true;
+      }
+    }
+    performance_timers->push_back(this);
+  }
+
+  ~PerformanceTimer()
+  {
+    performance_timers->pop_back();
+    ticks = epee::misc_utils::get_tick_count() - ticks;
+    char s[12];
+    snprintf(s, sizeof(s), "%8lu  ", ticks);
+    LOG_PRINT("PERF " << s << std::string(performance_timers->size() * 2, ' ') << "  " << name, level);
+    if (performance_timers->empty())
+    {
+      delete performance_timers;
+      performance_timers = NULL;
+    }
+  }
+
+private:
+  std::string name;
+  int level;
+  uint64_t ticks;
+  bool started;
+};
+
+void set_performance_timer_log_level(int level);
+
+#define PERF_TIMER(name) tools::PerformanceTimer pt_##name(#name, tools::performance_timer_log_level)
+#define PERF_TIMER_L(name, l) tools::PerformanceTimer pt_##name(#name, l)
+
+}
diff --git a/src/cryptonote_core/blockchain.cpp b/src/cryptonote_core/blockchain.cpp
index 83290796b..9d2bf9332 100644
--- a/src/cryptonote_core/blockchain.cpp
+++ b/src/cryptonote_core/blockchain.cpp
@@ -52,6 +52,7 @@
 #include "cryptonote_core/checkpoints.h"
 #include "cryptonote_core/cryptonote_core.h"
 #include "ringct/rctSigs.h"
+#include "common/perf_timer.h"
 #if defined(PER_BLOCK_CHECKPOINT)
 #include "blocks/blocks.h"
 #endif
@@ -2245,6 +2246,7 @@ bool Blockchain::have_tx_keyimges_as_spent(const transaction &tx) const
 }
 bool Blockchain::expand_transaction_2(transaction &tx, const crypto::hash &tx_prefix_hash, const std::vector<std::vector<rct::ctkey>> &pubkeys)
 {
+  PERF_TIMER(expand_transaction_2);
   CHECK_AND_ASSERT_MES(tx.version == 2, false, "Transaction version is not 2");
 
   rct::rctSig &rv = tx.rct_signatures;
@@ -2321,6 +2323,7 @@ bool Blockchain::expand_transaction_2(transaction &tx, const crypto::hash &tx_pr
 //        using threads, etc.)
 bool Blockchain::check_tx_inputs(transaction& tx, tx_verification_context &tvc, uint64_t* pmax_used_block_height)
 {
+  PERF_TIMER(check_tx_inputs);
   LOG_PRINT_L3("Blockchain::" << __func__);
   size_t sig_index = 0;
   if(pmax_used_block_height)
diff --git a/src/cryptonote_core/tx_pool.cpp b/src/cryptonote_core/tx_pool.cpp
index 5bfa7eca6..178cbda3c 100644
--- a/src/cryptonote_core/tx_pool.cpp
+++ b/src/cryptonote_core/tx_pool.cpp
@@ -42,6 +42,7 @@
 #include "common/int-util.h"
 #include "misc_language.h"
 #include "warnings.h"
+#include "common/perf_timer.h"
 #include "crypto/hash.h"
 
 DISABLE_VS_WARNINGS(4244 4345 4503) //'boost::foreach_detail_::or_' : decorated name length exceeded, name was truncated
@@ -78,6 +79,7 @@ namespace cryptonote
   //---------------------------------------------------------------------------------
   bool tx_memory_pool::add_tx(const transaction &tx, /*const crypto::hash& tx_prefix_hash,*/ const crypto::hash &id, size_t blob_size, tx_verification_context& tvc, bool kept_by_block, bool relayed, uint8_t version)
   {
+    PERF_TIMER(add_tx);
     if (tx.version == 0)
     {
       // v0 never accepted
diff --git a/src/ringct/rctSigs.cpp b/src/ringct/rctSigs.cpp
index 85d21e805..80ece9c44 100644
--- a/src/ringct/rctSigs.cpp
+++ b/src/ringct/rctSigs.cpp
@@ -29,6 +29,7 @@
 // THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 #include "misc_log_ex.h"
+#include "common/perf_timer.h"
 #include "rctSigs.h"
 #include "cryptonote_core/cryptonote_format_utils.h"
 
@@ -107,6 +108,7 @@ namespace rct {
     //   an x[i] such that x[i]G = one of P1[i] or P2[i]
     // Ver Verifies the signer knows a key for one of P1[i], P2[i] at each i    
     bool VerASNL(const key64 P1, const key64 P2, const asnlSig &as) {
+        PERF_TIMER(VerASNL);
         DP("Verifying Aggregate Schnorr Non-linkable Ring Signature\n");
         key LHS = identity();
         key RHS = scalarmultBase(as.s);
@@ -331,6 +333,7 @@ namespace rct {
     //   mask is a such that C = aG + bH, and b = amount
     //verRange verifies that \sum Ci = C and that each Ci is a commitment to 0 or 2^i
     bool verRange(const key & C, const rangeSig & as) {
+        PERF_TIMER(verRange);
         key64 CiH;
         int i = 0;
         key Ctmp = identity();
@@ -467,6 +470,7 @@ namespace rct {
     //Ver:    
     //   verifies the above sig is created corretly
     bool verRctMG(const mgSig &mg, const ctkeyM & pubs, const ctkeyV & outPk, key txnFeeKey, const key &message) {
+        PERF_TIMER(verRctMG);
         //setup vars
         size_t cols = pubs.size();
         CHECK_AND_ASSERT_MES(cols >= 1, false, "Empty pubs");
@@ -505,6 +509,7 @@ namespace rct {
     //This does a simplified version, assuming only post Rct
     //inputs
     bool verRctMGSimple(const key &message, const mgSig &mg, const ctkeyV & pubs, const key & C) {
+            PERF_TIMER(verRctMGSimple);
             //setup vars
             size_t rows = 1;
             size_t cols = pubs.size();
@@ -729,6 +734,7 @@ namespace rct {
     //   uses the attached ecdh info to find the amounts represented by each output commitment 
     //   must know the destination private key to find the correct amount, else will return a random number    
     bool verRct(const rctSig & rv) {
+        PERF_TIMER(verRct);
         CHECK_AND_ASSERT_MES(rv.type == RCTTypeFull, false, "verRct called on non-full rctSig");
         CHECK_AND_ASSERT_MES(rv.outPk.size() == rv.p.rangeSigs.size(), false, "Mismatched sizes of outPk and rv.p.rangeSigs");
         CHECK_AND_ASSERT_MES(rv.outPk.size() == rv.ecdhInfo.size(), false, "Mismatched sizes of outPk and rv.ecdhInfo");
@@ -769,6 +775,7 @@ namespace rct {
     //ver RingCT simple
     //assumes only post-rct style inputs (at least for max anonymity)
     bool verRctSimple(const rctSig & rv) {
+        PERF_TIMER(verRctSimple);
         size_t i = 0;
 
         CHECK_AND_ASSERT_MES(rv.type == RCTTypeSimple, false, "verRctSimple called on non simple rctSig");