TPDB.DP.Graph.components is slow

[jwaldmann]

.. for larger systems (> 1000 rules). Perhaps our hand-rolled unification is to blame. Need to make an exact profile first.

[jwaldmann]

profiling data:

        Wed Feb 23 17:57 2022 Time and Allocation Profiling Report  (Final)

           dp-performance +RTS -P -RTS

        total time  =        8.64 secs   (8636 ticks @ 1000 us, 1 processor)
        total alloc = 2,762,240,224 bytes  (excludes profiling overheads)

COST CENTRE MODULE          SRC                                    %time %alloc  ticks     bytes

components  TPDB.DP.Graph   src/TPDB/DP/Graph.hs:(27,1)-(41,44)     24.7    3.2   2135  87658792
usable      TPDB.DP.Usable  src/TPDB/DP/Usable.hs:(23,1)-(25,41)    22.7   21.9   1963 603894536
mgu         TPDB.DP.Unify   src/TPDB/DP/Unify.hs:(35,1)-(46,17)     18.9    0.5   1636  12439632
walk        TPDB.DP.TCap    src/TPDB/DP/TCap.hs:(22,1)-(28,18)       9.9    9.7    855 268296536
edges       TPDB.DP.Graph   src/TPDB/DP/Graph.hs:(42,1)-(48,16)      7.0    7.7    608 212878432
vmap        TPDB.Data.Term  src/TPDB/Data/Term.hs:(14,1)-(15,53)     6.1   42.9    525 1185112280
strict      TPDB.Data.Rule  src/TPDB/Data/Rule.hs:14:1-57            3.2    0.0    279         0
unifies     TPDB.DP.Unify   src/TPDB/DP/Unify.hs:(10,1)-(12,30)      2.6    0.0    224    188496
lexer       TPDB.Plain.Read src/TPDB/Plain/Read.hs:(46,1)-(57,8)     1.7   12.3    147 338536528
main        Main            test/dp-performance.hs:(16,1)-(28,66)    1.3    0.0    116   1326376

with --profiling-detail=all-functions:

        Wed Feb 23 18:01 2022 Time and Allocation Profiling Report  (Final)

           dp-performance +RTS -P -RTS

        total time  =        8.52 secs   (8516 ticks @ 1000 us, 1 processor)
        total alloc = 2,762,658,664 bytes  (excludes profiling overheads)

COST CENTRE   MODULE            SRC                                   %time %alloc  ticks     bytes

==            TPDB.DP.Transform src/TPDB/DP/Transform.hs:16:22-23      23.5    0.0   2002         0
mgu           TPDB.DP.Unify     src/TPDB/DP/Unify.hs:(35,1)-(46,17)    10.7    0.3    912   9358368
walk          TPDB.DP.TCap      src/TPDB/DP/TCap.hs:(22,1)-(28,18)      7.9    0.1    674   3982400
usable        TPDB.DP.Usable    src/TPDB/DP/Usable.hs:(23,1)-(25,41)    7.6   21.9    645 603894536
==            TPDB.Data.Term    src/TPDB/Data/Term.hs:11:16-17          7.2    0.0    613         0
edges         TPDB.DP.Graph     src/TPDB/DP/Graph.hs:(42,1)-(48,16)     7.1    7.7    606 212878432
vmap          TPDB.Data.Term    src/TPDB/Data/Term.hs:(14,1)-(15,53)    6.9   42.9    589 1185112280
compare       TPDB.DP.Transform src/TPDB/DP/Transform.hs:16:26-28       5.3    0.0    450         0
compare       TPDB.Data.Term    src/TPDB/Data/Term.hs:11:20-22          5.1    0.0    434         0
components.es TPDB.DP.Graph     src/TPDB/DP/Graph.hs:(28,9)-(29,50)     4.0    0.3    339   7780912
strict        TPDB.Data.Rule    src/TPDB/Data/Rule.hs:14:1-57           3.0    0.0    252         0
unifies       TPDB.DP.Unify     src/TPDB/DP/Unify.hs:(10,1)-(12,30)     2.1    0.0    181    233376
compare       TPDB.Data         src/TPDB/Data.hs:39:20-22               1.7    0.0    144         0
lexer         TPDB.Plain.Read   src/TPDB/Plain/Read.hs:(46,1)-(57,8)    1.6   11.7    139 323343584
walk.\        TPDB.DP.TCap      src/TPDB/DP/TCap.hs:25:25-77            1.4    9.6    120 264314136
==            TPDB.Data         src/TPDB/Data.hs:39:16-17               1.3    0.0    109         0
compare       TPDB.Data.Rule    src/TPDB/Data/Rule.hs:11:20-22          1.1    0.0     94         0
components    TPDB.DP.Graph     src/TPDB/DP/Graph.hs:(27,1)-(41,44)     0.8    2.8     65  77247416

[jwaldmann]

Now,

        Wed Feb 23 19:59 2022 Time and Allocation Profiling Report  (Final)

           dp-performance +RTS -P -RTS

        total time  =        8.33 secs   (8328 ticks @ 1000 us, 1 processor)
        total alloc = 2,759,789,472 bytes  (excludes profiling overheads)

COST CENTRE   MODULE            SRC                                   %time %alloc  ticks     bytes

==            TPDB.DP.Transform src/TPDB/DP/Transform.hs:30:22-23      16.3    0.0   1356         0
mgu           TPDB.DP.Unify     src/TPDB/DP/Unify.hs:(35,1)-(46,17)    13.2    0.3   1102   9358368
==            TPDB.Data.Term    src/TPDB/Data/Term.hs:11:16-17          9.4    0.0    779         0
compare       TPDB.Data.Term    src/TPDB/Data/Term.hs:11:20-22          9.2    0.0    770         0
components.es TPDB.DP.Graph     src/TPDB/DP/Graph.hs:(28,9)-(29,50)     9.1    0.3    755   7780912
edges         TPDB.DP.Graph     src/TPDB/DP/Graph.hs:(42,1)-(48,16)     7.4    7.7    616 212878432
usable        TPDB.DP.Usable    src/TPDB/DP/Usable.hs:(23,1)-(25,41)    7.3   21.8    606 600775200
vmap          TPDB.Data.Term    src/TPDB/Data/Term.hs:(14,1)-(15,53)    6.8   42.9    570 1185112280
walk          TPDB.DP.TCap      src/TPDB/DP/TCap.hs:(22,1)-(28,18)      6.7    0.1    554   3982400
strict        TPDB.Data.Rule    src/TPDB/Data/Rule.hs:14:1-57           2.9    0.0    238         0
unifies       TPDB.DP.Unify     src/TPDB/DP/Unify.hs:(10,1)-(12,30)     2.3    0.0    192    233376
walk.\        TPDB.DP.TCap      src/TPDB/DP/TCap.hs:25:25-77            1.6    9.6    133 264314136
lexer         TPDB.Plain.Read   src/TPDB/Plain/Read.hs:(46,1)-(57,8)    1.5   11.7    129 323343584
compare       TPDB.Data         src/TPDB/Data.hs:39:20-22               1.4    0.0    115         0
compare       TPDB.DP.Transform src/TPDB/DP/Transform.hs:30:26-28       1.3    0.0    110         0
components    TPDB.DP.Graph     src/TPDB/DP/Graph.hs:(27,1)-(41,44)     0.7    2.8     57  77247416

[jwaldmann]

Now,

        Wed Feb 23 22:59 2022 Time and Allocation Profiling Report  (Final)

           dp-performance +RTS -P -RTS

        total time  =        6.78 secs   (6776 ticks @ 1000 us, 1 processor)
        total alloc = 2,590,255,528 bytes  (excludes profiling overheads)

COST CENTRE   MODULE               SRC                                   %time %alloc  ticks     bytes

==            TPDB.DP.Transform    src/TPDB/DP/Transform.hs:30:22-23      14.4    0.0    976         0
compare       TPDB.Data.Term.Plain src/TPDB/Data/Term/Plain.hs:19:20-22   11.5    0.0    782         0
mgu           TPDB.DP.Unify        src/TPDB/DP/Unify.hs:(40,1)-(54,17)    11.3    0.4    763   9360272
==            TPDB.Data.Term.Plain src/TPDB/Data/Term/Plain.hs:19:16-17    9.8    0.0    664         0
components.es TPDB.DP.Graph        src/TPDB/DP/Graph.hs:(28,9)-(29,50)     9.4    0.3    637   7781184
usable        TPDB.DP.Usable       src/TPDB/DP/Usable.hs:(23,1)-(25,41)    9.3   23.2    628 600797600
edges         TPDB.DP.Graph        src/TPDB/DP/Graph.hs:(42,1)-(48,16)     9.1   24.9    614 644944896
walk          TPDB.DP.TCap         src/TPDB/DP/TCap.hs:(24,1)-(30,18)      6.3    0.2    430   3982400
walk.\        TPDB.DP.TCap         src/TPDB/DP/TCap.hs:27:25-77            3.4   30.7    230 794451240
strict        TPDB.Data.Rule       src/TPDB/Data/Rule.hs:14:1-57           2.9    0.0    196         0
unifies       TPDB.DP.Unify        src/TPDB/DP/Unify.hs:(13,1)-(15,30)     2.8    0.0    191    340104
compare       TPDB.DP.Transform    src/TPDB/DP/Transform.hs:30:26-28       2.1    0.0    145         0
lexer         TPDB.Plain.Read      src/TPDB/Plain/Read.hs:(46,1)-(57,8)    1.5   12.5    104 323343584
compare       TPDB.Data.Rule       src/TPDB/Data/Rule.hs:11:20-22          1.4    0.0     94         0
compare       TPDB.Data            src/TPDB/Data.hs:39:20-22               1.4    0.0     94         0
components    TPDB.DP.Graph        src/TPDB/DP/Graph.hs:(27,1)-(41,44)     0.8    3.0     54  77247416
needed.\      TPDB.DP.Usable       src/TPDB/DP/Usable.hs:39:27-82          0.2    3.1     16  79569024

[jwaldmann]

much better now

        Thu Feb 24 01:46 2022 Time and Allocation Profiling Report  (Final)

           dp-performance +RTS -P -RTS

        total time  =        3.42 secs   (3417 ticks @ 1000 us, 1 processor)
        total alloc = 2,340,395,096 bytes  (excludes profiling overheads)

COST CENTRE MODULE               SRC                                   %time %alloc  ticks     bytes

==          TPDB.Data.Term.Plain src/TPDB/Data/Term/Plain.hs:19:16-17   24.8    0.0    849         0
mgu         TPDB.DP.Unify        src/TPDB/DP/Unify.hs:(40,1)-(55,17)    22.9    0.3    783   7472040
edges       TPDB.DP.Graph        src/TPDB/DP/Graph.hs:(41,1)-(46,16)    17.0   57.7    580 1349595208
walk.go     TPDB.DP.TCap         src/TPDB/DP/TCap.hs:(25,7)-(30,22)      8.0    0.2    273   3612904
unifies     TPDB.DP.Unify        src/TPDB/DP/Unify.hs:(13,1)-(15,30)     4.3    0.0    147    339808
lexer       TPDB.Plain.Read      src/TPDB/Plain/Read.hs:(46,1)-(57,8)    3.6   13.8    122 323261408
==          TPDB.DP.Transform    src/TPDB/DP/Transform.hs:30:22-23       3.5    0.0    119         0
strict      TPDB.Data.Rule       src/TPDB/Data/Rule.hs:14:1-57           3.0    0.0    104         0
needed.\    TPDB.DP.Usable       src/TPDB/DP/Usable.hs:52:32-98          2.4    6.0     82 141451912
usable.dpi  TPDB.DP.Usable       src/TPDB/DP/Usable.hs:25:7-45           2.3    7.6     79 176893192
lhs         TPDB.Data.Rule       src/TPDB/Data/Rule.hs:7:22-24           1.9    0.0     66         0
needed      TPDB.DP.Usable       src/TPDB/DP/Usable.hs:(50,1)-(56,15)    1.9    4.5     65 106364256
walk.go.\   TPDB.DP.TCap         src/TPDB/DP/TCap.hs:28:27-79            0.8    3.4     27  79526760
usable.fp   TPDB.DP.Usable       src/TPDB/DP/Usable.hs:(26,7)-(28,71)    0.6    3.2     22  75930496