Assembly3: Solver speed debug

Discussion about the development of the Assembly workbench.
Forum rules
Be nice to others! Respect the FreeCAD code of conduct!
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Assembly3: Solver speed debug

Post by project4 »

Hi all and especially @realthunder,

I wonder is someone invested work in debugging the solver speed recently.
I tried to build an assembly for my project, for now it's a slider with some parts attached to it.
As far as I understand the attachment is the "cheapest" computational constraint, so all my models are attached, besides the slider that use 2xPointOnLine and SameOrientation constraints to have proper alignment with the channels it's slides on.
About 20 models in total in the assembly. All are imported from STEP files. Some are sub-assemblies with very few parts.

I was discouraged by the speed the slider is able to move on the screen when I try to drag it on the free-for-movement axis.
When only the slider moves (disabling the attachments for other parts that should move), it's not smooth, jumps on the screen, but pretty usable.
Having about 10 parts attached to that slider reduces the speed significantly, something that is more in the non-usable area.
Screenshot from 2022-10-25 10-42-39.png
Screenshot from 2022-10-25 10-42-39.png (61.64 KiB) Viewed 2061 times
So I started to add timestamps in the code to see where the time is spent...
I'm not familiar with the code yet, so have some questions to understand it better.

The function I started with is the AsmMovingPart::move() from mover.py, which takes about 254mSec to complete.
It's very hard for me to believe that the screen updates 4 times per second, probably there are other things done before and after that function call, but I continue with the investigation since the solver is called from that function.

Next stop are the solve() and _solve() functions from solver.py:
The assembly.recompute(True) call takes about 20mSec (7.8%)
==> Do we have to recompute the assembly all the time before the solver?
==> We're dragging the same assembly here, nothing changed between the calls to that function in the loop of the move events.

The creation of the Solver() instance (the Solver(assembly,reportFailed,dragPart,recompute,rollback) code) takes about 231mSec (91%), so I dived into the Solver::__init__() code to understand what it does there.

The Constraint.getFixedParts() takes about 18mSec (7%)
==> Again, we're dragging the same assembly, can't we use the same list and not re-build it for every call?

The following loop (constraints preparation, didn't dive deeper to see what it's doing), takes 23mSec (9%)

Code: Select all

        for cstr in cstrs:
            self.system.log('preparing {}',cstrName(cstr))
            self.system.GroupHandle += 1
            ret = Constraint.prepare(cstr,self)
            if ret:
                if isinstance(ret,(list,tuple)):
                    for h in ret:
                        if not isinstance(h,(list,tuple)):
                            self._cstrMap[h] = cstr
                else:
                    self._cstrMap[ret] = cstr
==> Same question: should the constraints be prepared for every call in the movement case?

The solver-neto execution by calling self.system.solve() takes about 11.5mSec (4.5%)

The following code (looks like parts placement updates) takes 24.6mSec (9.7%).
Not familiar with the code to understand if something can be optimized here...

Code: Select all

        touched = False
        updates = []
        for part,partInfo in self._partMap.items():
            if partInfo.Update:
                updates.append(partInfo)
            if part in self._fixedParts:
                continue
            if utils.isDraftWire(part):
                changed = False
                points = part.Points
                for key,h in partInfo.EntityMap.items():
                    if not isinstance(key, str) or\
                       not key.endswith('.p') or\
                       not key.startswith('Vertex'):
                        continue
                    v = [ self.system.getParam(p).val for p in h.params ]
                    v = FreeCAD.Vector(*v)
                    v = partInfo.Placement.inverse().multVec(v)
                    idx = utils.draftWireVertex2PointIndex(part,key[:-2])
                    if utils.isSamePos(points[idx],v):
                        self.system.log('not moving {} point {}',
                            partInfo.PartName,idx)
                    else:
                        changed = True
                        self.system.log('moving {} point{} from {}->{}',
                            partInfo.PartName,idx,points[idx],v)
                        if rollback is not None:
                            rollback.append((partInfo.PartName,
                                             part,
                                             (idx, points[idx])))
                        points[idx] = v
                if changed:
                    touched = True
                    part.Points = points
            else:
                params = [self.system.getParam(h).val for h in partInfo.Params]
                p = params[:3]
                q = (params[4],params[5],params[6],params[3])
                pla = FreeCAD.Placement(FreeCAD.Vector(*p),FreeCAD.Rotation(*q))
                if isSamePlacement(partInfo.Placement,pla):
                    self.system.log('not moving {}',partInfo.PartName)
                else:
                    touched = True
                    self.system.log('moving {} {} {} {}',
                        partInfo.PartName,partInfo.Params,params,pla)
                    if rollback is not None:
                        rollback.append((partInfo.PartName,
                                        part,
                                        partInfo.Placement.copy()))
                    partInfo.Placement.Base = pla.Base
                    partInfo.Placement.Rotation = pla.Rotation
                    setPlacement(part,pla)

                if utils.isDraftCircle(part):
                    changed = False
                    h = partInfo.EntityMap.get('Edge1.c',None)
                    if not h:
                        continue
                    v0 = (part.Radius.Value,
                          part.FirstAngle.Value,
                          part.LastAngle.Value)
                    if part.FirstAngle == part.LastAngle:
                        v = (self.system.getParam(h.radius).val,v0[1],v0[2])
                    else:
                        params = [self.system.getParam(p).val for p in h.params]
                        p0 = FreeCAD.Vector(1,0,0)
                        p1 = FreeCAD.Vector(params[0],params[1],0)
                        p2 = FreeCAD.Vector(params[2],params[3],0)
                        v = (p1.Length,
                             math.degrees(p0.getAngle(p1)),
                             math.degrees(p0.getAngle(p2)))

                    if utils.isSameValue(v0,v):
                        self.system.log('not change draft circle {}',
                            partInfo.PartName)
                    else:
                        touched = True
                        self.system.log('change draft circle {} {}->{}',
                            partInfo.PartName,v0,v)
                        if rollback is not None:
                            rollback.append((partInfo.PartName, part, v0))
                        part.Radius = v[0]
                        part.FirstAngle = v[1]
                        part.LastAngle = v[2]
And the winner is... the assembly.recompute(True) function call at the end of the __init__, it takes about 157mSec (61.8%).
==> Looks like that's the main place that should be optimized somehow... Will try to deep dive into that function to understand.

In summary, the slowness is absolutely not the solver fault as I thought, but the FreeCAD/Assembly3 code that should be re-checked to see if it can be optimized somehow.

If someone who is familiar with the code can comment, it will be very helpfull to go forward and prepare a change if possible.
Thanks
User avatar
jpg87
Posts: 809
Joined: Thu Mar 16, 2017 7:16 am
Location: Limoges - France
Contact:

Re: Assembly3: Solver speed debug

Post by jpg87 »

Hi,
Have you thought about freezing assemblies and sub-assemblies to gain speed?
My website : http://help-freecad-jpg87.fr updated 2023/11/06
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

jpg87 wrote: Tue Oct 25, 2022 11:05 am Hi,
Have you thought about freezing assemblies and sub-assemblies to gain speed?
From all the parts there maybe 2-3 sub-assemblies with 4-5 parts in them (similar to bearings sub-assemblies), but I'm in doubt those are causing the delays.

Besides that, the freeze option is very confusing...
Logical approach will be to prepare a sub-assembly, freeze it and use it in a bigger assembly.
But when you try yo attach it, it looks like the application want to change something in the sub-assembly and thows an error that I have to un-freeze it.
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

Update:
Tried to play around with the moved parts...
Thought maybe the sliding constraints affect something, so I left only 7 top parts that are all attached together.
Dragging them in the space is also very slow, so it's definitely not a solver problem.

Compiled FreeCAD in debug mode to see what recompute times are reported.
Looks like Python timing is very similar to the core, in tens of micro-seconds range, so my suspect in Python-C++ interface overhead is gone as well.

Checked if somehow the parts passed to recompute function have "touched" flag set for parts that do not move, everything looks fine.

I'm left with the deep-dive into the core recompute functionality...
https://forum.freecadweb.org/viewtopic.php?f=10&t=72919
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

Hmmm... I found what cause the slowdown...

Here's the flow (more or less):
Assembly3 python code gets the move event, using the solver to calculate the constraints, change the placement of moved parts and calls recompute of the FreeCAD core code.

FreeCAD core recompute code loops on all the parts and calls their "feature" recompute functions one by one.

Feature recompute function calls the extension's code.
Where's the extension recompute code runs? In Python...
And not only that, the code syncs between the C++ and Python objects for every property change as well, so every time C++ code changes the "touched" status, Python's onChange function is immediately called to reflect that.

There are 109 objects that are processed in the C++ recompute run, almost each has several calls to Python to sync the objects and execute needed(?) extension's logic.
Processing of every object takes few milli-seconds! Multiply it by 109 and we get to unusable move speed.
My assembly has only 21 parts, but the updated objects are also all other entries in the tree (constraints, connected elements).

FreeCAD code gurus, please advise how this C++/Python ping-pong can be optimized/eliminated during the move functionality?
I'm pretty happy with the rest of the performance for now (although it might get worse with bigger assemblies), but the move functionality is not usable with a pretty simple assembly as I have right now (21 parts, only 3 constraints that allow movement, the rest are attachments).

Thanks.
realthunder
Veteran
Posts: 2190
Joined: Tue Jan 03, 2017 10:55 am

Re: Assembly3: Solver speed debug

Post by realthunder »

Is it possible to share your file so that I can test?
Try Assembly3 with my custom build of FreeCAD at here.
And if you'd like to show your support, you can donate through patreon, liberapay, or paypal
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

It's currently 41Mb and I can't attach it here or on GitHub.
Will try to remove some non needed objects from the directory.
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

Uploaded here:
https://github.com/realthunder/FreeCAD_ ... ssues/1285

Try to move the top slider.

Hope the files will open properly since FreeCAD still doesn't like Linux mounted drives.
Can't save the same files at work and open on my hope PC.
At work the drive is NFS mounted and symbolic link as my Workspace directory -> adds lots of "../../../" to specify the location.
At home there's a RAID1 mount and symbolic link as my Workspace directory -> the paths looks ok.
That's another issue, I reported it 2-3 years ago but looks like it wasn't fixed yet.
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

@realthunder

I continued to add more parts to the assembly, all attached to the fixed part (the middle channel).
Unfortunately ZIPping all together creates a very big file, so I don't know how to add it here.
Right now, added link to a new part, trying to move it to to a better position where I want to attach it, so the solver will have an easier life.
One processing of the Move event for that single part takes more than 10sec in my printouts.
The event is run at least twice in my case, so currently I have to wait at least 20sec for GUI to respond.

Here are the printouts of the logs I have. The moved part label is "1204-0001-0001/001", link name is "Link047".

Logs:
test.log
(222.15 KiB) Downloaded 35 times

I've added many printouts in the code, the t1,t2,t3 traces are here:

Code: Select all

App::DocumentObjectExecReturn *DocumentObject::recompute()
{
    FC_TIME_LOG(t1,"DocumentObject::recompute " << this->);
    FC_TIME_INIT(t);
    FC_TIME_INIT(t1);

    //check if the links are valid before making the recompute
    if(!GeoFeatureGroupExtension::areLinksValid(this)) {
        // Get objects that have invalid link scope, and print their names.
        // Truncate the invalid object list name strings for readability, if they happen to be very long.
        std::vector<App::DocumentObject*> invalid_linkobjs;
        std::string objnames, scopenames;
        GeoFeatureGroupExtension::getInvalidLinkObjects(this, invalid_linkobjs);
        for (auto& obj : invalid_linkobjs) {
            objnames += obj->getNameInDocument();
            objnames += " ";
            for (auto& scope : obj->getParents()) {
                if (scopenames.length() > 80) {
                    scopenames += "... ";
                    break;
                }
                scopenames += scope.first->getNameInDocument();
                scopenames += " ";
            }
            if (objnames.length() > 80) {
                objnames += "... ";
                break;
            }
        }
        if (objnames.empty()) {
            objnames = "N/A";
        } else {
            objnames.pop_back();
        }
        if (scopenames.empty()) {
            scopenames = "N/A";
        } else {
            scopenames.pop_back();
        }
        Base::Console().Warning("%s: Link(s) to object(s) '%s' go out of the allowed scope '%s'. Instead, the linked object(s) reside within '%s'.\n", getTypeId().getName(), objnames.c_str(), getNameInDocument(), scopenames.c_str());
    }

    FC_TIME_LOG(t1,"DocumentObject::recompute t1");
    FC_TIME_INIT(t2);

    // set/unset the execution bit
    Base::ObjectStatusLocker<ObjectStatus, DocumentObject> exe(App::Recompute, this);

    // mark the object to recompute its extensions
    this->setStatus(App::RecomputeExtension, true);

    FC_TIME_LOG(t2,"DocumentObject::recompute t2");
    FC_TIME_INIT(t3);

    auto ret = this->execute();
    if (ret == StdReturn) {
        // most feature classes don't call the execute() method of its base class
        // so execute the extensions now
        if (this->testStatus(App::RecomputeExtension)) {
            ret = executeExtensions();
        }
    }

    FC_TIME_LOG(t3,"DocumentObject::recompute t3");
    FC_TIME_LOG(t,"DocumentObject::recompute total");

    return ret;
}
Hope that helps somehow. Right now I'm stuck, waiting 20-30 seconds for every GUI update is a show stopper.
I think that the biggest impact to the performance was addition of the round parts:
Screenshot from 2022-10-29 19-00-06.png
Screenshot from 2022-10-29 19-00-06.png (106 KiB) Viewed 1693 times
Please let me know if there's anything I can do to debug is further.

Thanks.
project4
Posts: 237
Joined: Fri Jul 12, 2013 12:53 pm

Re: Assembly3: Solver speed debug

Post by project4 »

I set "Skip recompute" on the main assembly file and turned off "Auto recompute" feature in hope I could continue with the assembly.
But the move update still takes tens of seconds :(

Hiding the round parts that I thought are causing the major slowdown didn't help either...

Python logs doesn't show that recompute is called (at least the logs I added), but there are many AsmElementLink::getInfo() calls...

Is there anything I can do to continue the work somehow?
Post Reply