Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GC not freeing short living variables under some circumstances #2436

Open
david-bouyssie opened this issue Nov 19, 2021 · 7 comments
Open

GC not freeing short living variables under some circumstances #2436

david-bouyssie opened this issue Nov 19, 2021 · 7 comments

Comments

@david-bouyssie
Copy link
Contributor

david-bouyssie commented Nov 19, 2021

I have observed that SN GC (tried on immix and commix) is not always freeing short living variables. This can be annoying because it can increase very quickly the total used memory of the program process.

Let's take this simple while loop example doing a high number of iterations:

var sum = 0
val nIters = 3000000

var i = 0
while (i < nIters) {

  var j = 1
  while (j < 10) {
    val buffer = new Array[Byte](1600)
    sum += buffer(0).toInt
    j += 1
  }

  i += 1
}

In this context the value called buffer, which is used o compute a total sum (not meaningful though in this example), is well freed after each iteration.

However if one adds a global allocation like this charsBuffer, then is totally changing the behavior of the GC:

var sum = 0
val nIters = 3000000
val charsBuffer = new ArrayBuffer[Array[Char]](nIters)

var i = 0
while (i < nIters) {

  var j = 1
  while (j < 10) {
    val buffer = new Array[Byte](1600)
    sum += buffer(0).toInt
    j += 1
  }

  charsBuffer += new Array[Char](0)

  i += 1
}

As a reference it is also possible to check the memory used when only appending to the charsBuffer alone:

val nIters = 3000000
val charsBuffer = new ArrayBuffer[Array[Char]](nIters)

var i = 0
while (i < nIters) {
  charsBuffer += new Array[Char](0)

  i += 1
}

As a summary here are the different memory peaks of the 3 previous examples (SN 0.4.1, Windows 10, immix, LTO thin, release-fast):

  • first example (computing sum without extra charsBuffer allocation) => 5 MB
  • second example (computing sum with extra charsBuffer allocation) => 470 MB
  • third example (charsBuffer allocation alone) => 81 MB

What I would expect in the case of the second example would be to have a memory peak close to the third example (81 MB).
It looks like all intermediate buffer values were not freed by the GC.

@ekrich mentioned on Discord that it could be a memory fragmentation issue, but it is not totally clear to me.

@david-bouyssie
Copy link
Contributor Author

Additionally I ran the same tests on Linux (Windows 10 WSL1).

Thus here are the results for Linux WSL1, SN 0.4.1, LTO thin, release-fast, using either:

  • immix GC

    • first example => 6 MB
    • second example => 468 MB
    • third example => 81 MB
  • boehm GC

    • first example => 2 MB
    • second example => 158 MB
    • third example => 127 MB

Also the third example was a lot faster compared to the two first ones in all different configurations.

@david-bouyssie
Copy link
Contributor Author

david-bouyssie commented Nov 19, 2021

And here is another series of example with Zones.

Example 1, no call to alloc in the first while loop:

var sum = 0
val nIters = 3000000

Zone { implicit z =>

  var i = 0
  while (i < nIters) {

    var j = 1
    while (j < 10) {
      val buffer = new Array[Byte](1600)
      sum += buffer(0).toInt
      j += 1
    }

    i += 1
  }
}

Example 2, call to alloc in the first while loop:

var sum = 0
val nIters = 3000000

Zone { implicit z =>

  var i = 0
  while (i < nIters) {

    var j = 1
    while (j < 10) {
      val buffer = new Array[Byte](1600)
      sum += buffer(0).toInt
      j += 1
    }

    alloc[CInt] // additional call compared to the previous example

    i += 1
  }
}

Example 3, a while loop containing only a call to alloc:

val nIters = 3000000

Zone { implicit z =>

  var i = 0
  while (i < nIters) {

    alloc[CInt]

    i += 1
  }
}

Example 4, combination of examples 1 and 3:

var sum = 0
val nIters = 3000000

Zone { implicit z =>

  var i = 0
  while (i < nIters) {

    var j = 1
    while (j < 10) {
      val buffer = new Array[Byte](1600)
      sum += buffer(0).toInt
      j += 1
    }

    i += 1
  }
}

Zone { implicit z =>

  var i = 0
  while (i < nIters) {

    alloc[CInt]

    i += 1
  }
}

Here are the results I get on Linux WSL1, SN 0.4.1, LTO thin, immix, release-fast:

  • first example => 6 MB
  • second example =>1.15 GB
  • third example =>295 MB
  • fourth example => 295 MB

I'm surprised by the used memory in the second example, which is really exploding.
It should also be noted that example 3 and 4 are leading to the same memory consumption.

@david-bouyssie
Copy link
Contributor Author

david-bouyssie commented Nov 19, 2021

A last example to show that this issue can be very important, when the operation performed inside the while generates more garbage:

val nIters = 3000000
val email = "miles.davis at anymail.com"

val objsBuffer = new ArrayBuffer[Object](nIters)

var i = 0
while (i < nIters) {

  val fixedEmail = email.replaceAll(raw"\sat\s","@")

  objsBuffer += new Object()

  i += 1
}

Here the problem is that email.replaceAll seems to generate a lot of garbage (maybe because of several underlying allocations to execute the regex).
This leads to a very high memory consumption, ~7.2 GB on Linux WSL1, SN 0.4.1, LTO thin, immix, release-fast.

By comparison, running the same example while commenting the line objsBuffer += new Object() leads to a consumption of 7 MB.

Note that regex memory issues were reported before:

@JD557
Copy link
Contributor

JD557 commented Dec 1, 2021

Another reproduction of this problem, kind of similar to the last comment, but without the Regex.

I'm not entirely sure how much memory the second example takes, because I'm using a VM with limited memory.

Tested with immix, both in debug and in release-full.

  // Split loops: ~ 150MB
  def main(args: Array[String]): Unit = {
    val nIters = 3000000
    val objsBuffer = Array.ofDim[Object](nIters)
    var num = 0

    var i = 0

    while (i < nIters) {
      num = Array.fill(100)(scala.util.Random.nextInt).sum
      i += 1
    }

    i = 0

    while (i < nIters) {
      objsBuffer(i) = new Object()
      i += 1
    }

    println(num)
    println(objsBuffer.##)
  }
  // Single loop: Quickly reaches 1.5GB usage
  def main(args: Array[String]): Unit = {
    val nIters = 3000000
    val objsBuffer = Array.ofDim[Object](nIters)
    var num = 0

    var i = 0

    while (i < nIters) {
      num = Array.fill(100)(scala.util.Random.nextInt).sum
      objsBuffer(i) = new Object()
      i += 1
    }

    println(num)
    println(objsBuffer.##)
  }

@JD557
Copy link
Contributor

JD557 commented Dec 2, 2021

Ran the previous code with GC logs (with val nIters = 1000000 to make sure that it would finish).

Good logs:
Collect


Block count: 128
Unavailable: 0
Free: 121
Recycled: 7
End collect
Growing small heap by 8947712 bytes, to 13421568 bytes

Collect


Block count: 384
Unavailable: 245
Free: 130
Recycled: 9
Growing small heap by 13421568 bytes, to 26843136 bytes
End collect

Collect


Block count: 768
Unavailable: 245
Free: 513
Recycled: 10
Growing small heap by 26843136 bytes, to 53686272 bytes
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1281
Recycled: 10
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1281
Recycled: 10
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1281
Recycled: 10
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1281
Recycled: 10
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1281
Recycled: 10
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1281
Recycled: 10
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1280
Recycled: 11
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1280
Recycled: 11
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1279
Recycled: 12
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1278
Recycled: 13
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1277
Recycled: 14
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1274
Recycled: 17
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1276
Recycled: 15
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1274
Recycled: 17
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1274
Recycled: 17
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1275
Recycled: 16
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1273
Recycled: 18
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1272
Recycled: 19
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1270
Recycled: 21
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1271
Recycled: 20
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 1269
Recycled: 22
End collect

Collect


Block count: 1536
Unavailable: 639
Free: 878
Recycled: 19
Growing small heap by 53686272 bytes, to 107372544 bytes
End collect
Bad logs:
Collect


Block count: 128
Unavailable: 0
Free: 121
Recycled: 7
End collect
Growing small heap by 8947712 bytes, to 13421568 bytes

Collect


Block count: 384
Unavailable: 245
Free: 1
Recycled: 138
Growing small heap by 13421568 bytes, to 26843136 bytes
End collect

Collect


Block count: 768
Unavailable: 245
Free: 5
Recycled: 518
Growing small heap by 26843136 bytes, to 53686272 bytes
End collect

Collect


Block count: 1536
Unavailable: 245
Free: 12
Recycled: 1279
Growing small heap by 53686272 bytes, to 107372544 bytes
End collect

Collect


Block count: 3072
Unavailable: 245
Free: 45
Recycled: 2782
Growing small heap by 107372544 bytes, to 214745088 bytes
End collect

Collect


Block count: 6144
Unavailable: 245
Free: 92
Recycled: 5807
Growing small heap by 88917888 bytes, to 303662976 bytes
End collect

Collect


Block count: 8688
Unavailable: 245
Free: 124
Recycled: 8319
Growing small heap by 125757296 bytes, to 429420272 bytes
End collect

Collect


Block count: 12286
Unavailable: 245
Free: 242
Recycled: 11799
Growing small heap by 177870728 bytes, to 607291000 bytes
End collect

Collect


Block count: 17375
Unavailable: 245
Free: 269
Recycled: 16861
Growing small heap by 251514592 bytes, to 858805592 bytes
End collect

Collect


Block count: 24571
Unavailable: 245
Free: 443
Recycled: 23883
Growing small heap by 355706504 bytes, to 1214512096 bytes
End collect

Collect


Block count: 34748
Unavailable: 245
Free: 577
Recycled: 33926
Growing small heap by 503064136 bytes, to 1717576232 bytes
End collect

Collect


Block count: 49141
Unavailable: 245
Free: 918
Recycled: 47978
Growing small heap by 711413008 bytes, to 2428989240 bytes
End collect

The second version seems to have much less collects, however it grows the heap on every collect... It also seems to have way more recycled blocks.

@david-bouyssie
Copy link
Contributor Author

Another reproduction of this problem, kind of similar to the last comment, but without the Regex.

I'm not entirely sure how much memory the second example takes, because I'm using a VM with limited memory.

Tested with immix, both in debug and in release-full.

I'm wondering if this could be explained by an issue in the current implementation of the escape analysis system.
It looks like the Array produced by Array.fill is put on the heap in the second example while it could be put on the stack. However I'm not totally sure if it is easily feasible. And maybe my assumption is also incorrect.

@david-bouyssie
Copy link
Contributor Author

I just tried the email.replaceAll example on SN 0.4.3 and its even worse:
I got a memory peek at ~13 GB on Linux WSL1, SN 0.4.1, LTO thin, immix, release-fast.

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

No branches or pull requests

2 participants