From 7b03d20a8281be5a9d616ceb646cc4aed68e9e11 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Mon, 26 Oct 2020 22:17:56 +0200 Subject: [PATCH 01/32] broken stuff but progress is made. --- .gitignore | 166 ++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 14 ++++ build.rs | 15 ++++ capara/__init__.py | 0 capara/profiler.py | 24 ++++++ pyproject.toml | 3 + src/lib.rs | 186 +++++++++++++++++++++++++++++++++++++++++++++ test.py | 24 ++++++ 8 files changed, 432 insertions(+) create mode 100644 Cargo.toml create mode 100644 build.rs create mode 100644 capara/__init__.py create mode 100644 capara/profiler.py create mode 100644 pyproject.toml create mode 100644 src/lib.rs create mode 100644 test.py diff --git a/.gitignore b/.gitignore index 088ba6b..2f79c0f 100644 --- a/.gitignore +++ b/.gitignore @@ -8,3 +8,169 @@ Cargo.lock # These are backup files generated by rustfmt **/*.rs.bk +# Byte-compiled / optimized / DLL files +__pycache__/ +*.py[cod] +*$py.class + +# C extensions +*.so + +# Distribution / packaging +.Python +build/ +develop-eggs/ +dist/ +downloads/ +eggs/ +.eggs/ +lib/ +lib64/ +parts/ +sdist/ +var/ +wheels/ +share/python-wheels/ +*.egg-info/ +.installed.cfg +*.egg +MANIFEST + +# PyInstaller +# Usually these files are written by a python script from a template +# before PyInstaller builds the exe, so as to inject date/other infos into it. +*.manifest +*.spec + +# Installer logs +pip-log.txt +pip-delete-this-directory.txt + +# Unit test / coverage reports +htmlcov/ +.tox/ +.nox/ +.coverage +.coverage.* +.cache +nosetests.xml +coverage.xml +*.cover +*.py,cover +.hypothesis/ +.pytest_cache/ +cover/ + +# Translations +*.mo +*.pot + +# Django stuff: +*.log +local_settings.py +db.sqlite3 +db.sqlite3-journal + +# Flask stuff: +instance/ +.webassets-cache + +# Scrapy stuff: +.scrapy + +# Sphinx documentation +docs/_build/ + +# PyBuilder +.pybuilder/ +target/ + +# Jupyter Notebook +.ipynb_checkpoints + +# IPython +profile_default/ +ipython_config.py + +# pyenv +# For a library or package, you might want to ignore these files since the code is +# intended to run in multiple environments; otherwise, check them in: +# .python-version + +# pipenv +# According to pypa/pipenv#598, it is recommended to include Pipfile.lock in version control. +# However, in case of collaboration, if having platform-specific dependencies or dependencies +# having no cross-platform support, pipenv may install dependencies that don't work, or not +# install all needed dependencies. +#Pipfile.lock + +# PEP 582; used by e.g. github.com/David-OConnor/pyflow +__pypackages__/ + +# Celery stuff +celerybeat-schedule +celerybeat.pid + +# SageMath parsed files +*.sage.py + +# Environments +.env +.venv +env/ +venv/ +ENV/ +env.bak/ +venv.bak/ + +# Spyder project settings +.spyderproject +.spyproject + +# Rope project settings +.ropeproject + +# mkdocs documentation +/site + +# mypy +.mypy_cache/ +.dmypy.json +dmypy.json + +# Pyre type checker +.pyre/ + +# pytype static type analyzer +.pytype/ + +# Cython debug symbols +cython_debug/ + +# General +.DS_Store +.AppleDouble +.LSOverride + +# Icon must end with two \r +Icon + + +# Thumbnails +._* + +# Files that might appear in the root of a volume +.DocumentRevisions-V100 +.fseventsd +.Spotlight-V100 +.TemporaryItems +.Trashes +.VolumeIcon.icns +.com.apple.timemachine.donotpresent + +# Directories potentially created on remote AFP share +.AppleDB +.AppleDesktop +Network Trash Folder +Temporary Items +.apdisk \ No newline at end of file diff --git a/Cargo.toml b/Cargo.toml new file mode 100644 index 0000000..f6ee586 --- /dev/null +++ b/Cargo.toml @@ -0,0 +1,14 @@ +[package] +name = "capara" +version = "0.1.0" +edition = "2018" +authors = ["Aviram Hassan "] + +[lib] +name = "capara" +crate-type = ["cdylib"] + +[dependencies.pyo3] +git = "https://github.com/aviramha/pyo3" +branch = "fix_pycodeobj_struct" +features = ["extension-module"] \ No newline at end of file diff --git a/build.rs b/build.rs new file mode 100644 index 0000000..a792d96 --- /dev/null +++ b/build.rs @@ -0,0 +1,15 @@ +use std::process::Command; + +fn main() { + let out = Command::new("python") + .args(&["-c", "import sys; print(sys.version_info[1])"]) + .output() + .expect("python version did not print"); + let minor = u8::from_str_radix(String::from_utf8_lossy(&out.stdout).trim(), 10) + .expect("python version was not parsed"); + + for i in 6..=minor { + println!("cargo:rustc-cfg=Py_3_{}", i); + } + println!("cargo:rustc-cfg=Py_3"); +} diff --git a/capara/__init__.py b/capara/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/capara/profiler.py b/capara/profiler.py new file mode 100644 index 0000000..4f39d22 --- /dev/null +++ b/capara/profiler.py @@ -0,0 +1,24 @@ +import sys +from . import capara +from contextvars import ContextVar + +_reference_count = 0 +_profiler_context: ContextVar[capara.ProfilerContext] = ContextVar('profiler_context') + +def lol(): + import time + #time.sleep(3) + + +def start() -> None: + _profiler_context.set(capara.ProfilerContext()) + capara.start(_profiler_context) + lol() + stop() + a = _profiler_context.get() + print(a.entries) + + + +def stop() -> None: + sys.setprofile(None) \ No newline at end of file diff --git a/pyproject.toml b/pyproject.toml new file mode 100644 index 0000000..548b353 --- /dev/null +++ b/pyproject.toml @@ -0,0 +1,3 @@ +[build-system] +requires = ["maturin"] +build-backend = "maturin" \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs new file mode 100644 index 0000000..5322d5f --- /dev/null +++ b/src/lib.rs @@ -0,0 +1,186 @@ +use pyo3::ffi::{ + PyContextVar_Get, PyEval_SetProfile, PyFrameObject, PyUnicode_AsUTF8, Py_tracefunc, +}; +use pyo3::prelude::*; +use pyo3::types::*; +use pyo3::wrap_pyfunction; +use pyo3::{AsPyPointer, PyAny, Python}; +use std::collections::HashMap; +use std::ffi::CStr; +use std::os::raw::c_int; +use std::time::{Duration, Instant}; + +#[allow(dead_code)] +#[repr(i32)] +enum TraceEvent { + Call, + Exception, + Line, + Return, + CCall, + CException, + CReturn, + Opcode +} + +struct FrameData { + func_name: String, + file_name: String, + identifier: usize +} + +#[cfg(Py_3_8)] +struct ProfilerEntry { + file_name: String, + func_name: String, + start: Instant, + end: Option, +} + +#[pyclass] +struct ProfilerContext { + entries: std::cell::Cell>, +} + +fn format_entry(entry: &ProfilerEntry) -> (String, String, Option) { + let duration = match entry.end { + Some(v) => Some(v.duration_since(entry.start).as_nanos()), + None => None + }; + (entry.file_name.clone(), entry.func_name.clone(), duration) +} + + +#[pymethods] +impl ProfilerContext { + #[new] + fn new() -> Self { + ProfilerContext { + entries: std::cell::Cell::new(HashMap::new()), + } + } + #[getter] + fn entries(&mut self) -> PyResult)>> { + let mut result = Vec::new(); + for (_, entry) in self.entries.get_mut().iter() { + result.push(format_entry(entry)); + } + Ok(result) + } +} + + +fn extract_context(context_var: *mut pyo3::ffi::PyObject) -> Option { + let gil = Python::acquire_gil(); + let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); + + unsafe { + match PyContextVar_Get( + context_var, + std::ptr::null_mut(), + &mut context_value as *mut *mut pyo3::ffi::PyObject, + ) { + 0 => (), + _ => return None + }; + } + + if context_value.is_null() { + return None + } + let context = match unsafe { Py::::from_borrowed_ptr_or_opt(gil.python(), context_value)} { + Some(v) => v, + None => return None + }; + + let cell = context.as_ref(gil.python()); + let mut ctx = cell.borrow_mut(); + + unsafe {pyo3::ffi::Py_XDECREF(context_value);} + ctx +} + +fn extract_from_frame(frame: *mut PyFrameObject) -> Option { + if frame.is_null() { + return None + } + + let dframe = *frame; + + if dframe.f_code.is_null() { + return None + } + + let code = *dframe.f_code; + unsafe { + let file_name = match code.co_filename.is_null() { + true => "null".to_string(), + false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_filename)) + .to_string_lossy() + .into_owned(), + }; + let func_name = match code.co_name.is_null() { + true => "null".to_string(), + false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_name)) + .to_string_lossy() + .into_owned(), + }; + Some(FrameData{func_name, file_name, identifier: frame as usize}) + } +} + +extern "C" fn callback( + obj: *mut pyo3::ffi::PyObject, + frame: *mut PyFrameObject, + what: c_int, + arg: *mut pyo3::ffi::PyObject, +) -> c_int { + let what: TraceEvent = unsafe {std::mem::transmute(what)}; + match what { + TraceEvent::Call | TraceEvent::Return => (), + _ => return 0, + }; + + let context = match extract_context(obj) { + Some(v) => v, + None => return 0, + }; + + let frame_data = match extract_from_frame(frame) { + Some(v) => v, + None => return 0, + }; + + + let start = Instant::now(); + let entry = ProfilerEntry { + func_name: frame_data.func_name, + file_name: frame_data.file_name, + start, + end: None, + }; + context.entries.get_mut().insert(frame_data.identifier, entry); + + 0 +} + +#[pyfunction] +fn start(context_var: &PyAny) -> PyResult<()> { + let cb: Py_tracefunc = callback; + unsafe { + PyEval_SetProfile(cb, context_var.as_ptr()); + } + Ok(()) +} + +// #[pyclass] +// struct Profiler { +// frames: Hash +// } +#[pymodule] +/// A Python module implemented in Rust. +fn capara(_py: Python, m: &PyModule) -> PyResult<()> { + m.add_function(wrap_pyfunction!(start, m)?)?; + m.add_class::()?; + Ok(()) +} diff --git a/test.py b/test.py new file mode 100644 index 0000000..7e9691b --- /dev/null +++ b/test.py @@ -0,0 +1,24 @@ +from capara import profiler +from contextvars import ContextVar + +profiler.start() +profiler.stop() + +# from contextvars import ContextVar +# import asyncio + +# c = ContextVar('lol') + +# async def main(): +# c.set([1]) +# f = asyncio.get_event_loop().create_task(lol()) +# await f +# print(c.get()) + +# async def lol(): +# print(c.get().append(2)) +# print(c.get()) + +# if __name__ == "__main__": +# loop = asyncio.get_event_loop() +# loop.run_until_complete(main()) \ No newline at end of file From 1b470849257a58619bbeda3e84ac459c27670dd4 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Wed, 28 Oct 2020 22:12:22 +0200 Subject: [PATCH 02/32] Seems to work now --- src/lib.rs | 159 ++++++++++++++++++++++++++++++++--------------------- 1 file changed, 96 insertions(+), 63 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 5322d5f..8fcaf2e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -2,14 +2,15 @@ use pyo3::ffi::{ PyContextVar_Get, PyEval_SetProfile, PyFrameObject, PyUnicode_AsUTF8, Py_tracefunc, }; use pyo3::prelude::*; -use pyo3::types::*; use pyo3::wrap_pyfunction; use pyo3::{AsPyPointer, PyAny, Python}; use std::collections::HashMap; +use std::convert::{TryFrom, TryInto}; use std::ffi::CStr; use std::os::raw::c_int; -use std::time::{Duration, Instant}; +use std::time::Instant; +/// Enum of possible Python's Trace/Profiling events #[allow(dead_code)] #[repr(i32)] enum TraceEvent { @@ -20,15 +21,30 @@ enum TraceEvent { CCall, CException, CReturn, - Opcode + Opcode, + __NonExhaustive, } +impl TryFrom for TraceEvent { + type Error = &'static str; + /// Cast i32 event (raw from Python) to Rust enum. + fn try_from(value: i32) -> Result { + if value > 7 || value < 0 { + return Err("Not valid enum value"); + } + Ok(unsafe { std::mem::transmute(value) }) + } +} + +/// Struct representing frame data +/// Identifier is frame pointer casted to usize. struct FrameData { func_name: String, file_name: String, - identifier: usize + identifier: usize, } +/// end can be None due to lack of Return callback #[cfg(Py_3_8)] struct ProfilerEntry { file_name: String, @@ -37,20 +53,21 @@ struct ProfilerEntry { end: Option, } +/// Profiler context to be used as a value for ContextVar. #[pyclass] struct ProfilerContext { entries: std::cell::Cell>, } +/// Format an entry into file_name, func_name and duration. fn format_entry(entry: &ProfilerEntry) -> (String, String, Option) { let duration = match entry.end { Some(v) => Some(v.duration_since(entry.start).as_nanos()), - None => None + None => None, }; (entry.file_name.clone(), entry.func_name.clone(), duration) } - #[pymethods] impl ProfilerContext { #[new] @@ -69,49 +86,21 @@ impl ProfilerContext { } } - -fn extract_context(context_var: *mut pyo3::ffi::PyObject) -> Option { - let gil = Python::acquire_gil(); - let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); - - unsafe { - match PyContextVar_Get( - context_var, - std::ptr::null_mut(), - &mut context_value as *mut *mut pyo3::ffi::PyObject, - ) { - 0 => (), - _ => return None - }; - } - - if context_value.is_null() { - return None - } - let context = match unsafe { Py::::from_borrowed_ptr_or_opt(gil.python(), context_value)} { - Some(v) => v, - None => return None - }; - - let cell = context.as_ref(gil.python()); - let mut ctx = cell.borrow_mut(); - - unsafe {pyo3::ffi::Py_XDECREF(context_value);} - ctx -} - +/// Extracts FrameData from FFI PyFrameObject +/// # Arguments +/// * ``frame`` - FFI Frame object pointer fn extract_from_frame(frame: *mut PyFrameObject) -> Option { if frame.is_null() { - return None + return None; } - let dframe = *frame; + let dframe = unsafe { *frame }; if dframe.f_code.is_null() { - return None + return None; } - let code = *dframe.f_code; + let code = unsafe { *dframe.f_code }; unsafe { let file_name = match code.co_filename.is_null() { true => "null".to_string(), @@ -122,45 +111,93 @@ fn extract_from_frame(frame: *mut PyFrameObject) -> Option { let func_name = match code.co_name.is_null() { true => "null".to_string(), false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_name)) - .to_string_lossy() - .into_owned(), + .to_string_lossy() + .into_owned(), }; - Some(FrameData{func_name, file_name, identifier: frame as usize}) + Some(FrameData { + func_name, + file_name, + identifier: frame as usize, + }) } } +/// Our profiler callback extern "C" fn callback( obj: *mut pyo3::ffi::PyObject, frame: *mut PyFrameObject, what: c_int, - arg: *mut pyo3::ffi::PyObject, + _arg: *mut pyo3::ffi::PyObject, ) -> c_int { - let what: TraceEvent = unsafe {std::mem::transmute(what)}; - match what { - TraceEvent::Call | TraceEvent::Return => (), + let event: TraceEvent = match what.try_into() { + Ok(event) => match event { + TraceEvent::Call | TraceEvent::Return => event, + _ => return 0, + }, _ => return 0, }; - let context = match extract_context(obj) { - Some(v) => v, - None => return 0, - }; + let gil = Python::acquire_gil(); + let py = gil.python(); let frame_data = match extract_from_frame(frame) { Some(v) => v, None => return 0, }; + let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); - let start = Instant::now(); - let entry = ProfilerEntry { - func_name: frame_data.func_name, - file_name: frame_data.file_name, - start, - end: None, + unsafe { + match PyContextVar_Get( + obj, + std::ptr::null_mut(), + &mut context_value as *mut *mut pyo3::ffi::PyObject, + ) { + 0 => (), + _ => return 0, + }; + } + + if context_value.is_null() { + return 0; + } + + let context_obj = + match unsafe { Py::::from_borrowed_ptr_or_opt(py, context_value) } { + Some(v) => v, + None => return 0, }; - context.entries.get_mut().insert(frame_data.identifier, entry); + let mut context = context_obj.as_ref(py).borrow_mut(); + + match event { + TraceEvent::Call => { + let start = Instant::now(); + let entry = ProfilerEntry { + func_name: frame_data.func_name, + file_name: frame_data.file_name, + start, + end: None, + }; + context + .entries + .get_mut() + .insert(frame_data.identifier, entry); + } + TraceEvent::Return => { + match context.entries.get_mut().get_mut(&frame_data.identifier) { + Some(entry) => { + entry.end = Some(Instant::now()); + } + None => println!("shouldn't happen"), + }; + } + _ => println!("shouldn't happen"), + } + + unsafe { + pyo3::ffi::Py_XDECREF(context_value); + } 0 } @@ -173,10 +210,6 @@ fn start(context_var: &PyAny) -> PyResult<()> { Ok(()) } -// #[pyclass] -// struct Profiler { -// frames: Hash -// } #[pymodule] /// A Python module implemented in Rust. fn capara(_py: Python, m: &PyModule) -> PyResult<()> { From 5d12c01f9ca4fc72a463a6008d38d6e9a10fe66c Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Wed, 28 Oct 2020 22:25:55 +0200 Subject: [PATCH 03/32] add basic test, formatting, noice --- capara/profiler.py | 32 +++++++++++++++++++++----------- src/lib.rs | 2 +- tests/requirements.txt | 1 + tests/test_main.py | 12 ++++++++++++ 4 files changed, 35 insertions(+), 12 deletions(-) create mode 100644 tests/requirements.txt create mode 100644 tests/test_main.py diff --git a/capara/profiler.py b/capara/profiler.py index 4f39d22..f634033 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -1,24 +1,34 @@ import sys -from . import capara + from contextvars import ContextVar +from typing import List, Tuple + +from . import capara _reference_count = 0 _profiler_context: ContextVar[capara.ProfilerContext] = ContextVar('profiler_context') -def lol(): - import time - #time.sleep(3) - def start() -> None: + """Starts the profiler. + + Notes: + In case the profiler was already started in the same task, this will override existing data. + """ _profiler_context.set(capara.ProfilerContext()) + global _reference_count + _reference_count += 1 capara.start(_profiler_context) - lol() - stop() - a = _profiler_context.get() - print(a.entries) +def stop() -> List[Tuple[str, str, int]]: + """Stops the profiler. Completely stops the profiler only if reference count equals to zero. -def stop() -> None: - sys.setprofile(None) \ No newline at end of file + Returns: + List of profiler events, each event is a tuple of (file_name, func_name, duration). + """ + global _reference_count + _reference_count -= 1 + if _reference_count == 0: + sys.setprofile(None) + return _profiler_context.get().entries \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs index 8fcaf2e..ddbd2fa 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -189,7 +189,7 @@ extern "C" fn callback( Some(entry) => { entry.end = Some(Instant::now()); } - None => println!("shouldn't happen"), + None => (), }; } _ => println!("shouldn't happen"), diff --git a/tests/requirements.txt b/tests/requirements.txt new file mode 100644 index 0000000..fa708f8 --- /dev/null +++ b/tests/requirements.txt @@ -0,0 +1 @@ +pytest>=6.1.2 \ No newline at end of file diff --git a/tests/test_main.py b/tests/test_main.py new file mode 100644 index 0000000..be1c758 --- /dev/null +++ b/tests/test_main.py @@ -0,0 +1,12 @@ +import time + +import capara.profiler + +def sleepy_function(): + time.sleep(0.5) + +def test_sanity(): + capara.profiler.start() + sleepy_function() + data = capara.profiler.stop() + print(data) \ No newline at end of file From 4022c75ae7d508560bb6f183d1d4400ebcaff372 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Thu, 29 Oct 2020 22:15:57 +0200 Subject: [PATCH 04/32] add async support and tests --- capara/profiler.py | 5 ++- src/lib.rs | 79 ++++++++++++++++++++++++++++------------------ tests/test_main.py | 31 +++++++++++++++--- 3 files changed, 80 insertions(+), 35 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index f634033..3972e4a 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -31,4 +31,7 @@ def stop() -> List[Tuple[str, str, int]]: _reference_count -= 1 if _reference_count == 0: sys.setprofile(None) - return _profiler_context.get().entries \ No newline at end of file + entries = _profiler_context.get().entries + # Remove stop function entry to avoid garbage + entries.remove((__file__, 'stop', None)) + return entries \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs index ddbd2fa..08474e8 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,5 +1,6 @@ use pyo3::ffi::{ PyContextVar_Get, PyEval_SetProfile, PyFrameObject, PyUnicode_AsUTF8, Py_tracefunc, + CO_ASYNC_GENERATOR, CO_COROUTINE, CO_ITERABLE_COROUTINE, }; use pyo3::prelude::*; use pyo3::wrap_pyfunction; @@ -42,6 +43,7 @@ struct FrameData { func_name: String, file_name: String, identifier: usize, + yielded_coroutine: bool, } /// end can be None due to lack of Return callback @@ -101,6 +103,12 @@ fn extract_from_frame(frame: *mut PyFrameObject) -> Option { } let code = unsafe { *dframe.f_code }; + let yielded_coroutine = { + (0 < (code.co_flags & CO_COROUTINE) + | (code.co_flags & CO_ITERABLE_COROUTINE) + | (code.co_flags & CO_ASYNC_GENERATOR)) + && (!dframe.f_stacktop.is_null()) + }; unsafe { let file_name = match code.co_filename.is_null() { true => "null".to_string(), @@ -118,10 +126,41 @@ fn extract_from_frame(frame: *mut PyFrameObject) -> Option { func_name, file_name, identifier: frame as usize, + yielded_coroutine, }) } } +fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option> { + let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); + + unsafe { + match PyContextVar_Get( + obj, + std::ptr::null_mut(), + &mut context_value as *mut *mut pyo3::ffi::PyObject, + ) { + 0 => (), + _ => return None, + }; + } + + if context_value.is_null() { + return None; + } + + let context_obj = + match unsafe { Py::::from_borrowed_ptr_or_opt(py, context_value) } { + Some(v) => v, + None => return None, + }; + + unsafe { + pyo3::ffi::Py_XDECREF(context_value); + } + Some(context_obj) +} + /// Our profiler callback extern "C" fn callback( obj: *mut pyo3::ffi::PyObject, @@ -137,38 +176,19 @@ extern "C" fn callback( _ => return 0, }; - let gil = Python::acquire_gil(); - let py = gil.python(); - let frame_data = match extract_from_frame(frame) { Some(v) => v, None => return 0, }; - let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); - - unsafe { - match PyContextVar_Get( - obj, - std::ptr::null_mut(), - &mut context_value as *mut *mut pyo3::ffi::PyObject, - ) { - 0 => (), - _ => return 0, - }; - } - - if context_value.is_null() { - return 0; - } - - let context_obj = - match unsafe { Py::::from_borrowed_ptr_or_opt(py, context_value) } { - Some(v) => v, - None => return 0, - }; + let gil = Python::acquire_gil(); + let py = gil.python(); - let mut context = context_obj.as_ref(py).borrow_mut(); + let context = match get_context(py, obj) { + Some(v) => v, + _ => return 0, + }; + let mut context = context.as_ref(py).borrow_mut(); match event { TraceEvent::Call => { @@ -185,6 +205,9 @@ extern "C" fn callback( .insert(frame_data.identifier, entry); } TraceEvent::Return => { + if frame_data.yielded_coroutine { + return 0; + } match context.entries.get_mut().get_mut(&frame_data.identifier) { Some(entry) => { entry.end = Some(Instant::now()); @@ -194,10 +217,6 @@ extern "C" fn callback( } _ => println!("shouldn't happen"), } - - unsafe { - pyo3::ffi::Py_XDECREF(context_value); - } 0 } diff --git a/tests/test_main.py b/tests/test_main.py index be1c758..69ab839 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -1,12 +1,35 @@ +import asyncio import time import capara.profiler -def sleepy_function(): - time.sleep(0.5) +SLEEP_TIME = 0.1 + +def sleep(): + time.sleep(SLEEP_TIME) + +async def async_sleep(): + time.sleep(SLEEP_TIME) def test_sanity(): capara.profiler.start() - sleepy_function() + sleep() + data = capara.profiler.stop() + assert len(data) == 1 + entry = data[0] + assert entry[0] == __file__ + assert entry[1] == 'sleep' + assert entry[2] // 100000000 == SLEEP_TIME * 10 + +def test_sanity_async(): + loop = asyncio.get_event_loop() + capara.profiler.start() + loop.run_until_complete(async_sleep()) data = capara.profiler.stop() - print(data) \ No newline at end of file + for entry in data: + if entry[1] == 'async_sleep': + break + + assert entry[0] == __file__ + assert entry[1] == 'async_sleep' + assert entry[2] // 100000000 == SLEEP_TIME * 10 From 59d90379faeebacb34ef6637e518f09e99a5e799 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:28:43 +0200 Subject: [PATCH 05/32] Add Makefile, document in README, add interface stub, fix linting errors, improved code by using TryFrom instead of function, more tests --- .flake8 | 2 + Makefile | 109 +++++++++++++++++++++++++++++++++++++++++++++ README.md | 34 ++++++++++++++ capara/capara.pyi | 7 +++ capara/profiler.py | 29 +++++++++--- pyproject.toml | 27 +++++++++++ src/lib.rs | 103 +++++++++++++++++++++--------------------- tests/test_main.py | 48 ++++++++++++++++---- 8 files changed, 292 insertions(+), 67 deletions(-) create mode 100644 .flake8 create mode 100644 Makefile create mode 100644 capara/capara.pyi diff --git a/.flake8 b/.flake8 new file mode 100644 index 0000000..79a16af --- /dev/null +++ b/.flake8 @@ -0,0 +1,2 @@ +[flake8] +max-line-length = 120 \ No newline at end of file diff --git a/Makefile b/Makefile new file mode 100644 index 0000000..d800427 --- /dev/null +++ b/Makefile @@ -0,0 +1,109 @@ +POETRY ?= $(HOME)/.poetry/bin/poetry + +all: lint-check build test + +build: + maturin develop + +.PHONY: install-poetry +install-poetry: + @curl -sSL https://raw.githubusercontent.com/sdispater/poetry/master/get-poetry.py | python + +.PHONY: install-deps +install-deps: + @$(POETRY) install -vv + +.PHONY: install +install: install-poetry install-deps + +.PHONY: lint-black +lint-black: + @echo "\033[92m< linting using black...\033[0m" + @$(POETRY) run black . + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-flake8 +lint-flake8: + @echo "\033[92m< linting using flake8...\033[0m" + @$(POETRY) run flake8 capara tests + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-isort +lint-isort: + @echo "\033[92m< linting using isort...\033[0m" + @$(POETRY) run isort --recursive . + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-mypy +lint-mypy: + @echo "\033[92m< linting using mypy...\033[0m" + @$(POETRY) run mypy --ignore-missing-imports --follow-imports=silent capara tests + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-cargo-fmt +lint-cargo-fmt: + @echo "\033[92m< linting using cargo-fmt...\033[0m" + cargo fmt + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint +lint: lint-cargo-fmt lint-black lint-flake8 lint-isort lint-mypy + +.PHONY: lint-check-black +lint-check-black: + @echo "\033[92m< linting using black...\033[0m" + @$(POETRY) run black --check --diff . + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-check-flake8 +lint-check-flake8: + @echo "\033[92m< linting using flake8...\033[0m" + @$(POETRY) run flake8 capara tests + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-check-isort +lint-check-isort: + @echo "\033[92m< linting using isort...\033[0m" + @$(POETRY) run isort --check-only --diff --recursive . + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-check-mypy +lint-check-mypy: + @echo "\033[92m< linting using mypy...\033[0m" + @$(POETRY) run mypy --ignore-missing-imports --follow-imports=silent capara tests + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-check-clippy +lint-check-clippy: + @echo "\033[92m< linting using clippy...\033[0m" + cargo clippy + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-check-rustfmt +lint-check-rustfmt: + @echo "\033[92m< linting using cargo fmt...\033[0m" + cargo fmt --all -- --check + @echo "\033[92m> done\033[0m" + @echo + +.PHONY: lint-check +lint-check: lint-check-black lint-check-flake8 lint-check-isort lint-check-mypy + +.PHONY: test +test: + @$(POETRY) run pytest + + +.PHONY: publish +publish: + @$(POETRY) publish --username=$(PYPI_USERNAME) --password=$(PYPI_PASSWORD) --build \ No newline at end of file diff --git a/README.md b/README.md index a8fc83e..0a75962 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,36 @@ # capara Context aware Python asyncio rust analyzer + +capara is a profiler written in Rust that uses `ContextVars` for storing the profile results. +The main goal is to be able to profile *certain* asyncio tasks, out of concurrently running ones. +It's written in Rust for performance and safety, and also because I like Rust and it's good FFI and soundness experience. + +Currently capara captures all calls, not aggregated data, and each function call has a duration of nanoseconds. +Some functions might have None duration in case the profiler stopped before the `stop` function was called. + +capara doesn't maintain order of call currently, but should be easily achieveable in next versions. + +Currently supports Python 3.8-3.9. Support of Python3.7 is achievable by sending a PR to PyO3 (I am lazy at this moment to solve this) +## Warning +capara heavily relies on Python FFI and is in very early development. Use with caution. + +# Why should I use capara? +You should use capara if you want to profile certain tasks in your asyncio code. +Other profilers would show data of all functions that ran, even if in background or not as part of your task. + +# Usage +```py +from capara.profiler import Profiler + +profiler = Profiler() +with profiler: + do_something + +profiler.results +## will return all functions profiled, in a list of tuple, each tuple containing an entry - (file_name, func_name, duration) +## duration is in nanoseconds. +``` + +# License +capara was written by Aviram Hassan , copyright 2020, licensed under MIT license. +See `LICENSE` \ No newline at end of file diff --git a/capara/capara.pyi b/capara/capara.pyi new file mode 100644 index 0000000..ea1e9c3 --- /dev/null +++ b/capara/capara.pyi @@ -0,0 +1,7 @@ +from contextvars import ContextVar +from typing import List, Optional, Tuple + +class ProfilerContext: + entries: List[Tuple[str, str, Optional[int]]] + +def start(context: ContextVar[Optional[ProfilerContext]]) -> None: ... diff --git a/capara/profiler.py b/capara/profiler.py index 3972e4a..2c85ae3 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -1,12 +1,11 @@ import sys - from contextvars import ContextVar -from typing import List, Tuple +from typing import List, Optional, Tuple from . import capara _reference_count = 0 -_profiler_context: ContextVar[capara.ProfilerContext] = ContextVar('profiler_context') +_profiler_context: ContextVar[Optional[capara.ProfilerContext]] = ContextVar("profiler_context") def start() -> None: @@ -21,7 +20,7 @@ def start() -> None: capara.start(_profiler_context) -def stop() -> List[Tuple[str, str, int]]: +def stop() -> List[Tuple[str, str, Optional[int]]]: """Stops the profiler. Completely stops the profiler only if reference count equals to zero. Returns: @@ -31,7 +30,23 @@ def stop() -> List[Tuple[str, str, int]]: _reference_count -= 1 if _reference_count == 0: sys.setprofile(None) - entries = _profiler_context.get().entries + context = _profiler_context.get() + if context is None: + raise RuntimeError("No context was found, stop called without start?") + entries = context.entries # Remove stop function entry to avoid garbage - entries.remove((__file__, 'stop', None)) - return entries \ No newline at end of file + entries.remove((__file__, "stop", None)) + _profiler_context.set(None) + return entries + + +class Profiler: + def __init__(self): + self.results: Optional[List[Tuple[str, str, Optional[int]]]] = None + + def __enter__(self): + start() + + def __exit__(self, exc_type, exc_value, exc_traceback): + self.results = stop() + self.results.remove((__file__, "__exit__", None)) diff --git a/pyproject.toml b/pyproject.toml index 548b353..dbdaef5 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,3 +1,30 @@ +[tool.poetry] +name = "capara" +version = "0.1.0" +description = "Profiler for Python written in Rust especially for asyncio." +authors = ["Aviram Hassan "] +license = "MIT" + +[tool.poetry.dependencies] +python = "^3.8" + +[tool.poetry.dev-dependencies] +pytest = "^6.0" +isort = "^5.6.4" +mypy = "^0.790" +flake8 = "^3.8.4" + + +[tool.maturin] +manylinux = "off" +rustc-extra-args = "-C target-feature=+sse2" +strip = "on" + +[tool.black] +line-length = 120 +target-version = ['py38'] +include = '\.pyi?$' + [build-system] requires = ["maturin"] build-backend = "maturin" \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs index 08474e8..cc9ee09 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -46,6 +46,50 @@ struct FrameData { yielded_coroutine: bool, } +impl TryFrom<*mut PyFrameObject> for FrameData { + type Error = &'static str; + fn try_from(frame: *mut PyFrameObject) -> Result { + if frame.is_null() { + return Err("frame is null"); + } + + let dframe = unsafe { *frame }; + + if dframe.f_code.is_null() { + return Err("f_code is null"); + } + + let code = unsafe { *dframe.f_code }; + let yielded_coroutine = { + (0 < (code.co_flags & CO_COROUTINE) + | (code.co_flags & CO_ITERABLE_COROUTINE) + | (code.co_flags & CO_ASYNC_GENERATOR)) + && (!dframe.f_stacktop.is_null()) + }; + + unsafe { + let file_name = match code.co_filename.is_null() { + true => "null".to_string(), + false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_filename)) + .to_string_lossy() + .into_owned(), + }; + let func_name = match code.co_name.is_null() { + true => "null".to_string(), + false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_name)) + .to_string_lossy() + .into_owned(), + }; + Ok(FrameData { + func_name, + file_name, + identifier: frame as usize, + yielded_coroutine, + }) + } + } +} + /// end can be None due to lack of Return callback #[cfg(Py_3_8)] struct ProfilerEntry { @@ -88,49 +132,6 @@ impl ProfilerContext { } } -/// Extracts FrameData from FFI PyFrameObject -/// # Arguments -/// * ``frame`` - FFI Frame object pointer -fn extract_from_frame(frame: *mut PyFrameObject) -> Option { - if frame.is_null() { - return None; - } - - let dframe = unsafe { *frame }; - - if dframe.f_code.is_null() { - return None; - } - - let code = unsafe { *dframe.f_code }; - let yielded_coroutine = { - (0 < (code.co_flags & CO_COROUTINE) - | (code.co_flags & CO_ITERABLE_COROUTINE) - | (code.co_flags & CO_ASYNC_GENERATOR)) - && (!dframe.f_stacktop.is_null()) - }; - unsafe { - let file_name = match code.co_filename.is_null() { - true => "null".to_string(), - false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_filename)) - .to_string_lossy() - .into_owned(), - }; - let func_name = match code.co_name.is_null() { - true => "null".to_string(), - false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_name)) - .to_string_lossy() - .into_owned(), - }; - Some(FrameData { - func_name, - file_name, - identifier: frame as usize, - yielded_coroutine, - }) - } -} - fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option> { let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); @@ -176,9 +177,12 @@ extern "C" fn callback( _ => return 0, }; - let frame_data = match extract_from_frame(frame) { - Some(v) => v, - None => return 0, + let frame_data = match FrameData::try_from(frame) { + Ok(v) => v, + Err(err) => { + println!("{}", err); + return 0; + } }; let gil = Python::acquire_gil(); @@ -208,11 +212,8 @@ extern "C" fn callback( if frame_data.yielded_coroutine { return 0; } - match context.entries.get_mut().get_mut(&frame_data.identifier) { - Some(entry) => { - entry.end = Some(Instant::now()); - } - None => (), + if let Some(entry) = context.entries.get_mut().get_mut(&frame_data.identifier) { + entry.end = Some(Instant::now()); }; } _ => println!("shouldn't happen"), diff --git a/tests/test_main.py b/tests/test_main.py index 69ab839..f01b5df 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -5,31 +5,61 @@ SLEEP_TIME = 0.1 -def sleep(): - time.sleep(SLEEP_TIME) -async def async_sleep(): - time.sleep(SLEEP_TIME) +def sleep(duration: float): + time.sleep(duration) + + +async def async_sleep(duration: float): + time.sleep(duration) + def test_sanity(): capara.profiler.start() - sleep() + sleep(SLEEP_TIME) data = capara.profiler.stop() assert len(data) == 1 entry = data[0] assert entry[0] == __file__ - assert entry[1] == 'sleep' + assert entry[1] == "sleep" + assert entry[2] // 100000000 == SLEEP_TIME * 10 + + +def test_sanity_context(): + profiler = capara.profiler.Profiler() + with profiler: + sleep(SLEEP_TIME) + data = profiler.results + assert len(data) == 1 + entry = data[0] + assert entry[0] == __file__ + assert entry[1] == "sleep" assert entry[2] // 100000000 == SLEEP_TIME * 10 + def test_sanity_async(): loop = asyncio.get_event_loop() capara.profiler.start() - loop.run_until_complete(async_sleep()) + loop.run_until_complete(async_sleep(SLEEP_TIME)) + data = capara.profiler.stop() + for entry in data: + if entry[1] == "async_sleep": + break + + assert entry[0] == __file__ + assert entry[1] == "async_sleep" + assert entry[2] // 100000000 == SLEEP_TIME * 10 + + +def test_concurrent_tasks(): + loop = asyncio.get_event_loop() + capara.profiler.start() + loop.run_until_complete(async_sleep(SLEEP_TIME)) data = capara.profiler.stop() for entry in data: - if entry[1] == 'async_sleep': + if entry[1] == "async_sleep": break assert entry[0] == __file__ - assert entry[1] == 'async_sleep' + assert entry[1] == "async_sleep" assert entry[2] // 100000000 == SLEEP_TIME * 10 From 58356205a3ae6ff0c88e3aed4b0e1fc3985befc2 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:37:50 +0200 Subject: [PATCH 06/32] add workflows --- .github/workflows/release.yml | 37 ++++++++++++++++++++++++++++++++++ .github/workflows/test.yml | 38 +++++++++++++++++++++++++++++++++++ 2 files changed, 75 insertions(+) create mode 100644 .github/workflows/release.yml create mode 100644 .github/workflows/test.yml diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml new file mode 100644 index 0000000..931936f --- /dev/null +++ b/.github/workflows/release.yml @@ -0,0 +1,37 @@ +name: Release +on: + push: + tags: + - '*.*.*' + + +jobs: + tests: + strategy: + matrix: + python-version: [3.8, 3.9] + platform: [ubuntu-latest, windows-latest, macos-latest] + runs-on: ${{ matrix.platform }} + steps: + - uses: actions/checkout@v2 + - name: Set up Python ${{ matrix.python-version }} + uses: actions/setup-python@v2 + with: + python-version: ${{ matrix.python-version }} + - name: Setup Poetry + run: | + python -m pip install --upgrade pip + pip install --pre poetry + - name: Setup Cache + uses: actions/cache@v2 + with: + path: ~/.cache/pypoetry + key: ${{ runner.os }}-pip-${{ matrix.platform }}-${{ matrix.python-version }} + restore-keys: | + ${{ runner.os }}-pip-${{ matrix.platform }}-${{ matrix.python-version }} + - name: Install dependencies + run: | + poetry install + - name: Publish + run: | + make publish diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml new file mode 100644 index 0000000..2405d97 --- /dev/null +++ b/.github/workflows/test.yml @@ -0,0 +1,38 @@ +name: Test capara + +on: + push: + branches: [ master ] + pull_request: + branches: [ master ] + +jobs: + tests: + strategy: + matrix: + python-version: [3.8, 3.9] + platform: [ubuntu-latest, windows-latest, macos-latest] + runs-on: ${{ matrix.platform }} + steps: + - uses: actions/checkout@v2 + - name: Set up Python ${{ matrix.python-version }} + uses: actions/setup-python@v2 + with: + python-version: ${{ matrix.python-version }} + - name: Setup Poetry + run: | + python -m pip install --upgrade pip + pip install --pre poetry + - name: Setup Cache + uses: actions/cache@v2 + with: + path: ~/.cache/pypoetry + key: ${{ runner.os }}-pip-${{ matrix.platform }}-${{ matrix.python-version }} + restore-keys: | + ${{ runner.os }}-pip-${{ matrix.platform }}-${{ matrix.python-version }} + - name: Install dependencies + run: | + poetry install + - name: Test + run: | + make From 6b47dfcc988ccc69b1acc15d410c3c8fe048e27a Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:39:40 +0200 Subject: [PATCH 07/32] fix makefile poetry location --- Makefile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Makefile b/Makefile index d800427..bc52819 100644 --- a/Makefile +++ b/Makefile @@ -1,4 +1,4 @@ -POETRY ?= $(HOME)/.poetry/bin/poetry +POETRY ?= poetry all: lint-check build test From 733bf393a5dd5f0e7095485161e480af3dff5abb Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:42:12 +0200 Subject: [PATCH 08/32] add black dependency --- pyproject.toml | 1 + 1 file changed, 1 insertion(+) diff --git a/pyproject.toml b/pyproject.toml index dbdaef5..3fd4504 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -13,6 +13,7 @@ pytest = "^6.0" isort = "^5.6.4" mypy = "^0.790" flake8 = "^3.8.4" +black = "^20.8b1" [tool.maturin] From 6d72fc46cb1568cef3a0cea3711a3474b4a47d42 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:45:04 +0200 Subject: [PATCH 09/32] remove testfile --- test.py | 24 ------------------------ 1 file changed, 24 deletions(-) delete mode 100644 test.py diff --git a/test.py b/test.py deleted file mode 100644 index 7e9691b..0000000 --- a/test.py +++ /dev/null @@ -1,24 +0,0 @@ -from capara import profiler -from contextvars import ContextVar - -profiler.start() -profiler.stop() - -# from contextvars import ContextVar -# import asyncio - -# c = ContextVar('lol') - -# async def main(): -# c.set([1]) -# f = asyncio.get_event_loop().create_task(lol()) -# await f -# print(c.get()) - -# async def lol(): -# print(c.get().append(2)) -# print(c.get()) - -# if __name__ == "__main__": -# loop = asyncio.get_event_loop() -# loop.run_until_complete(main()) \ No newline at end of file From ee1fb792d70f431d07f7efeffeaaebb610a21692 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:51:21 +0200 Subject: [PATCH 10/32] maturin stuff --- .github/workflows/test.yml | 5 +++++ pyproject.toml | 2 -- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 2405d97..f84b96b 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -33,6 +33,11 @@ jobs: - name: Install dependencies run: | poetry install + - name: Install Rust && maturin + run: | + curl https://sh.rustup.rs -sSf | sh -s -- -y + source $HOME/.cargo/env + pip install maturin - name: Test run: | make diff --git a/pyproject.toml b/pyproject.toml index 3fd4504..0d175f1 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -15,9 +15,7 @@ mypy = "^0.790" flake8 = "^3.8.4" black = "^20.8b1" - [tool.maturin] -manylinux = "off" rustc-extra-args = "-C target-feature=+sse2" strip = "on" From b9ab0fa32c3d0868ce46deac4a97d958eb505dee Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:51:46 +0200 Subject: [PATCH 11/32] update gitignore --- .gitignore | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/.gitignore b/.gitignore index 2f79c0f..35a7353 100644 --- a/.gitignore +++ b/.gitignore @@ -173,4 +173,7 @@ Icon .AppleDesktop Network Trash Folder Temporary Items -.apdisk \ No newline at end of file +.apdiskpoetry.lock +.vscode +poetry.lock +.cargo From 6696bbb55271bad7325df29a4dd31b72560ba923 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:55:56 +0200 Subject: [PATCH 12/32] fix makefile, use upstream pyo3 --- Cargo.toml | 3 +-- Makefile | 4 ++-- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index f6ee586..c48c69e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -9,6 +9,5 @@ name = "capara" crate-type = ["cdylib"] [dependencies.pyo3] -git = "https://github.com/aviramha/pyo3" -branch = "fix_pycodeobj_struct" +git = "https://github.com/pyo3/pyo3" features = ["extension-module"] \ No newline at end of file diff --git a/Makefile b/Makefile index bc52819..a15ca2c 100644 --- a/Makefile +++ b/Makefile @@ -3,7 +3,7 @@ POETRY ?= poetry all: lint-check build test build: - maturin develop + @$(POETRY) run maturin develop .PHONY: install-poetry install-poetry: @@ -97,7 +97,7 @@ lint-check-rustfmt: @echo .PHONY: lint-check -lint-check: lint-check-black lint-check-flake8 lint-check-isort lint-check-mypy +lint-check: lint-check-clippy lint-check-rustfmt lint-check-black lint-check-flake8 lint-check-isort lint-check-mypy .PHONY: test test: From beeda0ad40173d496b4e0da27477ec394f5ff498 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 10:58:56 +0200 Subject: [PATCH 13/32] fix test.yml --- .github/workflows/test.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index f84b96b..228f3c2 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -38,6 +38,7 @@ jobs: curl https://sh.rustup.rs -sSf | sh -s -- -y source $HOME/.cargo/env pip install maturin + rustup component add clippy - name: Test run: | make From d4c7f2a58cbb3042fbd15e605546021ea4cdd37c Mon Sep 17 00:00:00 2001 From: Aviram Hassan <41201924+aviramha@users.noreply.github.com> Date: Fri, 30 Oct 2020 11:11:04 +0200 Subject: [PATCH 14/32] Update src/lib.rs Co-authored-by: David Hewitt <1939362+davidhewitt@users.noreply.github.com> --- src/lib.rs | 15 +-------------- 1 file changed, 1 insertion(+), 14 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index cc9ee09..8536684 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -146,20 +146,7 @@ fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option::from_borrowed_ptr_or_opt(py, context_value) } { - Some(v) => v, - None => return None, - }; - - unsafe { - pyo3::ffi::Py_XDECREF(context_value); - } - Some(context_obj) + unsafe { Py::from_owned_ptr_or_opt(py, context_obj) } } /// Our profiler callback From 8f442d8c9ca0095c184f4c4d77f7e439ab709627 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 11:16:25 +0200 Subject: [PATCH 15/32] cr fixes --- capara/profiler.py | 3 ++- src/lib.rs | 4 ++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index 2c85ae3..d49229e 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -16,8 +16,9 @@ def start() -> None: """ _profiler_context.set(capara.ProfilerContext()) global _reference_count + if _reference_count == 0: + capara.start(_profiler_context) _reference_count += 1 - capara.start(_profiler_context) def stop() -> List[Tuple[str, str, Optional[int]]]: diff --git a/src/lib.rs b/src/lib.rs index 8536684..361a04e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -133,13 +133,13 @@ impl ProfilerContext { } fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option> { - let mut context_value: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); + let mut context_obj: *mut pyo3::ffi::PyObject = std::ptr::null_mut(); unsafe { match PyContextVar_Get( obj, std::ptr::null_mut(), - &mut context_value as *mut *mut pyo3::ffi::PyObject, + &mut context_obj as *mut *mut pyo3::ffi::PyObject, ) { 0 => (), _ => return None, From d38ae6c7d1abc986efee30370f0ea5e7d12262da Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 11:18:03 +0200 Subject: [PATCH 16/32] drop windows for now --- .github/workflows/release.yml | 2 +- .github/workflows/test.yml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index 931936f..6441050 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -10,7 +10,7 @@ jobs: strategy: matrix: python-version: [3.8, 3.9] - platform: [ubuntu-latest, windows-latest, macos-latest] + platform: [ubuntu-latest, macos-latest] runs-on: ${{ matrix.platform }} steps: - uses: actions/checkout@v2 diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 228f3c2..36aff7a 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -11,7 +11,7 @@ jobs: strategy: matrix: python-version: [3.8, 3.9] - platform: [ubuntu-latest, windows-latest, macos-latest] + platform: [ubuntu-latest, macos-latest] runs-on: ${{ matrix.platform }} steps: - uses: actions/checkout@v2 From 1f897011ede670063ff7fc06d06bd4126eb0679f Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 15:43:01 +0200 Subject: [PATCH 17/32] macos.. --- .github/workflows/test.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 36aff7a..e349587 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -39,6 +39,7 @@ jobs: source $HOME/.cargo/env pip install maturin rustup component add clippy + rustup component add rustfmt - name: Test run: | make From cf48f02ac89540b02f4edda08cb2f8dd131adb49 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 15:44:27 +0200 Subject: [PATCH 18/32] CR --- src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lib.rs b/src/lib.rs index 361a04e..36fa409 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -139,7 +139,7 @@ fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option (), _ => return None, From 4b8baac337a7c4543de8e811fe421a48c8ff8009 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 15:54:43 +0200 Subject: [PATCH 19/32] fix linting --- capara/profiler.py | 9 ++++++--- src/lib.rs | 6 +----- 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index d49229e..97abba5 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -5,15 +5,18 @@ from . import capara _reference_count = 0 -_profiler_context: ContextVar[Optional[capara.ProfilerContext]] = ContextVar("profiler_context") +_profiler_context: ContextVar[Optional[capara.ProfilerContext]] = ContextVar("profiler_context", default=None) def start() -> None: """Starts the profiler. Notes: - In case the profiler was already started in the same task, this will override existing data. + Raises RuntimeError if a context already exists in task. """ + context = _profiler_context.get() + if context: + raise RuntimeError("Profiler already exists") _profiler_context.set(capara.ProfilerContext()) global _reference_count if _reference_count == 0: @@ -31,7 +34,7 @@ def stop() -> List[Tuple[str, str, Optional[int]]]: _reference_count -= 1 if _reference_count == 0: sys.setprofile(None) - context = _profiler_context.get() + context = _profiler_context.get(None) if context is None: raise RuntimeError("No context was found, stop called without start?") entries = context.entries diff --git a/src/lib.rs b/src/lib.rs index 36fa409..32c3fe4 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -136,11 +136,7 @@ fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option (), _ => return None, }; From fe5e650ac141e371e9648e1db6316e8b26fee194 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 16:48:16 +0200 Subject: [PATCH 20/32] add flaky for tests --- pyproject.toml | 1 + tests/test_main.py | 6 ++++-- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 0d175f1..fb0619b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -14,6 +14,7 @@ isort = "^5.6.4" mypy = "^0.790" flake8 = "^3.8.4" black = "^20.8b1" +flaky = "^3.7.0" [tool.maturin] rustc-extra-args = "-C target-feature=+sse2" diff --git a/tests/test_main.py b/tests/test_main.py index f01b5df..3a87a7c 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -1,6 +1,7 @@ import asyncio import time +import pytest import capara.profiler SLEEP_TIME = 0.1 @@ -13,7 +14,7 @@ def sleep(duration: float): async def async_sleep(duration: float): time.sleep(duration) - +@pytest.mark.flaky def test_sanity(): capara.profiler.start() sleep(SLEEP_TIME) @@ -24,7 +25,7 @@ def test_sanity(): assert entry[1] == "sleep" assert entry[2] // 100000000 == SLEEP_TIME * 10 - +@pytest.mark.flaky def test_sanity_context(): profiler = capara.profiler.Profiler() with profiler: @@ -37,6 +38,7 @@ def test_sanity_context(): assert entry[2] // 100000000 == SLEEP_TIME * 10 +@pytest.mark.flaky def test_sanity_async(): loop = asyncio.get_event_loop() capara.profiler.start() From cc2e0e548bbc9b9cbc2d11847ba7c9711e487257 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 16:51:54 +0200 Subject: [PATCH 21/32] linting --- tests/test_main.py | 41 ++++++++++++++++++++++++++++++----------- 1 file changed, 30 insertions(+), 11 deletions(-) diff --git a/tests/test_main.py b/tests/test_main.py index 3a87a7c..3065ff7 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -2,6 +2,7 @@ import time import pytest + import capara.profiler SLEEP_TIME = 0.1 @@ -14,6 +15,7 @@ def sleep(duration: float): async def async_sleep(duration: float): time.sleep(duration) + @pytest.mark.flaky def test_sanity(): capara.profiler.start() @@ -25,6 +27,7 @@ def test_sanity(): assert entry[1] == "sleep" assert entry[2] // 100000000 == SLEEP_TIME * 10 + @pytest.mark.flaky def test_sanity_context(): profiler = capara.profiler.Profiler() @@ -53,15 +56,31 @@ def test_sanity_async(): assert entry[2] // 100000000 == SLEEP_TIME * 10 -def test_concurrent_tasks(): - loop = asyncio.get_event_loop() - capara.profiler.start() - loop.run_until_complete(async_sleep(SLEEP_TIME)) - data = capara.profiler.stop() - for entry in data: - if entry[1] == "async_sleep": - break +async def async_task_self_profiling(): + """ + Task that runs a profiler, then returns the results. + """ + profiler = capara.profiler.Profiler() + with profiler: + await async_sleep(SLEEP_TIME) + return profiler.results - assert entry[0] == __file__ - assert entry[1] == "async_sleep" - assert entry[2] // 100000000 == SLEEP_TIME * 10 + +async def run_multi_tasks(): + tasks = {async_task_self_profiling(), async_task_self_profiling(), async_task_self_profiling()} + done, pending = await asyncio.wait(tasks) + return [task.result() for task in done] + + +# def test_concurrent_tasks(): +# loop = asyncio.get_event_loop() +# data = loop.run_until_complete(run_multi_tasks()) +# data = capara.profiler.stop() +# for profiler in data: +# for entry in profiler: +# if entry[1] == "async_sleep": +# break + +# assert entry[0] == __file__ +# assert entry[1] == "async_sleep" +# assert entry[2] // 100000000 == SLEEP_TIME * 10 From 9d03d88cfabeb78b93402b31274d987d768114b0 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 17:03:16 +0200 Subject: [PATCH 22/32] add concurrency tests, fix some small stuff in profiler --- capara/profiler.py | 2 +- tests/test_main.py | 23 +++++++++++------------ 2 files changed, 12 insertions(+), 13 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index 97abba5..077177e 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -34,7 +34,7 @@ def stop() -> List[Tuple[str, str, Optional[int]]]: _reference_count -= 1 if _reference_count == 0: sys.setprofile(None) - context = _profiler_context.get(None) + context = _profiler_context.get() if context is None: raise RuntimeError("No context was found, stop called without start?") entries = context.entries diff --git a/tests/test_main.py b/tests/test_main.py index 3065ff7..071d265 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -72,15 +72,14 @@ async def run_multi_tasks(): return [task.result() for task in done] -# def test_concurrent_tasks(): -# loop = asyncio.get_event_loop() -# data = loop.run_until_complete(run_multi_tasks()) -# data = capara.profiler.stop() -# for profiler in data: -# for entry in profiler: -# if entry[1] == "async_sleep": -# break - -# assert entry[0] == __file__ -# assert entry[1] == "async_sleep" -# assert entry[2] // 100000000 == SLEEP_TIME * 10 +def test_concurrent_tasks(): + loop = asyncio.get_event_loop() + data = loop.run_until_complete(run_multi_tasks()) + for profiler in data: + for entry in profiler: + if entry[1] == "async_sleep": + break + + assert entry[0] == __file__ + assert entry[1] == "async_sleep" + assert entry[2] // 100000000 == SLEEP_TIME * 10 From 477aed81354cc57c12c1e78818408854c3ff3fbf Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 17:08:49 +0200 Subject: [PATCH 23/32] tests and fixces --- capara/profiler.py | 8 ++++++-- pyproject.toml | 1 + tests/test_main.py | 13 +++++++++++++ 3 files changed, 20 insertions(+), 2 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index 077177e..b1e505f 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -14,8 +14,7 @@ def start() -> None: Notes: Raises RuntimeError if a context already exists in task. """ - context = _profiler_context.get() - if context: + if not is_active(): raise RuntimeError("Profiler already exists") _profiler_context.set(capara.ProfilerContext()) global _reference_count @@ -44,6 +43,11 @@ def stop() -> List[Tuple[str, str, Optional[int]]]: return entries +def is_active() -> bool: + """Checks if profiler is active for current context.""" + return _profiler_context.get() is not None + + class Profiler: def __init__(self): self.results: Optional[List[Tuple[str, str, Optional[int]]]] = None diff --git a/pyproject.toml b/pyproject.toml index fb0619b..8ca99c2 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -15,6 +15,7 @@ mypy = "^0.790" flake8 = "^3.8.4" black = "^20.8b1" flaky = "^3.7.0" +pytest-sugar = "^0.9.4" [tool.maturin] rustc-extra-args = "-C target-feature=+sse2" diff --git a/tests/test_main.py b/tests/test_main.py index 071d265..450661c 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -72,6 +72,7 @@ async def run_multi_tasks(): return [task.result() for task in done] +@pytest.mark.flaky def test_concurrent_tasks(): loop = asyncio.get_event_loop() data = loop.run_until_complete(run_multi_tasks()) @@ -83,3 +84,15 @@ def test_concurrent_tasks(): assert entry[0] == __file__ assert entry[1] == "async_sleep" assert entry[2] // 100000000 == SLEEP_TIME * 10 + + +def test_double_start_error(): + capara.profiler.start() + with pytest.raises(RuntimeError): + capara.profiler.start() + capara.profiler.stop() + + +def test_stop_without_start(): + with pytest.raises(RuntimeError): + capara.profiler.stop() From f85fe9164dbbb3456194a990dc5c9051ff843846 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Fri, 30 Oct 2020 17:17:00 +0200 Subject: [PATCH 24/32] fix typo --- capara/profiler.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/capara/profiler.py b/capara/profiler.py index b1e505f..67754c1 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -14,7 +14,7 @@ def start() -> None: Notes: Raises RuntimeError if a context already exists in task. """ - if not is_active(): + if is_active(): raise RuntimeError("Profiler already exists") _profiler_context.set(capara.ProfilerContext()) global _reference_count From a0d109a56cab4b03e54ab551902e8a36444db7b0 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 01:44:50 +0200 Subject: [PATCH 25/32] guyzyl CR fixes --- capara/profiler.py | 48 ++++++++++++++++++++++++++++++------------ tests/requirements.txt | 1 - tests/test_main.py | 46 ++++++++++++++++++++-------------------- 3 files changed, 58 insertions(+), 37 deletions(-) delete mode 100644 tests/requirements.txt diff --git a/capara/profiler.py b/capara/profiler.py index 67754c1..7b769da 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -1,10 +1,33 @@ import sys from contextvars import ContextVar -from typing import List, Optional, Tuple +from dataclasses import dataclass +from typing import List, Optional from . import capara -_reference_count = 0 + +@dataclass +class ReferenceCount: + count: int = 0 + + +@dataclass +class ProfilerEntry: + func_name: str + file_name: str + duration: Optional[int] = None + + @classmethod + def from_tuple(cls, file_name: str, func_name: str, duration: Optional[int]) -> "ProfilerEntry": + return cls(file_name=file_name, func_name=func_name, duration=duration) + + +@dataclass +class ProfilerResult: + entries: List[ProfilerEntry] + + +_reference_count = ReferenceCount() _profiler_context: ContextVar[Optional[capara.ProfilerContext]] = ContextVar("profiler_context", default=None) @@ -17,21 +40,20 @@ def start() -> None: if is_active(): raise RuntimeError("Profiler already exists") _profiler_context.set(capara.ProfilerContext()) - global _reference_count - if _reference_count == 0: + + if _reference_count.count == 0: capara.start(_profiler_context) - _reference_count += 1 + _reference_count.count += 1 -def stop() -> List[Tuple[str, str, Optional[int]]]: +def stop() -> ProfilerResult: """Stops the profiler. Completely stops the profiler only if reference count equals to zero. Returns: - List of profiler events, each event is a tuple of (file_name, func_name, duration). + ProfilerResult """ - global _reference_count - _reference_count -= 1 - if _reference_count == 0: + _reference_count.count -= 1 + if _reference_count.count == 0: sys.setprofile(None) context = _profiler_context.get() if context is None: @@ -40,7 +62,7 @@ def stop() -> List[Tuple[str, str, Optional[int]]]: # Remove stop function entry to avoid garbage entries.remove((__file__, "stop", None)) _profiler_context.set(None) - return entries + return ProfilerResult(entries=[ProfilerEntry.from_tuple(*entry) for entry in entries]) def is_active() -> bool: @@ -50,11 +72,11 @@ def is_active() -> bool: class Profiler: def __init__(self): - self.results: Optional[List[Tuple[str, str, Optional[int]]]] = None + self.results: Optional[ProfilerResult] = None def __enter__(self): start() def __exit__(self, exc_type, exc_value, exc_traceback): self.results = stop() - self.results.remove((__file__, "__exit__", None)) + self.results.entries.remove(ProfilerEntry(file_name=__file__, func_name="__exit__", duration=None)) diff --git a/tests/requirements.txt b/tests/requirements.txt deleted file mode 100644 index fa708f8..0000000 --- a/tests/requirements.txt +++ /dev/null @@ -1 +0,0 @@ -pytest>=6.1.2 \ No newline at end of file diff --git a/tests/test_main.py b/tests/test_main.py index 450661c..ff61124 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -20,12 +20,12 @@ async def async_sleep(duration: float): def test_sanity(): capara.profiler.start() sleep(SLEEP_TIME) - data = capara.profiler.stop() - assert len(data) == 1 - entry = data[0] - assert entry[0] == __file__ - assert entry[1] == "sleep" - assert entry[2] // 100000000 == SLEEP_TIME * 10 + result = capara.profiler.stop() + assert len(result.entries) == 1 + entry = result.entries[0] + assert entry.file_name == __file__ + assert entry.func_name == "sleep" + assert entry.duration // 100000000 == SLEEP_TIME * 10 @pytest.mark.flaky @@ -33,12 +33,12 @@ def test_sanity_context(): profiler = capara.profiler.Profiler() with profiler: sleep(SLEEP_TIME) - data = profiler.results - assert len(data) == 1 - entry = data[0] - assert entry[0] == __file__ - assert entry[1] == "sleep" - assert entry[2] // 100000000 == SLEEP_TIME * 10 + result = profiler.results + assert len(result.entries) == 1 + entry = result.entries[0] + assert entry.file_name == __file__ + assert entry.func_name == "sleep" + assert entry.duration // 100000000 == SLEEP_TIME * 10 @pytest.mark.flaky @@ -46,14 +46,14 @@ def test_sanity_async(): loop = asyncio.get_event_loop() capara.profiler.start() loop.run_until_complete(async_sleep(SLEEP_TIME)) - data = capara.profiler.stop() - for entry in data: - if entry[1] == "async_sleep": + result = capara.profiler.stop() + for entry in result.entries: + if entry.func_name == "async_sleep": break - assert entry[0] == __file__ - assert entry[1] == "async_sleep" - assert entry[2] // 100000000 == SLEEP_TIME * 10 + assert entry.file_name == __file__ + assert entry.func_name == "async_sleep" + assert entry.duration // 100000000 == SLEEP_TIME * 10 async def async_task_self_profiling(): @@ -77,13 +77,13 @@ def test_concurrent_tasks(): loop = asyncio.get_event_loop() data = loop.run_until_complete(run_multi_tasks()) for profiler in data: - for entry in profiler: - if entry[1] == "async_sleep": + for entry in profiler.entries: + if entry.func_name == "async_sleep": break - assert entry[0] == __file__ - assert entry[1] == "async_sleep" - assert entry[2] // 100000000 == SLEEP_TIME * 10 + assert entry.file_name == __file__ + assert entry.func_name == "async_sleep" + assert entry.duration // 100000000 == SLEEP_TIME * 10 def test_double_start_error(): From 7577b2c34f0c8adbe6672c423e0b13901629e9b0 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 02:04:36 +0200 Subject: [PATCH 26/32] CR fixes by oskar --- src/lib.rs | 73 +++++++++++++++++++++++++++--------------------------- 1 file changed, 36 insertions(+), 37 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 32c3fe4..d5e2c14 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -13,6 +13,7 @@ use std::time::Instant; /// Enum of possible Python's Trace/Profiling events #[allow(dead_code)] +#[non_exhaustive] #[repr(i32)] enum TraceEvent { Call, @@ -23,14 +24,15 @@ enum TraceEvent { CException, CReturn, Opcode, - __NonExhaustive, } +const LARGER_THAN_ANY_TRACE_EVENT: i32 = TraceEvent::Opcode as i32 + 1; + impl TryFrom for TraceEvent { type Error = &'static str; /// Cast i32 event (raw from Python) to Rust enum. fn try_from(value: i32) -> Result { - if value > 7 || value < 0 { + if value >= LARGER_THAN_ANY_TRACE_EVENT || value < 0 { return Err("Not valid enum value"); } Ok(unsafe { std::mem::transmute(value) }) @@ -43,7 +45,7 @@ struct FrameData { func_name: String, file_name: String, identifier: usize, - yielded_coroutine: bool, + is_yielded_coroutine: bool, } impl TryFrom<*mut PyFrameObject> for FrameData { @@ -60,32 +62,29 @@ impl TryFrom<*mut PyFrameObject> for FrameData { } let code = unsafe { *dframe.f_code }; - let yielded_coroutine = { - (0 < (code.co_flags & CO_COROUTINE) - | (code.co_flags & CO_ITERABLE_COROUTINE) - | (code.co_flags & CO_ASYNC_GENERATOR)) + let is_yielded_coroutine = { + (code.co_flags & (CO_COROUTINE | CO_ITERABLE_COROUTINE | CO_ASYNC_GENERATOR) > 0) && (!dframe.f_stacktop.is_null()) }; - unsafe { - let file_name = match code.co_filename.is_null() { - true => "null".to_string(), - false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_filename)) - .to_string_lossy() - .into_owned(), - }; - let func_name = match code.co_name.is_null() { - true => "null".to_string(), - false => CStr::from_ptr(PyUnicode_AsUTF8(code.co_name)) - .to_string_lossy() - .into_owned(), - }; - Ok(FrameData { - func_name, - file_name, - identifier: frame as usize, - yielded_coroutine, - }) + let file_name = pyo3_to_string(code.co_filename); + let func_name = pyo3_to_string(code.co_name); + Ok(FrameData { + func_name, + file_name, + identifier: frame as usize, + is_yielded_coroutine, + }) + } +} + +fn pyo3_to_string(obj: *mut pyo3::ffi::PyObject) -> String { + unsafe { + match obj.is_null() { + true => "".to_string(), + false => CStr::from_ptr(PyUnicode_AsUTF8(obj)) + .to_string_lossy() + .into_owned(), } } } @@ -107,10 +106,9 @@ struct ProfilerContext { /// Format an entry into file_name, func_name and duration. fn format_entry(entry: &ProfilerEntry) -> (String, String, Option) { - let duration = match entry.end { - Some(v) => Some(v.duration_since(entry.start).as_nanos()), - None => None, - }; + let duration = entry + .end + .and_then(|v| Some(v.duration_since(entry.start).as_nanos())); (entry.file_name.clone(), entry.func_name.clone(), duration) } @@ -124,11 +122,12 @@ impl ProfilerContext { } #[getter] fn entries(&mut self) -> PyResult)>> { - let mut result = Vec::new(); - for (_, entry) in self.entries.get_mut().iter() { - result.push(format_entry(entry)); - } - Ok(result) + Ok(self + .entries + .get_mut() + .iter() + .map(|(_, entry)| format_entry(entry)) + .collect()) } } @@ -192,14 +191,14 @@ extern "C" fn callback( .insert(frame_data.identifier, entry); } TraceEvent::Return => { - if frame_data.yielded_coroutine { + if frame_data.is_yielded_coroutine { return 0; } if let Some(entry) = context.entries.get_mut().get_mut(&frame_data.identifier) { entry.end = Some(Instant::now()); }; } - _ => println!("shouldn't happen"), + _ => unreachable!(), } 0 } From 2f07fbf4b162de29bfd01588020196b7fb423ed1 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 16:38:06 +0200 Subject: [PATCH 27/32] more tests --- tests/test_main.py | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/tests/test_main.py b/tests/test_main.py index ff61124..65a7132 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -93,6 +93,21 @@ def test_double_start_error(): capara.profiler.stop() +def test_async_double_start_error(): + async def second_task(): + profiler = capara.profiler.Profiler() + with profiler: + await async_sleep(SLEEP_TIME) + + async def first_task(): + profiler = capara.profiler.Profiler() + with profiler, pytest.raises(RuntimeError): + await second_task() + + loop = asyncio.get_event_loop() + loop.run_until_complete(first_task()) + + def test_stop_without_start(): with pytest.raises(RuntimeError): capara.profiler.stop() From 960542129b9ed217b6ad3633bfa999db86a1a194 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 17:33:26 +0200 Subject: [PATCH 28/32] cr fixes --- capara/profiler.py | 37 +++++++++++++++---------------------- 1 file changed, 15 insertions(+), 22 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index 7b769da..119b762 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -1,49 +1,39 @@ import sys from contextvars import ContextVar from dataclasses import dataclass -from typing import List, Optional +from typing import List, NamedTuple, Optional from . import capara - -@dataclass -class ReferenceCount: - count: int = 0 +_reference_count = 0 +_profiler_context: ContextVar[Optional[capara.ProfilerContext]] = ContextVar("profiler_context", default=None) -@dataclass -class ProfilerEntry: - func_name: str +class ProfilerEntry(NamedTuple): file_name: str + func_name: str duration: Optional[int] = None - @classmethod - def from_tuple(cls, file_name: str, func_name: str, duration: Optional[int]) -> "ProfilerEntry": - return cls(file_name=file_name, func_name=func_name, duration=duration) - @dataclass class ProfilerResult: entries: List[ProfilerEntry] -_reference_count = ReferenceCount() -_profiler_context: ContextVar[Optional[capara.ProfilerContext]] = ContextVar("profiler_context", default=None) - - def start() -> None: """Starts the profiler. Notes: Raises RuntimeError if a context already exists in task. """ + global _reference_count if is_active(): raise RuntimeError("Profiler already exists") _profiler_context.set(capara.ProfilerContext()) - if _reference_count.count == 0: + if _reference_count == 0: capara.start(_profiler_context) - _reference_count.count += 1 + _reference_count += 1 def stop() -> ProfilerResult: @@ -52,8 +42,10 @@ def stop() -> ProfilerResult: Returns: ProfilerResult """ - _reference_count.count -= 1 - if _reference_count.count == 0: + global _reference_count + if _reference_count > 0: + _reference_count -= 1 + if _reference_count == 0: sys.setprofile(None) context = _profiler_context.get() if context is None: @@ -62,7 +54,7 @@ def stop() -> ProfilerResult: # Remove stop function entry to avoid garbage entries.remove((__file__, "stop", None)) _profiler_context.set(None) - return ProfilerResult(entries=[ProfilerEntry.from_tuple(*entry) for entry in entries]) + return ProfilerResult(entries=[ProfilerEntry(*entry) for entry in entries]) def is_active() -> bool: @@ -76,7 +68,8 @@ def __init__(self): def __enter__(self): start() + return self def __exit__(self, exc_type, exc_value, exc_traceback): self.results = stop() - self.results.entries.remove(ProfilerEntry(file_name=__file__, func_name="__exit__", duration=None)) + self.results.entries.remove(ProfilerEntry(__file__, "__exit__", None)) From b646c6a242fe3241f28c9ac2d3e502c3e08d6c7a Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 19:13:26 +0200 Subject: [PATCH 29/32] fix --- capara/capara.pyi | 3 ++- capara/profiler.py | 12 ++++++------ pyproject.toml | 1 + tests/test_main.py | 16 +++++++++++++--- 4 files changed, 22 insertions(+), 10 deletions(-) diff --git a/capara/capara.pyi b/capara/capara.pyi index ea1e9c3..3f48399 100644 --- a/capara/capara.pyi +++ b/capara/capara.pyi @@ -2,6 +2,7 @@ from contextvars import ContextVar from typing import List, Optional, Tuple class ProfilerContext: - entries: List[Tuple[str, str, Optional[int]]] + # file_name, func_name, duration, index + entries: List[Tuple[str, str, Optional[int], int]] def start(context: ContextVar[Optional[ProfilerContext]]) -> None: ... diff --git a/capara/profiler.py b/capara/profiler.py index 119b762..f8517c2 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -12,7 +12,8 @@ class ProfilerEntry(NamedTuple): file_name: str func_name: str - duration: Optional[int] = None + duration: Optional[int] + call_index: int @dataclass @@ -40,7 +41,7 @@ def stop() -> ProfilerResult: """Stops the profiler. Completely stops the profiler only if reference count equals to zero. Returns: - ProfilerResult + ProfilerResult, with entries sorted by call_index. """ global _reference_count if _reference_count > 0: @@ -51,10 +52,10 @@ def stop() -> ProfilerResult: if context is None: raise RuntimeError("No context was found, stop called without start?") entries = context.entries - # Remove stop function entry to avoid garbage - entries.remove((__file__, "stop", None)) _profiler_context.set(None) - return ProfilerResult(entries=[ProfilerEntry(*entry) for entry in entries]) + formatted_entries = [ProfilerEntry(*entry) for entry in entries] + formatted_entries.sort(key=lambda x: x.call_index) + return ProfilerResult(entries=formatted_entries) def is_active() -> bool: @@ -72,4 +73,3 @@ def __enter__(self): def __exit__(self, exc_type, exc_value, exc_traceback): self.results = stop() - self.results.entries.remove(ProfilerEntry(__file__, "__exit__", None)) diff --git a/pyproject.toml b/pyproject.toml index 8ca99c2..8163d1e 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -16,6 +16,7 @@ flake8 = "^3.8.4" black = "^20.8b1" flaky = "^3.7.0" pytest-sugar = "^0.9.4" +maturin = "^0.8.3" [tool.maturin] rustc-extra-args = "-C target-feature=+sse2" diff --git a/tests/test_main.py b/tests/test_main.py index 65a7132..df55d85 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -13,7 +13,10 @@ def sleep(duration: float): async def async_sleep(duration: float): - time.sleep(duration) + await asyncio.sleep(duration) + +async def real_sleep(duration: float): + sleep(duration) @pytest.mark.flaky @@ -21,11 +24,12 @@ def test_sanity(): capara.profiler.start() sleep(SLEEP_TIME) result = capara.profiler.stop() - assert len(result.entries) == 1 + assert len(result.entries) == 2 entry = result.entries[0] assert entry.file_name == __file__ assert entry.func_name == "sleep" assert entry.duration // 100000000 == SLEEP_TIME * 10 + assert entry.call_index == 0 @pytest.mark.flaky @@ -34,11 +38,12 @@ def test_sanity_context(): with profiler: sleep(SLEEP_TIME) result = profiler.results - assert len(result.entries) == 1 + assert len(result.entries) == 3 entry = result.entries[0] assert entry.file_name == __file__ assert entry.func_name == "sleep" assert entry.duration // 100000000 == SLEEP_TIME * 10 + assert entry.call_index == 0 @pytest.mark.flaky @@ -54,6 +59,7 @@ def test_sanity_async(): assert entry.file_name == __file__ assert entry.func_name == "async_sleep" assert entry.duration // 100000000 == SLEEP_TIME * 10 + assert entry.call_index == 20 async def async_task_self_profiling(): @@ -84,6 +90,7 @@ def test_concurrent_tasks(): assert entry.file_name == __file__ assert entry.func_name == "async_sleep" assert entry.duration // 100000000 == SLEEP_TIME * 10 + assert entry.call_index == 0 def test_double_start_error(): @@ -111,3 +118,6 @@ async def first_task(): def test_stop_without_start(): with pytest.raises(RuntimeError): capara.profiler.stop() + + +# def test_blocking_asyncio_concurrency(): From 2431c32d8fb4a9baf9a8e448950f172e22f6c40d Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 20:30:52 +0200 Subject: [PATCH 30/32] Add call index, stop now returns list sorted by call index. Fix handling None/invalid values in getcontext. Fixxed async tests --- src/lib.rs | 37 +++++++++++++++++++++++++++++++------ tests/test_main.py | 1 + 2 files changed, 32 insertions(+), 6 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index d5e2c14..b48cc4b 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -10,6 +10,7 @@ use std::convert::{TryFrom, TryInto}; use std::ffi::CStr; use std::os::raw::c_int; use std::time::Instant; +use std::cell::Cell; /// Enum of possible Python's Trace/Profiling events #[allow(dead_code)] @@ -96,20 +97,27 @@ struct ProfilerEntry { func_name: String, start: Instant, end: Option, + index: i32, } /// Profiler context to be used as a value for ContextVar. #[pyclass] struct ProfilerContext { - entries: std::cell::Cell>, + entries: Cell>, + count: i32, } /// Format an entry into file_name, func_name and duration. -fn format_entry(entry: &ProfilerEntry) -> (String, String, Option) { +fn format_entry(entry: &ProfilerEntry) -> (String, String, Option, i32) { let duration = entry .end .and_then(|v| Some(v.duration_since(entry.start).as_nanos())); - (entry.file_name.clone(), entry.func_name.clone(), duration) + ( + entry.file_name.clone(), + entry.func_name.clone(), + duration, + entry.index, + ) } #[pymethods] @@ -117,11 +125,12 @@ impl ProfilerContext { #[new] fn new() -> Self { ProfilerContext { - entries: std::cell::Cell::new(HashMap::new()), + entries: Cell::new(HashMap::new()), + count: 0, } } #[getter] - fn entries(&mut self) -> PyResult)>> { + fn entries(&mut self) -> PyResult, i32)>> { Ok(self .entries .get_mut() @@ -141,7 +150,13 @@ fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option().is_instance(&context) { + Ok(true) => Some(context), + _ => None + } } /// Our profiler callback @@ -178,17 +193,27 @@ extern "C" fn callback( match event { TraceEvent::Call => { + // Frame already exists in hashmap, means that we're in a yielded function. + if context + .entries + .get_mut() + .contains_key(&frame_data.identifier) + { + return 0; + } let start = Instant::now(); let entry = ProfilerEntry { func_name: frame_data.func_name, file_name: frame_data.file_name, start, end: None, + index: context.count, }; context .entries .get_mut() .insert(frame_data.identifier, entry); + context.count += 1; } TraceEvent::Return => { if frame_data.is_yielded_coroutine { diff --git a/tests/test_main.py b/tests/test_main.py index df55d85..76af8c4 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -66,6 +66,7 @@ async def async_task_self_profiling(): """ Task that runs a profiler, then returns the results. """ + print(capara.profiler._profiler_context.get()) profiler = capara.profiler.Profiler() with profiler: await async_sleep(SLEEP_TIME) From a5f3e5e3cac607f8e685030b78b0e2341f6b5005 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sat, 31 Oct 2020 20:33:51 +0200 Subject: [PATCH 31/32] just none comparison instead of type checking --- src/lib.rs | 18 +++++++++++------- tests/test_main.py | 1 + 2 files changed, 12 insertions(+), 7 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index b48cc4b..2e4bf46 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -5,12 +5,12 @@ use pyo3::ffi::{ use pyo3::prelude::*; use pyo3::wrap_pyfunction; use pyo3::{AsPyPointer, PyAny, Python}; +use std::cell::Cell; use std::collections::HashMap; use std::convert::{TryFrom, TryInto}; use std::ffi::CStr; use std::os::raw::c_int; use std::time::Instant; -use std::cell::Cell; /// Enum of possible Python's Trace/Profiling events #[allow(dead_code)] @@ -150,12 +150,11 @@ fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option().is_instance(&context) { - Ok(true) => Some(context), - _ => None + let context = unsafe { Py::from_owned_ptr_or_opt(py, context_obj)? }; + if context.is_none(py) { + None + } else { + Some(context) } } @@ -194,6 +193,7 @@ extern "C" fn callback( match event { TraceEvent::Call => { // Frame already exists in hashmap, means that we're in a yielded function. + if context .entries .get_mut() @@ -201,6 +201,7 @@ extern "C" fn callback( { return 0; } + let start = Instant::now(); let entry = ProfilerEntry { func_name: frame_data.func_name, @@ -209,16 +210,19 @@ extern "C" fn callback( end: None, index: context.count, }; + context .entries .get_mut() .insert(frame_data.identifier, entry); + context.count += 1; } TraceEvent::Return => { if frame_data.is_yielded_coroutine { return 0; } + if let Some(entry) = context.entries.get_mut().get_mut(&frame_data.identifier) { entry.end = Some(Instant::now()); }; diff --git a/tests/test_main.py b/tests/test_main.py index 76af8c4..13c09ed 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -15,6 +15,7 @@ def sleep(duration: float): async def async_sleep(duration: float): await asyncio.sleep(duration) + async def real_sleep(duration: float): sleep(duration) From e7b42d9308c201588112b8e96e89add7ed4cfa57 Mon Sep 17 00:00:00 2001 From: Aviram Hassan Date: Sun, 1 Nov 2020 08:52:11 +0200 Subject: [PATCH 32/32] beautification --- capara/profiler.py | 1 + src/lib.rs | 2 -- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/capara/profiler.py b/capara/profiler.py index f8517c2..24672f5 100644 --- a/capara/profiler.py +++ b/capara/profiler.py @@ -12,6 +12,7 @@ class ProfilerEntry(NamedTuple): file_name: str func_name: str + # Duration in nanoseconds. duration: Optional[int] call_index: int diff --git a/src/lib.rs b/src/lib.rs index 2e4bf46..30d8114 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -149,7 +149,6 @@ fn get_context(py: Python, obj: *mut pyo3::ffi::PyObject) -> Option return None, }; } - let context = unsafe { Py::from_owned_ptr_or_opt(py, context_obj)? }; if context.is_none(py) { None @@ -242,7 +241,6 @@ fn start(context_var: &PyAny) -> PyResult<()> { } #[pymodule] -/// A Python module implemented in Rust. fn capara(_py: Python, m: &PyModule) -> PyResult<()> { m.add_function(wrap_pyfunction!(start, m)?)?; m.add_class::()?;