Loops may not collect garbage, leading to very slow execution

[quexxon]

I tried unsuccessfully to boil this down to a simpler reproducible example. Something about the interplay of get without a default value in the filter procedure appears to cause the issue. Sample code for reproduction:

#!/usr/bin/env ysh

proc filter (; predicate) {
	for line in (io.stdin) {
		if (io->evalExpr(predicate, vars={_val: fromJson8(line)})) {
			write -- $line
		}
	}
}

var f = $(mktemp)

for i in (0..=100_000) {
	json write ({}, space=0) >> $f
}

write -- u'get() with default\n'
write -- 'BEFORE ------------------------------------------------------'

for _ in (0..<3) {
	time for line in (io.stdin) {
		call fromJson8(line)
	} < $f
	write
}

filter [get(_val, 'missing-key', 0) === 0] < $f >/dev/null

write -- 'AFTER -------------------------------------------------------'

for _ in (0..<3) {
	time for line in (io.stdin) {
		call fromJson8(line)
	} < $f
	write
}

write -- u'get() without default\n'
write -- 'BEFORE ------------------------------------------------------'

for _ in (0..<3) {
	time for line in (io.stdin) {
		call fromJson8(line)
	} < $f
	write
}

filter [get(_val, 'missing-key')] < $f >/dev/null

write -- 'AFTER -------------------------------------------------------'

for _ in (0..<3) {
	time for line in (io.stdin) {
		call fromJson8(line)
	} < $f
	write
}

rm $f

Output on my machine:

ysh-0.24.0$ uname -a
Linux rodan 6.8.0-48-generic #48-Ubuntu SMP PREEMPT_DYNAMIC Fri Sep 27 14:04:52 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
ysh-0.24.0$ ./bug.ysh
get() with default

BEFORE ------------------------------------------------------
real    0.071
user    0.071
sys     0.000

real    0.070
user    0.070
sys     0.000

real    0.070
user    0.070
sys     0.000

AFTER -------------------------------------------------------
real    0.071
user    0.071
sys     0.000

real    0.070
user    0.070
sys     0.000

real    0.071
user    0.071
sys     0.000

get() without default

BEFORE ------------------------------------------------------
real    0.071
user    0.071
sys     0.000

real    0.070
user    0.070
sys     0.000

real    0.070
user    0.070
sys     0.000

AFTER -------------------------------------------------------
real    0.928
user    0.927
sys     0.001

real    0.929
user    0.928
sys     0.001

real    0.937
user    0.932
sys     0.001

[quexxon]

I'm on 5a67993f

[andychu]

Hm thanks for the report! I have repro'd this

real    0.077
user    0.077
sys     0.000

AFTER -------------------------------------------------------
real    1.126
user    1.126
sys     0.000

real    1.120
user    1.120
sys     0.000

Let me see what's happening ...

first hunch: maybe OILS_GC_STATS=1 will tell us something

[andychu]

Gah, so yeah my hunch was right, this is a GC bug. If we do 3 iterations of the last loop, the GC spends 3+ seconds. If we do 4, it spends 4+ seconds

I am not sure why at the moment, but it is a bug

AFTER -------------------------------------------------------
real    1.148
user    1.148
sys     0.000

real    1.156
user    1.156
sys     0.000

real    1.140
user    1.140
sys     0.000

real    1.141
user    1.141
sys     0.000

  num live         =       6254
  max survived     =       3658

  num allocated    =   64310218
  num in heap      =    3600881
  num in pool 1    =   29104704
  num in pool 2    =   31604633
bytes allocated    =  410828957

  num gc points    =    1500048
  num collections  =       1256

   gc threshold    =      50000
  num growths      =          0

  max gc millis    =       28.4
total gc millis    =     4529.3

[andychu]

The command was

OILS_GC_STATS=1 _bin/cxx-opt/ysh test/bug-2123.ysh

The weird thing is that "num live" is small, which means the GC should be working correctly?

Or maybe it is growing to take a huge amount of memory, and then it's all freed?

So yeah the first thing to look at would be a memory leak ... possibly triggered by the get() somehow?

Yes I think so

[andychu]

OK, it does look like some kind of memory leak

• if I increase the number of iterations from 3 to 4, the maximum memory usage does not increase
• however, if I increase the lines from 100_000 to 200_00, the max RSS doubles

So basically the GC is thrashing on the internal data structures for 200,000 lines ....

---

going deeper ...

[andychu]

Thank you for the report, this is fixed!

http://op.oilshell.org/uuu/github-jobs/8263/

http://op.oilshell.org/uuu/github-jobs/8263/cpp-tarball.wwz/_release/oils-for-unix.tar

The problem was that in the filter loop we weren't GC-ing enough. Basically if the condition is FALSE, then we were skipping GC, and if it was true, then we would GC

---

It actually was not a memory leak -- it was building up a huge heap with the 100_000 line computation, and then GC'ing it all at the end

After that, I think there was less locality in all subsequence GC's! They went from 0.2 ms to ~30ms

[andychu]

Also, I noticed some places where we are allocating a lot in a loop, which is low hanging fruit for speeding up the interpreter. I checked in a change to benchmarks/callgrind.sh to show that

For the near future, we're focused on semantics more than speed

But there is plenty left to optimize, and I appreciate perf bugs like this one!