Skip to content

Integrate symgc in druntime - #4

Draft
kinke wants to merge 40 commits into
sym-1.41.xfrom
symgc
Draft

Integrate symgc in druntime#4
kinke wants to merge 40 commits into
sym-1.41.xfrom
symgc

Conversation

@kinke

@kinke kinke commented May 12, 2025

Copy link
Copy Markdown

No description provided.

@kinke
kinke force-pushed the symgc branch 2 times, most recently from 0711d28 to eed3016 Compare May 12, 2025 16:52
fi
cd runtime/symgc
# FIXME: hitting LLVM assertion with -g
DFLAGS="-O -gline-tables-only -singleobj" dub build -v --compiler=$PWD/../../../bootstrap-ldc/bin/ldc2

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

-singleobj compiles the whole symgc project to a single object file (in the produced static lib) - which is then LLVM-optimized as a single unit (=> implicit cross-module optimizations).

@kinke

kinke commented May 12, 2025

Copy link
Copy Markdown
Author

Okay, seems to work with both shared and static druntime:

hello.d:

extern(C) void _d_register_sdc_gc();

void main() {
    import std.stdio;
    writeln("Hello world!");
    auto dummyAlloc = new int;
    auto dummyRef = &_d_register_sdc_gc; // make sure to link symgc from static druntime
}
$ ldc2 hello.d -link-defaultlib-shared
$ ./hello --DRT-gcopt=gc:sdc
Hello world!
using SDC GC!

$ ldc2 hello.d
$ ./hello --DRT-gcopt=gc:sdc
Hello world!
using SDC GC!

@kinke
kinke force-pushed the symgc branch 3 times, most recently from ada4d81 to db4ea0e Compare May 12, 2025 21:42
@kinke

kinke commented May 14, 2025

Copy link
Copy Markdown
Author

Some metrics for the stdlib/core unittest runner, with the 2 AsyncProcess unittests commented out, on my 48-logical-cores Threadripper:

-j1

  • Old GC: pretty stable, especially the RSS:
      Command being timed: "bin/ut -q -j1"
      User time (seconds): 10.59
      System time (seconds): 7.29
      Percent of CPU this job got: 157%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:11.35
      Maximum resident set size (kbytes): 133524
    
  • New GC: quite unstable results, 3 consecutive runs:
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc"
      User time (seconds): 17.53
      System time (seconds): 21.82
      Percent of CPU this job got: 235%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:16.72
      Maximum resident set size (kbytes): 274752
    
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc"
      User time (seconds): 18.43
      System time (seconds): 21.30
      Percent of CPU this job got: 238%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:16.69
      Maximum resident set size (kbytes): 290764
    
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc"
      User time (seconds): 17.23
      System time (seconds): 18.53
      Percent of CPU this job got: 207%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:17.25
      Maximum resident set size (kbytes): 228884
    

-j1 with parallel:0:

Somehow very unstable RSS:

  • Old GC:
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=parallel:0"
      User time (seconds): 11.03
      System time (seconds): 6.93
      Percent of CPU this job got: 152%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:11.78
      Maximum resident set size (kbytes): 245512
    
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=parallel:0"
      User time (seconds): 11.07
      System time (seconds): 7.26
      Percent of CPU this job got: 154%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:11.89
      Maximum resident set size (kbytes): 132824
    
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=parallel:0"
      User time (seconds): 10.57
      System time (seconds): 7.17
      Percent of CPU this job got: 159%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:11.16
      Maximum resident set size (kbytes): 187096
    
  • New GC:
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 11.25
      System time (seconds): 10.45
      Percent of CPU this job got: 141%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.30
      Maximum resident set size (kbytes): 403452
    
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 11.40
      System time (seconds): 10.60
      Percent of CPU this job got: 142%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.41
      Maximum resident set size (kbytes): 263268
    
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 11.30
      System time (seconds): 10.39
      Percent of CPU this job got: 142%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.26
      Maximum resident set size (kbytes): 539884
    

-j16

  • Old GC:
      Command being timed: "bin/ut -q -j16"
      User time (seconds): 152.53
      System time (seconds): 239.80
      Percent of CPU this job got: 1137%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:34.49
      Maximum resident set size (kbytes): 1730216
    
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=parallel:0"
      User time (seconds): 150.32
      System time (seconds): 237.36
      Percent of CPU this job got: 1129%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:34.33
      Maximum resident set size (kbytes): 1824812
    
  • New GC: very unstable
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=gc:sdc"
      User time (seconds): 17.61
      System time (seconds): 18.35
      Percent of CPU this job got: 652%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.51
      Maximum resident set size (kbytes): 4134632
    
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=gc:sdc"
      User time (seconds): 24.83
      System time (seconds): 24.47
      Percent of CPU this job got: 687%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.16
      Maximum resident set size (kbytes): 2479572
    
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 13.49
      System time (seconds): 13.27
      Percent of CPU this job got: 436%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:06.13
      Maximum resident set size (kbytes): 4471096
    

-j48

  • Old GC:
      Command being timed: "bin/ut -q -j48"
      User time (seconds): 301.37
      System time (seconds): 689.55
      Percent of CPU this job got: 2519%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:39.33
      Maximum resident set size (kbytes): 2573520
    
  • New GC: less scanning threads help on my box, as with earlier results
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc"
      User time (seconds): 22.69
      System time (seconds): 22.88
      Percent of CPU this job got: 964%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:04.72
      Maximum resident set size (kbytes): 4977668
    
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc"
      User time (seconds): 22.37
      System time (seconds): 23.91
      Percent of CPU this job got: 952%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:04.85
      Maximum resident set size (kbytes): 4833344
    
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7"
      User time (seconds): 18.88
      System time (seconds): 14.47
      Percent of CPU this job got: 996%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:03.34
      Maximum resident set size (kbytes): 5228012
    
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:15"
      User time (seconds): 18.04
      System time (seconds): 14.74
      Percent of CPU this job got: 1101%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:02.97
      Maximum resident set size (kbytes): 5250092
    
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:31"
      User time (seconds): 23.74
      System time (seconds): 23.22
      Percent of CPU this job got: 980%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:04.78
      Maximum resident set size (kbytes): 4551148
    

I haven't hit a single assertion/crash anymore! Even with a high number of parallel scanning threads, which used to almost always crash.

@kinke

kinke commented May 14, 2025

Copy link
Copy Markdown
Author

And monorepo test runs with an unoptimized REPL:

  • Old GC:
    4140 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test"
      User time (seconds): 222.28
      System time (seconds): 142.12
      Percent of CPU this job got: 118%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:08.72
      Maximum resident set size (kbytes): 3476456
    
  • New GC: I was expecting lower RSS, but only ran it twice:
    4140 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test --DRT-gcopt=gc:sdc"
      User time (seconds): 332.12
      System time (seconds): 269.83
      Percent of CPU this job got: 194%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:09.66
      Maximum resident set size (kbytes): 3143188
    
    4140 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test --DRT-gcopt=gc:sdc"
      User time (seconds): 324.42
      System time (seconds): 266.29
      Percent of CPU this job got: 192%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:06.80
      Maximum resident set size (kbytes): 3775268
    

@kinke

kinke commented May 14, 2025

Copy link
Copy Markdown
Author

I haven't hit a single assertion/crash anymore! Even with a high number of parallel scanning threads, which used to almost always crash.

Okay, the test runner was just hanging for the 5th consecutive run of bin/ut -q -j48 --DRT-gcopt=gc:sdc.

56 consecutive runs passed with an additional --DRT-gcopt=parallel:0; the 57th one crashed because of the getenv race condition:

/home/mkinkelin/dlang/ldc-1.41.0-sym1-symgc1/bin/../lib/libdruntime-ldc-shared.so.111(_D4core7runtime18runModuleUnitTestsUZ19unittestSegvHandlerUNbNiiPSQCm3sys5posix6signal9siginfo_tPvZv+0x27)[0x7fe9c206e9a7]
/lib/x86_64-linux-gnu/libc.so.6(+0x45330)[0x7fe9c1d3b330]
/lib/x86_64-linux-gnu/libc.so.6(getenv+0x56)[0x7fe9c1d3e806]
/home/mkinkelin/dlang/ldc-1.41.0-sym1-symgc1/bin/../lib/libphobos2-ldc-shared.so.111(_D3std7process11environment3getFNfMAxaAyaZQe+0x47)[0x7fe9c2cc0577]

@kinke

kinke commented May 14, 2025

Copy link
Copy Markdown
Author

New GC: I was expecting lower RSS, but only ran it twice

Okay, looking better now with the thread hooks:

4140 test(s) run, 0 failed.
	Command being timed: "../SIL/artifacts/repl-full/sil test --DRT-gcopt=gc:sdc"
	User time (seconds): 345.87
	System time (seconds): 279.57
	Percent of CPU this job got: 199%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 5:13.35
	Maximum resident set size (kbytes): 2695696

4140 test(s) run, 0 failed.
	Command being timed: "../SIL/artifacts/repl-full/sil test --DRT-gcopt=gc:sdc"
	User time (seconds): 342.05
	System time (seconds): 295.56
	Percent of CPU this job got: 201%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 5:15.78
	Maximum resident set size (kbytes): 2571884

I must admit I was expecting something like ~2GB (starting from ~3.4 GB with old GC), based on old numbers from months ago (but the tests might have changed significantly since then too...).

@kinke
kinke force-pushed the symgc branch 3 times, most recently from eb29994 to d18fb28 Compare May 15, 2025 01:12
kinke and others added 16 commits June 7, 2025 14:14
Mainly to work around frontend assertions when building SIL.
Apparently needed for static druntime, where the strong `register_default_gcs()`
symbol in the symgc object doesn't seem to override the default @weak one in druntime.
Possibly because that would require dragging in the symgc object via an undefined
symbol *before*.
…built with SDC GC

To trivially switch to the new GC via env var `DRT_GCOPT=gc:sdc` without
breaking any programs using a druntime library without SDC GC support
(incl. LDC itself).
or terminating, to do necessary initialization or cleanup. Move blkcache
destruction to the the cleanup function from the conservative GC.
@kinke

kinke commented Jun 23, 2025

Copy link
Copy Markdown
Author

Updated metrics for the stdlib/core unittest runner, 3 consecutive runs each:

-j1

  • Old GC: runtime and RSS very stable; RSS now around 180 MB (was 130 MB earlier):
      Command being timed: "bin/ut -q -j1"
      User time (seconds): 10.51
      System time (seconds): 7.01
      Percent of CPU this job got: 157%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:11.11
      Maximum resident set size (kbytes): 183624
    
  • New GC: unlike earlier, the RSS is now significantly less than with the old GC (as expected); the runtime increase is still heavy (~60%):
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc"
      User time (seconds): 20.97
      System time (seconds): 26.43
      Percent of CPU this job got: 265%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:17.86
      Maximum resident set size (kbytes): 133344
    
      User time (seconds): 21.19
      System time (seconds): 24.92
      Percent of CPU this job got: 256%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:17.97
      Maximum resident set size (kbytes): 151048
    
      User time (seconds): 21.49
      System time (seconds): 25.19
      Percent of CPU this job got: 262%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:17.76
      Maximum resident set size (kbytes): 144344
    
  • New GC with parallel:0 decreases the runtime:
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 11.59
      System time (seconds): 11.19
      Percent of CPU this job got: 146%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.60
      Maximum resident set size (kbytes): 148452
    
      User time (seconds): 11.91
      System time (seconds): 11.84
      Percent of CPU this job got: 152%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.59
      Maximum resident set size (kbytes): 131584
    
      User time (seconds): 11.90
      System time (seconds): 11.06
      Percent of CPU this job got: 144%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.87
      Maximum resident set size (kbytes): 122268
    
  • New GC with parallel:7 slightly decreases the runtime further (but still ~35% higher than with old GC):
      Command being timed: "bin/ut -q -j1 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7"
      User time (seconds): 16.31
      System time (seconds): 12.41
      Percent of CPU this job got: 191%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.04
      Maximum resident set size (kbytes): 137276
    
      User time (seconds): 17.14
      System time (seconds): 12.77
      Percent of CPU this job got: 198%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.03
      Maximum resident set size (kbytes): 157772
    
      User time (seconds): 16.24
      System time (seconds): 11.59
      Percent of CPU this job got: 185%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:15.01
      Maximum resident set size (kbytes): 126336
    

-j16

  • Old GC:
      Command being timed: "bin/ut -q -j16"
      User time (seconds): 151.38
      System time (seconds): 244.20
      Percent of CPU this job got: 1124%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:35.16
      Maximum resident set size (kbytes): 2290576
    
      User time (seconds): 152.08
      System time (seconds): 243.44
      Percent of CPU this job got: 1121%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:35.28
      Maximum resident set size (kbytes): 2187728
    
      User time (seconds): 149.88
      System time (seconds): 240.93
      Percent of CPU this job got: 1111%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:35.15
      Maximum resident set size (kbytes): 2190972
    
  • New GC: a different world in both RSS and speed
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=gc:sdc"
      User time (seconds): 26.28
      System time (seconds): 26.61
      Percent of CPU this job got: 653%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:08.09
      Maximum resident set size (kbytes): 845232
    
      User time (seconds): 26.86
      System time (seconds): 27.91
      Percent of CPU this job got: 667%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:08.20
      Maximum resident set size (kbytes): 1075112
    
      User time (seconds): 26.06
      System time (seconds): 27.81
      Percent of CPU this job got: 682%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.88
      Maximum resident set size (kbytes): 982268
    
  • New GC with parallel:0: faster again
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 16.54
      System time (seconds): 16.13
      Percent of CPU this job got: 447%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.30
      Maximum resident set size (kbytes): 893188
    
      User time (seconds): 16.07
      System time (seconds): 11.83
      Percent of CPU this job got: 371%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.51
      Maximum resident set size (kbytes): 988896
    
      User time (seconds): 16.68
      System time (seconds): 13.29
      Percent of CPU this job got: 406%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.36
      Maximum resident set size (kbytes): 991588
    
  • New GC with parallel:7: significantly faster (and possibly tending towards a higher RSS)
      Command being timed: "bin/ut -q -j16 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7"
      User time (seconds): 20.48
      System time (seconds): 12.29
      Percent of CPU this job got: 634%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.16
      Maximum resident set size (kbytes): 1340356
    
      User time (seconds): 20.52
      System time (seconds): 15.14
      Percent of CPU this job got: 686%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.19
      Maximum resident set size (kbytes): 1374768
    
      User time (seconds): 20.41
      System time (seconds): 11.92
      Percent of CPU this job got: 625%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.17
      Maximum resident set size (kbytes): 1088632
    

-j48

  • Old GC:
      Command being timed: "bin/ut -q -j48"
      User time (seconds): 312.94
      System time (seconds): 728.29
      Percent of CPU this job got: 2595%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:40.11
      Maximum resident set size (kbytes): 3135836
    
      User time (seconds): 309.35
      System time (seconds): 718.54
      Percent of CPU this job got: 2646%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:38.83
      Maximum resident set size (kbytes): 3111432
    
      User time (seconds): 310.96
      System time (seconds): 725.08
      Percent of CPU this job got: 2624%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:39.48
      Maximum resident set size (kbytes): 2864948
    
  • New GC:
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc"
      User time (seconds): 31.48
      System time (seconds): 31.04
      Percent of CPU this job got: 889%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.02
      Maximum resident set size (kbytes): 2533664
    
      User time (seconds): 34.33
      System time (seconds): 34.12
      Percent of CPU this job got: 863%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.92
      Maximum resident set size (kbytes): 2388748
    
      User time (seconds): 35.62
      System time (seconds): 35.38
      Percent of CPU this job got: 883%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:08.04
      Maximum resident set size (kbytes): 3183824
    
  • New GC with parallel:0: faster once more than the default setting
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 20.48
      System time (seconds): 14.95
      Percent of CPU this job got: 541%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:06.53
      Maximum resident set size (kbytes): 2668016
    
      User time (seconds): 20.52
      System time (seconds): 14.78
      Percent of CPU this job got: 543%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:06.49
      Maximum resident set size (kbytes): 2927724
    
      User time (seconds): 20.49
      System time (seconds): 14.69
      Percent of CPU this job got: 533%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:06.59
      Maximum resident set size (kbytes): 2198168
    
  • New GC with parallel:7: significantly faster once more
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7"
      User time (seconds): 25.53
      System time (seconds): 16.15
      Percent of CPU this job got: 989%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:04.21
      Maximum resident set size (kbytes): 2477076
    
      User time (seconds): 28.58
      System time (seconds): 19.66
      Percent of CPU this job got: 958%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.03
      Maximum resident set size (kbytes): 2710864
    
      User time (seconds): 24.28
      System time (seconds): 15.03
      Percent of CPU this job got: 996%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:03.94
      Maximum resident set size (kbytes): 2105624
    
  • New GC with parallel:15: probably the sweet spot on my box
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:15"
      User time (seconds): 25.59
      System time (seconds): 19.18
      Percent of CPU this job got: 1138%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:03.93
      Maximum resident set size (kbytes): 2040392
    
      User time (seconds): 26.14
      System time (seconds): 19.50
      Percent of CPU this job got: 1137%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:04.01
      Maximum resident set size (kbytes): 2043400
    
      User time (seconds): 26.11
      System time (seconds): 19.86
      Percent of CPU this job got: 1196%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:03.84
      Maximum resident set size (kbytes): 2480236
    
  • New GC with parallel:23: significantly slower!
      Command being timed: "bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:23"
      User time (seconds): 31.89
      System time (seconds): 30.03
      Percent of CPU this job got: 926%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:06.68
      Maximum resident set size (kbytes): 2916912
    
      User time (seconds): 29.32
      System time (seconds): 27.11
      Percent of CPU this job got: 924%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:06.10
      Maximum resident set size (kbytes): 2619984
    
      User time (seconds): 31.66
      System time (seconds): 31.29
      Percent of CPU this job got: 879%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.15
      Maximum resident set size (kbytes): 2358036
    

@kinke

kinke commented Jun 23, 2025

Copy link
Copy Markdown
Author

The stress loop for i in {1..1000}; do echo "Run $i..."; bin/ut -q -j48 --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:15 || break; done reached iteration 120 before hitting a unittest failure (I guess SIL-multi-threading related) - so no crashes or hangs in 119 iterations with full -j48 test parallelization and the parallel:15 sweet spot. Some months ago, this would crash on almost every run.

@kinke

kinke commented Jun 23, 2025

Copy link
Copy Markdown
Author

And monorepo test runs with an unoptimized REPL:

  • Old GC:
    4172 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal"
      User time (seconds): 208.14
      System time (seconds): 143.28
      Percent of CPU this job got: 120%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:51.28
      Maximum resident set size (kbytes): 3385728
    
      User time (seconds): 206.87
      System time (seconds): 140.62
      Percent of CPU this job got: 117%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:56.70
      Maximum resident set size (kbytes): 3510072
    
      User time (seconds): 211.42
      System time (seconds): 136.57
      Percent of CPU this job got: 117%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:55.40
      Maximum resident set size (kbytes): 3215460
    
  • New GC: somewhat slower, and noticeably higher RSS
    4172 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal --DRT-gcopt=gc:sdc"
      User time (seconds): 314.86
      System time (seconds): 263.99
      Percent of CPU this job got: 186%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:09.73
      Maximum resident set size (kbytes): 4555164
    
      User time (seconds): 316.24
      System time (seconds): 260.07
      Percent of CPU this job got: 187%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:08.17
      Maximum resident set size (kbytes): 3856720
    
      User time (seconds): 309.67
      System time (seconds): 257.68
      Percent of CPU this job got: 186%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:04.17
      Maximum resident set size (kbytes): 4061548
    
  • New GC with parallel:7: minimally faster than old GC, and significantly reduced RSS (compared to default parallel setting at least - that's IMO surprising)
    4172 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7"
      User time (seconds): 281.24
      System time (seconds): 160.90
      Percent of CPU this job got: 153%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:48.87
      Maximum resident set size (kbytes): 2367316
    
      User time (seconds): 269.06
      System time (seconds): 153.32
      Percent of CPU this job got: 146%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:47.75
      Maximum resident set size (kbytes): 2876328
    
      User time (seconds): 274.04
      System time (seconds): 157.84
      Percent of CPU this job got: 148%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:50.44
      Maximum resident set size (kbytes): 2468624
    
  • New GC with parallel:0:
    4172 test(s) run, 0 failed.
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 211.59
      System time (seconds): 151.52
      Percent of CPU this job got: 116%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:11.35
      Maximum resident set size (kbytes): 2699208
    
      User time (seconds): 211.02
      System time (seconds): 154.81
      Percent of CPU this job got: 117%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:11.38
      Maximum resident set size (kbytes): 2628252
    
      User time (seconds): 210.85
      System time (seconds): 154.56
      Percent of CPU this job got: 118%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:07.11
      Maximum resident set size (kbytes): 3213416
    

@kinke

kinke commented Jun 23, 2025

Copy link
Copy Markdown
Author

Some stdlib unittest runner numbers from my local Windows qemu VM (no Sentinel), with 24 virtual CPU cores, using a little PowerShell helper to gather and print process stats:

$args = @("-j1", "-q", "--DRT-gcopt=gc:sdc", "--DRT-gcopt=parallel:7")

foreach ($i in 1..3) {
  Write-Host "Run $i with arguments:" $args
  $p = Start-Process "bin\ut.exe" -ArgumentList $args -WorkingDirectory "C:\Users\packer\dev\SIL\stdlib\core" -PassThru -WindowStyle Hidden

  $rss = 0
  while (-not $p.HasExited) {
    $rss = $p.PeakWorkingSet64
    sleep 0.25
    $p.Refresh()
  }

  $p.WaitForExit()

  if ($p.ExitCode -ne 0) {
    Write-Host -ForegroundColor Red "  Exit code: $($p.ExitCode)"
  }
  Write-Host "  Overall runtime:       " ($p.ExitTime - $p.StartTime)
  Write-Host "  Peak working set (MB): " ($rss / 1MB)
  Write-Host "  Total CPU time (s):    " $p.TotalProcessorTime.TotalSeconds
}

The RSS seems to vary wildly, with the old GC too. The new-GC runtime overhead seems similar to Linux, with similar speedups for the tweaked parallel values:

Run 1 with arguments: -j1 -q
  Overall runtime:        00:00:12.1223300
  Peak working set (MB):  173.71484375
  Total CPU time (s):     10.171875
Run 2 with arguments: -j1 -q
  Overall runtime:        00:00:12.5757755
  Peak working set (MB):  142.34765625
  Total CPU time (s):     10.75
Run 3 with arguments: -j1 -q
  Overall runtime:        00:00:11.5622452
  Peak working set (MB):  204.453125
  Total CPU time (s):     9.34375

Run 1 with arguments: -j1 -q --DRT-gcopt=gc:sdc
  Overall runtime:        00:00:17.3002510
  Peak working set (MB):  201.9375
  Total CPU time (s):     35.765625
Run 2 with arguments: -j1 -q --DRT-gcopt=gc:sdc
  Overall runtime:        00:00:18.5321470
  Peak working set (MB):  163.3515625
  Total CPU time (s):     37.3125
Run 3 with arguments: -j1 -q --DRT-gcopt=gc:sdc
  Overall runtime:        00:00:17.4703183
  Peak working set (MB):  220.23046875
  Total CPU time (s):     44.03125

Run 1 with arguments: -j1 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0
  Overall runtime:        00:00:15.9016020
  Peak working set (MB):  159.6484375
  Total CPU time (s):     13.359375
Run 2 with arguments: -j1 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0
  Overall runtime:        00:00:15.5782774
  Peak working set (MB):  192.609375
  Total CPU time (s):     13.09375
Run 3 with arguments: -j1 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0
  Overall runtime:        00:00:16.1627531
  Peak working set (MB):  159.1171875
  Total CPU time (s):     13.796875

Run 1 with arguments: -j1 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:15.1209729
  Peak working set (MB):  207.05078125
  Total CPU time (s):     20.90625
Run 2 with arguments: -j1 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:15.0735882
  Peak working set (MB):  158.4375
  Total CPU time (s):     18.140625
Run 3 with arguments: -j1 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:15.4542735
  Peak working set (MB):  176.04296875
  Total CPU time (s):     19.640625

When it comes to multi-threading, I see mostly hangs when trying to run with higher -j (haven't debugged where - using release druntime/Phobos). [EDIT: With the new GC only.] -j4 works most of the time:

Run 1 with arguments: -j4 -q
  Overall runtime:        00:00:29.7679064
  Peak working set (MB):  1113.44140625
  Total CPU time (s):     102.15625
Run 2 with arguments: -j4 -q
  Overall runtime:        00:00:28.2664684
  Peak working set (MB):  672.02734375
  Total CPU time (s):     97.671875
Run 3 with arguments: -j4 -q
  Overall runtime:        00:00:28.2224489
  Peak working set (MB):  478.71875
  Total CPU time (s):     95.484375

Run 1 with arguments: -j4 -q --DRT-gcopt=gc:sdc
  Overall runtime:        00:00:07.6166270
  Peak working set (MB):  387.28125
  Total CPU time (s):     33.765625
Run 2 with arguments: -j4 -q --DRT-gcopt=gc:sdc
  Overall runtime:        00:00:07.7829439
  Peak working set (MB):  449.5234375
  Total CPU time (s):     37.546875
Run 3 with arguments: -j4 -q --DRT-gcopt=gc:sdc
  Overall runtime:        00:00:07.7331915
  Peak working set (MB):  355.5625
  Total CPU time (s):     32.515625

Run 1 with arguments: -j4 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0
  Overall runtime:        00:00:09.6595190
  Peak working set (MB):  331.47265625
  Total CPU time (s):     18.265625
Run 2 with arguments: -j4 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0
  Overall runtime:        00:00:09.8032327
  Peak working set (MB):  305.58203125
  Total CPU time (s):     18.71875
Run 3 with arguments: -j4 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0
  Overall runtime:        00:00:09.8364374
  Peak working set (MB):  365.40625
  Total CPU time (s):     18.4375

Run 1 with arguments: -j4 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:07.5857229
  Peak working set (MB):  315.9765625
  Total CPU time (s):     23.234375
Run 2 with arguments: -j4 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:07.3860672
  Peak working set (MB):  342.75390625
  Total CPU time (s):     22.328125
Run 3 with arguments: -j4 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:07.5441800
  Peak working set (MB):  340.87890625
  Total CPU time (s):     23.65625

@kinke

kinke commented Jun 23, 2025

Copy link
Copy Markdown
Author

And monorepo test runs on Windows with an unoptimized REPL - seems like the RSS is more stable than on Linux, and significantly smaller with the new GC:

Run 1 with arguments: test --minimal
  Overall runtime:        00:05:22.4873760
  Peak working set (MB):  3127.59765625
  Total CPU time (s):     261.0625
Run 2 with arguments: test --minimal
  Overall runtime:        00:05:18.1133925
  Peak working set (MB):  3118.16015625
  Total CPU time (s):     259.140625
Run 3 with arguments: test --minimal
  Overall runtime:        00:05:18.4052668
  Peak working set (MB):  3091.375
  Total CPU time (s):     254.53125

Run 1 with arguments: test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:05:17.0703055
  Peak working set (MB):  2299.8984375
  Total CPU time (s):     346.75
Run 2 with arguments: test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:05:20.9639507
  Peak working set (MB):  2041.3671875
  Total CPU time (s):     342.34375
Run 3 with arguments: test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:05:21.2545901
  Peak working set (MB):  2112.90625
  Total CPU time (s):     341.671875

Edit: And as on Linux, the RSS seems to get worse with higher parallel (here probably defaulting to parallel:23 in the VM):

Run 1 with arguments: test --minimal --DRT-gcopt=gc:sdc
  Overall runtime:        00:05:19.3665545
  Peak working set (MB):  2649.67578125
  Total CPU time (s):     484.859375
Run 2 with arguments: test --minimal --DRT-gcopt=gc:sdc
  Overall runtime:        00:05:20.2220809
  Peak working set (MB):  3260.61328125
  Total CPU time (s):     528.421875
Run 3 with arguments: test --minimal --DRT-gcopt=gc:sdc
  Overall runtime:        00:05:15.1534806
  Peak working set (MB):  2630.2109375
  Total CPU time (s):     498.53125

@kinke

kinke commented Jun 24, 2025

Copy link
Copy Markdown
Author

Okay the Windows hang seems gone now with the latest update. There was a single (unittest) failure in 250+ runs with -j24, no hangs or crashes:

Run 1 with arguments: -j24 -q
  Overall runtime:        00:00:31.2788466
  Peak working set (MB):  2275.875
  Total CPU time (s):     417.21875
Run 2 with arguments: -j24 -q
  Overall runtime:        00:00:31.1341754
  Peak working set (MB):  2412.3671875
  Total CPU time (s):     424.6875
Run 3 with arguments: -j24 -q
  Overall runtime:        00:00:29.9951774
  Peak working set (MB):  1923.78125
  Total CPU time (s):     425.828125

Run 1 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.6153468
  Peak working set (MB):  2302.14453125
  Total CPU time (s):     31.5
Run 2 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.6511544
  Peak working set (MB):  2514.546875
  Total CPU time (s):     32.09375
Run 3 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.7186597
  Peak working set (MB):  2432.98046875
  Total CPU time (s):     31.5
Run 4 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:06.4493996
  Peak working set (MB):  2100.265625
  Total CPU time (s):     39.40625
Run 5 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.8023951
  Peak working set (MB):  2551.44921875
  Total CPU time (s):     31.828125
…
Run 45 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Exit code: 1
  Overall runtime:        00:00:05.7293303
  Peak working set (MB):  2351.44140625
  Total CPU time (s):     32.015625
…
Run 248 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.5742899
  Peak working set (MB):  2160.3515625
  Total CPU time (s):     31.53125
Run 249 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:06.4134304
  Peak working set (MB):  2474.11328125
  Total CPU time (s):     39.390625
Run 250 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.6151491
  Peak working set (MB):  2412.4375
  Total CPU time (s):     31.9375
Run 251 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.8823617
  Peak working set (MB):  2365.66796875
  Total CPU time (s):     33.46875
Run 252 with arguments: -j24 -q --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7
  Overall runtime:        00:00:05.5831676
  Peak working set (MB):  2275
  Total CPU time (s):     32.078125

@kinke

kinke commented Jun 24, 2025

Copy link
Copy Markdown
Author

The impact on RSS for the monorepo tests on Linux is very interesting, with absolutely brilliant numbers with parallel:7:

  • old GC:
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal"
      User time (seconds): 207.03
      System time (seconds): 143.95
      Percent of CPU this job got: 120%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:50.63
      Maximum resident set size (kbytes): 3298704
    
      User time (seconds): 206.69
      System time (seconds): 142.68
      Percent of CPU this job got: 120%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:50.89
      Maximum resident set size (kbytes): 3587036
    
      User time (seconds): 207.97
      System time (seconds): 137.39
      Percent of CPU this job got: 118%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:50.60
      Maximum resident set size (kbytes): 3345084
    
  • new GC, parallel:7: just wow!
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:7"
      User time (seconds): 295.69
      System time (seconds): 151.70
      Percent of CPU this job got: 155%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:47.72
      Maximum resident set size (kbytes): 1766784
    
      User time (seconds): 288.96
      System time (seconds): 155.67
      Percent of CPU this job got: 153%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:48.96
      Maximum resident set size (kbytes): 1711548
    
      User time (seconds): 288.48
      System time (seconds): 155.11
      Percent of CPU this job got: 155%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 4:45.69
      Maximum resident set size (kbytes): 1736924
    
  • new GC, parallel:0: higher RSS and runtime
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal --DRT-gcopt=gc:sdc --DRT-gcopt=parallel:0"
      User time (seconds): 216.62
      System time (seconds): 146.08
      Percent of CPU this job got: 116%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:12.34
      Maximum resident set size (kbytes): 2013392
    
      User time (seconds): 215.53
      System time (seconds): 143.26
      Percent of CPU this job got: 116%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:08.63
      Maximum resident set size (kbytes): 2051656
    
      User time (seconds): 219.68
      System time (seconds): 149.17
      Percent of CPU this job got: 118%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:10.81
      Maximum resident set size (kbytes): 2063640
    
  • new GC, default parallel=47: bad RSS
      Command being timed: "../SIL/artifacts/repl-full/sil test --minimal --DRT-gcopt=gc:sdc"
      User time (seconds): 322.54
      System time (seconds): 266.56
      Percent of CPU this job got: 191%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:06.89
      Maximum resident set size (kbytes): 3871248
    
      User time (seconds): 326.53
      System time (seconds): 270.51
      Percent of CPU this job got: 193%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:08.36
      Maximum resident set size (kbytes): 3442384
    
      User time (seconds): 321.34
      System time (seconds): 266.95
      Percent of CPU this job got: 192%
      Elapsed (wall clock) time (h:mm:ss or m:ss): 5:06.25
      Maximum resident set size (kbytes): 3359932
    

schveiguy and others added 9 commits June 24, 2025 20:31
…r when

appending to a large array that could potentially use extend, when the
requested array size is within a certain size for a multiple of pages.

The calculation had the wrong sign for the large padding (the 2 size_t +
1 byte), which made it end up sending a number very close to size_t.max
  into the extend function.

This affected both appending and setting length performance, though
appending also had a grow factor which may have mitigated this somewhat.

(dlang/dmd!21616)
schveiguy and others added 5 commits October 7, 2025 22:41
thread is no longer in the active thread list (and cannot be paused)
… _loadedDSOs'

This error currently happens when a D DSO is unloaded in a thread the DSO
wasn't registered with. So for example, loading a D Python extension DLL
via dlopen/LoadLibrary in a Python worker thread (dragging in the druntime
and Phobos DLLs etc., and initializing those in the worker thread), and
one of the D DLLs then being unloaded in the Python *main* thread at
Python exit.

druntime has no way of registering the unknown main thread with druntime
(registering the OS-initialized TLS data with the D GC, running the TLS
module ctors etc.). [Normally, if you spawn a new thread via druntime,
then that new thread inherits all the DSOs registered with the parent
thread.]

What we currently do in case a DSO is unloaded in such a thread is still
running the TLS module dtors (as well as the shared module dtors etc.) of
that DSO, but then printing that 'not in sync' message and aborting the
process, so not finalizing any remaining DSOs.

Try to handle such scenarios more gracefully by
* emitting a stderr warning (per unloaded DSO) instead of aborting (and
  so not skipping any remaining DSOs anymore, as well as not tampering
  with the exit code),
* emitting the warning *before* the DSO finalization, so that any
  issues there are easier to troubleshoot, and
* excluding the TLS module dtors for such not-registered-in-current-thread
  DSOs, as the TLS module ctors most likely haven't run either in that
  thread.
The macOS 13 image isn't available anymore.
kinke pushed a commit that referenced this pull request Feb 3, 2026
Limit the number of platforms that this is done on.  A inspection of
some libc implementations of fork has identified the main culprits,
don't need to apply this to any others.

MacOS testsuite also regressed as a result on calling this code, it's
not clear why, but the backtrace is:
```
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0)
  * frame #0: 0x00007ff81abe6ee3 libsystem_platform.dylib`_os_unfair_lock_recursive_abort + 23
    frame #1: 0x00007ff81abe12da libsystem_platform.dylib`_os_unfair_lock_lock_slow + 247
    frame #2: 0x00007ff81abccd44 libsystem_pthread.dylib`_pthread_atfork_prepare_handlers + 48
    frame #3: 0x00007ff825dc2705 libSystem.B.dylib`libSystem_atfork_prepare + 25
    frame #4: 0x00007ff81aac17e1 libsystem_c.dylib`fork + 24
    frame #5: 0x0000000101f730ee test_runner`core.internal.backtrace.dwarf.resolveAddressesWithAtos(Location[]) + 210
```
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants