From a7e816db2892efd1a019dc2d1d9bbda68e9ecf1a Mon Sep 17 00:00:00 2001 From: "alph@chromium.org" Date: Thu, 22 May 2014 05:36:27 +0000 Subject: [PATCH] Introduce a separate event for CodeDeopt The reuse of CodeCreateEvent for deopt events caused a CodeCreateEvent fired twice for a code object. When the event was processed for the first time it seized the no-fp-ranges from code object, so the second event had no ranges info leaving code entry without them. As a result when a cpu profile sample falls into the region it missed the 2nd stack frame. LOG=N BUG= R=bmeurer@chromium.org, loislo@chromium.org Review URL: https://codereview.chromium.org/290093005 git-svn-id: https://v8.googlecode.com/svn/branches/bleeding_edge@21418 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/cpu-profiler-inl.h | 8 ++++ src/cpu-profiler.cc | 9 +++++ src/cpu-profiler.h | 11 ++++++ src/log.cc | 22 +++++++++++ src/log.h | 4 ++ src/objects.cc | 4 +- src/serialize.cc | 3 ++ test/cctest/test-cpu-profiler.cc | 66 ++++++++++++++++++++++++++++++++ 8 files changed, 124 insertions(+), 3 deletions(-) diff --git a/src/cpu-profiler-inl.h b/src/cpu-profiler-inl.h index c4efef1b32..e088f2ef48 100644 --- a/src/cpu-profiler-inl.h +++ b/src/cpu-profiler-inl.h @@ -28,6 +28,14 @@ void CodeMoveEventRecord::UpdateCodeMap(CodeMap* code_map) { } +void CodeDisableOptEventRecord::UpdateCodeMap(CodeMap* code_map) { + CodeEntry* entry = code_map->FindEntry(start); + if (entry != NULL) { + entry->set_bailout_reason(bailout_reason); + } +} + + void SharedFunctionInfoMoveEventRecord::UpdateCodeMap(CodeMap* code_map) { code_map->MoveCode(from, to); } diff --git a/src/cpu-profiler.cc b/src/cpu-profiler.cc index abe29340d0..3a7c960871 100644 --- a/src/cpu-profiler.cc +++ b/src/cpu-profiler.cc @@ -304,6 +304,15 @@ void CpuProfiler::CodeMoveEvent(Address from, Address to) { } +void CpuProfiler::CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { + CodeEventsContainer evt_rec(CodeEventRecord::CODE_DISABLE_OPT); + CodeDisableOptEventRecord* rec = &evt_rec.CodeDisableOptEventRecord_; + rec->start = code->address(); + rec->bailout_reason = GetBailoutReason(shared->DisableOptimizationReason()); + processor_->Enqueue(evt_rec); +} + + void CpuProfiler::CodeDeleteEvent(Address from) { } diff --git a/src/cpu-profiler.h b/src/cpu-profiler.h index e87fe9e772..b9f9f98fd2 100644 --- a/src/cpu-profiler.h +++ b/src/cpu-profiler.h @@ -26,6 +26,7 @@ class ProfileGenerator; #define CODE_EVENTS_TYPE_LIST(V) \ V(CODE_CREATION, CodeCreateEventRecord) \ V(CODE_MOVE, CodeMoveEventRecord) \ + V(CODE_DISABLE_OPT, CodeDisableOptEventRecord) \ V(SHARED_FUNC_MOVE, SharedFunctionInfoMoveEventRecord) \ V(REPORT_BUILTIN, ReportBuiltinEventRecord) @@ -65,6 +66,15 @@ class CodeMoveEventRecord : public CodeEventRecord { }; +class CodeDisableOptEventRecord : public CodeEventRecord { + public: + Address start; + const char* bailout_reason; + + INLINE(void UpdateCodeMap(CodeMap* code_map)); +}; + + class SharedFunctionInfoMoveEventRecord : public CodeEventRecord { public: Address from; @@ -225,6 +235,7 @@ class CpuProfiler : public CodeEventListener { Code* code, int args_count); virtual void CodeMovingGCEvent() {} virtual void CodeMoveEvent(Address from, Address to); + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared); virtual void CodeDeleteEvent(Address from); virtual void GetterCallbackEvent(Name* name, Address entry_point); virtual void RegExpCodeCreateEvent(Code* code, String* source); diff --git a/src/log.cc b/src/log.cc index 623e08d8fa..5c88cb492c 100644 --- a/src/log.cc +++ b/src/log.cc @@ -230,6 +230,7 @@ class PerfBasicLogger : public CodeEventLogger { virtual ~PerfBasicLogger(); virtual void CodeMoveEvent(Address from, Address to) { } + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } virtual void CodeDeleteEvent(Address from) { } private: @@ -295,6 +296,7 @@ class PerfJitLogger : public CodeEventLogger { virtual ~PerfJitLogger(); virtual void CodeMoveEvent(Address from, Address to) { } + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } virtual void CodeDeleteEvent(Address from) { } private: @@ -457,6 +459,7 @@ class LowLevelLogger : public CodeEventLogger { virtual ~LowLevelLogger(); virtual void CodeMoveEvent(Address from, Address to); + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } virtual void CodeDeleteEvent(Address from); virtual void SnapshotPositionEvent(Address addr, int pos); virtual void CodeMovingGCEvent(); @@ -623,6 +626,7 @@ class JitLogger : public CodeEventLogger { explicit JitLogger(JitCodeEventHandler code_event_handler); virtual void CodeMoveEvent(Address from, Address to); + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } virtual void CodeDeleteEvent(Address from); virtual void AddCodeLinePosInfoEvent( void* jit_handler_data, @@ -1446,6 +1450,24 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, } +void Logger::CodeDisableOptEvent(Code* code, + SharedFunctionInfo* shared) { + PROFILER_LOG(CodeDisableOptEvent(code, shared)); + + if (!is_logging_code_events()) return; + CALL_LISTENERS(CodeDisableOptEvent(code, shared)); + + if (!FLAG_log_code || !log_->IsEnabled()) return; + Log::MessageBuilder msg(log_); + msg.Append("%s,", kLogEventsNames[CODE_DISABLE_OPT_EVENT]); + SmartArrayPointer name = + shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); + msg.Append("\"%s\",", name.get()); + msg.Append("\"%s\"\n", GetBailoutReason(shared->DisableOptimizationReason())); + msg.WriteToLogFile(); +} + + void Logger::CodeMovingGCEvent() { PROFILER_LOG(CodeMovingGCEvent()); diff --git a/src/log.h b/src/log.h index b1a41e949f..19adecba87 100644 --- a/src/log.h +++ b/src/log.h @@ -79,6 +79,7 @@ struct TickSample; #define LOG_EVENTS_AND_TAGS_LIST(V) \ V(CODE_CREATION_EVENT, "code-creation") \ + V(CODE_DISABLE_OPT_EVENT, "code-disable-optimization") \ V(CODE_MOVE_EVENT, "code-move") \ V(CODE_DELETE_EVENT, "code-delete") \ V(CODE_MOVING_GC, "code-moving-gc") \ @@ -237,6 +238,8 @@ class Logger { CompilationInfo* info, Name* source, int line, int column); void CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count); + // Emits a code deoptimization event. + void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared); void CodeMovingGCEvent(); // Emits a code create event for a RegExp. void RegExpCodeCreateEvent(Code* code, String* source); @@ -470,6 +473,7 @@ class CodeEventListener { virtual void CodeDeleteEvent(Address from) = 0; virtual void SharedFunctionInfoMoveEvent(Address from, Address to) = 0; virtual void CodeMovingGCEvent() = 0; + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) = 0; }; diff --git a/src/objects.cc b/src/objects.cc index 769d5fc8b6..2be60d8ec8 100644 --- a/src/objects.cc +++ b/src/objects.cc @@ -10706,9 +10706,7 @@ void SharedFunctionInfo::DisableOptimization(BailoutReason reason) { if (code()->kind() == Code::FUNCTION) { code()->set_optimizable(false); } - PROFILE(GetIsolate(), - LogExistingFunction(Handle(this), - Handle(code()))); + PROFILE(GetIsolate(), CodeDisableOptEvent(code(), this)); if (FLAG_trace_opt) { PrintF("[disabled optimization for "); ShortPrint(); diff --git a/src/serialize.cc b/src/serialize.cc index 2b43c0ee69..9d8a23db77 100644 --- a/src/serialize.cc +++ b/src/serialize.cc @@ -630,6 +630,9 @@ class CodeAddressMap: public CodeEventLogger { address_to_name_map_.Move(from, to); } + virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { + } + virtual void CodeDeleteEvent(Address from) { address_to_name_map_.Remove(from); } diff --git a/test/cctest/test-cpu-profiler.cc b/test/cctest/test-cpu-profiler.cc index 52e0fd6521..ce422b5b6b 100644 --- a/test/cctest/test-cpu-profiler.cc +++ b/test/cctest/test-cpu-profiler.cc @@ -587,6 +587,72 @@ TEST(CollectCpuProfile) { } +static const char* hot_deopt_no_frame_entry_test_source = +"function foo(a, b) {\n" +" try {\n" +" return a + b;\n" +" } catch (e) { }\n" +"}\n" +"function start(timeout) {\n" +" var start = Date.now();\n" +" do {\n" +" for (var i = 1; i < 1000; ++i) foo(1, i);\n" +" var duration = Date.now() - start;\n" +" } while (duration < timeout);\n" +" return duration;\n" +"}\n"; + +// Check that the profile tree for the script above will look like the +// following: +// +// [Top down]: +// 1062 0 (root) [-1] +// 1054 0 start [-1] +// 1054 1 foo [-1] +// 2 2 (program) [-1] +// 6 6 (garbage collector) [-1] +// +// The test checks no FP ranges are present in a deoptimized funcion. +// If 'foo' has no ranges the samples falling into the prologue will miss the +// 'start' function on the stack, so 'foo' will be attached to the (root). +TEST(HotDeoptNoFrameEntry) { + LocalContext env; + v8::HandleScope scope(env->GetIsolate()); + + v8::Script::Compile(v8::String::NewFromUtf8( + env->GetIsolate(), + hot_deopt_no_frame_entry_test_source))->Run(); + v8::Local function = v8::Local::Cast( + env->Global()->Get(v8::String::NewFromUtf8(env->GetIsolate(), "start"))); + + int32_t profiling_interval_ms = 200; + v8::Handle args[] = { + v8::Integer::New(env->GetIsolate(), profiling_interval_ms) + }; + v8::CpuProfile* profile = + RunProfiler(env.local(), function, args, ARRAY_SIZE(args), 200); + function->Call(env->Global(), ARRAY_SIZE(args), args); + + const v8::CpuProfileNode* root = profile->GetTopDownRoot(); + + ScopedVector > names(3); + names[0] = v8::String::NewFromUtf8( + env->GetIsolate(), ProfileGenerator::kGarbageCollectorEntryName); + names[1] = v8::String::NewFromUtf8(env->GetIsolate(), + ProfileGenerator::kProgramEntryName); + names[2] = v8::String::NewFromUtf8(env->GetIsolate(), "start"); + CheckChildrenNames(root, names); + + const v8::CpuProfileNode* startNode = + GetChild(env->GetIsolate(), root, "start"); + CHECK_EQ(1, startNode->GetChildrenCount()); + + GetChild(env->GetIsolate(), startNode, "foo"); + + profile->Delete(); +} + + TEST(CollectCpuProfileSamples) { LocalContext env; v8::HandleScope scope(env->GetIsolate());