Compilation time regression on nightly due to #41099

[benlorenz]

I have been trying to debug a regression in the compilation time for many tests of Polymake.jl, it started with this PkgEval report https://s3.amazonaws.com/julialang-reports/nanosoldier/pkgeval/by_date/2023-04/27/report.html where the tests jumped from about 13 minutes to a timeout (>45min). The tests are mostly checking compatibility of our own vector and matrix types with the corresponding julia types (for different element types). These types are mostly defined via CxxWrap and a corresponding libcxxwrap module.
In our own CI we see similar effects with nightly taking more than twice as long for the tests as 1.8 or 1.9.

I added a @time to several of the affected test groups and the output looks like this:

 22.716351 seconds (3.42 M allocations: 228.784 MiB, 0.16% gc time, 99.98% compilation time)

So this is indeed compilation time and not related to the actual computations. That timing was for this code block.

I bisected the regression to #41099 by @BioTurboNick but I don't really know how to debug this further.
In these timings below I noticed most of the extra time seems to be spent in AST_COMPRESS, which went from 4% to 51%. CODEGEN_LLVM also went up a bit. But I don't really know what to make of this now, especially why or how our code is triggering this in combination with that PR.

Timings

I ran some tests on a nightly build with WITH_TIMING_COUNTS=1. I added some extra verbosity to the test sets to see more timings and disabled several test sets which do not exhibit this problem.

This is for the current master (Commit f407a4c):

JULIA TIMINGS
Event                    , Self Cycles (% of Total)      , Total Cycles (% of Total)     
ADD_METHOD               ,           3514143189 ( 0.08 %),           3665570689 ( 0.08 %)
AST_COMPRESS             ,        2348395690639 (51.58 %),        2348395690639 (51.58 %)
AST_UNCOMPRESS           ,          15147700000 ( 0.33 %),          15378217751 ( 0.34 %)
CODEGEN_Codeinst         ,             98448269 ( 0.00 %),         265528616248 ( 5.83 %)
CODEGEN_LLVM             ,         264305217253 ( 5.81 %),         264865339231 ( 5.82 %)
CODEGEN_Workqueue        ,            139461127 ( 0.00 %),          12221039711 ( 0.27 %)
CODEINST_COMPILE         ,           1192903873 ( 0.03 %),        2043389338089 (44.88 %)
DL_OPEN                  ,             78957620 ( 0.00 %),             78957620 ( 0.00 %)
GC                       ,             47382498 ( 0.00 %),          15914524530 ( 0.35 %)
GC_Finalizers            ,            265416755 ( 0.01 %),            299007204 ( 0.01 %)
GC_FullSweep             ,            105122446 ( 0.00 %),            105122446 ( 0.00 %)
GC_IncrementalSweep      ,           7270270064 ( 0.16 %),           7270270064 ( 0.16 %)
GC_Mark                  ,           8192644545 ( 0.18 %),           8192644545 ( 0.18 %)
GC_Stop                  ,                97773 ( 0.00 %),                97773 ( 0.00 %)
INFERENCE                ,          86903454075 ( 1.91 %),        2482940830167 (54.54 %)
INIT_MODULE              ,           8107964312 ( 0.18 %),          19631247198 ( 0.43 %)
JULIA_INIT               ,             65782478 ( 0.00 %),            237956976 ( 0.01 %)
LLVM_OPT                 ,        1059662566154 (23.28 %),        1059662566154 (23.28 %)
LLVM_ORC                 ,         716882046556 (15.75 %),        1776544612710 (39.02 %)
LOAD_Pkgimg              ,            860054924 ( 0.02 %),           7402571632 ( 0.16 %)
LOAD_Processor           ,              1568929 ( 0.00 %),              1568929 ( 0.00 %)
LOAD_Require             ,            266486681 ( 0.01 %),          28020265123 ( 0.62 %)
LOAD_Sysimg              ,            140595865 ( 0.00 %),            140595865 ( 0.00 %)
LOWERING                 ,           4938725087 ( 0.11 %),           6081574799 ( 0.13 %)
MACRO_INVOCATION         ,             20986884 ( 0.00 %),            876916164 ( 0.02 %)
METHOD_LOOKUP_FAST       ,           3206808468 ( 0.07 %),           3986616164 ( 0.09 %)
METHOD_LOOKUP_SLOW       ,             91857246 ( 0.00 %),            875939345 ( 0.02 %)
METHOD_MATCH             ,          15893573564 ( 0.35 %),          16805438247 ( 0.37 %)
PARSING                  ,            691756980 ( 0.02 %),            691756980 ( 0.02 %)
ROOT                     ,           2482796762 ( 0.05 %),        4552689821858 (100.00 %)
STAGED_FUNCTION          ,              1190547 ( 0.00 %),            300850387 ( 0.01 %)
TYPE_CACHE_INSERT        ,            601778215 ( 0.01 %),            601778215 ( 0.01 %)
TYPE_CACHE_LOOKUP        ,           2759831421 ( 0.06 %),           2759831421 ( 0.06 %)
VERIFY_Edges             ,            328049638 ( 0.01 %),           2308738847 ( 0.05 %)
VERIFY_Graph             ,             20569865 ( 0.00 %),             20569865 ( 0.00 %)
VERIFY_Methods           ,              7921156 ( 0.00 %),              7921156 ( 0.00 %)

JULIA COUNTERS
Counter                  , Value               
Invalidations            ,                 2333
HeapSize                 ,            744737644
JITSize                  ,             33254347
JITCodeSize              ,             31432685
JITDataSize              ,              1821662
ImageSize                ,            395643680

And from another build where I reverted #41099 (and three other commits which I needed to revert to avoid conflicts, see at the end of this issue [1]):

JULIA TIMINGS
Event                    , Self Cycles (% of Total)      , Total Cycles (% of Total)     
ADD_METHOD               ,           3672342454 ( 0.17 %),           3875313788 ( 0.18 %)
AST_COMPRESS             ,          84232107470 ( 3.93 %),          84232107470 ( 3.93 %)
AST_UNCOMPRESS           ,          13816531605 ( 0.64 %),          14016252819 ( 0.65 %)
CODEGEN_Codeinst         ,             89608396 ( 0.00 %),          67777565810 ( 3.16 %)
CODEGEN_LLVM             ,          66328775206 ( 3.10 %),          67204589383 ( 3.14 %)
CODEGEN_Workqueue        ,            131226434 ( 0.01 %),           7151191775 ( 0.33 %)
CODEINST_COMPILE         ,           1128842086 ( 0.05 %),        1899161320883 (88.64 %)
DL_OPEN                  ,             82986960 ( 0.00 %),             82986960 ( 0.00 %)
GC                       ,             48344120 ( 0.00 %),          15536714911 ( 0.73 %)
GC_Finalizers            ,            239514645 ( 0.01 %),            239537348 ( 0.01 %)
GC_FullSweep             ,            110201791 ( 0.01 %),            110201791 ( 0.01 %)
GC_IncrementalSweep      ,           7615966878 ( 0.36 %),           7615966878 ( 0.36 %)
GC_Mark                  ,           7522571182 ( 0.35 %),           7522571182 ( 0.35 %)
GC_Stop                  ,                93592 ( 0.00 %),                93592 ( 0.00 %)
INFERENCE                ,          84077627794 ( 3.92 %),         215491286569 (10.06 %)
INIT_MODULE              ,           8636965446 ( 0.40 %),          20269670034 ( 0.95 %)
JULIA_INIT               ,             64656364 ( 0.00 %),            228045797 ( 0.01 %)
LLVM_OPT                 ,        1091348663673 (50.93 %),        1091348663673 (50.93 %)
LLVM_ORC                 ,         738791901545 (34.48 %),        1830140565218 (85.42 %)
LOAD_Pkgimg              ,            865851913 ( 0.04 %),           7686754456 ( 0.36 %)
LOAD_Processor           ,              1495812 ( 0.00 %),              1495812 ( 0.00 %)
LOAD_Require             ,            234657082 ( 0.01 %),          28759724671 ( 1.34 %)
LOAD_Sysimg              ,            131844838 ( 0.01 %),            131844838 ( 0.01 %)
LOWERING                 ,           5515049860 ( 0.26 %),           6406164444 ( 0.30 %)
MACRO_INVOCATION         ,             22419703 ( 0.00 %),            891114584 ( 0.04 %)
METHOD_LOOKUP_FAST       ,           3087070252 ( 0.14 %),           3905972971 ( 0.18 %)
METHOD_LOOKUP_SLOW       ,             88961303 ( 0.00 %),            872603509 ( 0.04 %)
METHOD_MATCH             ,          17020788685 ( 0.79 %),          17815537140 ( 0.83 %)
PARSING                  ,            757186245 ( 0.04 %),            757186245 ( 0.04 %)
ROOT                     ,           3265830601 ( 0.15 %),        2142638130876 (100.00 %)
STAGED_FUNCTION          ,              1308655 ( 0.00 %),            309384130 ( 0.01 %)
TYPE_CACHE_INSERT        ,            619835544 ( 0.03 %),            619835544 ( 0.03 %)
TYPE_CACHE_LOOKUP        ,           2722668821 ( 0.13 %),           2722668821 ( 0.13 %)
VERIFY_Edges             ,            331854785 ( 0.02 %),           2309098244 ( 0.11 %)
VERIFY_Graph             ,             24758419 ( 0.00 %),             24758419 ( 0.00 %)
VERIFY_Methods           ,              7620717 ( 0.00 %),              7620717 ( 0.00 %)

JULIA COUNTERS
Counter                  , Value               
Invalidations            ,                 2338
HeapSize                 ,            703725988
JITSize                  ,             33254191
JITCodeSize              ,             31432569
JITDataSize              ,              1821622
ImageSize                ,            375575800

The corresponding test timings for one test group which illustrates the problem quite well. This is for master:

  Polymake.SparseMatrix                                                         | 1757   1757  12m28.0s
    Constructors/Converts                                                       |  592    592     12.2s
    Low-level operations                                                        |  340    340     16.5s
      Polymake.SparseMatrix{Int64}                                              |   39     39      0.3s
      Polymake.SparseMatrix{Polymake.Integer}                                   |   39     39      0.2s
      Polymake.SparseMatrix{Polymake.Rational}                                  |   39     39      0.4s
      Polymake.SparseMatrix{Float64}                                            |   89     89      0.3s
      Polymake.SparseMatrix{Polymake.QuadraticExtension{Polymake.Rational}}     |   39     39      0.3s
      Polymake.SparseMatrix{Polymake.OscarNumber}                               |   39     39      0.2s
      Equality                                                                  |   56     56     14.8s
    Arithmetic                                                                  |  786    786  11m58.5s
      Arithmetic1                                                               |  310    310   3m04.8s
      Arithmetic2                                                               |  260    260   2m45.7s
      Arithmetic3                                                               |   39     39     25.3s
      Arithmetic4                                                               |  140    140   5m09.4s
        Arithmetic4 Int32                                                       |   10     10     17.2s
        Arithmetic4 Int64                                                       |   10     10     15.3s
        Arithmetic4 UInt64                                                      |   10     10     19.8s
        Arithmetic4 BigInt                                                      |   10     10     21.1s
        Arithmetic4 Polymake.Integer                                            |   10     10     17.0s
        Arithmetic4 Rational{Int32}                                             |   10     10     15.9s
        Arithmetic4 Rational{Int64}                                             |   10     10     16.1s
        Arithmetic4 Rational{UInt64}                                            |   10     10     16.7s
        Arithmetic4 Rational{BigInt}                                            |   10     10     23.9s
        Arithmetic4 Polymake.Rational                                           |   10     10     16.2s
        Arithmetic4 Float32                                                     |   10     10     24.2s
        Arithmetic4 Float64                                                     |   10     10     35.9s
        Arithmetic4 BigFloat                                                    |   10     10     35.7s
        Arithmetic4 Polymake.QuadraticExtension{Polymake.Rational}              |   10     10     34.3s
      Arithmetic5                                                               |   20     20     26.0s
    findnz                                                                      |    3      3      0.4s

And with the reverted commits:

  Polymake.SparseMatrix                                                         | 1757   1757   5m00.6s
    Constructors/Converts                                                       |  592    592      7.9s
    Low-level operations                                                        |  340    340     10.9s
      Polymake.SparseMatrix{Int64}                                              |   39     39      0.3s
      Polymake.SparseMatrix{Polymake.Integer}                                   |   39     39      0.3s
      Polymake.SparseMatrix{Polymake.Rational}                                  |   39     39      0.3s
      Polymake.SparseMatrix{Float64}                                            |   89     89      0.3s
      Polymake.SparseMatrix{Polymake.QuadraticExtension{Polymake.Rational}}     |   39     39      0.3s
      Polymake.SparseMatrix{Polymake.OscarNumber}                               |   39     39      0.2s
      Equality                                                                  |   56     56      9.3s
    Arithmetic                                                                  |  786    786   4m41.0s
      Arithmetic1                                                               |  310    310   1m09.0s
      Arithmetic2                                                               |  260    260   1m08.1s
      Arithmetic3                                                               |   39     39      9.4s
      Arithmetic4                                                               |  140    140   2m02.6s
        Arithmetic4 Int32                                                       |   10     10      8.1s
        Arithmetic4 Int64                                                       |   10     10      7.0s
        Arithmetic4 UInt64                                                      |   10     10      6.8s
        Arithmetic4 BigInt                                                      |   10     10      6.8s
        Arithmetic4 Polymake.Integer                                            |   10     10      9.1s
        Arithmetic4 Rational{Int32}                                             |   10     10     10.6s
        Arithmetic4 Rational{Int64}                                             |   10     10      9.2s
        Arithmetic4 Rational{UInt64}                                            |   10     10      6.6s
        Arithmetic4 Rational{BigInt}                                            |   10     10      6.2s
        Arithmetic4 Polymake.Rational                                           |   10     10      6.6s
        Arithmetic4 Float32                                                     |   10     10      8.5s
        Arithmetic4 Float64                                                     |   10     10     12.2s
        Arithmetic4 BigFloat                                                    |   10     10     11.8s
        Arithmetic4 Polymake.QuadraticExtension{Polymake.Rational}              |   10     10     13.1s
      Arithmetic5                                                               |   20     20      8.8s
    findnz                                                                      |    3      3      0.3s

Other packages

While looking at the PkgEval report mentioned earlier I noticed that MultivariatePolynomials.jl might have similar issues, at least for some of its tests:

MutableArithmetics with polynomials in Int64 | 6478      14   6492  1m09.8s

MutableArithmetics with polynomials in Int64 | 6478      14   6492  3m23.8s

before and after, from the second block with MutableArithmetics, the last one before the tests were killed.

additional notes:

• [1] reverted commits:

  * 971c2253ee - (bl/withsomereverts) Benjamin Lorenz : Revert "Lookup metadata for inlined frames for stacktraces (#41099)" (19 hours ago)
  * d450ad31e3 - Benjamin Lorenz : Revert "limit printing depth of argument types in stack traces (#49795)" (19 hours ago)
  * 173d8d4413 - Benjamin Lorenz : Revert "refactor `Base.StackTraces.show_spec_linfo` (#49951)" (19 hours ago)
  * 57d11b3b5d - Benjamin Lorenz : Revert "make `IRShow.method_name` inferrable (#49607)" (19 hours ago)
  

  I also checked that just reverting the other three commits behaves similar to the current master without the reverts to make sure that Lookup metadata for inlined frames for stack traces #41099 is the key change.
• I did most tests with julia nightly builds not on Polymake.jl master but on a custom branch but this should not affect these results, the original PkgEval report was referring to Polymake.jl release v0.9.0.

[BioTurboNick]

Unfortunately I won't be a lot of help on my own, though happy to do what I can with some pointers.

Is there a minimal test you could distill from this that I could use? At a minimum I can isolate which part of the PR may be responsible. Though I'd guess it's from storing MethodInstances in LineInfoNodes, somehow. But I may be a bit lost trying to figure out where in the compiler that's causing a problem.

[benlorenz]

I tried to find a minimal testcase, but the effect seems to disappear once I disable too many other tests. This somehow seems to depend on the amount of tests that are run before and the effect is a lot worse for the later tests:

For my previous test runs I had our container test groups like this, with SparseMatrix at the end taking very long:
master:

  Polymake.Vector                          | 1539   1539   1m36.9s
  Polymake.SparseVector                    | 1704   1704   2m27.0s
  Polymake.Matrix                          | 1667   1667   8m57.0s
  Polymake.SparseMatrix                    | 1757   1757  10m54.7s

with reverts:

  Polymake.Vector                          | 1539   1539   1m17.5s
  Polymake.SparseVector                    | 1704   1704   1m00.8s
  Polymake.Matrix                          | 1667   1667   4m26.0s
  Polymake.SparseMatrix                    | 1757   1757   4m54.2s

While trying to reduce this I tried reordering the test groups and got this, SparseMatrix only taking about 15% longer, but now Vector taking 4 times as much time:

master:

  Polymake.SparseMatrix                    | 1757   1757   4m55.6s
  Polymake.Matrix                          | 1667   1667   6m19.4s
  Polymake.SparseVector                    | 1704   1704   3m29.8s
  Polymake.Vector                          | 1539   1539   4m54.0s

with reverts:

  Polymake.SparseMatrix                    | 1757   1757   4m14.1s
  Polymake.Matrix                          | 1667   1667   3m55.8s
  Polymake.SparseVector                    | 1704   1704   1m22.1s
  Polymake.Vector                          | 1539   1539   1m12.5s

Is it possible that there are some caches, lookup tables, ... that are somehow getting large and slow?

[BioTurboNick]

I suppose we know all the slowdown is in here:

julia/src/ircode.c

Lines 767 to 858 in c4d162e

	JL_DLLEXPORT jl_string_t *jl_compress_ir(jl_method_t *m, jl_code_info_t *code)
	{
	JL_TIMING(AST_COMPRESS, AST_COMPRESS);
	JL_LOCK(&m->writelock); // protect the roots array (Might GC)
	assert(jl_is_method(m));
	assert(jl_is_code_info(code));
	ios_t dest;
	ios_mem(&dest, 0);
	int en = jl_gc_enable(0); // Might GC
	size_t i;
	if (m->roots == NULL) {
	m->roots = jl_alloc_vec_any(0);
	jl_gc_wb(m, m->roots);
	}
	jl_ircode_state s = {
	&dest,
	m,
	jl_current_task->ptls,
	1
	};
	jl_code_info_flags_t flags = code_info_flags(code->inferred, code->propagate_inbounds, code->has_fcall,
	code->nospecializeinfer, code->inlining, code->constprop);
	write_uint8(s.s, flags.packed);
	write_uint8(s.s, code->purity.bits);
	write_uint16(s.s, code->inlining_cost);
	size_t nslots = jl_array_len(code->slotflags);
	assert(nslots >= m->nargs && nslots < INT32_MAX); // required by generated functions
	write_int32(s.s, nslots);
	ios_write(s.s, (char*)jl_array_data(code->slotflags), nslots);
	// N.B.: The layout of everything before this point is explicitly referenced
	// by the various jl_ir_ accessors. Make sure to adjust those if you change
	// the data layout.
	for (i = 0; i < 6; i++) {
	int copy = 1;
	if (i == 1) { // skip codelocs
	assert(jl_field_offset(jl_code_info_type, i) == offsetof(jl_code_info_t, codelocs));
	continue;
	}
	if (i == 4) { // don't copy contents of method_for_inference_limit_heuristics field
	assert(jl_field_offset(jl_code_info_type, i) == offsetof(jl_code_info_t, method_for_inference_limit_heuristics));
	copy = 0;
	}
	jl_encode_value_(&s, jl_get_nth_field((jl_value_t*)code, i), copy);
	}
	// For opaque closure, also save the slottypes. We technically only need the first slot type,
	// but this is simpler for now. We may want to refactor where this gets stored in the future.
	if (m->is_for_opaque_closure)
	jl_encode_value_(&s, code->slottypes, 1);
	if (m->generator)
	// can't optimize generated functions
	jl_encode_value_(&s, (jl_value_t*)jl_compress_argnames(code->slotnames), 1);
	else
	jl_encode_value(&s, jl_nothing);
	size_t nstmt = jl_array_len(code->code);
	assert(nstmt == jl_array_len(code->codelocs));
	if (jl_array_len(code->linetable) < 256) {
	for (i = 0; i < nstmt; i++) {
	write_uint8(s.s, ((int32_t*)jl_array_data(code->codelocs))[i]);
	}
	}
	else if (jl_array_len(code->linetable) < 65536) {
	for (i = 0; i < nstmt; i++) {
	write_uint16(s.s, ((int32_t*)jl_array_data(code->codelocs))[i]);
	}
	}
	else {
	ios_write(s.s, (char*)jl_array_data(code->codelocs), nstmt * sizeof(int32_t));
	}
	write_uint8(s.s, s.relocatability);
	ios_flush(s.s);
	jl_string_t *v = jl_pchar_to_string(s.s->buf, s.s->size);
	ios_close(s.s);
	if (jl_array_len(m->roots) == 0) {
	m->roots = NULL;
	}
	JL_GC_PUSH1(&v);
	jl_gc_enable(en);
	JL_UNLOCK(&m->writelock); // Might GC
	JL_GC_POP();
	return v;
	}

I wonder if the timing mechanism could be extended to narrow down which specific portions are slower?

Though an educated guess would be that the linetables have more information in them and, therefore, take longer to compress? (But I may be reading this wrong...)

julia/src/ircode.c

Lines 830 to 842 in c4d162e

	if (jl_array_len(code->linetable) < 256) {
	for (i = 0; i < nstmt; i++) {
	write_uint8(s.s, ((int32_t*)jl_array_data(code->codelocs))[i]);
	}
	}
	else if (jl_array_len(code->linetable) < 65536) {
	for (i = 0; i < nstmt; i++) {
	write_uint16(s.s, ((int32_t*)jl_array_data(code->codelocs))[i]);
	}
	}
	else {
	ios_write(s.s, (char*)jl_array_data(code->codelocs), nstmt * sizeof(int32_t));
	}

[benlorenz]

That does fit my observations, it looks like it is spending quite some time in compressing the LineInfoNodes that now store the Methods / MethodInstances instead of the name.

I repeatedly hit the running process with USR1 and quite often I get backtraces that look like this:

signal (10): User defined signal 1
jl_egal_ at /home/lorenz/software/polymake/julia/julia/julia/src/julia.h:1493 [inlined]
literal_val_id at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:82 [inlined]
jl_encode_as_indexed_root at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:106
jl_encode_value_ at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:327
jl_encode_value_ at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:358
ijl_compress_ir at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:814
maybe_compress_codeinfo at ./compiler/typeinfer.jl:360
transform_result_for_cache at ./compiler/typeinfer.jl:379 [inlined]
cache_result! at ./compiler/typeinfer.jl:405
_typeinf at ./compiler/typeinfer.jl:283
typeinf at ./compiler/typeinfer.jl:216
typeinf_edge at ./compiler/typeinfer.jl:930
abstract_call_method at ./compiler/abstractinterpretation.jl:629
abstract_call_gf_by_type at ./compiler/abstractinterpretation.jl:95
abstract_call_known at ./compiler/abstractinterpretation.jl:2046
...

I also managed to hit such a backtrace with gdb which gives a bit more information:

#0  0x00007f8a4d2e7c17 in jl_egal__unboxed_ (dtag=140231691781904, b=0x7f89bc6e5500, a=0x7f8a428042e0)
    at /home/lorenz/software/polymake/julia/julia/julia/src/julia.h:1486
#1  jl_egal_ (b=0x7f89bc6e5500, a=0x7f8a428042e0)
    at /home/lorenz/software/polymake/julia/julia/julia/src/julia.h:1498
#2  literal_val_id (v=0x7f89bc6e5500, s=<optimized out>, rr=0x7ffe9addf2b0)
    at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:82
#3  jl_encode_as_indexed_root (s=s@entry=0x7ffe9addf450, v=0x7f89bc6e5500)
    at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:106
#4  0x00007f8a4d2e9176 in jl_encode_value_ (s=s@entry=0x7ffe9addf450, v=<optimized out>, 
    as_literal=as_literal@entry=0) at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:433
#5  0x00007f8a4d2e9630 in jl_encode_value_ (s=s@entry=0x7ffe9addf450, v=<optimized out>, 
    as_literal=as_literal@entry=0) at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:327
#6  0x00007f8a4d2e9a6d in jl_encode_value_ (s=s@entry=0x7ffe9addf450, v=<optimized out>, 
    as_literal=as_literal@entry=1) at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:358
#7  0x00007f8a4d2ea160 in ijl_compress_ir (m=0x7f8a3a0253d0 <jl_system_image_data+35479824>, 
    code=0x7f89b0d92380) at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:814
#8  0x00007f8a378b30b8 in julia_maybe_compress_codeinfo_38174 () at compiler/typeinfer.jl:360
#9  0x00007f8a3786f8db in transform_result_for_cache () at compiler/typeinfer.jl:379
#10 julia_cache_result!_38191 () at compiler/typeinfer.jl:405
#11 0x00007f8a37b171ac in julia__typeinf_38127 () at compiler/typeinfer.jl:283
#12 0x00007f8a3730c257 in julia_typeinf_38095 () at compiler/typeinfer.jl:216
#13 0x00007f8a37943e12 in julia_typeinf_edge_38296 () at compiler/typeinfer.jl:930
#14 0x00007f8a37bede16 in julia_abstract_call_method_36753 () at compiler/abstractinterpretation.jl:629
#15 0x00007f8a37705b73 in julia_abstract_call_gf_by_type_36579 ()
    at compiler/abstractinterpretation.jl:95
#16 0x00007f8a372143cc in julia_abstract_call_known_37367 () at compiler/abstractinterpretation.jl:2046
#17 0x00007f8a375bb2b2 in julia_abstract_call_37520 () at compiler/abstractinterpretation.jl:2122
#18 0x00007f8a3786e7e7 in julia_abstract_call_37602 () at compiler/abstractinterpretation.jl:2096
#19 0x00007f8a3730b88e in julia_abstract_call_37511 () at compiler/abstractinterpretation.jl:2279
#20 0x00007f8a375bbaef in julia_abstract_eval_call_37694 () at compiler/abstractinterpretation.jl:2299

Frame 7 is the ijl_compress_ir mentioned earlier, we are in line 814 which encodes the CodeInfo, and currently i=5, which should correspond to the linetable.

The next frame just unpacks that array.

Frame 5 is for encoding the LineInfoNode, and we are at i=1 which corresponds to the second field where the method / methodinstance should be:

324	    else if (jl_typetagis(v, jl_lineinfonode_type)) {
325	        write_uint8(s->s, TAG_LINEINFO);
326	        for (i = 0; i < jl_datatype_nfields(jl_lineinfonode_type); i++)
327	            jl_encode_value(s, jl_get_nth_field(v, i));
328	    }

And then for this encoding (via jl_encode_as_indexed_root) we run into literal_val_id where we seem to compare such a MethodInstance with all method roots via jl_egal:

#1  literal_val_id (v=0x7f89bb4343d0, s=<optimized out>, rr=0x7ffe9addafd0)
    at /home/lorenz/software/polymake/julia/julia/julia/src/ircode.c:82

70	static void literal_val_id(rle_reference *rr, jl_ircode_state *s, jl_value_t *v) JL_GC_DISABLED
71	{
72	    jl_array_t *rs = s->method->roots;
73	    int i, l = jl_array_len(rs);
74	    if (jl_is_symbol(v) || jl_is_concrete_type(v)) {
75	        for (i = 0; i < l; i++) {
76	            if (jl_array_ptr_ref(rs, i) == v)
77	                return tagged_root(rr, s, i);
78	        }
79	    }
80	    else {
81	        for (i = 0; i < l; i++) {
82	            if (jl_egal(jl_array_ptr_ref(rs, i), v))
83	                return tagged_root(rr, s, i);
84	        }
85	    }
86	    jl_add_method_root(s->method, jl_precompile_toplevel_module, v);
87	    return tagged_root(rr, s, jl_array_len(rs) - 1);
88	}

(gdb) call jl_(jl_typeof(v))
Core.MethodInstance
(gdb) call jl_(v)
(::Type{CxxWrap.CxxWrapCore.ConstCxxRef{Polymake.LibPolymake.SparseVector{Polymake.LibPolymake.Rational}}})(Ptr{Nothing}) from (::Type{CxxWrap.CxxWrapCore.ConstCxxRef{T}})(Ptr{T} where T) where {T}
(gdb) p s->method->roots->length
$13 = 33340

This second loop seems to take quite a while, there are also quite a lot of roots.
Without the change this field might have been a symbol and used the first (faster?) loop?

I wonder if the timing mechanism could be extended to narrow down which specific portions are slower?

Looks like it can, I added X(IRCOMP_LITVAL) to the timing subsystems in timing.h, added JL_TIMING(IRCOMP_LITVAL, IRCOMP_LITVAL); to the above function and got:

AST_COMPRESS             ,          19918970129 ( 0.55 %),        1487756848655 (41.14 %)
...
IRCOMP_LITVAL            ,        1467837878526 (40.59 %),        1467837878526 (40.59 %)

So if this works as expected, almost all the time inside AST_COMPRESS seems to be spent in this literal_val_id function.

PS: Line numbers correspond to commit f407a4c.

Edit:
For comparison I added the same timing statements to the build which has the reverted commits and I get just 2% in the new IRCOMP_LITVAL:

Event                    , Self Cycles (% of Total)      , Total Cycles (% of Total)     
ADD_METHOD               ,           3575935343 ( 0.16 %),           3767675666 ( 0.17 %)
AST_COMPRESS             ,          13102464145 ( 0.58 %),          61441313977 ( 2.74 %)
AST_UNCOMPRESS           ,          14145984302 ( 0.63 %),          14348582309 ( 0.64 %)
CODEGEN_Codeinst         ,             91633141 ( 0.00 %),          66084549691 ( 2.95 %)
CODEGEN_LLVM             ,          64617649983 ( 2.88 %),          65505328655 ( 2.92 %)
CODEGEN_Workqueue        ,            134335623 ( 0.01 %),           7532002742 ( 0.34 %)
CODEINST_COMPILE         ,           1145205447 ( 0.05 %),        1945422025519 (86.79 %)
DL_OPEN                  ,            100072739 ( 0.00 %),            100072739 ( 0.00 %)
GC                       ,             45712481 ( 0.00 %),          14239474721 ( 0.64 %)
GC_Finalizers            ,            259778430 ( 0.01 %),            259828974 ( 0.01 %)
GC_FullSweep             ,            107974667 ( 0.00 %),            107974667 ( 0.00 %)
GC_IncrementalSweep      ,           6800313932 ( 0.30 %),           6800313932 ( 0.30 %)
GC_Mark                  ,           7025563210 ( 0.31 %),           7025563210 ( 0.31 %)
GC_Stop                  ,                81457 ( 0.00 %),                81457 ( 0.00 %)
INFERENCE                ,          86722293188 ( 3.87 %),         195156770864 ( 8.71 %)
INIT_MODULE              ,          64294881505 ( 2.87 %),          86200640029 ( 3.85 %)
IRCOMP_LITVAL            ,          48338849832 ( 2.16 %),          48338849832 ( 2.16 %)
JULIA_INIT               ,             67818157 ( 0.00 %),            231329978 ( 0.01 %)
LLVM_OPT                 ,        1120071637440 (49.97 %),        1120071637440 (49.97 %)
LLVM_ORC                 ,         758003630861 (33.82 %),        1878075268301 (83.78 %)
LOAD_Pkgimg              ,            848177602 ( 0.04 %),           7388993626 ( 0.33 %)
LOAD_Processor           ,              1976376 ( 0.00 %),              1976376 ( 0.00 %)
LOAD_Require             ,            221449806 ( 0.01 %),          94751808669 ( 4.23 %)
LOAD_Sysimg              ,            131339745 ( 0.01 %),            131339745 ( 0.01 %)
LOWERING                 ,           5704511976 ( 0.25 %),           6833292884 ( 0.30 %)
MACRO_INVOCATION         ,             25892596 ( 0.00 %),           1128780908 ( 0.05 %)
METHOD_LOOKUP_FAST       ,           3149306459 ( 0.14 %),           4047836294 ( 0.18 %)
METHOD_LOOKUP_SLOW       ,             38612337 ( 0.00 %),            828309377 ( 0.04 %)
METHOD_MATCH             ,          17309173074 ( 0.77 %),          17875621316 ( 0.80 %)
PARSING                  ,            745536025 ( 0.03 %),            745536025 ( 0.03 %)
ROOT                     ,          20903426138 ( 0.93 %),        2241613887403 (100.00 %)
STAGED_FUNCTION          ,              2404728 ( 0.00 %),            514411583 ( 0.02 %)
TYPE_CACHE_INSERT        ,            600301181 ( 0.03 %),            600301181 ( 0.03 %)
TYPE_CACHE_LOOKUP        ,           2905647622 ( 0.13 %),           2905647622 ( 0.13 %)
VERIFY_Edges             ,            345359034 ( 0.02 %),           2150140787 ( 0.10 %)
VERIFY_Graph             ,             21222541 ( 0.00 %),             21222541 ( 0.00 %)
VERIFY_Methods           ,              7734280 ( 0.00 %),              7734280 ( 0.00 %)

[BioTurboNick]

That's awesome, thanks for poking into it! Love identifying a good quadratic-time algorithm to optimize.

Does Julia need to look up the root each time it's being compressed? If there are many copies of the same method instances, that's a lot of unnecessary repeated work. Can the root be stored with the method instance at an earlier point, so the lookup is only performed once?

Can the lookup operation be turned into a dictionary access rather than array iteration, so the lookup itself is constant-time?

[BioTurboNick]

@JeffBezanson @timholy - Since you've both most recently (2-3 years ago :-p) touched literal_val_id, what are your impressions? Are either of my suggestions potentially workable, or are there obvious reasons those couldn't work that I'm not seeing?

Trying to gauge if this is feasible for me to tackle, or if it's a much bigger problem to untangle.

[vtjnash]

That array should never be long, since that can cause a myriad of other problems. How is that happening and how can that be avoided?

[benlorenz]

I added a little bit of code to print the maximal size for that array:

    static int max = 0;
    if (l > 1000 && l > max) {
        max = l;
        printf("rootmax: %d\n", max);
    }

On master (more precisely f407a4c, including #41099) our testsuite ends with:

rootmax: 111575

On my other build where I reverted #41099 (see my earlier posts for the precise commits) I get:

rootmax: 13894

13894 seems quite large as well? But I guess it is a lot better than 111575.

I really don't understand the details, I am just trying to debug what is happening here.

So adding the Methods / MethodInstances to those LineNumberNodes seems to trigger a lot more roots?

[BioTurboNick]

Was just exploring the same kind of testing.

When Julia is started for the first time after building with that PR (make cleanall, deleted .julia), literal_val_id is called 1,702,882 times (compared with 109 on second run).

With the commit just before the PR merge, this count is 870,750.

EDIT: (The fact that it's almost exactly double seems suspicious.)

[BioTurboNick]

It appears that literal_val_id is the only method that adds to a method's root table (via jl_add_method_root).

So the MethodInstances being added to LineInfoNodes aren't present in the parent Method's root table, which results in them being added to the Method's roots. Previously, they would all just map to the method name (as a Symbol), and thus share the same root. I believe?

[benlorenz]

13894 seems quite large as well? But I guess it is a lot better than 111575.

Some more details from running our testsuite, inspired by the plots from #14556, number of times a specific roots array length is encountered in literal_val_id:

Total number of calls to jl_egal inside literal_val_id:

• master: 114202053625
• w/o 41099: 3059875551

[giordano]

I also noticed that running tests of a package of mine on c58e508 takes sensibly longer than on v1.9, but haven't investigate what's the cause of the longer runtime.