Commit ad943fe4 authored by cbruni's avatar cbruni Committed by Commit bot

Reland of [counters] moving runtime counters to counter.h (patchset #1 id:1 of...

Reland of [counters] moving runtime counters to counter.h (patchset #1 id:1 of https://codereview.chromium.org/1681923003/ )

Reason for revert:
This CL was not the cause for the TSAN failures, the instruction-selector backend for x64 emitted  a wrong compare which accidentally showed up with tsan + code moves.
The instruction-selectors changes have been reverted with https://codereview.chromium.org/1693433002

Original issue's description:
> Revert of [counters] moving runtime counters to counter.h (patchset #1 id:1 of https://codereview.chromium.org/1678973002/ )
>
> Reason for revert:
> [Sheriff] Breaks TSAN:
> https://build.chromium.org/p/client.v8/builders/V8%20Linux64%20TSAN/builds/7727
>
> Original issue's description:
> > [counters] moving runtime counters to counter.h
> >
> > Additionally list C++ builtins as well under --runtime_call_stats.
> > Let's try to keep all counters in one place, that makes it a bit
> > easier to maintain and especially discard unused ones.
> >
> > BUG=
> >
> > Committed: https://crrev.com/6bc71431995d49d4ca4a2ea9c75e5add5f345225
> > Cr-Commit-Position: refs/heads/master@{#33847}
>
> TBR=jarin@chromium.org,cbruni@chromium.org
> # Skipping CQ checks because original CL landed less than 1 days ago.
> NOPRESUBMIT=true
> NOTREECHECKS=true
> NOTRY=true
> BUG=
>
> Committed: https://crrev.com/2d669b96639517cfc33e6fc6d4c3814587bc7366
> Cr-Commit-Position: refs/heads/master@{#33848}

TBR=jarin@chromium.org,machenbach@chromium.org
# Not skipping CQ checks because original CL landed more than 1 days ago.
BUG=

Review URL: https://codereview.chromium.org/1688783005

Cr-Commit-Position: refs/heads/master@{#33887}
parent e519e6fa
......@@ -271,32 +271,30 @@ double ClobberDoubleRegisters(double x1, double x2, double x3, double x4);
#define CLOBBER_DOUBLE_REGISTERS()
#endif
#define RUNTIME_FUNCTION_RETURNS_TYPE(Type, Name) \
static INLINE(Type __RT_impl_##Name(Arguments args, Isolate* isolate)); \
Type Name(int args_length, Object** args_object, Isolate* isolate) { \
CLOBBER_DOUBLE_REGISTERS(); \
RuntimeCallStats* stats = isolate->runtime_state()->runtime_call_stats(); \
stats->Count_##Name++; \
base::ElapsedTimer timer; \
bool timing = false; \
if (FLAG_runtime_call_stats && !stats->in_runtime_call) { \
stats->in_runtime_call = true; \
timing = true; \
timer.Start(); \
} \
Arguments args(args_length, args_object); \
Type value = __RT_impl_##Name(args, isolate); \
if (timing) { \
stats->in_runtime_call = false; \
isolate->runtime_state()->runtime_call_stats()->Time_##Name += \
timer.Elapsed(); \
} \
return value; \
} \
#define RUNTIME_FUNCTION_RETURNS_TYPE(Type, Name) \
static INLINE(Type __RT_impl_##Name(Arguments args, Isolate* isolate)); \
Type Name(int args_length, Object** args_object, Isolate* isolate) { \
CLOBBER_DOUBLE_REGISTERS(); \
RuntimeCallStats* stats = isolate->counters()->runtime_call_stats(); \
stats->Count_##Name++; \
base::ElapsedTimer timer; \
bool timing = false; \
if (FLAG_runtime_call_stats && !stats->in_runtime_call) { \
stats->in_runtime_call = true; \
timing = true; \
timer.Start(); \
} \
Arguments args(args_length, args_object); \
Type value = __RT_impl_##Name(args, isolate); \
if (timing) { \
stats->in_runtime_call = false; \
isolate->counters()->runtime_call_stats()->Time_##Name += \
timer.Elapsed(); \
} \
return value; \
} \
static Type __RT_impl_##Name(Arguments args, Isolate* isolate)
#define RUNTIME_FUNCTION(Name) RUNTIME_FUNCTION_RETURNS_TYPE(Object*, Name)
#define RUNTIME_FUNCTION_RETURN_PAIR(Name) \
RUNTIME_FUNCTION_RETURNS_TYPE(ObjectPair, Name)
......
......@@ -142,10 +142,26 @@ BUILTIN_LIST_C(DEF_ARG_TYPE)
Isolate* isolate); \
MUST_USE_RESULT static Object* Builtin_##name( \
int args_length, Object** args_object, Isolate* isolate) { \
RuntimeCallStats* stats = isolate->counters()->runtime_call_stats(); \
stats->Count_Builtin_##name++; \
base::ElapsedTimer timer; \
bool timing = false; \
if (FLAG_runtime_call_stats && !stats->in_runtime_call) { \
stats->in_runtime_call = true; \
timing = true; \
timer.Start(); \
} \
name##ArgumentsType args(args_length, args_object); \
isolate->counters()->runtime_calls()->Increment(); \
return Builtin_Impl_##name(args, isolate); \
Object* value = Builtin_Impl_##name(args, isolate); \
if (timing) { \
stats->in_runtime_call = false; \
isolate->counters()->runtime_call_stats()->Time_Builtin_##name += \
timer.Elapsed(); \
} \
return value; \
} \
\
MUST_USE_RESULT static Object* Builtin_Impl_##name(name##ArgumentsType args, \
Isolate* isolate)
......
......@@ -4,6 +4,8 @@
#include "src/counters.h"
#include <iomanip>
#include "src/base/platform/platform.h"
#include "src/isolate.h"
#include "src/log-inl.h"
......@@ -193,5 +195,104 @@ void Counters::ResetHistograms() {
#undef HM
}
class RuntimeCallStatEntries {
public:
void Print(std::ostream& os) {
if (total_call_count > 0) {
std::sort(entries.rbegin(), entries.rend());
os << std::setw(50) << "Runtime Function/C++ Builtin" << std::setw(10)
<< "Time" << std::setw(18) << "Count" << std::endl
<< std::string(86, '=') << std::endl;
for (Entry& entry : entries) {
entry.SetTotal(total_time, total_call_count);
entry.Print(os);
}
os << std::string(86, '-') << std::endl;
Entry("Total", total_time, total_call_count).Print(os);
}
}
void Add(const char* name, base::TimeDelta time, uint32_t count) {
entries.push_back(Entry(name, time, count));
total_time += time;
total_call_count += count;
}
private:
class Entry {
public:
Entry(const char* name, base::TimeDelta time, uint64_t count)
: name_(name),
time_(time.InMilliseconds()),
count_(count),
time_percent_(100),
count_percent_(100) {}
bool operator<(const Entry& other) const {
if (time_ < other.time_) return true;
if (time_ > other.time_) return false;
return count_ < other.count_;
}
void Print(std::ostream& os) {
os.precision(2);
os << std::fixed;
os << std::setw(50) << name_;
os << std::setw(8) << time_ << "ms ";
os << std::setw(6) << time_percent_ << "%";
os << std::setw(10) << count_ << " ";
os << std::setw(6) << count_percent_ << "%";
os << std::endl;
}
void SetTotal(base::TimeDelta total_time, uint64_t total_count) {
time_percent_ = 100.0 * time_ / total_time.InMilliseconds();
count_percent_ = 100.0 * count_ / total_count;
}
private:
const char* name_;
int64_t time_;
uint64_t count_;
double time_percent_;
double count_percent_;
};
uint64_t total_call_count = 0;
base::TimeDelta total_time;
std::vector<Entry> entries;
};
void RuntimeCallStats::Print(std::ostream& os) {
RuntimeCallStatEntries entries;
#define PRINT_COUNTER(name, nargs, ressize) \
if (this->Count_Runtime_##name > 0) { \
entries.Add(#name, this->Time_Runtime_##name, this->Count_Runtime_##name); \
}
FOR_EACH_INTRINSIC(PRINT_COUNTER)
#undef PRINT_COUNTER
#define PRINT_COUNTER(name, type) \
if (this->Count_Builtin_##name > 0) { \
entries.Add(#name, this->Time_Builtin_##name, this->Count_Builtin_##name); \
}
BUILTIN_LIST_C(PRINT_COUNTER)
#undef PRINT_COUNTER
entries.Print(os);
}
void RuntimeCallStats::Reset() {
#define RESET_COUNTER(name, nargs, ressize) \
Count_Runtime_##name = 0; \
Time_Runtime_##name = base::TimeDelta();
FOR_EACH_INTRINSIC(RESET_COUNTER)
#undef RESET_COUNTER
#define RESET_COUNTER(name, type) \
Count_Builtin_##name = 0; \
Time_Builtin_##name = base::TimeDelta();
BUILTIN_LIST_C(RESET_COUNTER)
#undef RESET_COUNTER
}
} // namespace internal
} // namespace v8
......@@ -9,8 +9,10 @@
#include "src/allocation.h"
#include "src/base/platform/elapsed-timer.h"
#include "src/base/platform/time.h"
#include "src/builtins.h"
#include "src/globals.h"
#include "src/objects.h"
#include "src/runtime/runtime.h"
namespace v8 {
namespace internal {
......@@ -699,6 +701,30 @@ double AggregatedMemoryHistogram<Histogram>::Aggregate(double current_ms,
/* Total count of functions compiled using the baseline compiler. */ \
SC(total_baseline_compile_count, V8.TotalBaselineCompileCount)
struct RuntimeCallStats {
#define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
uint32_t Count_Runtime_##name; \
base::TimeDelta Time_Runtime_##name;
FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)
#undef CALL_RUNTIME_COUNTER
#define CALL_BUILTIN_COUNTER(name, type) \
uint32_t Count_Builtin_##name; \
base::TimeDelta Time_Builtin_##name;
BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)
#undef CALL_BUILTIN_COUNTER
// Dummy counter for the unexpected stub miss.
uint32_t Count_UnexpectedStubMiss;
base::TimeDelta Time_UnexpectedStubMiss;
bool in_runtime_call = false;
void Reset();
void Print(std::ostream& os);
RuntimeCallStats() { Reset(); }
};
// This file contains all the v8 counters that are in use.
class Counters {
public:
......@@ -809,6 +835,7 @@ class Counters {
void ResetCounters();
void ResetHistograms();
RuntimeCallStats* runtime_call_stats() { return &runtime_call_stats_; }
private:
#define HR(name, caption, min, max, num_buckets) Histogram name##_;
......@@ -870,6 +897,8 @@ class Counters {
CODE_AGE_LIST_COMPLETE(SC)
#undef SC
RuntimeCallStats runtime_call_stats_;
friend class Isolate;
explicit Counters(Isolate* isolate);
......
......@@ -2402,8 +2402,8 @@ void Isolate::DumpAndResetCompilationStats() {
hstatistics_ = nullptr;
if (FLAG_runtime_call_stats) {
OFStream os(stdout);
runtime_state()->runtime_call_stats()->Print(os);
runtime_state()->runtime_call_stats()->Reset();
counters()->runtime_call_stats()->Print(os);
counters()->runtime_call_stats()->Reset();
}
}
......
......@@ -482,10 +482,10 @@ RUNTIME_FUNCTION(Runtime_GetAndResetRuntimeCallStats) {
HandleScope scope(isolate);
DCHECK_EQ(0, args.length());
std::stringstream stats_stream;
isolate->runtime_state()->runtime_call_stats()->Print(stats_stream);
isolate->counters()->runtime_call_stats()->Print(stats_stream);
Handle<String> result =
isolate->factory()->NewStringFromAsciiChecked(stats_stream.str().c_str());
isolate->runtime_state()->runtime_call_stats()->Reset();
isolate->counters()->runtime_call_stats()->Reset();
return *result;
}
......
......@@ -4,8 +4,6 @@
#include "src/runtime/runtime.h"
#include <iomanip>
#include "src/assembler.h"
#include "src/contexts.h"
#include "src/handles-inl.h"
......@@ -133,79 +131,5 @@ std::ostream& operator<<(std::ostream& os, Runtime::FunctionId id) {
}
class RuntimeCallStatEntries {
public:
void Print(std::ostream& os) {
if (total_call_count > 0) {
std::sort(entries.rbegin(), entries.rend());
os << "Runtime function Time "
"Count"
<< std::endl
<< std::string(70, '=') << std::endl;
for (Entry& entry : entries) {
entry.Print(os);
}
os << std::string(60, '-') << std::endl;
Entry("Total", total_time, total_call_count).Print(os);
}
}
void Add(const char* name, base::TimeDelta time, uint32_t count) {
entries.push_back(Entry(name, time, count));
total_time += time;
total_call_count += count;
}
private:
class Entry {
public:
Entry(const char* name, base::TimeDelta time, uint64_t count)
: name_(name), time_(time.InMilliseconds()), count_(count) {}
bool operator<(const Entry& other) const {
if (time_ < other.time_) return true;
if (time_ > other.time_) return false;
return count_ < other.count_;
}
void Print(std::ostream& os) {
os << std::setw(50) << name_;
os << std::setw(8) << time_ << "ms";
os << std::setw(10) << count_ << std::endl;
}
private:
const char* name_;
int64_t time_;
uint64_t count_;
};
uint64_t total_call_count = 0;
base::TimeDelta total_time;
std::vector<Entry> entries;
};
void RuntimeCallStats::Print(std::ostream& os) {
RuntimeCallStatEntries entries;
#define PRINT_COUNTER(name, nargs, ressize) \
if (this->Count_Runtime_##name > 0) { \
entries.Add(#name, this->Time_Runtime_##name, this->Count_Runtime_##name); \
}
FOR_EACH_INTRINSIC(PRINT_COUNTER)
#undef PRINT_COUNTER
entries.Print(os);
}
void RuntimeCallStats::Reset() {
#define RESET_COUNTER(name, nargs, ressize) \
Count_Runtime_##name = 0; \
Time_Runtime_##name = base::TimeDelta();
FOR_EACH_INTRINSIC(RESET_COUNTER)
#undef RESET_COUNTER
}
} // namespace internal
} // namespace v8
......@@ -1185,26 +1185,6 @@ class Runtime : public AllStatic {
};
struct RuntimeCallStats {
#define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
uint32_t Count_Runtime_##name; \
base::TimeDelta Time_Runtime_##name;
FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)
#undef CALL_RUNTIME_COUNTER
// Dummy counter for the unexpected stub miss.
uint32_t Count_UnexpectedStubMiss;
base::TimeDelta Time_UnexpectedStubMiss;
bool in_runtime_call = false;
void Reset();
void Print(std::ostream& os);
RuntimeCallStats() { Reset(); }
};
class RuntimeState {
public:
unibrow::Mapping<unibrow::ToUppercase, 128>* to_upper_mapping() {
......@@ -1223,14 +1203,11 @@ class RuntimeState {
redirected_intrinsic_functions_.Reset(redirected_intrinsic_functions);
}
RuntimeCallStats* runtime_call_stats() { return &runtime_call_stats_; }
private:
RuntimeState() {}
unibrow::Mapping<unibrow::ToUppercase, 128> to_upper_mapping_;
unibrow::Mapping<unibrow::ToLowercase, 128> to_lower_mapping_;
RuntimeCallStats runtime_call_stats_;
base::SmartArrayPointer<Runtime::Function> redirected_intrinsic_functions_;
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment