diff --git a/deps/oblib/src/lib/oblog/ob_log.cpp b/deps/oblib/src/lib/oblog/ob_log.cpp index 6a9b415f2d..692513432d 100644 --- a/deps/oblib/src/lib/oblog/ob_log.cpp +++ b/deps/oblib/src/lib/oblog/ob_log.cpp @@ -40,6 +40,20 @@ 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 @@ -654,13 +668,20 @@ int ObLogger::log_tail(int32_t level, char *buf, const int64_t buf_len, int64_t return ret; } -int ObLogger::log_head(const char *mod_name, - const int32_t level, - const char *file, - const int32_t line, - const char *function, - const int errcode, - char *buf, const int64_t buf_len, int64_t &pos) +void ts_to_tv(int64_t ts, timeval &tv) +{ + tv.tv_sec = static_cast(ts / 1000000); + tv.tv_usec = static_cast(ts % 1000000); +} + +int ObLogger::log_head(const int64_t ts, + const char *mod_name, + const int32_t level, + const char *file, + const int32_t line, + const char *function, + const int errcode, + char *buf, const int64_t buf_len, int64_t &pos) { int ret = OB_SUCCESS; if (level >= 0 && level < static_cast(sizeof(errstr_) / sizeof(char *)) @@ -670,7 +691,7 @@ int ObLogger::log_head(const char *mod_name, base_file_name = (NULL != base_file_name) ? base_file_name + 1 : file; struct timeval tv; - (void)gettimeofday(&tv, NULL); + ts_to_tv(ts, tv); struct tm tm; ob_fast_localtime(last_unix_sec_, last_localtime_, static_cast(tv.tv_sec), &tm); const uint64_t *trace_id = ObCurTraceId::get(); diff --git a/deps/oblib/src/lib/oblog/ob_log.h b/deps/oblib/src/lib/oblog/ob_log.h index bdf91e4671..8b615377b2 100644 --- a/deps/oblib/src/lib/oblog/ob_log.h +++ b/deps/oblib/src/lib/oblog/ob_log.h @@ -58,6 +58,52 @@ namespace oceanbase namespace common { +inline int64_t log_cur_ts() +{ + struct timeval tv; + gettimeofday(&tv, NULL); + const int64_t us = + static_cast(tv.tv_sec) * static_cast(1000000) + static_cast(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; @@ -557,9 +603,6 @@ public: //will record log files in the directory for log file int set_record_old_log_file(bool rec_old_file_flag = false); - //@brief Get current time. - int64_t get_cur_us(); - //@brief Get the process-only ObLogger. static ObLogger &get_logger(); @@ -649,13 +692,14 @@ private: int log_tail(int32_t level, char *buf, const int64_t buf_len, int64_t &pos); - int log_head(const char *mod_name, - const int32_t level, - const char *file, - const int32_t line, - const char *function, - const int errcode, - char *buf, const int64_t buf_len, int64_t &pos); + int log_head(const int64_t ts, + const char *mod_name, + const int32_t level, + const char *file, + const int32_t line, + const char *function, + const int errcode, + char *buf, const int64_t buf_len, int64_t &pos); void insert_warning_buffer_line_column_info(const UserMsgLevel user_msg_level, const int line, @@ -928,7 +972,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(mod_name, level, file, line, function, errcode, buf, buf_len, pos); + ret = log_head(log_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); } @@ -1065,15 +1109,6 @@ inline int32_t ObLogger::get_log_level(const uint64_t par_mod_id, const uint64_t return cur_level; } -inline int64_t ObLogger::get_cur_us() -{ - struct timeval tv; - gettimeofday(&tv, NULL); - const int64_t us = - static_cast(tv.tv_sec) * static_cast(1000000) + static_cast(tv.tv_usec); - return us; -} - inline int ObLogger::set_mod_log_levels(const char *level_str, int64_t version) { return parse_set(level_str, static_cast(std::strlen(level_str)), version); @@ -1155,7 +1190,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; - const int64_t logging_time_us_begin = get_cur_us(); + ObSyslogTimeGuard tg; if (FD_TRACE_FILE != fd_type && OB_FAIL(check_tl_log_limiter(location_hash_val, level, errcode, log_size, allow))) { LOG_STDERR("precheck_tl_log_limiter error, ret=%d\n", ret); } else if (OB_UNLIKELY(!allow) && !need_print_log_limit_msg()) { @@ -1166,7 +1201,7 @@ inline void ObLogger::do_log_message(const bool is_async, ObPLogItem *log_item = new (local_buf_) ObPLogItem(); log_item->set_buf_size(MAX_LOG_SIZE); log_item->set_log_level(level); - log_item->set_timestamp(logging_time_us_begin); + log_item->set_timestamp(tg.get_start_ts()); log_item->set_tl_type(tl_type_); log_item->set_force_allow(is_force_allows()); log_item->set_fd_type(fd_type); @@ -1175,7 +1210,7 @@ inline void ObLogger::do_log_message(const bool is_async, int64_t buf_len = log_item->get_buf_size(); int64_t pos = log_item->get_data_len(); if (with_head) { - if (OB_FAIL(log_head(mod_name, level, file, line, function, errcode, + if (OB_FAIL(log_head(tg.get_start_ts(), mod_name, level, file, line, function, errcode, buf, buf_len, pos))) { LOG_STDERR("log_header error ret = %d\n", ret); } @@ -1208,6 +1243,7 @@ inline void ObLogger::do_log_message(const bool is_async, check_log_end(*log_item, pos); } } + tg.click("FORMAT_END"); if (OB_SUCC(ret)) { @@ -1227,6 +1263,7 @@ _Pragma("GCC diagnostic pop") // update buf_size new_log_item->set_buf_size(log_item->get_data_len()); log_item = new_log_item; + tg.click("ALLOC_END"); } if (OB_SUCC(ret)) { @@ -1239,10 +1276,12 @@ _Pragma("GCC diagnostic pop") (void)ATOMIC_AAF(current_written_count_ + tl_type, 1); } last_logging_seq_ = curr_logging_seq_; + tg.click("APPEND_END"); } } } else { flush_logs_to_file(&log_item, 1); + tg.click("FLUSH_END"); } // stat @@ -1252,11 +1291,18 @@ _Pragma("GCC diagnostic pop") free_log_item(log_item); } log_item = NULL; + tg.click("FREE_END"); } check_reset_force_allows(); } /* not allow */ } - last_logging_cost_time_us_ = get_cur_us() - logging_time_us_begin; + last_logging_cost_time_us_ = tg.get_diff(); + if (OB_UNLIKELY(last_logging_cost_time_us_ > 1000 * 1000)) { + char buf[256] = {'\0'}; + int64_t pos = tg.to_string(buf, sizeof buf); + fprintf(stderr, "LOGGER COST TOO MUCH TIME, tid: [%ld], start_ts: %ld, cost: %ld, %.*s, %s\n", + GETTID(), tg.get_start_ts(), last_logging_cost_time_us_, static_cast(pos), buf, lbt()); + } } template diff --git a/deps/oblib/src/lib/utility/utility.cpp b/deps/oblib/src/lib/utility/utility.cpp index 3f27cc3a97..a4a3dde60f 100644 --- a/deps/oblib/src/lib/utility/utility.cpp +++ b/deps/oblib/src/lib/utility/utility.cpp @@ -1272,67 +1272,27 @@ int ob_alloc_printf(ObString &result, ObIAllocator &alloc, const char* fmt, ...) int64_t ObTimeGuard::to_string(char *buf, const int64_t buf_len) const { + int ret = OB_SUCCESS; int64_t pos = 0; if (!need_record_log_) { - databuff_printf(buf, buf_len, pos, "time guard have no click events for optimization"); + ret = databuff_printf(buf, buf_len, pos, "time guard have no click events for optimization"); } else { int64_t i = 0; - bool has_click_str = (click_count_ > 0 && NULL != click_str_[0]); - databuff_printf(buf, buf_len, pos, "time guard '%s' cost too much time, used=%ld%s", + ret = databuff_printf(buf, buf_len, pos, "time guard '%s' cost too much time, used=%ld%s", owner_, common::ObTimeUtility::fast_current_time() - start_ts_, click_count_ > 0 ? ", time_dist: " : ""); - while ((i + 8) <= click_count_) { - databuff_printf(buf, buf_len, pos, FSTR FSTR FSTR FSTR FSTR FSTR FSTR FSTR, - VSTR(i), VSTR(i+1), VSTR(i+2), VSTR(i+3), VSTR(i+4), VSTR(i+5), VSTR(i+6), VSTR(i+7)); - i = i + 8; + if (OB_SUCC(ret) && click_count_ > 0) { + ret = databuff_printf(buf, buf_len, pos, "%s=%d", click_str_[0], click_[0]); } - switch (click_count_ - i) { - case 0: { - break; - } - case 1: { - databuff_printf(buf, buf_len, pos, FSTR, VSTR(i)); - break; - } - case 2: { - databuff_printf(buf, buf_len, pos, FSTR FSTR, VSTR(i), VSTR(i+1)); - break; - } - case 3: { - databuff_printf(buf, buf_len, pos, FSTR FSTR FSTR, VSTR(i), VSTR(i+1), VSTR(i+2)); - break; - } - case 4: { - databuff_printf(buf, buf_len, pos, FSTR FSTR FSTR FSTR, VSTR(i), VSTR(i+1), VSTR(i+2), - VSTR(i+3)); - break; - } - case 5: { - databuff_printf(buf, buf_len, pos, FSTR FSTR FSTR FSTR FSTR, VSTR(i), VSTR(i+1), VSTR(i+2), - VSTR(i+3), VSTR(i+4)); - break; - } - case 6: { - databuff_printf(buf, buf_len, pos, FSTR FSTR FSTR FSTR FSTR FSTR, VSTR(i), VSTR(i+1), VSTR(i+2), - VSTR(i+3), VSTR(i+4), VSTR(i+5)); - break; - } - case 7: { - databuff_printf(buf, buf_len, pos, FSTR FSTR FSTR FSTR FSTR FSTR FSTR, VSTR(i), VSTR(i+1), VSTR(i+2), - VSTR(i+3), VSTR(i+4), VSTR(i+5), VSTR(i+6)); - break; - } - default: { - // do nothing - } - } - // Remove the last comma - if (click_count_ > 0) { - pos -= COMMA_STR_LEN; + 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; }