feat: add constraint stream profiling

[Christopher-Chianelli]

Profiling constraints is notorishing difficult, since each component of a constraint are converted to nodes, some of which are shared. As such, a JVM method profile is basically unreadable and does not represent how much time is actually spent for each constraint.

To aid in profiling, an optional constraintStreamProfilingMode configuration was added. If set to a value other than NONE, it wraps each tuple lifecycle node inside a ProfilingTupleLifecycle, which will measure how long each lifecycle executes. The ProfilingTupleLifecycle find out what constraint is responsible for creating that lifecycle by getting snapshot of the stack traces from its constraint stream's creator (when a constraint stream is shared, their stack traces are merged into the same set).

At the end of solving, a profiling summary is then produced in the INFO log. The details differ depending on the profiling mode:

• In the BY_METHOD profiling mode, (className, methodName) is used as the key

• In the BY_LINE profiling mode, (className, methodName, lineNumber) is used as the key.

The methods/lines are printed in descending order of time percentage spent. The sum of time percentage spent may be over 100%, since methods/lines can share time spent with other methods/lines.

timefold.solver.constraint-stream-profiling-mode was added as a property to Quarkus and Spring Boot to configure profiling (defaults to NONE).

[sonarqubecloud]

Quality Gate failed

Failed conditions
C Reliability Rating on New Code (required ≥ A)

See analysis details on SonarQube Cloud

Catch issues before they fail your Quality Gate with our IDE extension SonarQube for IDE

[triceo]

I like this in principle! When it comes to the implementation, I have concerns. See specifically the comment regarding profiling mode.

I also see this hooks itself into tuple lifecycle. But I don't see it tracking propagation overhead anywhere. Arguably it should.

The logging aspect is OK, but I am missing any methods to consume this information at runtime. How about Micrometer metrics? Or custom JFR events? Thinking out loud here: if it triggered an event (micrometer / JFR) every time it finished a single measurement, these could be aggregated at the end as well as queried in-flight. More often than not, we will be run in the platform - people will want a way of monitoring their solvers.

I question the name "profiling"; this doesn't use a profiler, and doesn't work in a way in which profilers work. The name should be changed in order to not invite confusing comparisons with actual profiling.

[Christopher-Chianelli]

In regards to it tracking propagation overhead, it did in a previous implementation (by wrapping all the Propogators). However, this is a form of double counting; the Propogators fundamentally call lifecycles, which are profiled. Additionally, Propogators correspond to parents of nodes instead of nodes themselves, which can cause absurdities such as forEach taking a large percentage of a profile (since it is a parent to a join/filter).

[triceo]

However, this is a form of double counting; the Propogators fundamentally call lifecycles, which are profiled.

Not sure about that. These lifecycles count for a lot, true. But propagation also deals with the queues, and iterates a lot. IMO it's not necessarily a double count.

Additionally, Propogators correspond to parents of nodes instead of nodes themselves, which can cause absurdities such as forEach taking a large percentage of a profile (since it is a parent to a join/filter).

Which is another good argument that this should not profile per-method or per-line, but per-constraint. Doesn't matter which part takes such a long amount of time - it's the constraint that's what matters.

[Christopher-Chianelli]

This is what a profile looks like now:

Constraint Profiling Summary
  Work shared by org.acme.schooltimetabling.domain/Room conflict, org.acme.schooltimetabling.domain/Student group conflict, org.acme.schooltimetabling.domain/Student group subject variety, org.acme.schooltimetabling.domain/Teacher conflict, org.acme.schooltimetabling.domain/Teacher room stability, org.acme.schooltimetabling.domain/Teacher time efficiency (79.28%, 10464105459ns)
  Work shared by org.acme.schooltimetabling.domain/Teacher time efficiency (10.08%, 1329891726ns)
  Work shared by org.acme.schooltimetabling.domain/Teacher room stability (6.29%, 829846622ns)
  Work shared by org.acme.schooltimetabling.domain/Student group subject variety (3.67%, 483839225ns)
  Work shared by org.acme.schooltimetabling.domain/Student group conflict (0.37%, 49107293ns)
  Work shared by org.acme.schooltimetabling.domain/Room conflict (0.16%, 21585301ns)
  Work shared by org.acme.schooltimetabling.domain/Teacher conflict (0.15%, 20162643ns)

Constraint Profiling Breakdown
  Work shared by org.acme.schooltimetabling.domain/Room conflict, org.acme.schooltimetabling.domain/Student group conflict, org.acme.schooltimetabling.domain/Student group subject variety, org.acme.schooltimetabling.domain/Teacher conflict, org.acme.schooltimetabling.domain/Teacher room stability, org.acme.schooltimetabling.domain/Teacher time efficiency
    JOIN (72.98%, 7637089549ns)
      By Operation
        UPDATE (99.88%, 7628054546ns)
        INSERT (0.08%, 6372938ns)
        RETRACT (0.03%, 2662065ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#roomConflict:33 (24.54%, 1874118595ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupConflict:56 (21.19%, 1618086279ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherConflict:46 (19.82%, 1513463898ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherTimeEfficiency:77 (15.28%, 1166571547ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupSubjectVariety:92 (11.88%, 907564341ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherRoomStability:66 (7.30%, 557284889ns)
    PROPAGATION (27.02%, 2827015910ns)
      By Operation
        UPDATE (67.12%, 1897462674ns)
        INSERT (20.41%, 576988801ns)
        RETRACT (12.47%, 352564435ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherTimeEfficiency:77 (68.98%, 1950132747ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupSubjectVariety:92 (58.98%, 1667348577ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherRoomStability:66 (57.89%, 1636653143ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupConflict:56 (54.55%, 1542047166ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#roomConflict:33 (53.67%, 1517384171ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherConflict:46 (52.94%, 1496483996ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherTimeEfficiency:76 (49.40%, 1396606778ns)
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupSubjectVariety:91 (49.40%, 1396606778ns)

  Work shared by org.acme.schooltimetabling.domain/Teacher time efficiency
    FILTER (84.37%, 1122032509ns)
      By Operation
        UPDATE (51.17%, 574090252ns)
        RETRACT (27.04%, 303395964ns)
        INSERT (21.79%, 244546293ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherTimeEfficiency:79 (100.00%, 1122032509ns)
    SCORING (15.63%, 207859217ns)
      By Operation
        RETRACT (72.95%, 151623406ns)
        UPDATE (15.62%, 32462652ns)
        INSERT (11.44%, 23773159ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherTimeEfficiency:84 (100.00%, 207859217ns)

  Work shared by org.acme.schooltimetabling.domain/Teacher room stability
    FILTER (76.13%, 631772012ns)
      By Operation
        UPDATE (99.92%, 631243027ns)
        INSERT (0.06%, 395960ns)
        RETRACT (0.02%, 133025ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherRoomStability:68 (100.00%, 631772012ns)
    SCORING (23.87%, 198074610ns)
      By Operation
        UPDATE (55.41%, 109753784ns)
        RETRACT (44.48%, 88096546ns)
        INSERT (0.11%, 224280ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherRoomStability:69 (100.00%, 198074610ns)

  Work shared by org.acme.schooltimetabling.domain/Student group subject variety
    FILTER (87.20%, 421889685ns)
      By Operation
        UPDATE (51.68%, 218025826ns)
        RETRACT (26.59%, 112178665ns)
        INSERT (21.73%, 91685194ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupSubjectVariety:96 (100.00%, 421889685ns)
    SCORING (12.80%, 61949540ns)
      By Operation
        RETRACT (91.26%, 56536197ns)
        INSERT (4.39%, 2719814ns)
        UPDATE (4.35%, 2693529ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupSubjectVariety:101 (100.00%, 61949540ns)

  Work shared by org.acme.schooltimetabling.domain/Student group conflict
    SCORING (100.00%, 49107293ns)
      By Operation
        INSERT (62.38%, 30635185ns)
        RETRACT (37.12%, 18226439ns)
        UPDATE (0.50%, 245669ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#studentGroupConflict:59 (100.00%, 49107293ns)

  Work shared by org.acme.schooltimetabling.domain/Room conflict
    SCORING (100.00%, 21585301ns)
      By Operation
        INSERT (60.99%, 13165893ns)
        RETRACT (38.74%, 8361684ns)
        UPDATE (0.27%, 57724ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#roomConflict:39 (100.00%, 21585301ns)

  Work shared by org.acme.schooltimetabling.domain/Teacher conflict
    SCORING (100.00%, 20162643ns)
      By Operation
        INSERT (63.46%, 12795555ns)
        RETRACT (36.09%, 7275850ns)
        UPDATE (0.45%, 91238ns)
      By Location
        org.acme.schooltimetabling.solver.TimetableConstraintProvider#teacherConflict:49 (100.00%, 20162643ns)

By location percentage may add up to over 100% due to node sharing; the rest should always add up to 100%.

[triceo]

Constraint Profiling Summary
Work shared by org.acme.schooltimetabling.domain/Room conflict, org.acme.schooltimetabling.domain/Student group conflict, org.acme.schooltimetabling.domain/Student group subject variety, org.acme.schooltimetabling.domain/Teacher conflict, org.acme.schooltimetabling.domain/Teacher room stability, org.acme.schooltimetabling.domain/Teacher time efficiency (79.28%, 10464105459ns)

If we remove the package from this, suddenly this will be better readable. The packages are deprecated anyway. When they're gone though, it'll probably be useful to surround the constraint name with quotes.

What does "work shared by" mean? I'd understand it if it were only for multiple constraints, but the same is used below when only one constraint is listed.

10464105459ns is surely not the ideal way to represent this number. 10.464 seconds seems better.

Wouldn't a breakdown by node/operation make sense here as well? Overall for the entire constraint provider, if 80 % is just joins, that's useful information.

By location percentage may add up to over 100% due to node sharing; the rest should always add up to 100%.

I really don't like that it's there at all. It makes most of the output, you drown in the text, and apparently you also need to understand that the numbers there mean something else than everywhere else. This output doesn't help, only makes things more difficult.

[triceo]

The output could use being shorter and clearer.
The implementation around LifecycleKind needs rethinking.

[Christopher-Chianelli]

What does "work shared by" mean? I'd understand it if it were only for multiple constraints, but the same is used below when only one constraint is listed.

Work performed exclusively by the listed group. When more than one constraint is in the group, that means they are sharing some node, and thus removing a constraint does not remove the work it does in the group (unless all constraints in the group are removed). When it is alone, it means the work done exclusively by a given constraint (where removing the constraint guarantees removing that work).

10464105459ns is surely not the ideal way to represent this number. 10.464 seconds seems better.

Acknowledged, but it is the raw captured data. The issue is if we try to humanize the number, then we need to ask questions such as do we convert it to minutes above a certain duration? Then hours? And then there the potential of losing accuracy and making comparisons between constraints harder (as you need to convert them to a common unit).

Wouldn't a breakdown by node/operation make sense here as well? Overall for the entire constraint provider, if 80 % is just joins, that's useful information.

Useful infomation for who? This information also shows up in the location list.

By location percentage may add up to over 100% due to node sharing; the rest should always add up to 100%.

I really don't like that it's there at all. It makes most of the output, you drown in the text, and apparently you also need to understand that the numbers there mean something else than everywhere else. This output doesn't help, only makes things more difficult.

This is the only text that is actually actionable by the user; it tells them what is actually hot in their code, and they don't need to do a string/constant lookup.

[triceo]

When it is alone, it means the work done exclusively by a given constraint (where removing the constraint guarantees removing that work).

Arguably if this case used different words, I wouldn't have to ask the question.
Different cases require different descriptions.

Acknowledged, but it is the raw captured data. The issue is if we try to humanize the number, then we need to ask questions such as do we convert it to minutes above a certain duration? Then hours? And then there the potential of losing accuracy and making comparisons between constraints harder (as you need to convert them to a common unit).

You already picked a common unit, just the worst one. :-) I see how this could possibly be hours, days. Or nanos. Practically, it won't be either. It will not be much less (who stops the solver after a millisecond?), and it will not be much more (who needs hours to establish these numbers?).

IMO if we use seconds as a baseline, that's a reasonable estimate. Saying "5:25:00" (hms) also isn't too hard, if we decide we need to. The "problem" comes when the time is much smaller than a second - thankfully, it will not be.

Useful information for who? This information also shows up in the location list.

You probably noticed that I don't like the location list.

This is the only text that is actually actionable by the user; it tells them what is actually hot in their code, and they don't need to do a string/constant lookup.

Since it doesn't cross-link to code, you're copy-pasting anyway. IMO constraint names work much better; those will always be the same. With line numbers, you're making many assumptions; that the code over there is the same as the one you're looking at, that the code was compiled to include those line numbers, that no crazy tooling modified that code. (I love Lombok, which always points me to places that don't really exist.)

I know that this is one way how you can report node sharing. IMO the downsides outweigh that; this will not be reliable, and only leads to questions.

[triceo]

LGTM once documented.

[sonarqubecloud]

Quality Gate failed

Failed conditions
37.6% Coverage on New Code (required ≥ 70%)

See analysis details on SonarQube Cloud