GC bug: seems very slow where it shouldn't; maybe it leaks?

[timotheecour]

/cc @Araq
[painfully reduced from testament/tester]

there's a very strange bug that could be caused by memory leaks or other GC issue:

nim c -r -d:case_bug $timn_D/bugs/all/t0077.nim will print foo:1 through foo:16 and then increasingly slow down, eventually completing in ~ 50 seconds
nim c -r $timn_D/bugs/all/t0077.nim will complete in < 1 second

Maybe, depending on your machine, you can add more discard makeTest() lines if you can't reproduce this bug on your machine.

The program

proc test_bug*()=
  for i in 0..100:
    when defined(case_bug):
      let a =  "foo"
    else:
      let a =  i

var testCounter = 0

type
  TTest = object
    a1: string
    a2: string
    a3: string

proc makeTest(): TTest =
  result.a1 = "a1"
  result.a2 = "a2"
  result.a3 = "a3"

  for i in 0..<100: test_bug()

proc gcTests() =
  echo sizeof(TTest)

  template foo() =
    echo "foo:",testCounter
    testCounter.inc

    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()
    discard makeTest()

  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()
  foo()

gcTests()

[Araq]

--gc:markAndSweep is not affected.

[recloser]

The GC scans the stack for references conservatively and each call to discard makeTest() creates allocates a separate variable on the stack for the result (even though you discard it), so you end up with a ton of data that needs to be checked. The same issue occurs with large arrays allocated on the stack (see https://forum.nim-lang.org/t/3001). Wrapping the discard makeTest() call into a proc and calling that instead completely fixes the issue.

[timotheecour]

but the stack is not that huge is it?
17*12*sizeof(TTest)

[recloser]

Yeah, that indeed doesn't seem like it should cause such a performance issue. It looks like it's not the stack size that's the problem. I modified the test case a bit and the GC scan count stat looks really suspicious.

proc foo = 
  for i in 0..100*100:
    let a = "foo"

proc main =
  const StringCount = 495
  var strings: array[StringCount, string]
  for i, p in mpairs strings: p = newString(1)
  
  for i in 1..17:
    echo i
    for j in 1..12:
      foo()

  echo GC_getStatistics()

main()

As the StringCount gets larger the amount of stack scans grows exponentially. Going from 494 to 495 increases it by 100k from 400k, from 495 to 496 by 170k! At 500 the scan count is >2m.
This definitely feels like a bug in the implementation. Or maybe it's just the worst GC algorithm ever.

[Araq]

Seems to be a simple logic bug: ZctThreshold is set to 500, so if the "zero count table" reaches 500 the GC runs. Now it happens to be the case that there is no "success rate" computed so every single collection triggers a GC run.

[timotheecour]

see comment here: ef37e16#commitcomment-31738180