Macro Recompute Profiler
File:Text-x-python Macro Recompute Profiler |
Description |
---|
Measures time it takes to recompute each feature in your project Macro version: 0.1 Author: DeepSOIC |
Author |
DeepSOIC |
Download |
None |
Links |
Macros recipes How to install macros How to customize toolbars |
Macro Version |
0.1 |
Date last modified |
None |
FreeCAD Version(s) |
None |
Default shortcut |
None |
See also |
None |
UNDER CONSTRUCTION
Description
This macro is to help you find, what features cause long delays in updates to the project. It performs a recompute, measuring the time it takes to recompute each feature.
How to use
Save the macro to a file.
1. Open your project 2. Right-click an object in model tree, pick "Mark to recompute" 3. Run this macro. A progress bar will appear. As each object is recomputed, a line is printed to Report View, containing the time and the label of the object.
Post-processing results
The output of the macro will be interleaved with general messages produced by recomputing features. It generally looks like this:
Recomputing... (time in seconds, label)
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.00999999046326 Sketch - master section
0.0199999809265 Clone of Sketch - master section (2D)001
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.00999999046326 Sketch013
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.00999999046326 Sketch011
0.0 Clone of Sketch - master section (2D)
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.0 Sketch008
0.130000114441 LinearArray
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.0 Sketch010
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.0 Sketch001 - master xy
0.00999999046326 Clone of Sketch001 - master xy (2D)
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.0 Sketch002
0.0 Moved Sketch003
0.00999999046326 Moved Sketch002
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.0 Sketch009
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.00999999046326 Sketch003
0.0299999713898 Sweep
0.00999999046326 Populate ArrayFilter002 with Sweep
0.108999967575 Fusion
0.0 Extrude
0.591000080109 Slice
0.160000085831 CompoundFilter
0.0699999332428 Moved CompoundFilter
0.00999999046326 Compound
Populate004: There are fewer children to populate, than placements to be populated (2, 49). Extra placements will be dropped.
0.352999925613 Populate LinearArray with Compound
0.0 Clone of Sketch - master section (2D)002
Sketcher::setUpSketch()-T:0
Sketcher::Solve()-DogLeg-T:0
0.0 Sketch006
0.0 Revolve
0.00999999046326 Revolve001
0.0 Module002 - tire
0.0670001506805 Module - spokes
0.138999938965 Cut
0.0 Module001 - hub
0.0 Part001 - hub
0.0 Part - tire
0.010999917984 ArrayFilter003
Hide main window
Show main window
The result lines have an easy signature to separate them off: they start with a tab. So, if you copy-paste the whole chunk to a spreadsheet program, generic messages will end up in column 1, while the results are in columns 2 and 3. So, you can sort by column 2, to get a nice table like that:
0.59100008 Slice
0.352999926 Populate LinearArray with Compound
0.160000086 CompoundFilter
0.138999939 Cut
0.130000114 LinearArray
0.108999968 Fusion
0.069999933 Moved CompoundFilter
0.067000151 Module - spokes
0.029999971 Sweep
0.019999981 Clone of Sketch - master section (2D)001
0.010999918 ArrayFilter003
...
(For MS-Excel, make sure you start selecting the report view log from the first line with timing data. Otherwise, it pastes everything into first column, stripping away all tabs.)
Macro
RecomputeProfiler.FCMacro
__Title__="Macro Recompute Profiler"
__Author__ = "DeepSOIC"
__Version__ = "0.1"
__Date__ = "03.04.2017"
__Comment__ = "Measures time it takes to recmpute features in a project"
__Wiki__ = "https://www.freecadweb.org/wiki/index.php?title=Macro_Recompute_Profiler"
__Help__ = "Right-click an object, and pick 'Mark to recompute', then run this macro. This will only profile recomputing the subgraph. To profile the whole project, right-click the project in tree view, and pick 'Mark to recompute', then run this macro. Results will be printed to report view."
__Status__ = "experimental"
__Requires__ = "freecad 0.17.10644"
__Communication__ = "https://forum.freecadweb.org/memberlist.php?mode=viewprofile&u=3888"
import FreeCAD as App
import FreeCADGui as Gui
class ExecutionError(Exception):
pass
class CancelError(Exception):
pass
def execute(feature):
feature.recompute()
if 'Invalid' in feature.State:
raise ExecutionError("Feature '{label}' failed to recompute".format(label= feature.Label))
def msgbox(title, text):
from PySide import QtGui
mb = QtGui.QMessageBox()
mb.setIcon(mb.Icon.Information)
mb.setText(text)
mb.setWindowTitle(title)
mb.exec_()
def log(string):
App.Console.PrintWarning(string+"\n")
def getAllDependent(feat_list):
'''getAllDependent(feat): gets all features that depend on feat, directly or indirectly.
Returns a list, with deepest dependencies last. feat is not included in the list, except
if the feature depends on itself (dependency loop).'''
list_traversing_now = feat_list
set_of_deps = set()
list_of_deps = []
while len(list_traversing_now) > 0:
list_to_be_traversed_next = []
for feat in list_traversing_now:
for dep in feat.InList:
if not (dep in set_of_deps):
set_of_deps.add(dep)
list_of_deps.append(dep)
list_to_be_traversed_next.append(dep)
list_traversing_now = list_to_be_traversed_next
return set_of_deps
def run():
touched = [obj for obj in App.ActiveDocument.Objects if 'Touched' in obj.State]
if len(touched) == 0:
App.ActiveDocument.RecomputesFrozen = True
msgbox("Macro Recompute Profiler", "Project was switched to suspend recomputes. Please modify an object that triggers a recompute, and run this macro again. The macro will perform a step-by-step recompute, and measure the time it takes to recompute features.")
return
log("{n} features are touched".format(n= len(touched)))
log("Generating execution order...")
to_be_executed = set.union(getAllDependent(touched), set(touched))
log("Number of features to execute: {n}".format(n= len(to_be_executed)))
exec_list = []
for obj in App.ActiveDocument.ToplogicalSortedObjects[::-1]:
if obj in to_be_executed:
exec_list.append(obj)
assert(len(exec_list) == len(to_be_executed))
n = len(exec_list)
log("Execution order:")
for obj in exec_list:
log(" "+obj.Label)
import PySide
progress = PySide.QtGui.QProgressDialog(u"Recomputing", u"Abort", 0, n+1)
progress.setModal(True)
progress.show()
try:
log("Recomputing... (time in seconds, label)")
import time
for obj in exec_list:
progress.setValue(progress.value()+1)
if progress.wasCanceled():
raise CancelError()
time_start = time.time()
try:
execute(obj)
finally:
exec_time = time.time()-time_start
log("\t{time}\t{label}".format(time= exec_time, label= obj.Label))
progress.setValue(n+1)
msgbox("Macro Recompute Profiler", "Recompute completed. Results are in report view.")
for obj in exec_list:
obj.purgeTouched()
except Exception as err:
msgbox("Macro Recompute Profiler", "An error occured: {err}".format(err= str(err)))
finally:
progress.hide()
App.ActiveDocument.RecomputesFrozen = False
run()