[CP] check cost_time of ob_malloc

deps/oblib/src/common/ob_common_utility.cpp

@@ -12,7 +12,8 @@
 
 #define USING_LOG_PREFIX COMMON
 #include "common/ob_common_utility.h"
-
+#include "lib/string/ob_string.h"
+#include "lib/utility/ob_print_utils.h"
 using namespace oceanbase::lib;
 
 namespace oceanbase
@@ -154,5 +155,26 @@ const ObFatalErrExtraInfoGuard *ObFatalErrExtraInfoGuard::get_thd_local_val_ptr(
   return ObFatalErrExtraInfoGuard::get_val();
 }
 
+int64_t ObFatalErrExtraInfoGuard::to_string(char* buf, const int64_t buf_len) const
+{
+  int64_t pos = 0;
+  J_OBJ_START();
+  J_OBJ_END();
+  return pos;
+}
+
+int64_t ObBasicTimeGuard::to_string(char *buf, const int64_t buf_len) const
+{
+  int ret = OB_SUCCESS;
+  int64_t pos = 0;
+  if (click_count_ > 0) {
+    ret = databuff_printf(buf, buf_len, pos, "time dist: %s=%d", click_str_[0], click_[0]);
+    for (int i = 1; OB_SUCC(ret) && i < click_count_; i++) {
+      ret = databuff_printf(buf, buf_len, pos, ", %s=%d", click_str_[i], click_[i]);
+    }
+  }
+  if (OB_FAIL(ret)) pos = 0;
+  return pos;
+}
 } // end of namespace common
 } // end of namespace oceanbse

deps/oblib/src/common/ob_common_utility.h

@@ -12,11 +12,8 @@
 
 #ifndef _OCEABASE_COMMON_OB_COMMON_UTILITY_H_
 #define _OCEABASE_COMMON_OB_COMMON_UTILITY_H_
-
+#include <sys/time.h>
 #include "lib/ob_define.h"
-#include "lib/string/ob_string.h"
-#include "lib/utility/ob_print_utils.h"
-
 namespace oceanbase
 {
 namespace common
@@ -52,12 +49,58 @@ public:
   explicit ObFatalErrExtraInfoGuard();
   virtual ~ObFatalErrExtraInfoGuard();
   static const ObFatalErrExtraInfoGuard *get_thd_local_val_ptr();
-  DEFINE_VIRTUAL_TO_STRING();
+  virtual int64_t to_string(char* buf, const int64_t buf_len) const;
 private:
   static ObFatalErrExtraInfoGuard *&get_val();
   ObFatalErrExtraInfoGuard *last_;
 };
 
+inline int64_t get_cur_ts()
+{
+  struct timeval tv;
+  gettimeofday(&tv, NULL);
+  const int64_t us =
+            static_cast<int64_t>(tv.tv_sec) * static_cast<int64_t>(1000000) + static_cast<int64_t>(tv.tv_usec);
+  return us;
+}
+
+class ObBasicTimeGuard
+{
+public:
+  explicit ObBasicTimeGuard()
+  {
+    start_ts_ = get_cur_ts();
+    last_ts_ = start_ts_;
+    click_count_ = 0;
+  }
+  void click(const char *mod = NULL)
+  {
+    const int64_t cur_ts = get_cur_ts();
+    if (OB_LIKELY(click_count_ < MAX_CLICK_COUNT)) {
+      click_str_[click_count_] = mod;
+      click_[click_count_++] = (int32_t)(cur_ts - last_ts_);
+      last_ts_ = cur_ts;
+    }
+  }
+  int64_t get_start_ts() const
+  {
+    return start_ts_;
+  }
+  int64_t get_diff() const
+  {
+    return get_cur_ts() - start_ts_;
+  }
+  int64_t to_string(char *buf, const int64_t buf_len) const;
+protected:
+  static const int64_t MAX_CLICK_COUNT = 16;
+private:
+  int64_t start_ts_;
+  int64_t last_ts_;
+  int64_t click_count_;
+  int32_t click_[MAX_CLICK_COUNT];
+  const char *click_str_[MAX_CLICK_COUNT];
+};
+
 } // end of namespace common
 } // end of namespace oceanbase
 

deps/oblib/src/common/ob_smart_var.h

@@ -15,6 +15,7 @@
 
 #include "common/ob_common_utility.h"
 #include "lib/utility/ob_macro_utils.h"
+#include "lib/utility/ob_print_utils.h"
 
 namespace oceanbase
 {

deps/oblib/src/lib/CMakeLists.txt

@@ -304,6 +304,7 @@ ob_set_subtarget(ob_malloc_object_list common_alloc
   alloc/ob_malloc_allocator.cpp
   alloc/ob_malloc_callback.cpp
   alloc/ob_malloc_sample_struct.cpp
+  alloc/ob_malloc_time_monitor.cpp
   alloc/ob_tenant_ctx_allocator.cpp
   alloc/object_mgr.cpp
   alloc/object_set.cpp

deps/oblib/src/lib/alloc/ob_malloc_time_monitor.cpp

@@ -0,0 +1,58 @@
+/**
+ * Copyright (c) 2021 OceanBase
+ * OceanBase CE is licensed under Mulan PubL v2.
+ * You can use this software according to the terms and conditions of the Mulan PubL v2.
+ * You may obtain a copy of Mulan PubL v2 at:
+ *          http://license.coscl.org.cn/MulanPubL-2.0
+ * THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND,
+ * EITHER EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT,
+ * MERCHANTABILITY OR FIT FOR A PARTICULAR PURPOSE.
+ * See the Mulan PubL v2 for more details.
+ */
+#define USING_LOG_PREFIX LIB
+
+#include "lib/alloc/ob_malloc_time_monitor.h"
+#include "lib/utility/ob_print_utils.h"
+using namespace oceanbase::lib;
+using namespace oceanbase::common;
+
+volatile int64_t ObMallocTimeMonitor::WARN_THRESHOLD = 100000;
+__thread ObBasicTimeGuard *ObMallocTimeMonitor::tl_time_guard = NULL;
+
+ObMallocTimeMonitor::Guard::Guard(const int64_t size, const ObMemAttr &attr)
+  : size_(size), attr_(attr), last_time_guard_(tl_time_guard), time_guard_()
+{
+  tl_time_guard = &time_guard_;
+}
+
+ObMallocTimeMonitor::Guard::~Guard()
+{
+  int64_t cost_time = time_guard_.get_diff();
+  ObMallocTimeMonitor::get_instance().inc(cost_time);
+  if (OB_UNLIKELY(cost_time > WARN_THRESHOLD)) {
+    LIB_LOG_RET(WARN, OB_ERR_TOO_MUCH_TIME, "[MALLOC_TIME_MONITOR]", K(cost_time), K_(time_guard), K_(attr), K_(size));
+  }
+
+  tl_time_guard = last_time_guard_;
+}
+void ObMallocTimeMonitor::print()
+{
+  char buf[1024] = {'\0'};
+  int64_t pos = 0;
+  for (int i = 0; i < TIME_SLOT_NUM; ++i) {
+    int64_t total_cost_time = total_cost_times_[i].value();
+    int64_t count = counts_[i].value();
+    int64_t delta_total_cost_time = total_cost_time - last_total_cost_times_[i];
+    int64_t delta_count = count - last_counts_[i];
+    int64_t avg_cost_time = (0 == delta_count ? 0 : delta_total_cost_time / delta_count);
+    last_total_cost_times_[i] = total_cost_time;
+    last_counts_[i] = count;
+    int64_t left = (0 == i ? 0 : TIME_SLOT[i-1]);
+    int64_t right = TIME_SLOT[i];
+    databuff_printf(buf, sizeof(buf), pos, "[MALLOC_TIME_MONITOR] [%8ld,%20ld): delta_total_cost_time=%15ld, delta_count=%15ld, avg_cost_time=%8ld\n",
+                    left, right, delta_total_cost_time, delta_count, avg_cost_time);
+
+  }
+  buf[pos] = '\0';
+  _OB_LOG(INFO, "[MALLOC_TIME_MONITOR] show the distribution of ob_malloc's cost_time\n%s", buf);
+}

deps/oblib/src/lib/alloc/ob_malloc_time_monitor.h

@@ -0,0 +1,76 @@
+/**
+ * Copyright (c) 2021 OceanBase
+ * OceanBase CE is licensed under Mulan PubL v2.
+ * You can use this software according to the terms and conditions of the Mulan PubL v2.
+ * You may obtain a copy of Mulan PubL v2 at:
+ *          http://license.coscl.org.cn/MulanPubL-2.0
+ * THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND,
+ * EITHER EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT,
+ * MERCHANTABILITY OR FIT FOR A PARTICULAR PURPOSE.
+ * See the Mulan PubL v2 for more details.
+ */
+
+#ifndef OCEABASE_MALLOC_TIME_MONITOR_H_
+#define OCEABASE_MALLOC_TIME_MONITOR_H_
+#include "lib/alloc/alloc_struct.h"
+#include "lib/metrics/ob_counter.h"
+#include "lib/oblog/ob_log.h"
+namespace oceanbase
+{
+namespace lib
+{
+class ObMallocTimeMonitor
+{
+public:
+struct Guard
+{
+  Guard(const int64_t size, const ObMemAttr &attr);
+  ~Guard();
+  const int64_t size_;
+  const ObMemAttr &attr_;
+  ObBasicTimeGuard *last_time_guard_;
+  ObBasicTimeGuard time_guard_;
+};
+public:
+  static volatile int64_t WARN_THRESHOLD;
+  static constexpr const int64_t TIME_SLOT[] = {10, 100, 1000, 10000, 100000, 1000000, INT64_MAX};
+  static const int64_t TIME_SLOT_NUM = ARRAYSIZEOF(TIME_SLOT);
+  ObMallocTimeMonitor()
+  {
+    MEMSET(this, 0, sizeof(*this));
+  }
+
+  static ObMallocTimeMonitor &get_instance()
+  {
+    static ObMallocTimeMonitor instance;
+    return instance;
+  }
+  static void click(const char *mod = NULL)
+  {
+    if (NULL != tl_time_guard) {
+      tl_time_guard->click(mod);
+    }
+  }
+  void inc(int64_t cost_time)
+  {
+    for (int i = 0; i < TIME_SLOT_NUM; ++i) {
+      if (cost_time < TIME_SLOT[i]) {
+        total_cost_times_[i].inc(cost_time);
+        counts_[i].inc(1);
+        break;
+      }
+    }
+  }
+  void print();
+private:
+  static __thread ObBasicTimeGuard *tl_time_guard;
+private:
+  int64_t last_total_cost_times_[TIME_SLOT_NUM];
+  int64_t last_counts_[TIME_SLOT_NUM];
+  common::ObTCCounter total_cost_times_[TIME_SLOT_NUM];
+  common::ObTCCounter counts_[TIME_SLOT_NUM];
+};
+} // end of namespace lib
+} // end of namespace oceanbase
+
+#endif

deps/oblib/src/lib/alloc/ob_tenant_ctx_allocator.cpp

@@ -14,7 +14,7 @@
 
 #include "lib/alloc/ob_tenant_ctx_allocator.h"
 #include "lib/alloc/ob_malloc_sample_struct.h"
-#include "lib/alloc/ob_free_log_printer.h"
+#include "lib/alloc/ob_malloc_time_monitor.h"
 #include "lib/allocator/ob_mem_leak_checker.h"
 #include "lib/allocator/ob_tc_malloc.h"
 #include "lib/utility/ob_print_utils.h"
@@ -426,11 +426,13 @@ void* ObTenantCtxAllocator::common_alloc(const int64_t size, const ObMemAttr &at
 
   if (OB_UNLIKELY(is_errsim)) {
   } else {
+    ObMallocTimeMonitor::Guard guard(size, attr);
     sample_allowed = ObMallocSampleLimiter::malloc_sample_allowed(size, attr);
     alloc_size = sample_allowed ? (size + AOBJECT_BACKTRACE_SIZE) : size;
     obj = allocator.alloc_object(alloc_size, attr);
     if (OB_ISNULL(obj) && g_alloc_failed_ctx().need_wash()) {
       int64_t total_size = ta.sync_wash();
+      ObMallocTimeMonitor::click("SYNC_WASH_END");
       obj = allocator.alloc_object(alloc_size, attr);
     }
   }
@@ -498,11 +500,13 @@ void* ObTenantCtxAllocator::common_realloc(const void *ptr, const int64_t size,
 
   if (OB_UNLIKELY(is_errsim)) {
   } else {
+    ObMallocTimeMonitor::Guard guard(size, attr);
     sample_allowed = ObMallocSampleLimiter::malloc_sample_allowed(size, attr);
     alloc_size = sample_allowed ? (size + AOBJECT_BACKTRACE_SIZE) : size;
     obj = allocator.realloc_object(obj, alloc_size, attr);
     if(OB_ISNULL(obj) && g_alloc_failed_ctx().need_wash()) {
       int64_t total_size = ta.sync_wash();
+      ObMallocTimeMonitor::click("SYNC_WASH_END");
       obj = allocator.realloc_object(obj, alloc_size, attr);
     }
   }

deps/oblib/src/lib/oblog/ob_log.cpp

@@ -39,21 +39,6 @@ namespace oceanbase
 {
 namespace common
 {
-
-int64_t ObSyslogTimeGuard::to_string(char *buf, const int64_t buf_len) const
-{
-  int ret = OB_SUCCESS;
-  int64_t pos = 0;
-  if (click_count_ > 0) {
-    ret = databuff_printf(buf, buf_len, pos, "time dist: %s=%d", click_str_[0], click_[0]);
-    for (int i = 1; OB_SUCC(ret) && i < click_count_; i++) {
-      ret = databuff_printf(buf, buf_len, pos, ", %s=%d", click_str_[i], click_[i]);
-    }
-  }
-  if (OB_FAIL(ret)) pos = 0;
-  return pos;
-}
-
 void __attribute__((weak)) allow_next_syslog(int64_t)
 {
   // do nothing

deps/oblib/src/lib/oblog/ob_log.h

@@ -43,6 +43,7 @@
 #include "lib/utility/ob_defer.h"
 #include "lib/oblog/ob_syslog_rate_limiter.h"
 #include "lib/signal/ob_signal_handlers.h"
+#include "common/ob_common_utility.h"
 
 #define OB_LOG_MAX_PAR_MOD_SIZE 64
 #define OB_LOG_MAX_SUB_MOD_SIZE 64
@@ -57,53 +58,6 @@ namespace oceanbase
 {
 namespace common
 {
-
-inline int64_t log_cur_ts()
-{
-  struct timeval tv;
-  gettimeofday(&tv, NULL);
-  const int64_t us =
-            static_cast<int64_t>(tv.tv_sec) * static_cast<int64_t>(1000000) + static_cast<int64_t>(tv.tv_usec);
-  return us;
-}
-
-class ObSyslogTimeGuard
-{
-public:
-  explicit ObSyslogTimeGuard()
-  {
-    start_ts_ = log_cur_ts();
-    last_ts_ = start_ts_;
-    click_count_ = 0;
-  }
-  void click(const char *mod = NULL)
-  {
-    const int64_t cur_ts = log_cur_ts();
-    if (OB_LIKELY(click_count_ < MAX_CLICK_COUNT)) {
-      click_str_[click_count_] = mod;
-      click_[click_count_++] = (int32_t)(cur_ts - last_ts_);
-      last_ts_ = cur_ts;
-    }
-  }
-  int64_t get_start_ts() const
-  {
-    return start_ts_;
-  }
-  int64_t get_diff() const
-  {
-    return log_cur_ts() - start_ts_;
-  }
-  int64_t to_string(char *buf, const int64_t buf_len) const;
-private:
-  static const int64_t MAX_CLICK_COUNT = 16;
-private:
-  int64_t start_ts_;
-  int64_t last_ts_;
-  int64_t click_count_;
-  int32_t click_[MAX_CLICK_COUNT];
-  const char *click_str_[MAX_CLICK_COUNT];
-};
-
 class ObVSliceAlloc;
 class ObBlockAllocMgr;
 class ObFIFOAllocator;
@@ -975,7 +929,7 @@ void ObLogger::log_it(const char *mod_name,
             int64_t buf_len = tb->get_cap();
             int64_t &pos = tb->get_pos();
             int64_t orig_pos = pos;
-            ret = log_head(log_cur_ts(), mod_name, level, file, line, function, errcode, buf, buf_len, pos);
+            ret = log_head(get_cur_ts(), mod_name, level, file, line, function, errcode, buf, buf_len, pos);
             if (OB_SUCC(ret)) {
               ret = log_data_func(buf, buf_len, pos);
             }
@@ -1194,7 +1148,7 @@ inline void ObLogger::do_log_message(const bool is_async,
   auto fd_type = get_fd_type(mod_name);
   const int64_t log_size = limited_left_log_size_ + NORMAL_LOG_SIZE;
   limited_left_log_size_ = 0;
-  ObSyslogTimeGuard tg;
+  ObBasicTimeGuard tg;
   if (FD_TRACE_FILE != fd_type && OB_FAIL(check_tl_log_limiter(location_hash_val, level, errcode, log_size,
           allow, limiter_info))) {
     LOG_STDERR("precheck_tl_log_limiter error, ret=%d\n", ret);

deps/oblib/src/lib/resource/ob_resource_mgr.cpp

@@ -17,6 +17,7 @@
 #include <stdlib.h>
 
 #include "lib/alloc/memory_sanity.h"
+#include "lib/alloc/ob_malloc_time_monitor.h"
 #include "lib/oblog/ob_log.h"
 #include "lib/stat/ob_diagnose_info.h"
 #include "lib/utility/utility.h"
@@ -74,10 +75,9 @@ AChunk *ObTenantMemoryMgr::alloc_chunk(const int64_t size, const ObMemAttr &attr
         update_cache_hold(hold_size);
       }
     }
-
+    ObMallocTimeMonitor::click("ALLOC_CHUNK_END");
     if (!reach_ctx_limit && NULL != cache_washer_ && NULL == chunk && hold_size < cache_hold_
         && attr.label_ != ObNewModIds::OB_KVSTORE_CACHE_MB) {
-      common::ObTimeGuard time_guard("sync wash", 1000 * 1000);
       // try wash memory from cache
       ObICacheWasher::ObCacheMemBlock *washed_blocks = NULL;
       bool wash_single_mb = true;
@@ -151,6 +151,7 @@ AChunk *ObTenantMemoryMgr::alloc_chunk(const int64_t size, const ObMemAttr &attr
           }
         }
       }
+      ObMallocTimeMonitor::click("WASH_KVCACHE_END");
     }
   }
   return chunk;

src/storage/tx_storage/ob_tenant_memory_printer.cpp

@@ -14,6 +14,7 @@
 
 #include "lib/utility/ob_print_utils.h"
 #include "lib/alloc/memory_dump.h"
+#include "lib/alloc/ob_malloc_time_monitor.h"
 #include "observer/omt/ob_multi_tenant.h"                  // ObMultiTenant
 #include "share/ob_tenant_mgr.h"                           // get_virtual_memory_used
 #include "storage/tx_storage/ob_tenant_freezer.h"          // ObTenantFreezer
@@ -159,6 +160,7 @@ int ObTenantMemoryPrinter::print_tenant_usage()
         memory_used - CHUNK_MGR.get_shadow_hold(), memory_used
 #endif
         );
+    ObMallocTimeMonitor::get_instance().print();
     print_mutex_.unlock();
   }
   return ret;