Macro Recompute Profiler

From FreeCAD Documentation
Revision as of 09:32, 3 April 2017 by DeepSOIC (talk | contribs)

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()
Retrieved from "http://wiki.freecad.org/index.php?title=Macro_Recompute_Profiler&oldid=228369"