Macro Recompute Profiler: Difference between revisions
(Created page with "{{Macro|Icon=Text-x-python|Name=Macro Recompute Profiler|Description=Measures time it takes to recompute each feature in your project|Author=DeepSOIC|Version=0.1}} UNDER CONS...") |
No edit summary |
||
Line 2: | Line 2: | ||
UNDER CONSTRUCTION |
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== |
==How to use== |
||
Line 77: | Line 79: | ||
}} |
}} |
||
The result lines have an easy |
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: |
||
{{code|code= |
{{code|code= |
||
Line 91: | Line 93: | ||
0.019999981 Clone of Sketch - master section (2D)001 |
0.019999981 Clone of Sketch - master section (2D)001 |
||
0.010999918 ArrayFilter003 |
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''' |
|||
{{Code|code= |
|||
__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() |
|||
}} |
}} |
Revision as of 09:32, 3 April 2017
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()