From 2d3710909017239828c51cd5901c23415b865c49 Mon Sep 17 00:00:00 2001 From: LHesperus <2639350497@qq.com> Date: Sat, 25 Nov 2023 17:05:11 +0800 Subject: [PATCH] Dealing with situations where 'sched' are missing --- extra-tools/da-tool/analysis/config.cpp | 4 +- extra-tools/da-tool/analysis/config.h | 3 +- .../da-tool/analysis/function_stack.cpp | 2 +- extra-tools/da-tool/analysis/time_pair.cpp | 23 +++- .../da-tool/analysis/trace_resolve.cpp | 105 +++++++++++++++++- extra-tools/da-tool/analysis/trace_resolve.h | 28 +++-- extra-tools/da-tool/main.cpp | 8 +- extra-tools/da-tool/script/da-tool.sh | 25 +++-- 8 files changed, 159 insertions(+), 39 deletions(-) diff --git a/extra-tools/da-tool/analysis/config.cpp b/extra-tools/da-tool/analysis/config.cpp index 08420ad..d84cc5b 100644 --- a/extra-tools/da-tool/analysis/config.cpp +++ b/extra-tools/da-tool/analysis/config.cpp @@ -45,7 +45,6 @@ void Config::pathInit() // debug filename[FILE_TYPE_OUTPUT_RUN_LOG] = pathOutputDebug + "/run.log"; - filename[FILE_TYPE_OUTPUT_FUNC_STACK_ALL_INFO] = pathOutput + "/func_stack_all_info"; filename[FILE_TYPE_DEBUG_TIME_PAIE] = pathOutputDebug + "/debug_time_pair"; filename[FILE_TYPE_DEBUG_TRACE] = pathOutputDebug + "/debug_trace"; filename[FILE_TYPE_DEBUG_FUNC_STACK_TRACE] = pathOutputDebug + "/debug_funcstk_trace"; @@ -129,6 +128,7 @@ void Config::functionCfgInit() std::ofstream fileDebug(filename[FILE_TYPE_DEBUG_CONFIG], std::ios::out | std::ios::trunc); if (!fileDebug) { std::cout << "file open failed:" << filename[FILE_TYPE_DEBUG_CONFIG] << std::endl; + file.close(); return; } @@ -157,7 +157,7 @@ void Config::configInit(int argc, char *argv[]) readTraceBegin = std::stoi(optarg); break; case 'l': - readTraceEnd = std::stoi(optarg); + readTraceLen = std::stoi(optarg); break; case 'g': if (std::stoi(optarg) < DEBUG_LEVEL_MAX) { diff --git a/extra-tools/da-tool/analysis/config.h b/extra-tools/da-tool/analysis/config.h index ccce0f2..e1a5d4a 100644 --- a/extra-tools/da-tool/analysis/config.h +++ b/extra-tools/da-tool/analysis/config.h @@ -26,7 +26,6 @@ typedef enum { FILE_TYPE_OUTPUT_DELAY, FILE_TYPE_OUTPUT_RUN_LOG, FILE_TYPE_OUTPUT_FUNC_STACK_DELALY, - FILE_TYPE_OUTPUT_FUNC_STACK_ALL_INFO, FILE_TYPE_OUTPUT_PROCESS_SCHED_INFO, FILE_TYPE_OUTPUT_SUMMARY_SCHED_INFO, @@ -109,7 +108,7 @@ public: // function cfg std::vector(FILE_TYPE_MAX, "")}; int readTraceBegin; - int readTraceEnd; + int readTraceLen; void configInit(int argc, char *argv[]); DEBUG_LEVEL_E getDebugLevel(); }; diff --git a/extra-tools/da-tool/analysis/function_stack.cpp b/extra-tools/da-tool/analysis/function_stack.cpp index fcc2a8d..f1a8312 100644 --- a/extra-tools/da-tool/analysis/function_stack.cpp +++ b/extra-tools/da-tool/analysis/function_stack.cpp @@ -341,7 +341,7 @@ void FunctionStack::processDelayAnalysis() void FunctionStack::stackNodeMapDisplay() { Config &cfg = Config::getInstance(); - std::cout << "Display the function delay of each pid " << std::endl; + std::cout << "[INFO] display the function delay of each pid " << std::endl; for (const auto &processInfo : stackNodeMap) { int pid = processInfo.first; if (cfg.filterCfgMap.size() == 0 || cfg.filterCfgMap.count(pid) != 0) { diff --git a/extra-tools/da-tool/analysis/time_pair.cpp b/extra-tools/da-tool/analysis/time_pair.cpp index 037bce1..2c1f813 100644 --- a/extra-tools/da-tool/analysis/time_pair.cpp +++ b/extra-tools/da-tool/analysis/time_pair.cpp @@ -85,6 +85,7 @@ void TimePair::saveFuncStkDebugToFile(std::ofstream &file, const int &pid, const continue; } file << "pid" << "," << pid << ","; + file << "stk_pid" << "," << stk_pid << ","; file << "timestamp" << "," << timestamp << ","; file << "functionIndex" << "," << functionIndex << ","; file << "isRet" << "," << isRet << ","; @@ -152,6 +153,20 @@ void TimePair::timePairUpdateLoop(const int &pid, const int &functionIndex, cons timePairMap[pid].emplace(functionIndex, infoTmp); } + Config &cfg = Config::getInstance(); + bool isCfgSchedSwitch = cfg.funcCfgMap.count("sched_switch") > 0; + int sched_switch_funcidx = -1; + if (isCfgSchedSwitch) { + sched_switch_funcidx = cfg.funcCfgMap["sched_switch"].functionIndex; + const TraceResolve &trace_resolve_inst = TraceResolve::getInstance(); + const FirstInfo &firstInfo = trace_resolve_inst.getTraceFirstInfo(); + int coreIndex = line_info_tmp.core; + // This process cannot find the starting sched switch on this core, ignore trace after timestamp + if (timestamp <= firstInfo.schedSwitchTime[coreIndex] && functionIndex != sched_switch_funcidx) { + timePairMap[pid][functionIndex].minEndTimeInvalid = timestamp; + } + } + if (isRet) { if (timePairMap[pid][functionIndex].startTime.size() == 0) { // fist is endtime ,startime=endtime timePairMap[pid][functionIndex].startTime.emplace_back(timestamp); @@ -496,14 +511,18 @@ void TimePair::saveDelayInfoToFile() file << "call_times(r<0),ave(r<0),sum(r<0),min(r<0),max(r<0),p50(r<0),p80(r<0),p95(r<0),p99(r<0),"; file << std::endl; for (const auto &processInfo : timePairMap) { + int pid = processInfo.first; + if (pid == 0) { + continue; + } for (const auto &funcInfo : processInfo.second) { - if (cfg.filterCfgMap.size() != 0 && cfg.filterCfgMap.count(processInfo.first) == 0) { + if (cfg.filterCfgMap.size() != 0 && cfg.filterCfgMap.count(pid) == 0) { continue; } if (funcInfo.second.summary.callTimes[DELAY_INFO_ALL] <= 0) { continue; } - file << "," << processInfo.first << ","; + file << "," << pid << ","; file << cfg.IndexToFunction[funcInfo.first] << ","; for (int i = 0; i < DELAY_INFO_MAX; i++) { diff --git a/extra-tools/da-tool/analysis/trace_resolve.cpp b/extra-tools/da-tool/analysis/trace_resolve.cpp index 8424464..38e6d2b 100644 --- a/extra-tools/da-tool/analysis/trace_resolve.cpp +++ b/extra-tools/da-tool/analysis/trace_resolve.cpp @@ -56,6 +56,12 @@ const std::vector &TraceResolve::getTraceLine() const return traceLineVec; } +const FirstInfo &TraceResolve::getTraceFirstInfo() const +{ + return firstInfo; +} + + void SchedSwitchLine::processStateToEnum(std::string state) { if (state == "R") { @@ -68,9 +74,36 @@ void SchedSwitchLine::processStateToEnum(std::string state) } } +int countLines(const std::string& filename) { + std::ifstream file(filename); + if (!file.is_open()) { + std::cout << "file open failed:" << filename << std::endl; + return -1; + } + + int lineCount = 0; + std::string line; + while (std::getline(file, line)) { + lineCount++; + } + + file.close(); + return lineCount; +} + void TraceResolve::resolveTrace() { Config &cfg = Config::getInstance(); + int readTraceLen = 0; + if (cfg.readTraceLen == 0) { + readTraceLen = countLines(cfg.filename[FILE_TYPE_TRACE]); + if (readTraceLen <= 0) { + return; + } + } else { + readTraceLen = cfg.readTraceLen; + } + std::ifstream file(cfg.filename[FILE_TYPE_TRACE]); if (!file) { std::cout << "file open failed:" << cfg.filename[FILE_TYPE_TRACE] << std::endl; @@ -83,7 +116,6 @@ void TraceResolve::resolveTrace() file.close(); return; } - int line_num = 0; int regex_num = 0; bool isFirstMatch = true; @@ -94,13 +126,15 @@ void TraceResolve::resolveTrace() std::regex patternSchedSwitch(R"(\s+(.+)-(\d+)\s+\[(\d+)\]\s+(.)(.)(.)(.)\s+(\d+)\.(\d+):\s+(sched_switch):\s+prev_comm=.+prev_pid=(\d+)\s+prev_prio=(\d+)\s+prev_state=(\S+)\s+==>\s+next_comm=.+next_pid=(\d+)\s+next_prio=(\d+))"); while (getline(file, line)) { line_num++; - if (line_num % 10000 == 0) { - std::cout << regex_num << "/" << line_num << " (matched/lines)" << std::endl; - } if (line_num < cfg.readTraceBegin) { continue; } - if (cfg.readTraceEnd != 0 && line_num > cfg.readTraceBegin + cfg.readTraceEnd) { + if (line_num % 10000 == 0) { + double rate = (line_num - cfg.readTraceBegin) * 1.0/ readTraceLen; + std::cout << "[Resolve] " << std::fixed << std::setprecision(3) << rate * 100 << "%, "; + std::cout << "Match " << regex_num << std::endl; + } + if (cfg.readTraceLen != 0 && line_num > cfg.readTraceBegin + cfg.readTraceLen) { break; } @@ -143,6 +177,9 @@ void TraceResolve::resolveTrace() if (isMatch) { if (isFirstMatch) { startTimeIntPart = std::stoi(match[TRACE_INFO_TIMESTAMP_INT].str()); + firstInfo.coreId = std::stoi(match[TRACE_INFO_CPU].str()); + firstInfo.startTime = (std::stoi(match[TRACE_INFO_TIMESTAMP_INT].str()) - startTimeIntPart) * MICRO_PER_SEC \ + + std::stoi(match[TRACE_INFO_TIMESTAMP_FLOAT].str()); isFirstMatch = false; } match_info.timestamp = (std::stoi(match[TRACE_INFO_TIMESTAMP_INT].str()) - startTimeIntPart) * MICRO_PER_SEC \ @@ -165,7 +202,7 @@ void TraceResolve::resolveTrace() } if (traceLineVec.size() > 0) { - std::cout << "trace delay :" << traceLineVec[traceLineVec.size() - 1].timestamp - traceLineVec[0].timestamp << std::endl; + std::cout << "[INFO] trace delay : " << traceLineVec[traceLineVec.size() - 1].timestamp - traceLineVec[0].timestamp << std::endl; } file.close(); @@ -206,8 +243,64 @@ double TraceResolve::convertTimeIntToDouble(const int ×tamp) return timestamp * 1.0 / MICRO_PER_SEC + startTimeIntPart; } +void TraceResolve::firstSchedSwitchTimeAnalysis() +{ + Config &cfg = Config::getInstance(); + bool isCfgSchedSwitch = cfg.funcCfgMap.count("sched_switch") > 0; + int sched_switch_funcidx = -1; + if (isCfgSchedSwitch) { + sched_switch_funcidx = cfg.funcCfgMap["sched_switch"].functionIndex; + } else { + return; + } + + firstInfo.schedSwitchTime.resize(CPU_CORE_NUM_MAX, INT_MAX); + firstInfo.coreTime.resize(CPU_CORE_NUM_MAX, INT_MAX); + firstInfo.schedSwitchTime[firstInfo.coreId] = firstInfo.startTime; + firstInfo.coreTime[firstInfo.coreId] = firstInfo.startTime; + + for (const auto &line_info_tmp : traceLineVec) { + std::string functionName = line_info_tmp.functionName; + int pid = line_info_tmp.pid; + if (cfg.funcCfgMap.count(functionName) == 0) { + continue; + } + + int timestamp = line_info_tmp.timestamp; + int coreIndex = line_info_tmp.core; + int functionIndex = cfg.funcCfgMap[functionName].functionIndex; + // first appearance of coreIndex in trace + if (firstInfo.coreTime[coreIndex] == INT_MAX) { + firstInfo.coreTime[coreIndex] = timestamp; + } + // first appearance of sched_switch in coreIndex's trace + if (functionIndex == sched_switch_funcidx && firstInfo.schedSwitchTime[coreIndex] == INT_MAX) { + firstInfo.schedSwitchTime[coreIndex] = timestamp; + } + } +} + void TraceResolve::trace_resolve_proc() { resolveTrace(); saveTraceRegexRstToFile(); + + firstSchedSwitchTimeAnalysis(); +} + +void TraceResolve::trace_check_show() +{ + Config &cfg = Config::getInstance(); + for (int coreId = 0; coreId < CPU_CORE_NUM_MAX; coreId++) { + int firstSchedSwitchTime = firstInfo.schedSwitchTime[coreId]; + int firstCoreTime = firstInfo.coreTime[coreId]; + if (cfg.getDebugLevel() >= DEBUG_LEVEL_1) { + std::cout << "coreId:" << coreId; + std::cout << ",firstSchedSwitchTime:" << firstSchedSwitchTime; + std::cout << ",firstCoreTime:" << firstCoreTime << std::endl; + } + if (firstSchedSwitchTime != firstCoreTime) { + std::cout << "[ERROR] core " << coreId << " missing starting scheduling information, result maybe error!!!" << std::endl; + } + } } \ No newline at end of file diff --git a/extra-tools/da-tool/analysis/trace_resolve.h b/extra-tools/da-tool/analysis/trace_resolve.h index df330d5..e943d20 100644 --- a/extra-tools/da-tool/analysis/trace_resolve.h +++ b/extra-tools/da-tool/analysis/trace_resolve.h @@ -23,18 +23,8 @@ // include\linux\sched.h typedef enum { - PROCESS_STATE_TASK_RUNNING, // R - PROCESS_STATE_TASK_INTERRUPTIBLE, // S -// PROCESS_STATE_TASK_UNINTERRUPTIBL, // D -// PROCESS_STATE_TASK_STOPPED, // T -// PROCESS_STATE_TASK_TRACED, //t -// -// PROCESS_STATE_EXIT_DEAD, // X -// PROCESS_STATE_EXIT_ZOMBIE, // Z -// PROCESS_STATE_EXIT_TRACE, -// -// PROCESS_STATE_TASK_PARKED, // P -// PROCESS_STATE_TASK_DEAD, // I + PROCESS_STATE_TASK_RUNNING, // R + PROCESS_STATE_TASK_INTERRUPTIBLE, // S PROCESS_STATE_MAX, } PROCESS_STATE_E; @@ -64,6 +54,14 @@ public: int functionIndex; }; +class FirstInfo { +public: + std::vector schedSwitchTime; // [coreId] + std::vector coreTime; // [coreId] + int coreId; // first core in trace + int startTime; +}; + class TraceResolve { public: static TraceResolve &getInstance() { @@ -81,10 +79,16 @@ private: // regex void resolveTrace(); void saveTraceRegexRstToFile(); +private: + FirstInfo firstInfo; + void firstSchedSwitchTimeAnalysis(); + public: const std::vector &getTraceLine() const; + const FirstInfo &getTraceFirstInfo() const; double convertTimeIntToDouble(const int ×tamp); void trace_resolve_proc(); + void trace_check_show(); }; #endif \ No newline at end of file diff --git a/extra-tools/da-tool/main.cpp b/extra-tools/da-tool/main.cpp index b6ec46d..34652f0 100644 --- a/extra-tools/da-tool/main.cpp +++ b/extra-tools/da-tool/main.cpp @@ -21,10 +21,10 @@ using namespace std; int main(int argc, char *argv[]) { - cout << "analysis start..." << endl; + cout << "[STEP 2] analysis start..." << endl; Config &cfg = Config::getInstance(); cfg.configInit(argc, argv); - cout << "analysis resolve..." << endl; + cout << "[STEP 2-1] resolve trace..." << endl; TraceResolve &trace_resolve_inst = TraceResolve::getInstance(); trace_resolve_inst.trace_resolve_proc(); @@ -36,6 +36,8 @@ int main(int argc, char *argv[]) FunctionStack &fstk = FunctionStack::getInstance(); fstk.function_stack_proc(); - cout << "analysis finish" << endl; + + trace_resolve_inst.trace_check_show(); + cout << "[STEP 2-2] analysis finish" << endl; return 0; } \ No newline at end of file diff --git a/extra-tools/da-tool/script/da-tool.sh b/extra-tools/da-tool/script/da-tool.sh index a25c347..14fd009 100755 --- a/extra-tools/da-tool/script/da-tool.sh +++ b/extra-tools/da-tool/script/da-tool.sh @@ -316,7 +316,7 @@ function opt_check() { } function clear_env() { - echo "clear env..." + echo "[INFO] clear env..." echo 0 >/sys/kernel/debug/tracing/tracing_on events_folder="/sys/kernel/debug/tracing/events/" @@ -361,7 +361,7 @@ function clear_env() { echo 0 >"$event_file" fi done - echo "clear env finish" + echo "[INFO] clear env finish" } function sample_init() { @@ -528,10 +528,12 @@ function trace_analysis() { } ###################### main proc #################################### +echo "[STEP 1] da-tool start" +echo "[STEP 1-1] resolve config" config_file_resolve - +echo "[STEP 1-2] environment initialization" if [ $is_clear = true ]; then - echo "clear" + echo "[INFO] clear" clear_env exit 1 fi @@ -555,28 +557,29 @@ uprobe_event_enable $is_uprobe_sample kprobe_event_enable $is_kprobe_sample sched_event_enable $is_kprobe_sample -# sampling +echo "[STEP 1-3] start tracing..." +# tracing trace_record_begin for ((i = 1; i <= ${sleep_time}; i++)); do - # trace_line_num=$(wc -l < /sys/kernel/debug/tracing/trace) # wrong - echo "sampling " $i/${sleep_time} #", trace line" $trace_line_num + echo "[INFO] tracing " $i/${sleep_time} sleep 1 done -#trace_line_num=$(wc -l < /sys/kernel/debug/tracing/trace) # slow -#echo "trace line" $trace_line_num trace_record_end +echo "[STEP 1-4] environment reset..." clear_env gen_config_for_analysis + +echo "[STEP 1-5] save trace..." storage_data echo "" >/sys/kernel/debug/tracing/trace # only enable = 0 , clear event echo >/sys/kernel/debug/tracing/uprobe_events echo >/sys/kernel/debug/tracing/kprobe_events -echo "sample finish" - +echo "[STEP 1-6] finish tracing ..." if [ $is_sample_with_analysis = true ]; then trace_analysis fi +echo "[EXIT] da-tool exit..." -- 2.33.0