}
+double CpuProfileNode::GetTotalTime() const {
+ IsDeadCheck("v8::CpuProfileNode::GetTotalTime");
+ return reinterpret_cast<const i::ProfileNode*>(this)->GetTotalMillis();
+}
+
+
+double CpuProfileNode::GetSelfTime() const {
+ IsDeadCheck("v8::CpuProfileNode::GetSelfTime");
+ return reinterpret_cast<const i::ProfileNode*>(this)->GetSelfMillis();
+}
+
+
double CpuProfileNode::GetTotalSamplesCount() const {
IsDeadCheck("v8::CpuProfileNode::GetTotalSamplesCount");
return reinterpret_cast<const i::ProfileNode*>(this)->total_ticks();
TickSample* ProfilerEventsProcessor::TickSampleEvent() {
+ generator_->Tick();
TickSampleEventRecord* evt =
TickSampleEventRecord::init(ticks_buffer_.Enqueue());
evt->order = enqueue_order_; // No increment!
CpuProfile* CpuProfiler::StopCollectingProfile(const char* title) {
+ const double actual_sampling_rate = generator_->actual_sampling_rate();
StopProcessorIfLastProfile();
- CpuProfile* result = profiles_->StopProfiling(title);
+ CpuProfile* result = profiles_->StopProfiling(title, actual_sampling_rate);
if (result != NULL) {
result->Print();
}
CpuProfile* CpuProfiler::StopCollectingProfile(String* title) {
+ const double actual_sampling_rate = generator_->actual_sampling_rate();
StopProcessorIfLastProfile();
- return profiles_->StopProfiling(title);
+ return profiles_->StopProfiling(title, actual_sampling_rate);
}
// Converts tag to a corresponding NATIVE_... if the script is native.
INLINE(static LogEventsAndTags ToNativeByScript(LogEventsAndTags, Script*));
- private:
-
// Profiler's sampling interval (in milliseconds).
static const int kSamplingIntervalMs = 1;
+ private:
+
// Size of window used for log records compression.
static const int kCompressionWindowSize = 4;
}
-ProfileNode::ProfileNode(CodeEntry* entry)
- : entry_(entry),
+ProfileNode::ProfileNode(ProfileTree* tree, CodeEntry* entry)
+ : tree_(tree),
+ entry_(entry),
total_ticks_(0),
self_ticks_(0),
children_(CodeEntriesMatch) {
children_.Lookup(entry, CodeEntryHash(entry), true);
if (map_entry->value == NULL) {
// New node added.
- ProfileNode* new_node = new ProfileNode(entry);
+ ProfileNode* new_node = new ProfileNode(tree_, entry);
map_entry->value = new_node;
children_list_.Add(new_node);
}
}
+double ProfileNode::GetSelfMillis() const {
+ return tree_->TicksToMillis(self_ticks_);
+}
+
+
+double ProfileNode::GetTotalMillis() const {
+ return tree_->TicksToMillis(total_ticks_);
+}
+
+
void ProfileNode::Print(int indent) {
OS::Print("%5u %5u %*c %s%s",
total_ticks_, self_ticks_,
ProfileTree::ProfileTree()
: root_entry_(Logger::FUNCTION_TAG, "", "(root)", "", 0),
- root_(new ProfileNode(&root_entry_)) {
+ root_(new ProfileNode(this, &root_entry_)) {
}
ProfileTree::~ProfileTree() {
DeleteNodesCallback cb;
- TraverseBreadthFirstPostOrder(&cb);
+ TraverseDepthFirstPostOrder(&cb);
}
}
+void ProfileTree::SetTickRatePerMs(double ticks_per_ms) {
+ ms_to_ticks_scale_ = ticks_per_ms > 0 ? 1.0 / ticks_per_ms : 1.0;
+}
+
+
namespace {
class Position {
} // namespace
-// Non-recursive implementation of breadth-first post-order tree traversal.
+// Non-recursive implementation of a depth-first post-order tree traversal.
template <typename Callback>
-void ProfileTree::TraverseBreadthFirstPostOrder(Callback* callback) {
+void ProfileTree::TraverseDepthFirstPostOrder(Callback* callback) {
List<Position> stack(10);
stack.Add(Position(root_));
do {
void ProfileTree::CalculateTotalTicks() {
CalculateTotalTicksCallback cb;
- TraverseBreadthFirstPostOrder(&cb);
+ TraverseDepthFirstPostOrder(&cb);
}
void ProfileTree::ShortPrint() {
- OS::Print("root: %u %u\n", root_->total_ticks(), root_->self_ticks());
+ OS::Print("root: %u %u %.2fms %.2fms\n",
+ root_->total_ticks(), root_->self_ticks(),
+ root_->GetTotalMillis(), root_->GetSelfMillis());
}
}
+void CpuProfile::SetActualSamplingRate(double actual_sampling_rate) {
+ top_down_.SetTickRatePerMs(actual_sampling_rate);
+ bottom_up_.SetTickRatePerMs(actual_sampling_rate);
+}
+
+
void CpuProfile::ShortPrint() {
OS::Print("top down ");
top_down_.ShortPrint();
}
-CpuProfile* CpuProfilesCollection::StopProfiling(const char* title) {
+CpuProfile* CpuProfilesCollection::StopProfiling(const char* title,
+ double actual_sampling_rate) {
const int title_len = StrLength(title);
CpuProfile* profile = NULL;
current_profiles_semaphore_->Wait();
if (profile != NULL) {
profile->CalculateTotalTicks();
+ profile->SetActualSamplingRate(actual_sampling_rate);
profiles_.Add(profile);
HashMap::Entry* entry =
profiles_uids_.Lookup(reinterpret_cast<void*>(profile->uid()),
}
-CpuProfile* CpuProfilesCollection::StopProfiling(String* title) {
- return StopProfiling(GetName(title));
+CpuProfile* CpuProfilesCollection::StopProfiling(String* title,
+ double actual_sampling_rate) {
+ return StopProfiling(GetName(title), actual_sampling_rate);
}
}
+void SampleRateCalculator::Tick() {
+ if (--wall_time_query_countdown_ == 0)
+ UpdateMeasurements(OS::TimeCurrentMillis());
+}
+
+
+void SampleRateCalculator::UpdateMeasurements(double current_time) {
+ if (measurements_count_++ != 0) {
+ const double measured_ticks_per_ms =
+ (kWallTimeQueryIntervalMs * ticks_per_ms_) /
+ (current_time - last_wall_time_);
+ // Update the average value.
+ ticks_per_ms_ +=
+ (measured_ticks_per_ms - ticks_per_ms_) / measurements_count_;
+ // Update the externally accessible result.
+ result_ = static_cast<AtomicWord>(ticks_per_ms_ * kResultScale);
+ }
+ last_wall_time_ = current_time;
+ wall_time_query_countdown_ =
+ static_cast<unsigned>(kWallTimeQueryIntervalMs * ticks_per_ms_);
+}
+
+
const char* ProfileGenerator::kAnonymousFunctionName = "(anonymous function)";
const char* ProfileGenerator::kProgramEntryName = "(program)";
const char* ProfileGenerator::kGarbageCollectorEntryName =
};
+class ProfileTree;
+
class ProfileNode {
public:
- INLINE(explicit ProfileNode(CodeEntry* entry));
+ INLINE(ProfileNode(ProfileTree* tree, CodeEntry* entry));
ProfileNode* FindChild(CodeEntry* entry);
ProfileNode* FindOrAddChild(CodeEntry* entry);
INLINE(void IncreaseTotalTicks(unsigned amount)) { total_ticks_ += amount; }
INLINE(CodeEntry* entry() const) { return entry_; }
- INLINE(unsigned total_ticks() const) { return total_ticks_; }
INLINE(unsigned self_ticks() const) { return self_ticks_; }
+ INLINE(unsigned total_ticks() const) { return total_ticks_; }
INLINE(const List<ProfileNode*>* children() const) { return &children_list_; }
+ double GetSelfMillis() const;
+ double GetTotalMillis() const;
void Print(int indent);
return static_cast<int32_t>(reinterpret_cast<intptr_t>(entry));
}
+ ProfileTree* tree_;
CodeEntry* entry_;
unsigned total_ticks_;
unsigned self_ticks_;
void AddPathFromStart(const Vector<CodeEntry*>& path);
void CalculateTotalTicks();
+ double TicksToMillis(unsigned ticks) const {
+ return ticks * ms_to_ticks_scale_;
+ }
ProfileNode* root() const { return root_; }
+ void SetTickRatePerMs(double ticks_per_ms);
void ShortPrint();
void Print() {
private:
template <typename Callback>
- void TraverseBreadthFirstPostOrder(Callback* callback);
+ void TraverseDepthFirstPostOrder(Callback* callback);
CodeEntry root_entry_;
ProfileNode* root_;
+ double ms_to_ticks_scale_;
DISALLOW_COPY_AND_ASSIGN(ProfileTree);
};
// Add pc -> ... -> main() call path to the profile.
void AddPath(const Vector<CodeEntry*>& path);
void CalculateTotalTicks();
+ void SetActualSamplingRate(double actual_sampling_rate);
INLINE(const char* title() const) { return title_; }
INLINE(unsigned uid() const) { return uid_; }
INLINE(const ProfileTree* top_down() const) { return &top_down_; }
INLINE(const ProfileTree* bottom_up() const) { return &bottom_up_; }
+ void UpdateTicksScale();
+
void ShortPrint();
void Print();
bool StartProfiling(const char* title, unsigned uid);
bool StartProfiling(String* title, unsigned uid);
- CpuProfile* StopProfiling(const char* title);
- CpuProfile* StopProfiling(String* title);
+ CpuProfile* StopProfiling(const char* title, double actual_sampling_rate);
+ CpuProfile* StopProfiling(String* title, double actual_sampling_rate);
INLINE(List<CpuProfile*>* profiles()) { return &profiles_; }
CpuProfile* GetProfile(unsigned uid);
inline bool is_last_profile();
};
+class SampleRateCalculator {
+ public:
+ SampleRateCalculator()
+ : result_(Logger::kSamplingIntervalMs * kResultScale),
+ ticks_per_ms_(Logger::kSamplingIntervalMs),
+ measurements_count_(0),
+ wall_time_query_countdown_(1) {
+ }
+
+ double ticks_per_ms() {
+ return result_ / static_cast<double>(kResultScale);
+ }
+ void Tick();
+ void UpdateMeasurements(double current_time);
+
+ // Instead of querying current wall time each tick,
+ // we use this constant to control query intervals.
+ static const unsigned kWallTimeQueryIntervalMs = 100;
+
+ private:
+ // As the result needs to be accessed from a different thread, we
+ // use type that guarantees atomic writes to memory. There should
+ // be <= 1000 ticks per second, thus storing a value of a 10 ** 5
+ // order should provide enough precision while keeping away from a
+ // potential overflow.
+ static const int kResultScale = 100000;
+
+ AtomicWord result_;
+ // All other fields are accessed only from the sampler thread.
+ double ticks_per_ms_;
+ unsigned measurements_count_;
+ unsigned wall_time_query_countdown_;
+ double last_wall_time_;
+};
+
+
class ProfileGenerator {
public:
explicit ProfileGenerator(CpuProfilesCollection* profiles);
INLINE(CodeMap* code_map()) { return &code_map_; }
+ INLINE(void Tick()) { sample_rate_calc_.Tick(); }
+ INLINE(double actual_sampling_rate()) {
+ return sample_rate_calc_.ticks_per_ms();
+ }
+
static const char* kAnonymousFunctionName;
static const char* kProgramEntryName;
static const char* kGarbageCollectorEntryName;
CodeMap code_map_;
CodeEntry* program_entry_;
CodeEntry* gc_entry_;
+ SampleRateCalculator sample_rate_calc_;
DISALLOW_COPY_AND_ASSIGN(ProfileGenerator);
};
processor.Stop();
processor.Join();
- CpuProfile* profile = profiles.StopProfiling("");
+ CpuProfile* profile = profiles.StopProfiling("", 1);
CHECK_NE(NULL, profile);
// Check call trees.
using i::ProfileNode;
using i::ProfileTree;
using i::ProfileGenerator;
+using i::SampleRateCalculator;
using i::TickSample;
using i::Vector;
TEST(ProfileNodeFindOrAddChild) {
- ProfileNode node(NULL);
+ ProfileNode node(NULL, NULL);
CodeEntry entry1(i::Logger::FUNCTION_TAG, "", "aaa", "", 0);
ProfileNode* childNode1 = node.FindOrAddChild(&entry1);
CHECK_NE(NULL, childNode1);
sample3.frames_count = 2;
generator.RecordTickSample(sample3);
- CpuProfile* profile = profiles.StopProfiling("");
+ CpuProfile* profile = profiles.StopProfiling("", 1);
CHECK_NE(NULL, profile);
ProfileTreeTestHelper top_down_test_helper(profile->top_down());
CHECK_EQ(NULL, top_down_test_helper.Walk(entry2));
CHECK_EQ(entry1, node4->entry());
}
+
+TEST(SampleRateCalculator) {
+ const double kSamplingIntervalMs = i::Logger::kSamplingIntervalMs;
+
+ // Verify that ticking exactly in query intervals results in the
+ // initial sampling interval.
+ double time = 0.0;
+ SampleRateCalculator calc1;
+ CHECK_EQ(kSamplingIntervalMs, calc1.ticks_per_ms());
+ calc1.UpdateMeasurements(time);
+ CHECK_EQ(kSamplingIntervalMs, calc1.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs;
+ calc1.UpdateMeasurements(time);
+ CHECK_EQ(kSamplingIntervalMs, calc1.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs;
+ calc1.UpdateMeasurements(time);
+ CHECK_EQ(kSamplingIntervalMs, calc1.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs;
+ calc1.UpdateMeasurements(time);
+ CHECK_EQ(kSamplingIntervalMs, calc1.ticks_per_ms());
+
+ SampleRateCalculator calc2;
+ time = 0.0;
+ CHECK_EQ(kSamplingIntervalMs, calc2.ticks_per_ms());
+ calc2.UpdateMeasurements(time);
+ CHECK_EQ(kSamplingIntervalMs, calc2.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs * 0.5;
+ calc2.UpdateMeasurements(time);
+ // (1.0 + 2.0) / 2
+ CHECK_EQ(kSamplingIntervalMs * 1.5, calc2.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs * 0.75;
+ calc2.UpdateMeasurements(time);
+ // (1.0 + 2.0 + 2.0) / 3
+ CHECK_EQ(kSamplingIntervalMs * 1.66666, calc2.ticks_per_ms());
+
+ SampleRateCalculator calc3;
+ time = 0.0;
+ CHECK_EQ(kSamplingIntervalMs, calc3.ticks_per_ms());
+ calc3.UpdateMeasurements(time);
+ CHECK_EQ(kSamplingIntervalMs, calc3.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs * 2;
+ calc3.UpdateMeasurements(time);
+ // (1.0 + 0.5) / 2
+ CHECK_EQ(kSamplingIntervalMs * 0.75, calc3.ticks_per_ms());
+ time += SampleRateCalculator::kWallTimeQueryIntervalMs * 1.5;
+ calc3.UpdateMeasurements(time);
+ // (1.0 + 0.5 + 0.5) / 3
+ CHECK_EQ(kSamplingIntervalMs * 0.66666, calc3.ticks_per_ms());
+}
+
#endif // ENABLE_LOGGING_AND_PROFILING