Revision: 4427
Author: [email protected]
Date: Thu Apr 15 04:37:29 2010
Log: Report approximated duration in milliseconds for profile nodes.
The simple formula "ms = ticks * sampler_interval" doesn't work,
because e.g. on Linux, the actual sampling rate can be 5 times
lower than the one set up in the code. To calculate actual sampling
rate, current time is periodically queried and processed along with
actual sampling ticks count.
Review URL: http://codereview.chromium.org/1539038
http://code.google.com/p/v8/source/detail?r=4427
Modified:
/branches/bleeding_edge/src/api.cc
/branches/bleeding_edge/src/cpu-profiler-inl.h
/branches/bleeding_edge/src/cpu-profiler.cc
/branches/bleeding_edge/src/log.h
/branches/bleeding_edge/src/profile-generator-inl.h
/branches/bleeding_edge/src/profile-generator.cc
/branches/bleeding_edge/src/profile-generator.h
/branches/bleeding_edge/test/cctest/test-cpu-profiler.cc
/branches/bleeding_edge/test/cctest/test-profile-generator.cc
=======================================
--- /branches/bleeding_edge/src/api.cc Wed Apr 14 11:48:05 2010
+++ /branches/bleeding_edge/src/api.cc Thu Apr 15 04:37:29 2010
@@ -4056,6 +4056,18 @@
IsDeadCheck("v8::CpuProfileNode::GetLineNumber");
return reinterpret_cast<const
i::ProfileNode*>(this)->entry()->line_number();
}
+
+
+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 {
=======================================
--- /branches/bleeding_edge/src/cpu-profiler-inl.h Wed Apr 14 11:48:05 2010
+++ /branches/bleeding_edge/src/cpu-profiler-inl.h Thu Apr 15 04:37:29 2010
@@ -71,6 +71,7 @@
TickSample* ProfilerEventsProcessor::TickSampleEvent() {
+ generator_->Tick();
TickSampleEventRecord* evt =
TickSampleEventRecord::init(ticks_buffer_.Enqueue());
evt->order = enqueue_order_; // No increment!
=======================================
--- /branches/bleeding_edge/src/cpu-profiler.cc Wed Apr 14 11:48:05 2010
+++ /branches/bleeding_edge/src/cpu-profiler.cc Thu Apr 15 04:37:29 2010
@@ -436,8 +436,9 @@
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();
}
@@ -446,8 +447,9 @@
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);
}
=======================================
--- /branches/bleeding_edge/src/log.h Wed Apr 14 11:48:05 2010
+++ /branches/bleeding_edge/src/log.h Thu Apr 15 04:37:29 2010
@@ -268,11 +268,11 @@
// 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;
=======================================
--- /branches/bleeding_edge/src/profile-generator-inl.h Wed Apr 14 11:48:05
2010
+++ /branches/bleeding_edge/src/profile-generator-inl.h Thu Apr 15 04:37:29
2010
@@ -59,8 +59,9 @@
}
-ProfileNode::ProfileNode(CodeEntry* entry)
- : entry_(entry),
+ProfileNode::ProfileNode(ProfileTree* tree, CodeEntry* entry)
+ : tree_(tree),
+ entry_(entry),
total_ticks_(0),
self_ticks_(0),
children_(CodeEntriesMatch) {
=======================================
--- /branches/bleeding_edge/src/profile-generator.cc Wed Apr 14 11:48:05
2010
+++ /branches/bleeding_edge/src/profile-generator.cc Thu Apr 15 04:37:29
2010
@@ -54,12 +54,22 @@
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);
}
return reinterpret_cast<ProfileNode*>(map_entry->value);
}
+
+
+double ProfileNode::GetSelfMillis() const {
+ return tree_->TicksToMillis(self_ticks_);
+}
+
+
+double ProfileNode::GetTotalMillis() const {
+ return tree_->TicksToMillis(total_ticks_);
+}
void ProfileNode::Print(int indent) {
@@ -95,13 +105,13 @@
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);
}
@@ -129,6 +139,11 @@
}
node->IncrementSelfTicks();
}
+
+
+void ProfileTree::SetTickRatePerMs(double ticks_per_ms) {
+ ms_to_ticks_scale_ = ticks_per_ms > 0 ? 1.0 / ticks_per_ms : 1.0;
+}
namespace {
@@ -153,9 +168,9 @@
} // 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 {
@@ -194,12 +209,14 @@
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());
}
@@ -213,6 +230,12 @@
top_down_.CalculateTotalTicks();
bottom_up_.CalculateTotalTicks();
}
+
+
+void CpuProfile::SetActualSamplingRate(double actual_sampling_rate) {
+ top_down_.SetTickRatePerMs(actual_sampling_rate);
+ bottom_up_.SetTickRatePerMs(actual_sampling_rate);
+}
void CpuProfile::ShortPrint() {
@@ -326,7 +349,8 @@
}
-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();
@@ -340,6 +364,7 @@
if (profile != NULL) {
profile->CalculateTotalTicks();
+ profile->SetActualSamplingRate(actual_sampling_rate);
profiles_.Add(profile);
HashMap::Entry* entry =
profiles_uids_.Lookup(reinterpret_cast<void*>(profile->uid()),
@@ -352,8 +377,9 @@
}
-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);
}
@@ -464,6 +490,29 @@
}
current_profiles_semaphore_->Signal();
}
+
+
+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)";
=======================================
--- /branches/bleeding_edge/src/profile-generator.h Wed Apr 14 11:48:05 2010
+++ /branches/bleeding_edge/src/profile-generator.h Thu Apr 15 04:37:29 2010
@@ -70,9 +70,11 @@
};
+class ProfileTree;
+
class ProfileNode {
public:
- INLINE(explicit ProfileNode(CodeEntry* entry));
+ INLINE(ProfileNode(ProfileTree* tree, CodeEntry* entry));
ProfileNode* FindChild(CodeEntry* entry);
ProfileNode* FindOrAddChild(CodeEntry* entry);
@@ -80,9 +82,11 @@
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);
@@ -95,6 +99,7 @@
return static_cast<int32_t>(reinterpret_cast<intptr_t>(entry));
}
+ ProfileTree* tree_;
CodeEntry* entry_;
unsigned total_ticks_;
unsigned self_ticks_;
@@ -115,7 +120,11 @@
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() {
@@ -124,10 +133,11 @@
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);
};
@@ -141,11 +151,14 @@
// 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();
@@ -208,8 +221,8 @@
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();
@@ -256,6 +269,42 @@
};
+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);
@@ -286,6 +335,11 @@
void RecordTickSample(const TickSample& sample);
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;
@@ -298,6 +352,7 @@
CodeMap code_map_;
CodeEntry* program_entry_;
CodeEntry* gc_entry_;
+ SampleRateCalculator sample_rate_calc_;
DISALLOW_COPY_AND_ASSIGN(ProfileGenerator);
};
=======================================
--- /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Wed Apr 14
11:48:05 2010
+++ /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Thu Apr 15
04:37:29 2010
@@ -176,7 +176,7 @@
processor.Stop();
processor.Join();
- CpuProfile* profile = profiles.StopProfiling("");
+ CpuProfile* profile = profiles.StopProfiling("", 1);
CHECK_NE(NULL, profile);
// Check call trees.
=======================================
--- /branches/bleeding_edge/test/cctest/test-profile-generator.cc Wed Apr
14 11:48:05 2010
+++ /branches/bleeding_edge/test/cctest/test-profile-generator.cc Thu Apr
15 04:37:29 2010
@@ -17,12 +17,13 @@
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);
@@ -424,7 +425,7 @@
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));
@@ -442,5 +443,55 @@
CHECK_NE(NULL, node4);
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
--
v8-dev mailing list
[email protected]
http://groups.google.com/group/v8-dev
To unsubscribe, reply using "remove me" as the subject.
