The culprit:
```
Tuple counts for PointsTo::InterProceduralPointsTo::scope_entry_value_transfer_from_earlier#741b54e2#ffff#join_rhs/5@eb1340iv after 12.6s:
72973 ~3% {2} r1 = JOIN PointsToContext::TImportContext#cf3039a0#f WITH Definitions::NonEscapingGlobalVariable#class#486534ab#f CARTESIAN PRODUCT OUTPUT Rhs.0, Lhs.0 'arg1'
537932 ~0% {3} r2 = JOIN r1 WITH Essa::EssaDefinition::getSourceVariable#dispred#f0820431#ff_10#join_rhs ON FIRST 1 OUTPUT Rhs.1 'arg2', Lhs.1 'arg1', Lhs.0
982333 ~0% {4} r3 = JOIN r2 WITH Essa::EssaVariable::getAUse#dispred#f0820431#ff ON FIRST 1 OUTPUT Lhs.2, Lhs.1 'arg1', Lhs.0 'arg2', Rhs.1 'arg0'
37029774 ~0% {4} r4 = JOIN r3 WITH Essa::TEssaNodeDefinition#24e22a14#ffff ON FIRST 1 OUTPUT Rhs.3 'arg3', Lhs.1 'arg1', Lhs.2 'arg2', Lhs.3 'arg0'
35956211 ~0% {5} r5 = JOIN r4 WITH Essa::ScopeEntryDefinition::getScope#dispred#f0820431#ff ON FIRST 1 OUTPUT Lhs.3 'arg0', Lhs.1 'arg1', Lhs.2 'arg2', Lhs.0 'arg3', Rhs.1 'arg4'
return r5
```
You may notice that this is a predicate that's _materialised_, but it's
never actually used anywhere. It's the old "standard order" bringing
much sadness.
The problem here is that in the standard order (which we never actually
use here), we end up with a join between the bits above, `getRootCall`,
and `appliesToScope`. The `join_rhs` bit is joined twice, once with
`getRootCall#prev` and `appliesToScope#prev_delta` (in that order), and
once with `prev` and `prev_delta` swapped.
So to fix this, I used the unbinding pragma to force `appliesToScope` to
appear first in the join order. This was enough to make the compiler
_not_ push the common context into its own `join_rhs` predicate (and
the join-order is still decent.)
On certain databases, the evaluation of this predicate was running out
of memory due to the way the `count` aggregate was being used. Here's
an example of the tuple counts involved:
```
Tuple counts for PointsToContext::syntactic_call_count#cf3039a0#ff#antijoin_rhs/1@d2199bb8 after 1m27s:
595518502 ~521250% {1} r1 = JOIN PointsToContext::syntactic_call_count#cf3039a0#ff#shared#3 WITH Flow::CallNode::getFunction#dispred#f0820431#ff_1#join_rhs ON FIRST 1 OUTPUT Lhs.1 'arg0'
26518709 ~111513% {1} r2 = JOIN PointsToContext::syntactic_call_count#cf3039a0#ff#shared#2 WITH Flow::CallNode::getFunction#dispred#f0820431#ff_1#join_rhs ON FIRST 1 OUTPUT Lhs.1 'arg0'
622037211 ~498045% {1} r3 = r1 UNION r2
return r3
```
and a timing report that looked like this:
```
time | evals | max @ iter | predicate
------|-------|--------------|----------
5m8s | | | PointsToContext::syntactic_call_count#cf3039a0#ff#shared#2@6d98d1nd
4m38s | | | PointsToContext::syntactic_call_count#cf3039a0#ff#count_range@f5df1do4
3m51s | | | PointsToContext::syntactic_call_count#cf3039a0#ff#shared#3@da3b4abf
1m58s | 7613 | 37ms @ 4609 | MRO::ClassListList::removedClassParts#f0820431#fffff#reorder_2_3_4_0_1@8155axyi
1m37s | 7613 | 33ms @ 3904 | MRO::ClassListList::bestMergeCandidate#f0820431#2#fff@8155a83w
1m27s | | | PointsToContext::syntactic_call_count#cf3039a0#ff#antijoin_rhs@d2199bb8
1m8s | 1825 | 63ms @ 404 | PointsTo::Expressions::equalityEvaluatesTo#741b54e2#fffff@8155aw7w
37.6s | | | PointsToContext::syntactic_call_count#cf3039a0#ff#join_rhs@e348fc1p
...
```
To make optimising this easier for the compiler, I moved the bodies of
the `count` aggregate into their own helper predicates (with size
linear in the number of `CallNode`s), and also factored out the many
calls to `f.getName()`.
The astute reader will notice that in writing this as a sum of `count`s
rather than a count of a disjunction, the intersection (if it exists)
will be counted twice, and so the semantics may be different. However,
since `method_call` and `function_call` require `AttrNode` and
`NameNode` functions respectively, and as these two types are disjoint,
there is no intersection, and so the semantics should be preserved.
After the change, the evaluation of `syntactic_call_count` now looks as
follows:
```
Tuple counts for PointsToContext::syntactic_call_count#cf3039a0#ff/2@662dd8s0 after 216ms:
23960 ~0% {1} r1 = @py_scope#f AND NOT py_Functions_0#antijoin_rhs(Lhs.0 's')
23960 ~0% {2} r2 = SCAN r1 OUTPUT In.0 's', 0
276309 ~7% {2} r3 = SCAN @py_scope#f OUTPUT In.0 's', "__init__"
11763 ~0% {2} r4 = JOIN r3 WITH Scope::Scope::getName#dispred#f0820431#fb ON FIRST 2 OUTPUT Lhs.0 's', 1
35723 ~0% {2} r5 = r2 UNION r4
252349 ~0% {2} r6 = JOIN @py_scope#f WITH Function::Function::getName#dispred#f0820431#ff ON FIRST 1 OUTPUT Lhs.0 's', Rhs.1
240586 ~0% {2} r7 = SELECT r6 ON In.1 != "__init__"
131727 ~4% {2} r8 = r7 AND NOT project#PointsToContext::method_call#cf3039a0#ff(Lhs.1)
131727 ~0% {3} r9 = SCAN r8 OUTPUT In.1, In.0 's', 0
240586 ~0% {2} r10 = SCAN r7 OUTPUT In.1, In.0 's'
108859 ~0% {3} r11 = JOIN r10 WITH PointsToContext::syntactic_call_count#cf3039a0#ff#join_rhs ON FIRST 1 OUTPUT Lhs.0, Lhs.1 's', Rhs.1
240586 ~0% {3} r12 = r9 UNION r11
24100 ~0% {2} r13 = JOIN r12 WITH PointsToContext::syntactic_call_count#cf3039a0#ff#join_rhs#1 ON FIRST 1 OUTPUT Lhs.1 's', (Rhs.1 + Lhs.2)
240586 ~0% {2} r14 = SELECT r6 ON In.1 != "__init__"
131727 ~4% {2} r15 = r14 AND NOT project#PointsToContext::method_call#cf3039a0#ff(Lhs.1)
131727 ~0% {3} r16 = SCAN r15 OUTPUT In.0 's', In.1, 0
108859 ~4% {3} r17 = JOIN r10 WITH PointsToContext::syntactic_call_count#cf3039a0#ff#join_rhs ON FIRST 1 OUTPUT Lhs.1 's', Lhs.0, Rhs.1
240586 ~4% {3} r18 = r16 UNION r17
216486 ~2% {3} r19 = r18 AND NOT project#PointsToContext::function_call#cf3039a0#ff(Lhs.1)
216486 ~0% {2} r20 = SCAN r19 OUTPUT In.0 's', (0 + In.2)
240586 ~0% {2} r21 = r13 UNION r20
276309 ~0% {2} r22 = r5 UNION r21
return r22
```
This bad join was identified by the join-order-badness report, which
showed that:
py/use-of-input:MRO::flatten_list#f4eaf05f#fff#9c5fe54whnlqffdgu65vhb8uhpg# (order_500000)
calculated a whopping 212,820,108 tuples in order to produce an output of
size 55516, roughly 3833 times more effort than needed.
Here's a snippet of the slowest iteration of that predicate:
```
Tuple counts for MRO::flatten_list#f4eaf05f#fff/3@i1839#0265eb3w after 14ms:
0 ~0% {3} r1 = JOIN MRO::need_flattening#f4eaf05f#f#prev_delta WITH MRO::ConsList#f4eaf05f#fff#reorder_2_0_1#prev ON FIRST 1 OUTPUT Rhs.1, Lhs.0 'list', Rhs.2
0 ~0% {3} r2 = JOIN r1 WITH MRO::ClassList::length#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.2, Lhs.1 'list', Rhs.1 'n'
0 ~0% {3} r3 = JOIN r2 WITH MRO::ClassListList::flatten#dispred#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.1 'list', Lhs.2 'n', Rhs.1 'result'
0 ~0% {3} r4 = SCAN MRO::ConsList#f4eaf05f#fff#prev_delta OUTPUT In.2 'list', In.0, In.1
0 ~0% {3} r5 = JOIN r4 WITH MRO::need_flattening#f4eaf05f#f#prev ON FIRST 1 OUTPUT Lhs.1, Lhs.2, Lhs.0 'list'
0 ~0% {3} r6 = JOIN r5 WITH MRO::ClassList::length#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.1, Lhs.2 'list', Rhs.1 'n'
0 ~0% {3} r7 = JOIN r6 WITH MRO::ClassListList::flatten#dispred#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.1 'list', Lhs.2 'n', Rhs.1 'result'
0 ~0% {3} r8 = r3 UNION r7
26355 ~2% {3} r9 = SCAN MRO::ConsList#f4eaf05f#fff#prev OUTPUT In.2 'list', In.0, In.1
0 ~0% {3} r10 = JOIN r9 WITH MRO::need_flattening#f4eaf05f#f#prev ON FIRST 1 OUTPUT Lhs.1, Lhs.2, Lhs.0 'list'
0 ~0% {3} r11 = JOIN r10 WITH MRO::ClassList::length#f0820431#ff#prev_delta ON FIRST 1 OUTPUT Lhs.1, Lhs.2 'list', Rhs.1 'n'
0 ~0% {3} r12 = JOIN r11 WITH MRO::ClassListList::flatten#dispred#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.1 'list', Lhs.2 'n', Rhs.1 'result'
...
```
(... and a bunch more lines. The same construction appears several times,
but the join order is the same each time.)
Clearly it would be better to start with whatever is in `need_flattening`,
and then do the other joins. This is what the present fix does (by
unbinding `list` in all but the `needs_flattening` call).
After the fix, the slowest iteration is as follows:
```
Tuple counts for MRO::flatten_list#f4eaf05f#fff/3@i2617#8155ab3w after 9ms:
0 ~0% {2} r1 = SCAN MRO::need_flattening#f4eaf05f#f#prev_delta OUTPUT In.0 'list', In.0 'list'
0 ~0% {3} r2 = JOIN r1 WITH MRO::ConsList#f4eaf05f#fff#reorder_2_0_1#prev ON FIRST 1 OUTPUT Rhs.1, Lhs.1 'list', Rhs.2
0 ~0% {3} r3 = JOIN r2 WITH MRO::ClassList::length#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.2, Lhs.1 'list', Rhs.1 'n'
0 ~0% {3} r4 = JOIN r3 WITH MRO::ClassListList::flatten#dispred#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.1 'list', Lhs.2 'n', Rhs.1 'result'
1 ~0% {2} r5 = SCAN MRO::need_flattening#f4eaf05f#f#prev OUTPUT In.0 'list', In.0 'list'
0 ~0% {3} r6 = JOIN r5 WITH MRO::ConsList#f4eaf05f#fff#reorder_2_0_1#prev_delta ON FIRST 1 OUTPUT Rhs.1, Lhs.1 'list', Rhs.2
0 ~0% {3} r7 = JOIN r6 WITH MRO::ClassList::length#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.2, Lhs.1 'list', Rhs.1 'n'
0 ~0% {3} r8 = JOIN r7 WITH MRO::ClassListList::flatten#dispred#f0820431#ff#prev ON FIRST 1 OUTPUT Lhs.1 'list', Lhs.2 'n', Rhs.1 'result'
...
```
(... and so on. The remainder is 0 tuples all the way.)
In total, we went from
```
40.6s | 7614 | 15ms @ 1839 | MRO::flatten_list#f4eaf05f#fff@0265eb3w
```
to
```
7.8s | 7614 | 11ms @ 2617 | MRO::flatten_list#f4eaf05f#fff@8155ab3w
```
Fixes a bad join in `list_of_linearization_of_bases_plus_bases`.
Previvously, we joined together `ConsList` and `getBase` before filtering
these out using the recursive call. Now we do the recursion first.
Co-authored-by: yoff <yoff@github.com>
For the most part, these boil down to "some global property holds, and
so this relation contains all instances of class `X`". The fix is to
explicitly build the cartesian product (which we were already building
implicitly anyway) by adding `and exists(var)` to the disjunct that did
not mention `var`.
Note that these cartesian products are always with singletons on one
side, and so should be unproblematic.
From `pritomrajkhowa/LoopBound`:
```
Definitions.ql-7:PointsTo::PointsToInternal::scope_entry_points_to#ffff#antijoin_rhs#2 ........... 55.1s
```
specifically
```
(443s) Tuple counts for PointsTo::PointsToInternal::scope_entry_points_to#ffff#antijoin_rhs#2/3@74a7cart after 55.1s:
184070 ~0% {3} r1 = JOIN PointsTo::PointsToInternal::scope_entry_points_to#ffff#shared#1 WITH Variables::GlobalVariable#class#f ON FIRST 1 OUTPUT Lhs.0 'arg2', Lhs.1 'arg0', Lhs.2 'arg1'
184070 ~0% {3} r2 = STREAM DEDUP r1
919966523 ~2% {4} r3 = JOIN r2 WITH Essa::EssaDefinition::getSourceVariable_dispred#ff_10#join_rhs ON FIRST 1 OUTPUT Rhs.1, Lhs.1 'arg0', Lhs.2 'arg1', Lhs.0 'arg2'
4281779 ~2293% {3} r4 = JOIN r3 WITH Essa::EssaVariable::getScope_dispred#ff ON FIRST 2 OUTPUT Lhs.1 'arg0', Lhs.2 'arg1', Lhs.3 'arg2'
return r4
```
First, this is an `antijoin`, so there's likely some negation involved.
Also, there's mention of `GlobalVariable`, `getScope`, and
`getSourceVariable`, none of which appear in `scope_entry_points_to`, so
it's likely that something got inlined.
Taking a closer look at the predicates mentioned in the body, we spot
`undefined_variable` as a likely culprit.
Evaluating this predicate in isolation reveals that it's not terribly
big, so we could try just marking it with `pragma[noinline]` (I opted
for the slightly more solid `nomagic`) and see how that fares. I also
checked that `builtin_not_in_outer_scope` was similarly small, and
made that one un-inlineable as well.
The result? Well, I can't even show you. Both `scope_entry_points_to`
and `undefined_variable` are so fast that they don't appear in the
clause timing report (so they can at most take 3.5s each to evaluate, as
that is the smallest timing in the list).
From `pritomrajkhowa/LoopBound`:
```
Definitions.ql-7:PointsTo::InterProceduralPointsTo::callsite_points_to#ffff#join_rhs#3 ........... 5m53s
```
specifically
```
(767s) Tuple counts for PointsTo::InterProceduralPointsTo::callsite_points_to#ffff#join_rhs#3/3@f8f86764 after 5m53s:
832806293 ~0% {4} r1 = JOIN PointsTo::InterProceduralPointsTo::callsite_points_to#ffff#shared#1 WITH PointsTo::InterProceduralPointsTo::var_at_exit#fff ON FIRST 1 OUTPUT Lhs.0, Lhs.1 'arg1', Rhs.1 'arg2', Rhs.2 'arg0'
832806293 ~0% {3} r2 = JOIN r1 WITH Essa::TEssaNodeRefinement#ffff_03#join_rhs ON FIRST 2 OUTPUT Lhs.3 'arg0', Lhs.1 'arg1', Lhs.2 'arg2'
return r2
```
This one is a bit tricky to unpack. Where is this `shared#1` defined?
```
EVALUATE NONRECURSIVE RELATION:
SYNTHETIC PointsTo::InterProceduralPointsTo::callsite_points_to#ffff#shared#1(int arg0, numbered_tuple arg1) :-
SENTINEL PointsTo::InterProceduralPointsTo::callsite_points_to#ffff#shared
SENTINEL Definitions::EscapingAssignmentGlobalVariable#class#f
SENTINEL Essa::TEssaNodeRefinement#ffff_03#join_rhs
{2} r1 = JOIN PointsTo::InterProceduralPointsTo::callsite_points_to#ffff#shared WITH Definitions::EscapingAssignmentGlobalVariable#class#f ON FIRST 1 OUTPUT Lhs.0 'arg0', Lhs.1 'arg1'
{2} r2 = STREAM DEDUP r1
{2} r3 = JOIN r2 WITH Essa::TEssaNodeRefinement#ffff_03#join_rhs ON FIRST 2 OUTPUT Lhs.0 'arg0', Lhs.1 'arg1'
{2} r4 = STREAM DEDUP r3
return r4
```
Looking at `callsite_points_to`, we see a likely candidate in `srcvar`.
It is guarded with an `instanceof` check for
`EscapingAssignmentGlobalVariable` (which lines up nicely with the
sentinel on its charpred) and `getSourceVariable` is just a projection
of `TEssaNodeRefinement`.
So let's try unbinding `srcvar` to prevent an early join.
The timing is now:
```
Definitions.ql-7:PointsTo::InterProceduralPointsTo::callsite_points_to#ffff ...................... 31.3s (2554 evaluations with max 101ms in PointsTo::InterProceduralPointsTo::callsite_points_to#ffff/4@i516#581fap5w)
```
(Showing the tuple counts doesn't make sense here, since all of the
`shared` and `join_rhs` predicates have been smooshed around.)
This predicate was materialised as a _big_, _cached_ relation:
```
(169s) Tuple counts for PointsTo::InterProceduralPointsTo::named_argument_transfer#ffff#join_rhs/4@38ce07 after 53.4s:
25212 ~4% {3} r1 = SCAN Function::Function::getArgByName_dispred#fff OUTPUT In.1, In.0 'arg1', In.2 'arg2'
159751200 ~0% {4} r2 = JOIN r1 WITH Flow::CallNode::getArgByName_dispred#fff_102#join_rhs ON FIRST 1 OUTPUT Rhs.1 'arg0', Lhs.1 'arg1', Lhs.2 'arg2', Rhs.2 'arg3'
return r2
```
... However it's only used in a single place (where it is immediately
joined with the points-to relation to relate the caller and argument),
none of these joins were ever larger than 2000 tuples. This made it
pretty clear that we could gain something by pushing in that points-to
join as a bit of manual magic.
However, doing so didn't actually fix anything, since the join-orderer
then decided to join `func.getArgByName(name)` with
`call.getArgByName(name)` on `name` as the first thing (which caused a
join of the same size as above).
Unbinding didn't work, since `name` would then be an unbound `string`,
so instead I factored out relating the function, parameter, and name
thereof into its own predicate. (I could also have done this with the
call, but I would expect there to be more calls than function
definitions in general.)
Overall, this resulted in going from
```
(709s)
Definitions.ql-7:PointsTo::InterProceduralPointsTo::named_argument_transfer#ffff#join_rhs ......... 53.5s
Definitions.ql-7:Instances::InstanceObject::initializer_dispred#fbf ............................... 35.3s (456 evaluations with max 136ms in Instances::InstanceObject::initializer_dispred#fbf/3@i110#0508e8)
Definitions.ql-10:DefinitionTracking::jump_to_defn_attribute#fbf .................................. 27s (100 evaluations with max 12.8s in DefinitionTracking::jump_to_defn_attribute#fbf/3@i1#fc1f7x)
Definitions.ql-7:PointsTo::PointsToInternal::pointsTo#ffff ........................................ 16.1s (681 evaluations with max 2.5s in PointsTo::PointsToInternal::pointsTo#ffff/4@i4#0508eg)
Definitions.ql-7:Constants::ConstantObjectInternal::attribute#ffff ................................ 13.4s (505 evaluations with max 50ms in Constants::ConstantObjectInternal::attribute#ffff/4@i153#0508e5)
Definitions.ql-10:DefinitionTracking::assignment_jump_to_defn_attribute#fbf ....................... 12.4s (99 evaluations with max 11.8s in DefinitionTracking::assignment_jump_to_defn_attribute#fbf/3@i2#fc1f
7z)
...
```
to
```
(668s)
Definitions.ql-7:Instances::InstanceObject::initializer_dispred#fbf ................... 35.4s (456 evaluations with max 140ms in Instances::InstanceObject::initializer_dispred#fbf/3@i110#bf4328)
Definitions.ql-10:DefinitionTracking::jump_to_defn_attribute#fbf ...................... 27.4s (100 evaluations with max 13.3s in DefinitionTracking::jump_to_defn_attribute#fbf/3@i1#679d7x)
Definitions.ql-7:PointsTo::PointsToInternal::pointsTo#ffff ............................ 16.1s (681 evaluations with max 2.5s in PointsTo::PointsToInternal::pointsTo#ffff/4@i4#bf432g)
Definitions.ql-7:Constants::ConstantObjectInternal::attribute#ffff .................... 14.4s (505 evaluations with max 51ms in Constants::ConstantObjectInternal::attribute#ffff/4@i140#bf4325)
Definitions.ql-10:DefinitionTracking::assignment_jump_to_defn_attribute#fbf ........... 12.3s (99 evaluations with max 11.7s in DefinitionTracking::assignment_jump_to_defn_attribute#fbf/3@i2#679d
7z)
...
```
