[vm] Misc timeline tweaks. - Move compiler pass events to a new CompilerVerbose stream - Remove serialization phase events - Add class name to class finalization event (lost along with finalization events in recent cleanups of finalization) - Add event for kernel loading Change-Id: Ie72bced978400ea174c1551c961baa55c691b019 Reviewed-on: https://dart-review.googlesource.com/c/90883 Commit-Queue: Ryan Macnak <rmacnak@google.com> Reviewed-by: Zach Anderson <zra@google.com> Reviewed-by: Alexander Markov <alexmarkov@google.com>
diff --git a/runtime/vm/class_finalizer.cc b/runtime/vm/class_finalizer.cc index 847a4a1..a4c53f2 100644 --- a/runtime/vm/class_finalizer.cc +++ b/runtime/vm/class_finalizer.cc
@@ -1116,17 +1116,26 @@ } void ClassFinalizer::FinalizeClass(const Class& cls) { - Thread* thread = Thread::Current(); - HANDLESCOPE(thread); ASSERT(cls.is_type_finalized()); if (cls.is_finalized()) { return; } + + Thread* thread = Thread::Current(); + HANDLESCOPE(thread); + if (FLAG_trace_class_finalization) { THR_Print("Finalize %s\n", cls.ToCString()); } - TIMELINE_DURATION(thread, Compiler, "ClassFinalizer::FinalizeClass"); +#if defined(SUPPORT_TIMELINE) + TimelineDurationScope tds(thread, Timeline::GetCompilerStream(), + "FinalizeClass"); + if (tds.enabled()) { + tds.SetNumArguments(1); + tds.CopyArgument(0, "class", cls.ToCString()); + } +#endif // defined(SUPPORT_TIMELINE) #if !defined(DART_PRECOMPILED_RUNTIME) // If loading from a kernel, make sure that the class is fully loaded.
diff --git a/runtime/vm/clustered_snapshot.cc b/runtime/vm/clustered_snapshot.cc index 3c9d19a..7261e1c 100644 --- a/runtime/vm/clustered_snapshot.cc +++ b/runtime/vm/clustered_snapshot.cc
@@ -593,8 +593,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "Function"); - if (kind == Snapshot::kFullAOT) { Function& func = Function::Handle(zone); for (intptr_t i = start_index_; i < stop_index_; i++) { @@ -1006,8 +1004,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "Field"); - Field& field = Field::Handle(zone); if (!Isolate::Current()->use_field_guards()) { for (intptr_t i = start_index_; i < stop_index_; i++) { @@ -1319,8 +1315,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "KernelProgramInfo"); - Array& array = Array::Handle(zone); KernelProgramInfo& info = KernelProgramInfo::Handle(zone); for (intptr_t id = start_index_; id < stop_index_; id++) { @@ -2332,8 +2326,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "MegamorphicCache"); - #if defined(DART_PRECOMPILED_RUNTIME) if (FLAG_use_bare_instructions) { // By default, every megamorphic call site will load the target @@ -2869,8 +2861,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "Type"); - Type& type = Type::Handle(zone); Code& stub = Code::Handle(zone); @@ -2969,8 +2959,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "TypeRef"); - TypeRef& type_ref = TypeRef::Handle(zone); Code& stub = Code::Handle(zone); @@ -3065,8 +3053,6 @@ } void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "TypeParameter"); - TypeParameter& type_param = TypeParameter::Handle(zone); Code& stub = Code::Handle(zone); @@ -3228,8 +3214,6 @@ void ReadFill(Deserializer* d) {} void PostLoad(const Array& refs, Snapshot::Kind kind, Zone* zone) { - TIMELINE_DURATION(Thread::Current(), Isolate, "Mint"); - const Class& mint_cls = Class::Handle(zone, Isolate::Current()->object_store()->mint_class()); mint_cls.set_constants(Object::empty_array()); @@ -5101,30 +5085,24 @@ num_base_objects_, next_ref_index_ - 1); } - { - TIMELINE_DURATION(thread(), Isolate, "ReadAlloc"); - for (intptr_t i = 0; i < num_clusters_; i++) { - clusters_[i] = ReadCluster(); - clusters_[i]->ReadAlloc(this); + for (intptr_t i = 0; i < num_clusters_; i++) { + clusters_[i] = ReadCluster(); + clusters_[i]->ReadAlloc(this); #if defined(DEBUG) - intptr_t serializers_next_ref_index_ = Read<int32_t>(); - ASSERT(serializers_next_ref_index_ == next_ref_index_); + intptr_t serializers_next_ref_index_ = Read<int32_t>(); + ASSERT(serializers_next_ref_index_ == next_ref_index_); #endif - } } // We should have completely filled the ref array. ASSERT((next_ref_index_ - 1) == num_objects_); - { - TIMELINE_DURATION(thread(), Isolate, "ReadFill"); - for (intptr_t i = 0; i < num_clusters_; i++) { - clusters_[i]->ReadFill(this); + for (intptr_t i = 0; i < num_clusters_; i++) { + clusters_[i]->ReadFill(this); #if defined(DEBUG) - int32_t section_marker = Read<int32_t>(); - ASSERT(section_marker == kSectionMarker); + int32_t section_marker = Read<int32_t>(); + ASSERT(section_marker == kSectionMarker); #endif - } } } @@ -5233,11 +5211,8 @@ isolate()->ValidateClassTable(); #endif - { - TIMELINE_DURATION(thread(), Isolate, "PostLoad"); - for (intptr_t i = 0; i < num_clusters_; i++) { - clusters_[i]->PostLoad(refs, kind_, zone_); - } + for (intptr_t i = 0; i < num_clusters_; i++) { + clusters_[i]->PostLoad(refs, kind_, zone_); } } @@ -5282,11 +5257,8 @@ isolate->heap()->Verify(); #endif - { - TIMELINE_DURATION(thread(), Isolate, "PostLoad"); - for (intptr_t i = 0; i < num_clusters_; i++) { - clusters_[i]->PostLoad(refs, kind_, zone_); - } + for (intptr_t i = 0; i < num_clusters_; i++) { + clusters_[i]->PostLoad(refs, kind_, zone_); } // Setup native resolver for bootstrap impl.
diff --git a/runtime/vm/compiler/aot/precompiler.cc b/runtime/vm/compiler/aot/precompiler.cc index 49c5b8f..0f3c66f 100644 --- a/runtime/vm/compiler/aot/precompiler.cc +++ b/runtime/vm/compiler/aot/precompiler.cc
@@ -2295,9 +2295,6 @@ } bool is_compiled = false; Zone* const zone = thread()->zone(); -#ifndef PRODUCT - TimelineStream* compiler_timeline = Timeline::GetCompilerStream(); -#endif // !PRODUCT HANDLESCOPE(thread()); // We may reattempt compilation if the function needs to be assembled using @@ -2323,7 +2320,7 @@ { ic_data_array = new (zone) ZoneGrowableArray<const ICData*>(); - TIMELINE_DURATION(thread(), Compiler, "BuildFlowGraph"); + TIMELINE_DURATION(thread(), CompilerVerbose, "BuildFlowGraph"); flow_graph = pipeline->BuildFlowGraph(zone, parsed_function(), ic_data_array, Compiler::kNoOSRDeoptId, optimized()); @@ -2348,10 +2345,9 @@ pass_state.block_scheduler = &block_scheduler; pass_state.reorder_blocks = FlowGraph::ShouldReorderBlocks(function, optimized()); - NOT_IN_PRODUCT(pass_state.compiler_timeline = compiler_timeline); if (optimized()) { - TIMELINE_DURATION(thread(), Compiler, "OptimizationPasses"); + TIMELINE_DURATION(thread(), CompilerVerbose, "OptimizationPasses"); pass_state.inline_id_to_function.Add(&function); // We do not add the token position now because we don't know the @@ -2395,12 +2391,12 @@ pass_state.inline_id_to_token_pos, pass_state.caller_inline_id, ic_data_array, function_stats); { - TIMELINE_DURATION(thread(), Compiler, "CompileGraph"); + TIMELINE_DURATION(thread(), CompilerVerbose, "CompileGraph"); graph_compiler.CompileGraph(); pipeline->FinalizeCompilation(flow_graph); } { - TIMELINE_DURATION(thread(), Compiler, "FinalizeCompilation"); + TIMELINE_DURATION(thread(), CompilerVerbose, "FinalizeCompilation"); ASSERT(thread()->IsMutatorThread()); FinalizeCompilation(&assembler, &graph_compiler, flow_graph, function_stats);
diff --git a/runtime/vm/compiler/backend/type_propagator.cc b/runtime/vm/compiler/backend/type_propagator.cc index 8653b9f..4f707cd 100644 --- a/runtime/vm/compiler/backend/type_propagator.cc +++ b/runtime/vm/compiler/backend/type_propagator.cc
@@ -40,7 +40,8 @@ } void FlowGraphTypePropagator::Propagate(FlowGraph* flow_graph) { - TIMELINE_DURATION(flow_graph->thread(), Compiler, "FlowGraphTypePropagator"); + TIMELINE_DURATION(flow_graph->thread(), CompilerVerbose, + "FlowGraphTypePropagator"); FlowGraphTypePropagator propagator(flow_graph); propagator.Propagate(); }
diff --git a/runtime/vm/compiler/compiler_pass.cc b/runtime/vm/compiler/compiler_pass.cc index d0f3d32..39cfdec 100644 --- a/runtime/vm/compiler/compiler_pass.cc +++ b/runtime/vm/compiler/compiler_pass.cc
@@ -173,7 +173,7 @@ PrintGraph(state, kTraceBefore, round); { - TIMELINE_DURATION(thread, Compiler, name()); + TIMELINE_DURATION(thread, CompilerVerbose, name()); repeat = DoBody(state); DEBUG_ASSERT(state->flow_graph->VerifyUseLists()); thread->CheckForSafepoint();
diff --git a/runtime/vm/compiler/compiler_pass.h b/runtime/vm/compiler/compiler_pass.h index 8166644..044ae6e 100644 --- a/runtime/vm/compiler/compiler_pass.h +++ b/runtime/vm/compiler/compiler_pass.h
@@ -64,9 +64,6 @@ precompiler(precompiler), inlining_depth(0), sinking(NULL), -#ifndef PRODUCT - compiler_timeline(NULL), -#endif call_specializer(NULL), speculative_policy(speculative_policy), reorder_blocks(false), @@ -80,8 +77,6 @@ int inlining_depth; AllocationSinking* sinking; - NOT_IN_PRODUCT(TimelineStream* compiler_timeline); - // Maps inline_id_to_function[inline_id] -> function. Top scope // function has inline_id 0. The map is populated by the inliner. GrowableArray<const Function*> inline_id_to_function;
diff --git a/runtime/vm/compiler/frontend/bytecode_reader.cc b/runtime/vm/compiler/frontend/bytecode_reader.cc index 271ccdd..6dff9ce 100644 --- a/runtime/vm/compiler/frontend/bytecode_reader.cc +++ b/runtime/vm/compiler/frontend/bytecode_reader.cc
@@ -310,7 +310,7 @@ void BytecodeMetadataHelper::ReadConstantPool(const Function& function, const ObjectPool& pool) { - TIMELINE_DURATION(Thread::Current(), Compiler, + TIMELINE_DURATION(Thread::Current(), CompilerVerbose, "BytecodeMetadataHelper::ReadConstantPool"); // These enums and the code below reading the constant pool from kernel must @@ -639,7 +639,7 @@ } RawBytecode* BytecodeMetadataHelper::ReadBytecode(const ObjectPool& pool) { - TIMELINE_DURATION(Thread::Current(), Compiler, + TIMELINE_DURATION(Thread::Current(), CompilerVerbose, "BytecodeMetadataHelper::ReadBytecode"); intptr_t size = helper_->ReadUInt(); intptr_t offset = Utils::RoundUp(helper_->reader_.offset(), sizeof(KBCInstr)); @@ -658,7 +658,7 @@ void BytecodeMetadataHelper::ReadExceptionsTable(const Bytecode& bytecode, bool has_exceptions_table) { - TIMELINE_DURATION(Thread::Current(), Compiler, + TIMELINE_DURATION(Thread::Current(), CompilerVerbose, "BytecodeMetadataHelper::ReadExceptionsTable"); const intptr_t try_block_count =
diff --git a/runtime/vm/compiler/jit/compiler.cc b/runtime/vm/compiler/jit/compiler.cc index 2fa6596..6a8dbc1 100644 --- a/runtime/vm/compiler/jit/compiler.cc +++ b/runtime/vm/compiler/jit/compiler.cc
@@ -556,8 +556,6 @@ return Code::null(); } Zone* const zone = thread()->zone(); - NOT_IN_PRODUCT(TimelineStream* compiler_timeline = - Timeline::GetCompilerStream()); HANDLESCOPE(thread()); // We may reattempt compilation if the function needs to be assembled using @@ -618,7 +616,7 @@ } } - TIMELINE_DURATION(thread(), Compiler, "BuildFlowGraph"); + TIMELINE_DURATION(thread(), CompilerVerbose, "BuildFlowGraph"); flow_graph = pipeline->BuildFlowGraph( zone, parsed_function(), ic_data_array, osr_id(), optimized()); } @@ -636,18 +634,17 @@ const bool reorder_blocks = FlowGraph::ShouldReorderBlocks(function, optimized()); if (reorder_blocks) { - TIMELINE_DURATION(thread(), Compiler, + TIMELINE_DURATION(thread(), CompilerVerbose, "BlockScheduler::AssignEdgeWeights"); block_scheduler.AssignEdgeWeights(); } CompilerPassState pass_state(thread(), flow_graph, &speculative_policy); - NOT_IN_PRODUCT(pass_state.compiler_timeline = compiler_timeline); pass_state.block_scheduler = &block_scheduler; pass_state.reorder_blocks = reorder_blocks; if (optimized()) { - TIMELINE_DURATION(thread(), Compiler, "OptimizationPasses"); + TIMELINE_DURATION(thread(), CompilerVerbose, "OptimizationPasses"); pass_state.inline_id_to_function.Add(&function); // We do not add the token position now because we don't know the @@ -674,12 +671,12 @@ pass_state.inline_id_to_token_pos, pass_state.caller_inline_id, ic_data_array); { - TIMELINE_DURATION(thread(), Compiler, "CompileGraph"); + TIMELINE_DURATION(thread(), CompilerVerbose, "CompileGraph"); graph_compiler.CompileGraph(); pipeline->FinalizeCompilation(flow_graph); } { - TIMELINE_DURATION(thread(), Compiler, "FinalizeCompilation"); + TIMELINE_DURATION(thread(), CompilerVerbose, "FinalizeCompilation"); if (thread()->IsMutatorThread()) { *result = FinalizeCompilation(&assembler, &graph_compiler, flow_graph);
diff --git a/runtime/vm/dart.cc b/runtime/vm/dart.cc index 96c2426..ad749aa 100644 --- a/runtime/vm/dart.cc +++ b/runtime/vm/dart.cc
@@ -235,7 +235,7 @@ ICData::Init(); if (vm_isolate_snapshot != NULL) { #if defined(SUPPORT_TIMELINE) - TimelineDurationScope tds(Timeline::GetVMStream(), "VMIsolateSnapshot"); + TimelineDurationScope tds(Timeline::GetVMStream(), "ReadVMSnapshot"); #endif ASSERT(snapshot != nullptr); vm_snapshot_kind_ = snapshot->kind(); @@ -599,10 +599,7 @@ ASSERT(I != NULL); StackZone zone(T); HandleScope handle_scope(T); - { - TIMELINE_DURATION(T, Isolate, "ObjectStore::Init"); - ObjectStore::Init(I); - } + ObjectStore::Init(I); Error& error = Error::Handle(T->zone()); error = Object::Init(I, kernel_buffer, kernel_buffer_size); @@ -613,7 +610,7 @@ // Read the snapshot and setup the initial state. #if defined(SUPPORT_TIMELINE) TimelineDurationScope tds(T, Timeline::GetIsolateStream(), - "IsolateSnapshotReader"); + "ReadIsolateSnapshot"); #endif // TODO(turnidge): Remove once length is not part of the snapshot. const Snapshot* snapshot = Snapshot::SetupFromBuffer(snapshot_data);
diff --git a/runtime/vm/heap/marker.cc b/runtime/vm/heap/marker.cc index 23fe586..cda05d6 100644 --- a/runtime/vm/heap/marker.cc +++ b/runtime/vm/heap/marker.cc
@@ -589,16 +589,16 @@ #endif // !PRODUCT } -class MarkTask : public ThreadPool::Task { +class ParallelMarkTask : public ThreadPool::Task { public: - MarkTask(GCMarker* marker, - Isolate* isolate, - MarkingStack* marking_stack, - ThreadBarrier* barrier, - SyncMarkingVisitor* visitor, - intptr_t task_index, - intptr_t num_tasks, - uintptr_t* num_busy) + ParallelMarkTask(GCMarker* marker, + Isolate* isolate, + MarkingStack* marking_stack, + ThreadBarrier* barrier, + SyncMarkingVisitor* visitor, + intptr_t task_index, + intptr_t num_tasks, + uintptr_t* num_busy) : marker_(marker), isolate_(isolate), marking_stack_(marking_stack), @@ -613,7 +613,7 @@ Thread::EnterIsolateAsHelper(isolate_, Thread::kMarkerTask, true); ASSERT(result); { - TIMELINE_FUNCTION_GC_DURATION(Thread::Current(), "MarkTask"); + TIMELINE_FUNCTION_GC_DURATION(Thread::Current(), "ParallelMark"); int64_t start = OS::GetCurrentMonotonicMicros(); // Phase 1: Iterate over roots and drain marking stack in tasks. @@ -705,7 +705,7 @@ const intptr_t num_tasks_; uintptr_t* num_busy_; - DISALLOW_COPY_AND_ASSIGN(MarkTask); + DISALLOW_COPY_AND_ASSIGN(ParallelMarkTask); }; class ConcurrentMarkTask : public ThreadPool::Task { @@ -737,7 +737,7 @@ Thread::EnterIsolateAsHelper(isolate_, Thread::kMarkerTask, true); ASSERT(result); { - TIMELINE_FUNCTION_GC_DURATION(Thread::Current(), "ConcurrentMarkTask"); + TIMELINE_FUNCTION_GC_DURATION(Thread::Current(), "ConcurrentMark"); int64_t start = OS::GetCurrentMonotonicMicros(); marker_->IterateRoots(visitor_, task_index_, num_tasks_); @@ -942,11 +942,9 @@ skipped_code_functions); } - MarkTask* mark_task = - new MarkTask(this, isolate_, &marking_stack_, &barrier, visitor, i, - num_tasks, &num_busy); - ThreadPool* pool = Dart::thread_pool(); - bool result = pool->Run(mark_task); + bool result = Dart::thread_pool()->Run( + new ParallelMarkTask(this, isolate_, &marking_stack_, &barrier, + visitor, i, num_tasks, &num_busy)); ASSERT(result); } bool more_to_mark = false;
diff --git a/runtime/vm/heap/marker.h b/runtime/vm/heap/marker.h index a4424cf..a95db6a 100644 --- a/runtime/vm/heap/marker.h +++ b/runtime/vm/heap/marker.h
@@ -71,7 +71,7 @@ int64_t marked_micros_; friend class ConcurrentMarkTask; - friend class MarkTask; + friend class ParallelMarkTask; DISALLOW_IMPLICIT_CONSTRUCTORS(GCMarker); };
diff --git a/runtime/vm/heap/pages.h b/runtime/vm/heap/pages.h index 7829cc0..3020b92 100644 --- a/runtime/vm/heap/pages.h +++ b/runtime/vm/heap/pages.h
@@ -518,7 +518,7 @@ friend class ExclusiveLargePageIterator; friend class HeapIterationScope; friend class PageSpaceController; - friend class SweeperTask; + friend class ConcurrentSweeperTask; friend class GCCompactor; friend class CompactorTask;
diff --git a/runtime/vm/heap/sweeper.cc b/runtime/vm/heap/sweeper.cc index 7e477d7..7474009 100644 --- a/runtime/vm/heap/sweeper.cc +++ b/runtime/vm/heap/sweeper.cc
@@ -104,13 +104,13 @@ return words_to_end; } -class SweeperTask : public ThreadPool::Task { +class ConcurrentSweeperTask : public ThreadPool::Task { public: - SweeperTask(Isolate* isolate, - PageSpace* old_space, - HeapPage* first, - HeapPage* last, - FreeList* freelist) + ConcurrentSweeperTask(Isolate* isolate, + PageSpace* old_space, + HeapPage* first, + HeapPage* last, + FreeList* freelist) : task_isolate_(isolate), old_space_(old_space), first_(first), @@ -132,7 +132,7 @@ ASSERT(result); { Thread* thread = Thread::Current(); - TIMELINE_FUNCTION_GC_DURATION(thread, "SweeperTask"); + TIMELINE_FUNCTION_GC_DURATION(thread, "ConcurrentSweep"); GCSweeper sweeper; HeapPage* page = first_; @@ -182,10 +182,9 @@ HeapPage* first, HeapPage* last, FreeList* freelist) { - SweeperTask* task = new SweeperTask(isolate, isolate->heap()->old_space(), - first, last, freelist); - ThreadPool* pool = Dart::thread_pool(); - pool->Run(task); + bool result = Dart::thread_pool()->Run(new ConcurrentSweeperTask( + isolate, isolate->heap()->old_space(), first, last, freelist)); + ASSERT(result); } } // namespace dart
diff --git a/runtime/vm/kernel_loader.cc b/runtime/vm/kernel_loader.cc index 05bf407..b94c500 100644 --- a/runtime/vm/kernel_loader.cc +++ b/runtime/vm/kernel_loader.cc
@@ -211,6 +211,7 @@ Object& KernelLoader::LoadEntireProgram(Program* program, bool process_pending_classes) { Thread* thread = Thread::Current(); + TIMELINE_DURATION(thread, Isolate, "LoadKernel"); if (program->is_single_program()) { KernelLoader loader(program); @@ -1337,6 +1338,8 @@ intptr_t class_offset, const ClassIndex& class_index, ClassHelper* class_helper) { + TIMELINE_DURATION(Thread::Current(), Isolate, "FinishClassLoading"); + fields_.Clear(); functions_.Clear(); ActiveClassScope active_class_scope(&active_class_, &klass);
diff --git a/runtime/vm/timeline.cc b/runtime/vm/timeline.cc index e26ff04..c19b685 100644 --- a/runtime/vm/timeline.cc +++ b/runtime/vm/timeline.cc
@@ -47,8 +47,8 @@ timeline_streams, NULL, "Comma separated list of timeline streams to record. " - "Valid values: all, API, Compiler, Dart, Debugger, Embedder, " - "GC, Isolate, and VM."); + "Valid values: all, API, Compiler, CompilerVerbose, Dart, " + "Debugger, Embedder, GC, Isolate, and VM."); DEFINE_FLAG(charp, timeline_recorder, "ring",
diff --git a/runtime/vm/timeline.h b/runtime/vm/timeline.h index 8160c99..7b8baf0 100644 --- a/runtime/vm/timeline.h +++ b/runtime/vm/timeline.h
@@ -34,6 +34,7 @@ #define TIMELINE_STREAM_LIST(V) \ V(API, false) \ V(Compiler, false) \ + V(CompilerVerbose, false) \ V(Dart, false) \ V(Debugger, false) \ V(Embedder, false) \