Reland "Optimize VlogInfo::GetVlogLevel"
This is a reland of 290a1c1f74bb9943d3673eeb6e6d2feb1b02577a
Prior to the reverted change, no synchronization was needed because we
only read VlogInfo::vmodule_levels_; it was never modified outside of
the constructor.
For this reland, I've added a base::Lock to guard the field. This is
necessary because one of the optimizations involves swapping the most
desirable values of vmodule_levels_ towards the front.
At this point in time, I was not quite able to reproduce the performance
improvement described in the original message.
Recomputing the stats over four runs on an official build, using the
same GN args:
- Before: the perftest averages 10 gets/us (631ms total)
- With reverted code: the perftest averages 10 gets/us (551.25ms total)
- With base::Lock: the perftest averages 11 gets/us (564.5ms total)
Percentage-wise, the before-and-after improvement now is 10.5%. Included
in that, adding the base::Lock was only a 2% penalty.
Original change's description:
> Optimize VlogInfo::GetVlogLevel
>
> On ChromeOS-Wide Profiling, I noticed that VlogInfo::GetVlogLevel takes
> up 0.78% of running time, which seems significant.
>
> This CL adds a perftest and the changes described below.
>
> 1. I believe that calls to GetVlogLevel have high locality. That is, the
> function is likely to see calls from the same file near each other.
> We can maintain the vector of patterns such that the
> highest-probability patterns are near the front.
>
> 2. There's a bunch of places where we used references to StringPiece
> instead of just plain values. This is an easy fix and it's
> recommended by StringPiece's documentation.
>
> 3. The GetModule() helper function, which removes the file extension,
> "-inl" suffix, and the path leading up to the file name, can be
> reorganized to do less work on each of its right-to-left scans of the
> input string. Specifically, we want to remove the file extension and
> "-inl" suffix *before* scanning right-to-left for the last forward or
> backward slash.
>
> Hastily-computed results on my Linux workstation, averaged over two
> runs on an official build:
> - Before: the perftest averages 10 gets/us (609ms total).
> - After: the perftest averages 13 gets/us (476ms total).
>
> That's an improvement of 22%! (Calculated as 1 - 476/609.)
>
> Aside: on my local builds with GN args "is_debug = false", I observed
> that redundant occurrences of CHECK_LT were not being optimized, but
> when converted to plain CHECK, they were correctly optimized. This
> stopped happening when I switched to an official build. Specifically,
> the bounds check in base::StringPiece::at was not being eliminated, even
> though MatchVlogPattern does its own bounds checking.
>
> GN args used:
> is_debug = false
> is_component_build = false
> is_official_build = true
> blink_symbol_level = 0
> symbol_level = 0
>
> Change-Id: I226b4ea67fc46a1b075f02b7e47c0be073a40301
> Bug: 489441
> Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3046418
> Reviewed-by: Daniel Cheng <[email protected]>
> Commit-Queue: Dan McArdle <[email protected]>
> Cr-Commit-Position: refs/heads/master@{#906903}
Bug: 489441, 1238262
Change-Id: Iefd94c171db02e91ad3a01d5f49531ce1711ebdb
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3086662
Reviewed-by: Daniel Cheng <[email protected]>
Commit-Queue: Dan McArdle <[email protected]>
Cr-Commit-Position: refs/heads/master@{#910601}
diff --git a/base/vlog.cc b/base/vlog.cc
index cdc30c3..a973b317 100644
--- a/base/vlog.cc
+++ b/base/vlog.cc
@@ -5,11 +5,11 @@
#include "base/vlog.h"
#include <stddef.h>
-
+#include <algorithm>
+#include <limits>
#include <ostream>
#include <utility>
-#include "base/cxx17_backports.h"
#include "base/logging.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/string_split.h"
@@ -24,17 +24,16 @@
explicit VmodulePattern(const std::string& pattern);
- VmodulePattern();
+ VmodulePattern() = default;
std::string pattern;
- int vlog_level;
- MatchTarget match_target;
+ int vlog_level = VlogInfo::kDefaultVlogLevel;
+ MatchTarget match_target = MATCH_MODULE;
+ size_t score = 0;
};
VlogInfo::VmodulePattern::VmodulePattern(const std::string& pattern)
- : pattern(pattern),
- vlog_level(VlogInfo::kDefaultVlogLevel),
- match_target(MATCH_MODULE) {
+ : pattern(pattern) {
// If the pattern contains a {forward,back} slash, we assume that
// it's meant to be tested against the entire __FILE__ string.
std::string::size_type first_slash = pattern.find_first_of("\\/");
@@ -42,10 +41,6 @@
match_target = MATCH_FILE;
}
-VlogInfo::VmodulePattern::VmodulePattern()
- : vlog_level(VlogInfo::kDefaultVlogLevel),
- match_target(MATCH_MODULE) {}
-
VlogInfo::VlogInfo(const std::string& v_switch,
const std::string& vmodule_switch,
int* min_log_level)
@@ -86,31 +81,59 @@
// Given a path, returns the basename with the extension chopped off
// (and any -inl suffix). We avoid using FilePath to minimize the
// number of dependencies the logging system has.
-base::StringPiece GetModule(const base::StringPiece& file) {
- base::StringPiece module(file);
- base::StringPiece::size_type last_slash_pos =
- module.find_last_of("\\/");
- if (last_slash_pos != base::StringPiece::npos)
- module.remove_prefix(last_slash_pos + 1);
+base::StringPiece GetModule(base::StringPiece file) {
+ base::StringPiece module = file;
+
+ // Chop off the file extension.
base::StringPiece::size_type extension_start = module.rfind('.');
module = module.substr(0, extension_start);
- static const char kInlSuffix[] = "-inl";
- static const int kInlSuffixLen = base::size(kInlSuffix) - 1;
+
+ // Chop off the -inl suffix.
+ static constexpr base::StringPiece kInlSuffix("-inl");
if (base::EndsWith(module, kInlSuffix))
- module.remove_suffix(kInlSuffixLen);
+ module.remove_suffix(kInlSuffix.size());
+
+ // Chop off the path up to the start of the file name. Using single-character
+ // overload of `base::StringPiece::find_last_of` for speed; this overload does
+ // not build a lookup table.
+ base::StringPiece::size_type last_slash_pos = module.find_last_of('/');
+ if (last_slash_pos != base::StringPiece::npos) {
+ module.remove_prefix(last_slash_pos + 1);
+ return module;
+ }
+ last_slash_pos = module.find_last_of('\\');
+ if (last_slash_pos != base::StringPiece::npos)
+ module.remove_prefix(last_slash_pos + 1);
return module;
}
} // namespace
-int VlogInfo::GetVlogLevel(const base::StringPiece& file) const {
+int VlogInfo::GetVlogLevel(base::StringPiece file) {
+ base::AutoLock lock(vmodule_levels_lock_);
if (!vmodule_levels_.empty()) {
base::StringPiece module(GetModule(file));
- for (const auto& it : vmodule_levels_) {
- base::StringPiece target(
- (it.match_target == VmodulePattern::MATCH_FILE) ? file : module);
- if (MatchVlogPattern(target, it.pattern))
- return it.vlog_level;
+ for (size_t i = 0; i < vmodule_levels_.size(); i++) {
+ VmodulePattern& it = vmodule_levels_[i];
+
+ const bool kUseFile = it.match_target == VmodulePattern::MATCH_FILE;
+ if (!MatchVlogPattern(kUseFile ? file : module, it.pattern)) {
+ continue;
+ }
+ const int ret = it.vlog_level;
+
+ // Since `it` matched, increase its score because we believe it has a
+ // higher probability of winning next time.
+ if (it.score == std::numeric_limits<size_t>::max()) {
+ for (VmodulePattern& pattern : vmodule_levels_) {
+ pattern.score = 0;
+ }
+ }
+ ++it.score;
+ if (i > 0 && it.score > vmodule_levels_[i - 1].score)
+ std::swap(it, vmodule_levels_[i - 1]);
+
+ return ret;
}
}
return GetMaxVlogLevel();
@@ -125,23 +148,20 @@
return -*min_log_level_;
}
-bool MatchVlogPattern(const base::StringPiece& string,
- const base::StringPiece& vlog_pattern) {
- base::StringPiece pat(vlog_pattern);
- base::StringPiece str(string);
-
+bool MatchVlogPattern(base::StringPiece string,
+ base::StringPiece vlog_pattern) {
// The code implements the glob matching using a greedy approach described in
// https://research.swtch.com/glob.
size_t s = 0, nexts = 0;
size_t p = 0, nextp = 0;
- size_t slen = str.size(), plen = pat.size();
+ const size_t slen = string.size(), plen = vlog_pattern.size();
while (s < slen || p < plen) {
if (p < plen) {
- switch (pat[p]) {
+ switch (vlog_pattern[p]) {
// A slash (forward or back) must match a slash (forward or back).
case '/':
case '\\':
- if (s < slen && (str[s] == '/' || str[s] == '\\')) {
+ if (s < slen && (string[s] == '/' || string[s] == '\\')) {
p++, s++;
continue;
}
@@ -160,7 +180,7 @@
continue;
// Anything else must match literally.
default:
- if (s < slen && str[s] == pat[p]) {
+ if (s < slen && string[s] == vlog_pattern[p]) {
p++, s++;
continue;
}
