From e513e20d841277f40e4d903c65dc84c413a824dd Mon Sep 17 00:00:00 2001 From: mmorozov Date: Wed, 7 Jun 2023 16:28:54 +0300 Subject: [PATCH] Profiler: Add info about sent signals and created samples Change-Id: I4edb039cffb93a17d4e509b3dde2c52437ebf22d Signed-off-by: mmorozov --- runtime/options.yaml | 9 +++- runtime/tooling/sampler/sampling_profiler.cpp | 51 ++++++++++++++++++- runtime/tooling/sampler/sampling_profiler.h | 28 ++++++++++ runtime/tooling/thread_sampling_info.h | 11 ++++ tools/sampler/README.md | 30 +++++++++-- tools/sampler/options.yaml | 14 ++--- tools/sampler/trace_dumper.h | 15 +++++- 7 files changed, 143 insertions(+), 15 deletions(-) diff --git a/runtime/options.yaml b/runtime/options.yaml index 34c531c3e..43c8d9864 100644 --- a/runtime/options.yaml +++ b/runtime/options.yaml @@ -125,7 +125,7 @@ options: - name: sampling-profiler-interval type: uint32_t - default: 500 + default: 997 description: Sampling profiler interval in microseconds - name: sampling-profiler-output-file @@ -133,6 +133,11 @@ options: default: "" description: Name of file to collect trace in .aspt format +- name: sampling-profiler-collect-stats + type: bool + default: false + description: Enables collecting stats about sent signals and collected samples + - name: debugger-port type: uint32_t default: 19015 @@ -847,4 +852,4 @@ options: - name: coroutines-stack-mem-limit type: uint64_t default: 134217728 - description: defines the total amount of memory that can be used for stackful coroutine stacks allocation (in bytes) \ No newline at end of file + description: defines the total amount of memory that can be used for stackful coroutine stacks allocation (in bytes) diff --git a/runtime/tooling/sampler/sampling_profiler.cpp b/runtime/tooling/sampler/sampling_profiler.cpp index d188639c5..7a8f2c93e 100644 --- a/runtime/tooling/sampler/sampling_profiler.cpp +++ b/runtime/tooling/sampler/sampling_profiler.cpp @@ -97,6 +97,10 @@ void Sampler::Destroy(Sampler *sampler) ASSERT(instance_->agent_tid_ == os::thread::GetNativeHandle()); ASSERT(!sampler->is_active_); + if (Runtime::GetOptions().IsSamplingProfilerCollectStats()) { + sampler->WriteSamplerInfo(); + } + LOG(INFO, PROFILER) << "Total samples: " << S_TOTAL_SAMPLES << "\nLost samples: " << S_LOST_SAMPLES; LOG(INFO, PROFILER) << "Lost samples(Invalid method ptr): " << S_LOST_INVALID_SAMPLES << "\nLost samples(Invalid pf ptr): " << S_LOST_NOT_FIND_SAMPLES; @@ -117,12 +121,17 @@ Sampler::Sampler() : runtime_(Runtime::GetCurrent()), sample_interval_(DEFAULT_S void Sampler::AddThreadHandle(ManagedThread *thread) { os::memory::LockHolder holder(managed_threads_lock_); + signal_counter_[thread->GetId()] = 0; + sample_counter_[thread->GetId()] = 0; + discard_counter_start_[thread->GetId()] = 0; managed_threads_.insert(thread->GetId()); } void Sampler::EraseThreadHandle(ManagedThread *thread) { os::memory::LockHolder holder(managed_threads_lock_); + sample_counter_[thread->GetId()] = /*value from thread*/; + discard_counter_start_[thread->GetId()] = /*value from thread*/; managed_threads_.erase(thread->GetId()); } @@ -272,18 +281,22 @@ void SigProfSamplingProfilerHandler([[maybe_unused]] int signum, [[maybe_unused] [[maybe_unused]] void *ptr) { if (S_CURRENT_HANDLERS_COUNTER == 0) { + std::map &discard_counter_start = Sampler::GetDiscardCounterStartStatic(); + ++discard_counter_start.at(os::thread::GetCurrentThreadId()); // Sampling ended if S_CURRENT_HANDLERS_COUNTER is 0. Thread started executing handler for signal // that was sent before end, so thread is late now and we should return from handler return; } - auto scoped_handlers_counting = ScopedHandlersCounting(); + auto scoped_handlers_counting = ScopedHandlersCounting(); ManagedThread *mthread = ManagedThread::GetCurrent(); ASSERT(mthread != nullptr); // Checking that code is being executed auto frame_ptr = reinterpret_cast(mthread->GetCurrentFrame()); if (frame_ptr == nullptr) { + std::map &discard_counter_start = Sampler::GetDiscardCounterStartStatic(); + discard_counter_start.at(os::thread::GetCurrentThreadId())++; return; } @@ -298,6 +311,8 @@ void SigProfSamplingProfilerHandler([[maybe_unused]] int signum, [[maybe_unused] Method *top_method = frame->GetMethod(); + std::map &sample_counter = Sampler::GetSampleCounterStatic(); + sample_counter.at(os::thread::GetCurrentThreadId())++; S_TOTAL_SAMPLES++; const LockFreeQueue &pfs_queue = Sampler::GetSampleQueuePF(); @@ -461,6 +476,7 @@ void Sampler::SamplerThreadEntry() if (syscall(SYS_tgkill, pid, thread_id, SIGPROF) != 0) { LOG(ERROR, PROFILER) << "Can't send signal to thread"; } + signal_counter_[thread_id]++; } } os::thread::NativeSleepUS(sample_interval_); @@ -506,4 +522,37 @@ void Sampler::ListenerThreadEntry(std::string output_file) } } +void Sampler::WriteSamplerInfo() +{ + auto t = std::time(nullptr); + auto tm = *std::localtime(&t); + std::stringstream unique_stats_sstream; + unique_stats_sstream << std::put_time(&tm, "%H-%M-%S"); + std::string unique_stats_string = unique_stats_sstream.str() + "_sampler_stats.csv"; + + std::ofstream stats(unique_stats_string); + std::string tid = " Thread_id"; + std::string sig_send = "Signals sent"; + std::string samples_created = "Samples created"; + std::string lost_thread_concurrency = "LOST(Posix thread suspended)"; + std::string lost_timer = "LOST(Small sampling timer)"; + std::string lost_other = "LOST(other reasons)"; + stats << tid << ", " << sig_send << ", " << samples_created << ", " << lost_thread_concurrency << ", " << lost_other + << std::endl; + ASSERT(sample_counter_.size() == signal_counter_.size()); + ASSERT(sample_counter_.size() == discard_counter_start_.size()); + + for (auto it_1 = signal_counter_.begin(), end_1 = signal_counter_.end(), it_2 = sample_counter_.begin(), + it_3 = discard_counter_start_.begin(); + it_1 != end_1; ++it_1, ++it_2, ++it_3) { + ASSERT(it_1->first == it_2->first); + ASSERT(it_1->first == it_3->first); + stats << std::setw(tid.size()) << it_1->first << ", "; + stats << std::setw(sig_send.size()) << it_1->second << ", "; + stats << std::setw(samples_created.size()) << it_2->second << ", "; + stats << std::setw(lost_thread_concurrency.size()) << it_1->second - it_2->second - it_3->second << ", "; + stats << std::setw(lost_other.size()) << it_3->second << std::endl; + } +} + } // namespace panda::tooling::sampler diff --git a/runtime/tooling/sampler/sampling_profiler.h b/runtime/tooling/sampler/sampling_profiler.h index af7e3a4cf..2e24b153c 100644 --- a/runtime/tooling/sampler/sampling_profiler.h +++ b/runtime/tooling/sampler/sampling_profiler.h @@ -66,6 +66,28 @@ public: return loaded_pfs_queue_; } + static std::map &GetSampleCounterStatic() + { + ASSERT(instance_ != nullptr); + return instance_->GetSampleCounter(); + } + + std::map &GetSampleCounter() + { + return sample_counter_; + } + + static std::map &GetDiscardCounterStartStatic() + { + ASSERT(instance_ != nullptr); + return instance_->GetDiscardCounterStart(); + } + + std::map &GetDiscardCounterStart() + { + return discard_counter_start_; + } + void SetSampleInterval(uint32_t us) { ASSERT(is_active_ == false); @@ -106,6 +128,8 @@ private: void WritePandaFiles(const StreamWriter *writer_ptr); void WriteLoadedPandaFiles(const StreamWriter *writer_ptr); + void WriteSamplerInfo(); + static Sampler *instance_; Runtime *runtime_ {nullptr}; @@ -130,6 +154,10 @@ private: std::chrono::microseconds sample_interval_; + std::map signal_counter_; + std::map sample_counter_; + std::map discard_counter_start_; + friend class test::SamplerTest; NO_COPY_SEMANTIC(Sampler); diff --git a/runtime/tooling/thread_sampling_info.h b/runtime/tooling/thread_sampling_info.h index 3a31c79f0..3160a9071 100644 --- a/runtime/tooling/thread_sampling_info.h +++ b/runtime/tooling/thread_sampling_info.h @@ -44,12 +44,23 @@ public: return sigsegv_jmp_env_; } + uint64_t GetSampleCounter() { + return sample_counter_; + } + + uint64_t GetDiscardCounterStart() { + return discard_counter_start_; + } + private: bool is_thread_sampling_ {false}; // Environment that saved by setjmp in SIGPROF handler in Sampler // Used for longjmp in case of SIGSEGV during thread sampling jmp_buf sigsegv_jmp_env_ {}; + + uint64_t sample_counter_ = 0; + uint64_t discard_counter_start_ = 0; }; } // namespace panda::tooling::sampler diff --git a/tools/sampler/README.md b/tools/sampler/README.md index 450358270..cf1385de0 100644 --- a/tools/sampler/README.md +++ b/tools/sampler/README.md @@ -11,7 +11,7 @@ git clone https://github.com/brendangregg/FlameGraph.git ```bash # get abc bin -${BUILD_DIR}/bin/es2panda ${BUILD_SOURCE}/plugins/ets/tests/runtime/tooling.sampler/SamplerTest.ets ${BUILD_DIR}/sampling_app.abc +${BUILD_DIR}/bin/es2panda ${BUILD_SOURCE}/plugins/ets/tests/runtime/tooling/sampler/SamplerTest.ets ${BUILD_DIR}/sampling_app.abc # get sample dump ${BUILD_DIR}/bin/ark --load-runtimes=ets --boot-panda-files=${BUILD_DIR}/plugins/ets/etsstdlib.abc --sampling-profiler-enable --sampling-profiler-interval=200 --sampling-profiler-output-file=${BUILD_DIR}/outfile.aspt ${BUILD_DIR}/sampling_app.abc ETSGLOBAL::main @@ -23,13 +23,35 @@ ${BUILD_DIR}/bin/aspt_converter --input=${BUILD_DIR}/outfile.aspt --output=${BUI ${BUILD_DIR}/FlameGraph/flamegraph.pl ${BUILD_DIR}/traceout.csv > ${BUILD_DIR}/out.svg ``` -In current implementation of aspt_converter two vizual modes are supported: +If option `--sampling-profiler-collect-stats` passed on ark launch it creates file at the end of vm's life with information about quantity of sent signal to every thread and created samples. + Signals can be ignored if threads are suspended to wait for cpu time(99.9% of ignored signals), or mutator threads are not executing bytecode (not started or finished) + + +In current implementation of aspt_converter theese vizual modes are supported: ```bash +# convert sample dump to single csv without separating samples by threads +--csv-tid-separation=single-csv-single-tid + # convert sample dump to single csv with separating samples by threads -${BUILD_DIR}/bin/aspt_converter --input=${BUILD_DIR}/outfile.aspt --output=${BUILD_DIR}/traceout.csv --thread-separation-by-tid +--csv-tid-separation=thread-separation-by-tid #DEFAULT OPTION # convert sample dump many csv files with one thread per file. Name of ouput file will concatinate with thread_id -${BUILD_DIR}/bin/aspt_converter --input=${BUILD_DIR}/outfile.aspt --output=${BUILD_DIR}/traceout.csv --thread-separation-by-csv +--csv-tid-separation=multi-csv + +# To collect information about thread status running or suspended use next option +--cold-graph-enable=true # false by default + +# To enable directory substitution in collected panda files this option is used +--substitude-module-dir + +# Pass directories to substitude +--substitude-source-str=${dir1},${dir2} + +# Pass directories that will be place instead +--substitude-destination-str=${dir_target1},${dir_target2} + +# Number of strings should be equal and i-th string from source changes only to i-th from destination + ``` ## Limitations diff --git a/tools/sampler/options.yaml b/tools/sampler/options.yaml index 16af2c607..de6dce47f 100644 --- a/tools/sampler/options.yaml +++ b/tools/sampler/options.yaml @@ -40,19 +40,19 @@ options: default: false description: Builds cold flame graph -- name: substitude-module-dir +- name: substitute-module-dir type: bool default: false description: Enable substitution of panda files directories e.g. run converter on host for .aspt got from device -- name: substitude-source-str +- name: substitute-source-str type: arg_list_t default: [] - description: Substring that will be replaced with substitude-destination - delimiter: ':' + description: Substrings that will be replaced with substitute-destination + delimiter: ',' -- name: substitude-destination-str +- name: substitute-destination-str type: arg_list_t default: [] - description: Substring that will be places instead of substitude-source - delimiter: ':' + description: Substrings that will be places instead of substitute-source + delimiter: ',' diff --git a/tools/sampler/trace_dumper.h b/tools/sampler/trace_dumper.h index 82a60095c..3607c4fdb 100644 --- a/tools/sampler/trace_dumper.h +++ b/tools/sampler/trace_dumper.h @@ -111,7 +111,20 @@ public: stream_ << "thread_id = " << sample.thread_info.thread_id << "; "; } if (build_cold_graph_) { - stream_ << "status = " << static_cast(sample.thread_info.thread_status) << "; "; + stream_ << "status = "; + switch (sample.thread_info.thread_status) { + case SampleInfo::ThreadStatus::RUNNING: { + stream_ << "active; "; + break; + } + case SampleInfo::ThreadStatus::SUSPENDED: { + stream_ << "suspended; "; + break; + } + default: { + UNREACHABLE(); + } + } } return stream_; } -- Gitee