diff --git a/include/pocketpy/profiler.h b/include/pocketpy/profiler.h index 20971ef4..e414924d 100644 --- a/include/pocketpy/profiler.h +++ b/include/pocketpy/profiler.h @@ -1,9 +1,38 @@ #pragma once +#include "frame.h" + namespace pkpy { -struct LineProfiler{ +struct LineRecord{ + int line; + SourceData* src; + i64 hits; + clock_t time; + + clock_t time_per_hit() const { + return time / hits; + } + + LineRecord(int line, SourceData* src): line(line), src(src), hits(0), time(0) {} + + std::string_view line_content() const; +}; + +struct LineProfiler{ + clock_t prev_time; + LineRecord* prev_record; + int prev_line; + + // filename -> records + std::map> records; + + void begin(); + void _step(Frame* frame); + void _step_end(); + void end(); + Str stats(); }; } // namespace pkpy diff --git a/src/ceval.cpp b/src/ceval.cpp index bc8d6f95..973bccaf 100644 --- a/src/ceval.cpp +++ b/src/ceval.cpp @@ -67,7 +67,8 @@ PyObject* VM::_run_top_frame(){ { #define CEVAL_STEP_CALLBACK() \ - if(_ceval_on_step) _ceval_on_step(this, frame.get(), byte); + if(_ceval_on_step) _ceval_on_step(this, frame.get(), byte); \ + if(_profiler) _profiler->_step(frame.get()); #define DISPATCH_OP_CALL() { frame = top_frame(); goto __NEXT_FRAME; } __NEXT_FRAME: diff --git a/src/modules.cpp b/src/modules.cpp index 7e04b472..8180bab9 100644 --- a/src/modules.cpp +++ b/src/modules.cpp @@ -254,10 +254,12 @@ struct LineProfilerW{ vm->ValueError("only one profiler can be enabled at a time"); } vm->_profiler = &profiler; + profiler.begin(); } void disable_by_count(VM* vm){ vm->_profiler = nullptr; + profiler.end(); } static void _register(VM* vm, PyObject* mod, PyObject* type){ @@ -273,15 +275,17 @@ struct LineProfilerW{ self.enable_by_count(vm); PyObject* func = view[1]; const Tuple& args = CAST(Tuple&, view[2]); - for(PyObject* arg : args) vm->s_data.push(arg); vm->s_data.push(func); + vm->s_data.push(PY_NULL); + for(PyObject* arg : args) vm->s_data.push(arg); PyObject* ret = vm->vectorcall(args.size()); self.disable_by_count(vm); return ret; }); vm->bind(type, "print_stats(self)", [](VM* vm, ArgsView args){ - // ... + LineProfilerW& self = PK_OBJ_GET(LineProfilerW, args[0]); + vm->stdout_write(self.profiler.stats()); return vm->None; }); } diff --git a/src/profiler.cpp b/src/profiler.cpp index 690fd01b..34238554 100644 --- a/src/profiler.cpp +++ b/src/profiler.cpp @@ -2,6 +2,84 @@ namespace pkpy{ +static std::string left_pad(std::string s, int width){ + int n = width - s.size(); + if(n <= 0) return s; + return std::string(n, ' ') + s; +} +static std::string to_string_1f(double x){ + char buf[32]; + snprintf(buf, 32, "%.1f", x); + return buf; +} + +std::string_view LineRecord::line_content() const { + auto [_0, _1] = src->_get_line(line); + return std::string_view(_0, _1-_0); +} + +void LineProfiler::begin(){ + prev_time = 0; + prev_record = nullptr; + prev_line = -1; + records.clear(); +} + +void LineProfiler::_step(Frame *frame){ + std::string_view filename = frame->co->src->filename.sv(); + int line = frame->co->lines[frame->_ip]; + // std::string_view function = frame->co->name.sv(); + + if(prev_record == nullptr){ + prev_time = clock(); + }else{ + _step_end(); + } + + std::map& file_records = records[filename]; + auto [it, ok] = file_records.insert({line, LineRecord(line, frame->co->src.get())}); + prev_record = &(it->second); +} + +void LineProfiler::_step_end(){ + clock_t now = clock(); + clock_t delta = now - prev_time; + prev_time = now; + if(prev_record->line != prev_line){ + prev_record->hits++; + prev_line = prev_record->line; + } + prev_record->time += delta; +} + +void LineProfiler::end(){ + _step_end(); +} + +Str LineProfiler::stats(){ + SStream ss; + for(auto& [filename, file_records] : records){ + clock_t total_time = 0; + for(auto& [line, record] : file_records){ + total_time += record.time; + } + ss << "Total time: " << (double)total_time / CLOCKS_PER_SEC << "s\n"; + ss << "File: " << filename << "\n"; + // ss << "Function: " << "" << "at line " << -1 << "\n"; + ss << "Line # Hits Time Per Hit % Time Line Contents\n"; + ss << "==============================================================\n"; + for(auto& [line, record]: file_records){ + ss << left_pad(std::to_string(line), 6); + ss << left_pad(std::to_string(record.hits), 10); + ss << left_pad(std::to_string(record.time), 13); + ss << left_pad(std::to_string(record.time_per_hit()), 9); + ss << left_pad(to_string_1f(record.time * 100.0 / total_time), 9); + ss << " " << record.line_content() << "\n"; + } + ss << "\n"; + } + return ss.str(); +} } // namespace pkpy \ No newline at end of file diff --git a/tests/80_array2d.py b/tests/83_array2d.py similarity index 100% rename from tests/80_array2d.py rename to tests/83_array2d.py diff --git a/tests/84_line_profiler.py b/tests/84_line_profiler.py new file mode 100644 index 00000000..7e864940 --- /dev/null +++ b/tests/84_line_profiler.py @@ -0,0 +1,15 @@ +from line_profiler import LineProfiler + +def my_func(): + a = 0 + for i in range(1000000): + a += i + return a + +lp = LineProfiler() + +lp.add_function(my_func) + +lp.runcall(my_func) + +lp.print_stats()