Did anyone mess with profiler & blender plugins? If so, could you share your experience, and how you implemented your profiler in your plugin? Bonus Points if it is a non-intrusive way.
$\begingroup$
$\endgroup$
Add a comment
|
2 Answers
$\begingroup$
$\endgroup$
I found two potential ways of implementing a profiler in a blender plugin:
1: create your own profiler, this can be done, in theory, by procedurally injecting a wrapper on every functions found on your plugin modules (quite tricky as blender will check for functions positional arguments)
2: use the
cProfilemodule. It has the advantage of being natively integrated in Python, therefore the implementation is done on a much lower level. the data can then be dumped & imported in visualization apps such as tuna or snakeviz ( usepip installfirst of course)
Find hereby two profilers class with an implementation proposal/example
#TODO: cProfile filter plugin modules only?
#TODO: cProfile real time printing maybe?
#TODO: create a plugin out of this
# .oooooo. ooooooooo. .o88o. o8o oooo
# d8P' `Y8b `888 `Y88. 888 `" `"' `888
# 888 888 .d88' oooo d8b .ooooo. o888oo oooo 888 .ooooo.
# 888 888ooo88P' `888""8P d88' `88b 888 `888 888 d88' `88b
# 888 888 888 888 888 888 888 888 888ooo888
# `88b ooo 888 888 888 888 888 888 888 888 .o
# `Y8bood8P' o888o d888b `Y8bod8P' o888o o888o o888o `Y8bod8P'
class cProfiler:
app = None
#EventProfiler Parmeters:
#print stats to console?
outputprint = False
#updatelog, will overwrite old log
outputlog = True
#log name
logname = "profile"
#try to run vizualisation sofware?
runviz = True
#snakeviz|tuna ? use "pip install x" first
vizapp = "snakeviz"
@classmethod
def start(cls):
import cProfile
print("\n","Starting cProfiler","\n")
cls.app = cProfile.Profile()
cls.app.enable()
return None
@classmethod
def end(cls,):
if (cls.app is None):
return None
print("\n","Ending cProfiler","\n")
import pstats
import io
cls.app.disable()
s = io.StringIO()
ps = pstats.Stats(cls.app, stream=s).sort_stats(pstats.SortKey.CUMULATIVE)
if (cls.outputlog or cls.runviz):
import os
import bpy
filename = f"{cls.logname}.log"
localpath = os.path.dirname(bpy.utils.resource_path("LOCAL"))
path = os.path.join(localpath,filename)
print("\n",f"cProfiler Dumping Stats : {path}","\n")
ps.dump_stats(path)
if cls.runviz:
import shlex
import subprocess
command = f"python -m {cls.vizapp} {filename}"
print("\n",f"Trying to run {cls.vizapp.title()} : {command}","\n")
try:
#os.system(command)
subprocess.Popen(shlex.split(command))
except Exception as e:
print("\n","VizApp failed, did you tried pip install?\nif so please check our source code and see if your OS is properly supported","\n")
if cls.outputprint:
ps.print_stats()
print(s.getvalue())
return None
# ooooo ooooo .o8
# `888' `888' "888
# 888 888 .ooooo. ooo. .oo. .oo. .ooooo. ooo. .oo. .oo. .oooo. .oooo888 .ooooo.
# 888ooooo888 d88' `88b `888P"Y88bP"Y88b d88' `88b `888P"Y88bP"Y88b `P )88b d88' `888 d88' `88b
# 888 888 888 888 888 888 888 888ooo888 888 888 888 .oP"888 888 888 888ooo888
# 888 888 888 888 888 888 888 888 .o 888 888 888 d8( 888 888 888 888 .o
# o888o o888o `Y8bod8P' o888o o888o o888o `Y8bod8P' o888o o888o o888o `Y888""8o `Y8bod88P" `Y8bod8P'
# This version still need more work,
# wrapping is very tricky
class EventProfiler:
#main registry
registry = {}
#EventProfiler Parmeters:
#please define your plugin main module here, it should be the name of your folder
plugin_main_module = ""
#print all event?
event_prints = True
print_extra_info = False
#end() parameter
outputprint=True
#ignore parameters, typically ui functions/modules
ignore_fcts = []
ignore_module = []
@classmethod
def register(cls, fct, exec_time=0):
"""update internal registry with exec time and calls"""
key = f"{fct.__module__}.{fct.__name__}"
r = cls.registry.get(key)
if (r is None):
cls.registry[key] = {}
cls.registry[key]["calls"] = 0
cls.registry[key]["runtime"] = 0
r = cls.registry[key]
r["calls"] +=1
r["runtime"] += exec_time
return None
@classmethod
def event_printer(cls, fct, runtime):
"""print event to console"""
if not cls.event_prints:
return None
if cls.print_extra_info:
extra_info = f"\n POS_ARG: {args}\n WK_ARG:{kwargs}\n RETURN:{r}\n RUNTIME:{runtime:.4f}s"
else: extra_info = ""
return print(f"PROFILER : {fct.__module__}.{fct.__name__}",extra_info)
@classmethod
def wrapper(cls, fct):
"""wrap-profile any functions with our benchmark & counter"""
#ignore some function?
if (fct.__name__ in cls.ignore_fcts):
return fct
#Blender might check your function.__code__.co_argcount. this make wrapping way more complex
#https://stackoverflow.com/questions/73601340/how-to-wrap-a-function-with-accurate-code-argcount?noredirect=1#comment129973896_73601340
#so fct.__code__.co_argcount will be accurate
if (fct.__defaults__ is not None):
posonly = fct.__code__.co_argcount - len(fct.__defaults__)
else: posonly = fct.__code__.co_argcount
#ignore some function?
if (fct.__name__ in cls.ignore_fcts):
return fct
#debug function?
# if (fct.__name__=="_global_to_surface_space"):
# print("\n\n","_DEBUG_"*100,"\n\n")
# print("_global_to_surface_space")
# print("fct.__code__.co_argcount : ",fct.__code__.co_argcount)
# print("len(fct.__defaults__) : ",len(fct.__defaults__))
# print("posonly : ",posonly)
# print("\n\n","_DEBUG_"*100,"\n\n")
import functools
import time
if (posonly==0):
@functools.wraps(fct)
def inner(*args,**kwargs):
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==1):
@functools.wraps(fct)
def inner(a,*args,**kwargs):
args += (a,)
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==2):
@functools.wraps(fct)
def inner(a,b,*args,**kwargs):
args += a,b
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==3):
@functools.wraps(fct)
def inner(a,b,c,*args,**kwargs):
args += a,b,c
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==4):
@functools.wraps(fct)
def inner(a,b,c,d,*args,**kwargs):
args += a,b,c,d
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==5):
@functools.wraps(fct)
def inner(a,b,c,d,e,*args,**kwargs):
args += a,b,c,d,e
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==6):
@functools.wraps(fct)
def inner(a,b,c,d,e,f,*args,**kwargs):
args += a,b,c,d,e,f
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==7):
@functools.wraps(fct)
def inner(a,b,c,d,e,f,g,*args,**kwargs):
args += a,b,c,d,e,f,g
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==8):
@functools.wraps(fct)
def inner(a,b,c,d,e,f,g,h,*args,**kwargs):
args += a,b,c,d,e,f,g,h
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==9):
@functools.wraps(fct)
def inner(a,b,c,d,e,f,g,h,i,*args,**kwargs):
args += a,b,c,d,e,f,g,h,i
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
elif (posonly==10):
@functools.wraps(fct)
def inner(a,b,c,d,e,f,g,h,i,j,*args,**kwargs):
args += a,b,c,d,e,f,g,h,i,j
t = time.time()
r = fct(*args,**kwargs)
runtime = time.time()-t
cls.register(fct, exec_time=runtime,)
cls.event_printer(fct, runtime,)
return r
else:
raise Exception("PROFILER_ERROR >>> my_wrapper() do not support more than 10 positional argument")
return inner
@classmethod
def start(cls):
"""inject the profiler wrapper for every functions for every modules of our plugin
used for benchmark or debugging purpose only"""
import sys
import types
print("\n","Injecting EventProfiler","\n")
def is_function(obj):
"""check if given object is a function"""
return isinstance(obj, types.FunctionType)
#for all modules in sys.modules
for mod_k,mod in sys.modules.copy().items():
#separate module componments names
mod_list = mod_k.split('.')
#fileter module that isn't ours
if (mod_list[0]!=cls.plugin_main_module):
continue
#ignore main __init__ module
if ((len(mod_list)==1) and (mod_list[0]==cls.plugin_main_module)):
continue
#ignore some modules?
if any([m in cls.ignore_module for m in mod_list]):
continue
#for each objects found in module
for ele_k,ele in mod.__dict__.items():
#if it does not have a name, skip
if (not hasattr(ele,"__name__")):
continue
#we have a global function
elif is_function(ele):
print(f"- Inject : Local-Fct : {mod_k}.{ele_k}")
mod.__dict__[ele_k] = cls.wrapper(ele)
#then we have a homebrewed class?
elif repr(ele).startswith(f"<class '{cls.plugin_main_module}."):
for class_k,class_e in ele.__dict__.items():
if is_function(class_e):
print(f"- Inject : Class-Fct : {mod_k}.{ele_k}.{class_k}")
setattr( mod.__dict__[ele_k], class_k, cls.wrapper(class_e),) #class.__dict__ are mapping proxies, need to assign this way
continue
print("")
return None
@classmethod
def end(cls,):
"""calculate averages & optionally print output"""
print("\n","Generating EventProfiler Sum","\n")
for k,v in cls.registry.copy().items():
cls.registry[k]["averagetime"] = v["runtime"]/v["calls"]
if cls.outputprint:
print("\n","Outputing EventProfiler Result","\n")
sorted_registry = dict(sorted(cls.registry.items(), key=lambda item:item[1]["runtime"], reverse=False))
for k,v in sorted_registry.items():
print("\n",k,":")
for a,val in v.items():
print(" "*6,a,":",val)
return None
# ooooo oooo .
# `888' `888 .o8
# 888 ooo. .oo. .oo. oo.ooooo. 888 .ooooo. ooo. .oo. .oo. .ooooo. ooo. .oo. .o888oo
# 888 `888P"Y88bP"Y88b 888' `88b 888 d88' `88b `888P"Y88bP"Y88b d88' `88b `888P"Y88b 888
# 888 888 888 888 888 888 888 888ooo888 888 888 888 888ooo888 888 888 888
# 888 888 888 888 888 888 888 888 .o 888 888 888 888 .o 888 888 888 .
# o888o o888o o888o o888o 888bod8P' o888o `Y8bod8P' o888o o888o o888o `Y8bod8P' o888o o888o "888"
# 888
# o888o
#Implementation proposal, in main __init__.register/unregister
"""
#Homebrewed profiler: Best for live prints / debugging
from . profiler import EventProfiler
#Options
EventProfiler.plugin_main_module = "Scatter5" #filter modules, cannot be ""
EventProfiler.event_prints = True #print live execution?
EventProfiler.print_extra_info = False #print arguments, return values, & execution time of function?
EventProfiler.outputprint = False #print final statistics in console?
EventProfiler.ignore_module = ["ui"] #ignore some modules ? (ui drawing fct?)
EventProfiler.ignore_fcts = [ #ignore some functions (ui drawing fct?)
"is_compatible_instance",
"get_psy_active",
"is_category_used",
"is_synchronized",
"is_locked",
"get_surfaces",
"get_scatter_mod",
"translate",
"cust_icon",
"get_s_surface_main_features",
"get_s_distribution_main_features",
"get_s_mask_main_features",
"get_s_scale_main_features",
"get_s_rot_main_features",
"get_s_pattern_main_features",
"get_s_abiotic_main_features",
"get_s_proximity_main_features",
"get_s_ecosystem_main_features",
"get_s_push_main_features",
"get_s_wind_main_features",
"get_s_instances_main_features",
"get_s_visibility_main_features",
"get_s_display_main_features",
]
#cProfile profiler: Great for benchmark & final statistics with visualizer app
from . profiler import cProfiler
#Options
cProfiler.outputprint = False #print final stats in console?
cProfiler.outputlog = True #write log needed for viz sofware (will overwrite log with same names)
cProfiler.logname = "my_benchmark" #name of the log file? (path will be located in your local blender installation, where blender.exe is located)
cProfiler.runviz = True #run vizualisation sofware? please fit requirements first
cProfiler.vizapp = "snakeviz" #which viz app to call ? snakeviz or tuna ? -> use "pip install xxx" first
#Turn Profiler on/off here
use_profiler = True
def register():
if use_profiler:
cProfiler.start()
EventProfiler.start()
for m in main_modules:
m.register()
return None
def unregister():
for m in reversed(main_modules):
m.unregister()
if use_profiler:
cProfiler.end()
EventProfiler.end()
return None
"""
$\begingroup$
$\endgroup$
Find hereby a dedicated profiler plugin https://devtalk.blender.org/t/plugin-profiler-benchmark-debug-your-bpy-work/25787