Add speedscope renderer #160

goxberry · 2021-10-25T14:57:46Z

This pull request adds a renderer that outputs JSON conforming to speedscope's JSON schema; in particular, speedscope's "evented" format is used.

This implementation is very rough, and intended as a request for comment. I expect to revise this pull request based on feedback from the project maintainer(s) to better conform with project style.

Closes #89.

joerick

Thank you @goxberry ! This could be a nice addition. I haven't had time for a full review, but here are some thoughts.

joerick · 2021-10-27T08:20:02Z

pyinstrument/renderers/speedscope.py

+def encode_speedscope_frame(sframe: SpeedscopeFrame) -> str:
+    """Returns a string encoding a SpeedscopeFrame as a JSON object."""
+
+    property_decls: list[str] = []
+    property_decls.append('"name": %s' % encode_str(sframe.name))
+    property_decls.append('"file": %s' % encode_str(sframe.file))
+    property_decls.append('"line": %d' % sframe.line)
+
+    return "{%s}" % ",".join(property_decls)


The existing jsonmodule.py uses this structure to encode JSON due to limits on the depth of objects that the built-in json module can't handle. This code would be neater just using json.dumps.

I see there are a few other places where the code is building json as strings. The thing to try here is to add your renderer to the overflow test - test/test_overflow.py - if that passes, and you can use the built-in json module, that would be preferable.

To make the code neater, I have:

added JSON encoders for SpeedscopeEvent and SpeedscopeFrame in beb07eac and 9d32a191, respectively

replaced the encode_speedscope_event and encode_speedscope_frame calls with calls to json.dumps in 582925f5 and a78ee717, respectively

deleted the encode_speedscope_event and encode_speedscope_frame functions in 7a4f2e8b and 4a9ccfd4, respectively

So far, the overflow test passes. I think converting other parts of SpeedscopeRenderer to use json.dumps should be straightforward.

As part of porting the rest of the SpeedscopeRenderer implementation to use json.dumps, I ended up replacing the NamedTuple types with dataclasses, because those are easier to serialize to JSON via the __dict__ field. This work should be done as of e66984e4.

pyinstrument/renderers/speedscope.py

goxberry · 2021-10-28T06:58:25Z

I think this PR is probably ready for a second review.

joerick

Brilliant, this is looking really good, @goxberry! I appreciate the effort you've put into this :)

Would you be able to add the Speedscope renderer to the overflow test and write a simple test for the speedscope output?

I'm thinking something like:

test starts profiler
test calls function a
- function a calls function b
  - function b sleeps (you can use 'fake time' for this, see other tests)
  - function b returns
- function a returns
test stops profiler
test renders speedscope JSON
test loads speedscope JSON
test checks a few things about the JSON, I suppose, a few things about events and metadata. I'm not sure of the specifics, perhaps the events should be [open, open, close, close]?

goxberry · 2021-11-05T20:29:10Z

@joerick Thanks! And thank you for your review and for writing this profiler! Your design has made it straightforward to add this new feature. As you've suggested, I've added SpeedscopeRenderer to the tests in test/test_overflow.py and test/test_profiler.py. Because the functions long_function_a and long_function_b within test/test_profiler.py call the sleep function, calling both long_function_a and long_function_b suffices to generate an event timeline with nested function calls, so I elected to make the test_speedscope_output test similar to the other test_*_output tests for simplicity.

As a result of testing, I noticed something peculiar in SpeedscopeRenderer and wanted to get your insight about what might be happening. When I run test_profiler.test_speedscope_output in a debugger and:

set a breakpoint at test/test_profiler.py:149 and continue until I reach it
step into pyinstrument/renderers/speedscope.py
set another breakpoint at pyinstrument/renderers/speedscopy.py:220 and continue until I reach it

I notice that the value of session.duration at that line is less than the value of self._event_time, and I'm not sure why session.duration < self._event_time; I would have expected session.duration >= self._event_time.

You should be able to reproduce this phenomenon yourself by running in a terminal:

> pytest --trace ${PATH_TO_PYINSTRUMENT_REPO}/test/test_profiler.py -k "test_speedscope_output"
(Pdb) b 149
(Pdb) c
(Pdb) s    # should step into speedscope.py.__init__() here
(Pdb) b 220
(Pdb) c
(Pdb) p session.duration     # on my machine, this command prints the value 0.00041103363037109375
(Pdb) p self._event_time      # on my machine, this command prints 0.75, as expected, within a tolerance of 0.3

where the first > denotes a shell prompt, and the (Pdb) denotes a pdb debugger prompt.

Do you have any insight as to why this behavior might occur?

joerick · 2021-11-06T15:19:36Z

Hi @goxberry! Yes, I can offer an explanation. The session.duration is computed by calling time.time() before and after profiling. But we are using 'fake time', which is defined here:

pyinstrument/test/fake_time_util.py

Lines 23 to 32 in 96dcb80

    
           @contextlib.contextmanager 
        
           def fake_time(fake_clock=None): 
        
               fake_clock = fake_clock or FakeClock() 
        
               stack_sampler.get_stack_sampler().timer_func = fake_clock.get_time 
        
               try: 
        
                   with mock.patch("time.sleep", new=fake_clock.sleep): 
        
                       yield fake_clock 
        
               finally: 
        
                   stack_sampler.get_stack_sampler().timer_func = None

This monkeypatches time.sleep and some internal machinery, but not time.time. So in the reality the session duration is correct, very little time has passed, but the test has a simulated reality, where time has passed!

If this is causing a problem, you could edit the fake_time function to also monkeypatch time.time (returning fake_clock.get_time should do the trick). Or we can just ignore the difference :)

goxberry · 2021-11-07T01:47:26Z

Thanks for the explanation!

If this is causing a problem, you could edit the fake_time function to also monkeypatch time.time (returning fake_clock.get_time should do the trick). Or we can just ignore the difference :)

In the interest of pragmatism, let's ignore the difference. I'll revert the change in SpeedscopeRenderer regarding session.duration vs self._event_time and remove the assertion checking the endValue field in the Speedscope output.

joerick

Hi @goxberry! Thanks for adding the test. I have a couple requests :)

test/test_profiler.py

This commit starts the implementation of a speedscope renderer by: * copying the existing JSONRenderer to a new SpeedscopeRenderer class in `speedscope.py` of the `renderers` directory * adding an import hook to `__init__.py` of the `renderers` directory * adding a `speedscope` option to the `-r` flag at the command line

This commit replaces the SpeedscopeRenderer implementation copied from JSONRenderer with an implementation of an "evented" speedscope JSON profile output file writer. The file format is documented in a few different ways, listed below: * the speedscope GitHub repo wiki: https://github.com/jlfwong/speedscope/wiki/Importing-from-custom-sources * the speedscope JSON schema: https://www.speedscope.app/file-format-schema.json * a Typescript file documenting the schema https://github.com/jlfwong/speedscope/blob/master/src/lib/file-format-spec.ts * a simple example https://github.com/jlfwong/speedscope/blob/100578c536a3afab39fb6803d28913d12eac29c5/sample/profiles/speedscope/0.0.1/simple.speedscope.json The style of the implementation needs obvious work; this commit is intended as a starting point for a pull request with the expectation that upstream maintainer feedback will be needed to fix any style or documentation issues.

This commit deletes the jsonrenderer comment in the SpeedscopeRenderer implementation; the source file is obviously not named jsonrenderer.

This commit converts SpeedscopeFrame from a non-class-style namedtuple to a class-style namedtuple for readability.

This commit uncomments the SpeedscopeEventType enumeration class and uses it in the SpeedscopeRenderer implementation.

This commit converts the SpeedscopeEvent namedtuple from non-class-type to class-type to make it more self-documenting and to conform with project guidelines regarding type hints.

This commit revises the docstring for SpeedscopeRenderer.render_frame by deleting text that no longer applies to the implementation of this method.

This commit uses the previously-unused profile_name object within SpeedscopeRenderer.render.

This commit adds a JSON encoder class for the SpeedscopeEvent namedtuple in order to stand up a SpeedscopeRenderer implementation based on the Python json module.

This commit renames the _total_time field to _event_time in order to clarify its purpose in the SpeedscopeRenderer class.

This commit replaces calls of the encode_speedscope_frame function with json.dumps calls.

This commit deletes the encode_speedscope_event function because it is no longer needed, and has been replaced with calls to json.dumps and SpeedscopeEventEncoder.

This commit adds a JSON encoder for the SpeedscopeFrame class to try to stand up a SpeedscopeRenderer implementation that uses the json module.

This commit replaces calls of encode_frame with calls of json.dumps.

This commit deletes the encode_frame function because it is no longer used.

This commit adds type hints to the Speedscope-related JSON encoders.

This commit deletes the import of `collections.namedtuple` because the speedscope renderer now uses class-style namedtuple definitions.

This commit corrects the type hints by making each field a union type with None, because `pyright` does not detect that `frame` cannot be `None` where `SpeedscopeFrame.__init__` is invoked.

This commit removes type hints from `SpeedscopeEventType` in order to silence some `pyright` errors regarding incorrect types when using `str` as the type hint for each value.

This commit changes the SpeedscopeFrame and SpeedscopeEvent types from class-style namedtuples to dataclasses because I couldn't figure out how to serialize namedtuples to JSON objects via: * subclassing json.JSONEncoder * defining a default method Attempting to return a dictionary using the data in each namedtuple did not seem to yield a string containing a JSON object; instead, a string containing a JSON array was returned. Changing the namedtuple types to dataclasses and leveraging the __dict__ dunder field, in concert with subclassing json.JSONEncoder and defining a default method, yielded the desired result, although memory usage will increase slightly.

This commit adds a SpeedscopeProfile class that stores the data corresponding to speedscope "profile" objects, and adds a SpeedscopeProfileEncoder class to serialize that class to JSON. The encoder classes will be consolidated in a later commit.

This commit deletes the commented-out dead code used by the pure string approach to serializing speedscope profile objects.

This commit deletes an orphaned LIFO iteration order comment about dictionaries in Python 3.7+.

This commit adds a SpeedscopeFile data class and a SpeedscopeEncoder class to serialize to JSON the SpeedscopeFrame, SpeedscopeEvent, SpeedscopeProfile, SpeedscopeEventType, and SpeedscopeFile data classes.

This commit revises the SpeedscopeRenderer class by removing a lot of dead code and updating docstrings and comments in the class and its auxiliary classes.

This commit deletes the processor.aggregate_repeated_calls method from the list of default processors returned by SpeedscopeRenderer because speedscope is a timeline-based format, and aggregating repeated calls fouls up a timeline view.

This commit updates a code comment within SpeedscopeRenderer.render discussing why the frame list is constructed as it is.

This commit fixes some pyright errors in pyinstrument/renderers/speedscope.py.

This commit replaces the for loop that builds up the speedscope frame list with a list comprehension.

This commit adds SpeedscopeRenderer and the `-r speedscope` flag to the pyinstrument documentation.

This commit removes the dataclass arguments from the SpeedscopeEvent class because this class does not need to be hashable.

This commit modifies the display title of a speedscope profile exported from pyinstrument to include the timestamp of when the profile was generated (which also happens to be argument to `--load-prev` needed to render output in other formats).

This commit changes the SpeedscopeRenderer code to comply with project style guidelines regarding code formatting with black and isort.

This commit adds SpeedscopeRenderer to the overflow test in pyinstrument's test suite.

This commit fixes an apparent inconsistency in the profiles[0].endValue field of the Speedscope output from SpeedscopeRenderer. In unit testing, the value of session.duration (within a call to SpeedscopeRenderer.render) may not be equal to the event time of the last event in the profiles[0].events field of the Speedscope output. In fact, in the test_speedscope_output test within test_profiler.py, the value of session duration was approximately 0.0047s (in local testing on my laptop), whereas the time value of the last event generated by the profile in that test should be 0.75s +/- 0.3s. To correct this inconsistency, the end value of profile is set equal to the event time of the last event.

This commit adds a test to test_profiler that tests the JSON output emitted by SpeedscopeRenderer against known properties it should have.

This commit: * Removes, in `test/test_profiler.py`, the test of the value of the `"profiles[0].endValue"` field in the Speedscope JSON output. The difference between the value of `profiles[0].endValue` (equal to `session.duration` from the `session` argument passed to `SpeedscopeRenderer.render`) and the time of the last event can be attributed to the `fake_time` context manager used as a mock timer in the profiler/renderer tests. * Changes the value assigned to the `profiles[0].endValue` field via the last positional argument to `SpeedscopeProfile.__init__` from `self._event_time` (which, at that point in `SpeedscopeRenderer.render` equals the last event time) back to `session.duration`. This change is made because the discrepancy between the values of `session.duration` and `self._event_time` can be attributed to the `fake_time` context manager used as a mock timer in the profiler/renderer tests.

This commit aims to make the `test_speedscope_output` test in `test/test_profiler.py` less wordy and more readable by: * deleting message arguments to assertions * replacing local variables with literals or expressions, because many of these variables were motivated by keeping line length low in message arguments passed to assertions * removing tolerances in the pytest.approx calls because CI jitter should not affect timings, and all floating point numbers involved are exactly representable per the IEEE-754 standard

goxberry · 2021-11-08T03:56:46Z

Rebased on main.

joerick

Looks good!

RyannDaGreat · 2021-11-15T06:36:13Z

Whoah :O Thank you guys so much!! This is so cool!! :D

joerick reviewed Oct 27, 2021

View reviewed changes

goxberry force-pushed the add-speedscope-renderer branch from a6ede78 to 4a9ccfd Compare October 27, 2021 23:06

goxberry mentioned this pull request Oct 28, 2021

Add developer tools used in CI checks to requirements and add documentation on their use in this project #161

Merged

goxberry requested a review from joerick November 2, 2021 20:05

joerick reviewed Nov 4, 2021

View reviewed changes

goxberry requested a review from joerick November 5, 2021 20:01

joerick reviewed Nov 7, 2021

View reviewed changes

test/test_profiler.py Outdated Show resolved Hide resolved

test/test_profiler.py Outdated Show resolved Hide resolved

test/test_profiler.py Outdated Show resolved Hide resolved

test/test_profiler.py Outdated Show resolved Hide resolved

goxberry requested a review from joerick November 8, 2021 03:41

goxberry added 18 commits November 7, 2021 19:56

SpeedscopeRenderer: delete jsonrender comment

bc075bb

This commit deletes the jsonrenderer comment in the SpeedscopeRenderer implementation; the source file is obviously not named jsonrenderer.

SpeedscopeFrame: change to class-style namedtuple

ce9ee0e

This commit converts SpeedscopeFrame from a non-class-style namedtuple to a class-style namedtuple for readability.

SpeedscopeEventType: uncomment and use

f5a6018

This commit uncomments the SpeedscopeEventType enumeration class and uses it in the SpeedscopeRenderer implementation.

SpeedscopeEvent: convert to class style namedtuple

1da0f1d

This commit converts the SpeedscopeEvent namedtuple from non-class-type to class-type to make it more self-documenting and to conform with project guidelines regarding type hints.

SpeedscopeRenderer.render_frame: revise docstring

6c7f5ef

This commit revises the docstring for SpeedscopeRenderer.render_frame by deleting text that no longer applies to the implementation of this method.

SpeedscopeRenderer.render: use profile_name object

8ae2047

This commit uses the previously-unused profile_name object within SpeedscopeRenderer.render.

SpeedscopeEvent: add JSON encoder class

6e3284d

This commit adds a JSON encoder class for the SpeedscopeEvent namedtuple in order to stand up a SpeedscopeRenderer implementation based on the Python json module.

SpeedscopeRenderer: s/_total_time/_event_time/g;

c26322a

This commit renames the _total_time field to _event_time in order to clarify its purpose in the SpeedscopeRenderer class.

SpeedscopeRenderer: use SpeedscopeEventEncoder

82d6466

This commit replaces calls of the encode_speedscope_frame function with json.dumps calls.

SpeedscopeRenderer: delete encode_speedscope_event

8703aff

This commit deletes the encode_speedscope_event function because it is no longer needed, and has been replaced with calls to json.dumps and SpeedscopeEventEncoder.

SpeedscopeFrame: add JSON encoder

26936ce

This commit adds a JSON encoder for the SpeedscopeFrame class to try to stand up a SpeedscopeRenderer implementation that uses the json module.

SpeedscopeRenderer: use json.dumps for frames

dda76a6

This commit replaces calls of encode_frame with calls of json.dumps.

SpeedscopeRenderer: delete encode_frame function

e8df04f

This commit deletes the encode_frame function because it is no longer used.

Speedscope-related JSON encoders: add type hints

b475eee

This commit adds type hints to the Speedscope-related JSON encoders.

SpeedscopeRenderer: delete "import collections"

ff1562b

This commit deletes the import of `collections.namedtuple` because the speedscope renderer now uses class-style namedtuple definitions.

SpeedscopeFrame: correct type hints

4c71e66

This commit corrects the type hints by making each field a union type with None, because `pyright` does not detect that `frame` cannot be `None` where `SpeedscopeFrame.__init__` is invoked.

goxberry added 20 commits November 7, 2021 19:56

SpeedscopeEventType: remove type hints

8d43512

This commit removes type hints from `SpeedscopeEventType` in order to silence some `pyright` errors regarding incorrect types when using `str` as the type hint for each value.

SpeedscopeRenderer: delete commented-out dead code

ccf7fab

This commit deletes the commented-out dead code used by the pure string approach to serializing speedscope profile objects.

SpeedscopeRenderer: remove LIFO dict comment

7a22c2f

This commit deletes an orphaned LIFO iteration order comment about dictionaries in Python 3.7+.

SpeedscopeRenderer: add SpeedscopeFile data class

e2a7d43

This commit adds a SpeedscopeFile data class and a SpeedscopeEncoder class to serialize to JSON the SpeedscopeFrame, SpeedscopeEvent, SpeedscopeProfile, SpeedscopeEventType, and SpeedscopeFile data classes.

SpeedscopeRenderer: remove dead code, update docs

7443eba

This commit revises the SpeedscopeRenderer class by removing a lot of dead code and updating docstrings and comments in the class and its auxiliary classes.

SpeedscopeRenderer: omit repeated call aggregator

826f310

This commit deletes the processor.aggregate_repeated_calls method from the list of default processors returned by SpeedscopeRenderer because speedscope is a timeline-based format, and aggregating repeated calls fouls up a timeline view.

SpeedscopeRenderer: update comment re: frame list

43492ce

This commit updates a code comment within SpeedscopeRenderer.render discussing why the frame list is constructed as it is.

speedscope.py: fix pyright errors

d255022

This commit fixes some pyright errors in pyinstrument/renderers/speedscope.py.

SpeedscopeRenderer: use frame list comprehension

94a3bd3

This commit replaces the for loop that builds up the speedscope frame list with a list comprehension.

SpeedscopeRenderer: add it to documentation

a9c95e2

This commit adds SpeedscopeRenderer and the `-r speedscope` flag to the pyinstrument documentation.

SpeedscopeEvent: remove dataclass args

91416ad

This commit removes the dataclass arguments from the SpeedscopeEvent class because this class does not need to be hashable.

SpeedscopeRenderer: fix code for black, isort

3a8fa9c

This commit changes the SpeedscopeRenderer code to comply with project style guidelines regarding code formatting with black and isort.

SpeedscopeRenderer: add overflow test

57e6bd8

This commit adds SpeedscopeRenderer to the overflow test in pyinstrument's test suite.

SpeedscopeRenderer: add test_profiler test

93f5560

This commit adds a test to test_profiler that tests the JSON output emitted by SpeedscopeRenderer against known properties it should have.

goxberry force-pushed the add-speedscope-renderer branch from 97925fb to 99dd85f Compare November 8, 2021 03:56

joerick mentioned this pull request Nov 8, 2021

Add support for IPython/Jupyter notebook magics #157

Merged

joerick approved these changes Nov 8, 2021

View reviewed changes

joerick merged commit a7dfa37 into joerick:main Nov 14, 2021

joerick mentioned this pull request Nov 14, 2021

Add note about pyinstrument support wiki page jlfwong/speedscope#377

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add speedscope renderer #160

Add speedscope renderer #160

goxberry commented Oct 25, 2021

joerick left a comment

joerick Oct 27, 2021

joerick Oct 27, 2021

goxberry Oct 27, 2021

goxberry Oct 28, 2021

goxberry commented Oct 28, 2021

joerick left a comment

goxberry commented Nov 5, 2021

joerick commented Nov 6, 2021

goxberry commented Nov 7, 2021

joerick left a comment

goxberry commented Nov 8, 2021

joerick left a comment

RyannDaGreat commented Nov 15, 2021

Add speedscope renderer #160

Add speedscope renderer #160

Conversation

goxberry commented Oct 25, 2021

joerick left a comment

Choose a reason for hiding this comment

joerick Oct 27, 2021

Choose a reason for hiding this comment

joerick Oct 27, 2021

Choose a reason for hiding this comment

goxberry Oct 27, 2021

Choose a reason for hiding this comment

goxberry Oct 28, 2021

Choose a reason for hiding this comment

goxberry commented Oct 28, 2021

joerick left a comment

Choose a reason for hiding this comment

goxberry commented Nov 5, 2021

joerick commented Nov 6, 2021

goxberry commented Nov 7, 2021

joerick left a comment

Choose a reason for hiding this comment

goxberry commented Nov 8, 2021

joerick left a comment

Choose a reason for hiding this comment

RyannDaGreat commented Nov 15, 2021