grafana / pyroscope

Continuous Profiling Platform. Debug performance issues down to a single line of code
https://grafana.com/oss/pyroscope/
GNU Affero General Public License v3.0
9.87k stars 585 forks source link

Timeslices during continuous profiling isn't showing entire execution time #1311

Closed corsairius closed 1 year ago

corsairius commented 2 years ago

Discussed in https://github.com/pyroscope-io/pyroscope/discussions/1298

Originally posted by **corsairius** July 21, 2022 A script runs for 12 minutes and not seeing any consistency in the elapsed time for the script's activities. The Python script is executed within a vscode Python testing setup profiling parsing a sample script. When the timeslice is selected, the expected visualization would be expected to indicate total execution time, however, the total execution time slips to seconds instead of 12 minutes. It would be expected that continuous profiling would indicate an aggregate of time for the selected preset, or zero when idle. pyroscope.configure( application_name = "Parser.app", # replace this with some name for your application server_address = "http://192.168.64.240:4040", # replace this with the address of your pyroscope server sample_rate = 100, # default is 100 detect_subprocesses = True, # detect subprocesses started by the main process default is False oncpu = False, # report cpu time only; default is True native = False, # profile native extensions; default is False gil_only = False, # only include traces for threads that are holding on to the Global Interpreter Lock; default is True log_level = "info", # default is info, possible values: trace, debug, info, warn, error and critical ) After Python Test (11.46 minutes): ![PythonTesting](https://user-images.githubusercontent.com/32410410/180306637-9a3e5705-50a1-4a58-aa11-1702dc706a6f.jpg) Selecting the above time range does not show the correct total time (17.13 seconds): ![PythonTestingAfterRun](https://user-images.githubusercontent.com/32410410/180306665-aa114e1d-6e34-47c8-899e-01af46cc6588.jpg) Any help is appreciated. Thanks! --Joe.
petethepig commented 2 years ago

Hi @corsairius

Thank you for reporting this!

With the parameters you've provided it seems like you should be seeing 12 minutes in pyroscope.

When the timeslice is selected, the expected visualization would be expected to indicate total execution time

How long is the time slice you've selected? Note that each yellow line corresponds to 10 seconds in real time. So if you're selecting 2 yellow lines, it's normal to see 17.13 seconds of CPU time during those 20 seconds of real time.


It would be helpful if you've provided:


Another thing I'll mention is that currently there might be some profiling data loss at the very end of the process's lifetime. Pyroscope collects data in 10 seconds batches, and so if you have a process that starts at 12:00:00 and ends at 12:00:15, that last 5 second period of time will be lost because the profiling session is not properly finilized. We're working on a long term solution to this problem. For now you can add a 10 second sleep at the end of your script if you really need those last few seconds.

Rperry2174 commented 2 years ago

also FYI (not sure if code is too sensitive to post here) but another option instead of screenshots is getting a shareable link via flamegraph.com image

Up to you though if you feel comfortable sharing that vs sharing the screenshot :)

corsairius commented 2 years ago

I just ran the script, and then a selection of the timeline that is circled should, imho, show the same numbers.

The flamegraph appears different as well. What is the expected visualization after selecting the timeslices?

pyroscope

pyroscopeAfter

Rperry2174 commented 1 year ago

closing as i believe this is functioning correctly and more an issue of cpu vs wall time. Let us know if you still run into this issue