From 9521f8ac02ec63e6ae06f0456f2afb2edad5d867 Mon Sep 17 00:00:00 2001 From: Sergey Yagovtsev Date: Mon, 5 Sep 2016 22:11:03 +0300 Subject: [PATCH] Store context switch timestamp on linux. It's need to run systemtap util for loading kernel module. This kernel module capture context switch timestamp and systemtap store it in the temp file. Before running profiling application you should run systemtap script with root privileges as following: \# stap -o /tmp/cs_profiling_info.log scripts/context_switch_logger.stp name APPLICATION_NAME where APPLICATION_NAME is profiling application --- include/profiler/profiler.h | 12 +++++---- scripts/context_switch_logger.stp | 36 +++++++++++++++++++++++++++ src/profile_manager.cpp | 41 +++++++++++++++++++++++++++++++ src/profile_manager.h | 13 ++++++++++ 4 files changed, 97 insertions(+), 5 deletions(-) create mode 100644 scripts/context_switch_logger.stp diff --git a/include/profiler/profiler.h b/include/profiler/profiler.h index d3a6eab..cd1e5d0 100644 --- a/include/profiler/profiler.h +++ b/include/profiler/profiler.h @@ -214,11 +214,13 @@ namespace profiler { class StaticBlockDescriptor; extern "C"{ - void PROFILER_API beginBlock(Block& _block); - void PROFILER_API endBlock(); - void PROFILER_API setEnabled(bool isEnable); - uint32_t PROFILER_API dumpBlocksToFile(const char* filename); - void PROFILER_API setThreadName(const char* name, const char* filename, const char* _funcname, int line); + void PROFILER_API beginBlock(Block& _block); + void PROFILER_API endBlock(); + void PROFILER_API setEnabled(bool isEnable); + uint32_t PROFILER_API dumpBlocksToFile(const char* filename); + void PROFILER_API setThreadName(const char* name, const char* filename, const char* _funcname, int line); + void PROFILER_API setContextSwitchLogFilename(const char* name); + const char* PROFILER_API getContextSwitchLogFilename(); } typedef uint64_t timestamp_t; diff --git a/scripts/context_switch_logger.stp b/scripts/context_switch_logger.stp new file mode 100644 index 0000000..b9f8c7a --- /dev/null +++ b/scripts/context_switch_logger.stp @@ -0,0 +1,36 @@ +global target_pid +global target_name + +probe scheduler.ctxswitch { + + if (target_pid != 0 + && next_pid != target_pid + && prev_pid != target_pid) + next + + if (target_name != "" + && prev_task_name != target_name + && next_task_name != target_name) + next + + //printf("Switch from %d(%s) to %d(%s) at %d\n",prev_tid, prev_task_name,next_tid,next_task_name, gettimeofday_ns()) + printf("%d %d %d\n",gettimeofday_ns(),prev_tid, next_tid ) +} + +probe begin +{ + target_pid = 0 + target_name = "" + + %( $# == 1 || $# > 2 %? + log("Wrong number of arguments, use none, 'pid nr' or 'name proc'") + exit() + %) + + %( $# == 2 %? + if(@1 == "pid") + target_pid = strtol(@2, 10) + if(@1 == "name") + target_name = @2 + %) +} diff --git a/src/profile_manager.cpp b/src/profile_manager.cpp index bc4bd9e..c95536c 100644 --- a/src/profile_manager.cpp +++ b/src/profile_manager.cpp @@ -26,10 +26,12 @@ extern "C"{ void PROFILER_API setEnabled(bool isEnable) { MANAGER.setEnabled(isEnable); +#ifdef _WIN32 if (isEnable) EasyEventTracer::instance().enable(true); else EasyEventTracer::instance().disable(); +#endif } void PROFILER_API beginBlock(Block& _block) @@ -47,6 +49,16 @@ extern "C"{ return MANAGER.setThreadName(name, filename, _funcname, line); } + void PROFILER_API setContextSwitchLogFilename(const char* name) + { + return MANAGER.setContextSwitchLogFilename(name); + } + + const char* PROFILER_API getContextSwitchLogFilename() + { + return MANAGER.getContextSwitchLogFilename(); + } + } SerializedBlock::SerializedBlock(const Block& block, uint16_t name_length) @@ -165,6 +177,16 @@ void ProfileManager::_cswitchBeginBlock(profiler::timestamp_t _time, profiler::b thread_storage->sync.openedList.emplace(_time, profiler::BLOCK_TYPE_CONTEXT_SWITCH, _id, ""); } +void ProfileManager::_cswitchStoreBlock(profiler::timestamp_t _time, profiler::block_id_t _id, profiler::thread_id_t _thread_id) +{ + auto thread_storage = _threadStorage(_thread_id); + if (thread_storage != nullptr){ + profiler::Block lastBlock(_time, profiler::BLOCK_TYPE_CONTEXT_SWITCH, _id, ""); + lastBlock.finish(_time); + thread_storage->storeCSwitch(lastBlock); + } +} + void ProfileManager::endBlock() { if (!m_isEnabled) @@ -236,6 +258,25 @@ uint32_t ProfileManager::dumpBlocksToFile(const char* filename) if (wasEnabled) ::profiler::setEnabled(false); +#ifndef _WIN32 + uint64_t timestamp; + uint32_t thread_from, thread_to; + + std::ifstream infile(m_csInfoFilename.c_str()); + + if(infile.is_open()) + { + while (infile >> timestamp >> thread_from >> thread_to ) + { + static const ::profiler::StaticBlockDescriptor desc("OS.ContextSwitch", __FILE__, __LINE__, ::profiler::BLOCK_TYPE_CONTEXT_SWITCH, ::profiler::colors::White); + _cswitchBeginBlock(timestamp, desc.id(), thread_from); + _cswitchEndBlock(thread_to, timestamp); + } + } + +#endif + + FileWriter of(filename); uint64_t usedMemorySize = 0; diff --git a/src/profile_manager.h b/src/profile_manager.h index 38c1c04..6151691 100644 --- a/src/profile_manager.h +++ b/src/profile_manager.h @@ -150,6 +150,8 @@ class ProfileManager final profiler::spin_lock m_storedSpin; bool m_isEnabled = false; + std::string m_csInfoFilename = "/tmp/cs_profiling_info.log"; + public: static ProfileManager& instance(); @@ -161,7 +163,18 @@ public: uint32_t dumpBlocksToFile(const char* filename); void setThreadName(const char* name, const char* filename, const char* _funcname, int line); + void setContextSwitchLogFilename(const char* name) + { + m_csInfoFilename = name; + } + + const char* getContextSwitchLogFilename() const + { + return m_csInfoFilename.c_str(); + } + void _cswitchBeginBlock(profiler::timestamp_t _time, profiler::block_id_t _id, profiler::thread_id_t _thread_id); + void _cswitchStoreBlock(profiler::timestamp_t _time, profiler::block_id_t _id, profiler::thread_id_t _thread_id); void _cswitchEndBlock(profiler::thread_id_t _thread_id, profiler::timestamp_t _endtime); private: