runtime: memory not being returned to OS

[randall77]

package main

import (
  "bytes"
  "fmt"
  "io/ioutil"
  "math/rand"
  "runtime"
  "time"
)

func main() {
  for i := 0; i < 1000; i++ {
    time.Sleep(time.Millisecond * 1)
    go fakeGetAndSaveData()
  }
  runtime.GC()
  time.Sleep(10 * time.Minute)
}

func fakeGetAndSaveData() {
  var buf bytes.Buffer
  for i := 0; i < 40000; i++ {
    buf.WriteString(fmt.Sprintf("the number is %d\n", i))
  }

  ioutil.WriteFile(fmt.Sprintf("%d.txt", rand.Int()), buf.Bytes(), 0644)
}

Copied from issue #9869 .

Reporter thinks the memory used by this program is not returned to the OS during the Sleep(10*minute) call.

On Linux, I'm using top -b | grep memoryLeak command and on Windows, I use Task Manager. I just ran this again on Ubuntu 16.04 and it looks like it isn't exhibiting the problem after all. When I ran it yesterday it crashed my VM, but it wasn't due to out of memory as I'd assumed. But, I do see the problem clearly on Windows. Sorry, I'll put together a different example for Linux.

Here's what I see on Windows. This is after it's gone idle. Nothing new is being spawned. It's just sitting there. It stays like this for 10 minutes until the program closes.

[randall77]

@6degreeshealth
Please try and run with the environment variable GODEBUG set to gctrace=1. Let it run to completion.
Grab all the lines starting with scvg and post them here.

My current suspicion is that we're actually returning pages to the OS, but it isn't taking them. We've seen this before, where the OS doesn't actually remove the pages from the process unless there is demand for them elsewhere in the system.

A scavenger trace (the scvg lines) will let us know for sure one way or the other.

[alexbrainman]

Please try and run with the environment variable GODEBUG set to gctrace=1. Let it run to completion.
Grab all the lines starting with scvg and post them here.

@randall77 I replaced your 10 minutes sleep with

	time.Sleep(5 * time.Minute)
	fmt.Printf("5 minutes passed\n")
	time.Sleep(5 * time.Minute)

and I am posting whole output

gc 1 @0.006s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 2 @0.010s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 3 @0.012s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 4 @0.014s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 5 @0.019s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 6 @0.024s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 7 @0.027s 0%: 0.39+0.12+0 ms clock, 1.1+0.12/0.12/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 8 @0.035s 0%: 0.41+0.004+0 ms clock, 1.2+0/0/0+0 ms cpu, 13->14->4 MB, 14 MB goal, 4 P
gc 9 @0.038s 0%: 0+1.0+0 ms clock, 0+1.0/1.0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 10 @0.042s 0%: 0+0+1.0 ms clock, 0+0/0/0+2.0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 11 @0.046s 0%: 0.91+0.017+0 ms clock, 2.7+0/0.017/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 12 @0.049s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 13 @0.054s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 14 @0.063s 0%: 0+0+3.5 ms clock, 0+0/0/0+14 ms cpu, 15->15->3 MB, 16 MB goal, 4 P
gc 15 @0.068s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 16 @0.074s 0%: 0+0.50+0 ms clock, 0+1.5/0.50/0+0 ms cpu, 9->9->2 MB, 10 MB goal, 4 P
gc 17 @0.075s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 18 @0.078s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 19 @0.081s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 20 @0.084s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 21 @0.087s 0%: 0+0.99+0 ms clock, 0+2.9/0.99/0+0 ms cpu, 7->8->4 MB, 9 MB goal, 4 P
gc 22 @0.090s 0%: 1.0+0+0 ms clock, 4.0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 23 @0.095s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 24 @0.100s 0%: 0+0.73+0 ms clock, 0+0.007/0.73/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 25 @0.107s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 14->14->4 MB, 15 MB goal, 4 P
gc 26 @0.113s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 27 @0.116s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->3 MB, 7 MB goal, 4 P
gc 28 @0.119s 0%: 0.69+0.067+0 ms clock, 2.0+0/0/0+0 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 29 @0.123s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 30 @0.127s 0%: 0+0.99+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 31 @0.131s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->1 MB, 7 MB goal, 4 P
gc 32 @0.134s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 33 @0.135s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 34 @0.141s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->10->6 MB, 9 MB goal, 4 P
gc 35 @0.146s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->0 MB, 12 MB goal, 4 P
gc 36 @0.150s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 37 @0.152s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 38 @0.154s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 39 @0.157s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 40 @0.158s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 41 @0.163s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 42 @0.169s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 43 @0.172s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 44 @0.176s 0%: 0.50+0.12+0 ms clock, 2.0+0/0/0+0 ms cpu, 10->10->6 MB, 11 MB goal, 4 P
gc 45 @0.182s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->7 MB, 13 MB goal, 4 P
gc 46 @0.190s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 15->15->4 MB, 16 MB goal, 4 P
gc 47 @0.194s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 48 @0.198s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 49 @0.203s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 50 @0.206s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 51 @0.212s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->6 MB, 13 MB goal, 4 P
gc 52 @0.217s 0%: 0+0+1.0 ms clock, 0+0/0/0+4.0 ms cpu, 12->12->6 MB, 13 MB goal, 4 P
gc 53 @0.223s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 11->11->6 MB, 12 MB goal, 4 P
gc 54 @0.229s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->6 MB, 13 MB goal, 4 P
gc 55 @0.233s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 11->11->4 MB, 12 MB goal, 4 P
gc 56 @0.239s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 57 @0.242s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 58 @0.245s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 59 @0.249s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 60 @0.253s 0%: 1.0+0+0 ms clock, 2.0+0/0/0+0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 61 @0.257s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 62 @0.260s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 63 @0.264s 0%: 0.50+0+0 ms clock, 2.0+0/0/0+0 ms cpu, 8->9->3 MB, 9 MB goal, 4 P
gc 64 @0.268s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->2 MB, 8 MB goal, 4 P
gc 65 @0.270s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 66 @0.273s 0%: 0+0.50+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 67 @0.279s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->5 MB, 12 MB goal, 4 P
gc 68 @0.285s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 10->12->5 MB, 13 MB goal, 4 P
gc 69 @0.289s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 70 @0.296s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->3 MB, 14 MB goal, 4 P
gc 71 @0.299s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 72 @0.304s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->2 MB, 9 MB goal, 4 P
gc 73 @0.305s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 74 @0.310s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->2 MB, 8 MB goal, 4 P
gc 75 @0.311s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 76 @0.316s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 77 @0.321s 0%: 0+0.55+0 ms clock, 0+0/0.004/0+0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 78 @0.325s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->7 MB, 11 MB goal, 4 P
gc 79 @0.331s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 14->14->4 MB, 15 MB goal, 4 P
gc 80 @0.336s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 81 @0.339s 0%: 0.86+0.12+0 ms clock, 3.4+0/0.12/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 82 @0.343s 0%: 0.34+0.018+0 ms clock, 1.3+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 83 @0.348s 0%: 1.0+0+0 ms clock, 4.0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 84 @0.352s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 85 @0.356s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->2 MB, 10 MB goal, 4 P
gc 86 @0.358s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 87 @0.361s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 88 @0.364s 0%: 0+0.50+0 ms clock, 0+0.50/0.50/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 89 @0.367s 0%: 0.50+0+0 ms clock, 1.0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 90 @0.372s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 91 @0.375s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 92 @0.380s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 93 @0.386s 0%: 0.65+0.11+0 ms clock, 2.6+0/0/0+0 ms cpu, 14->14->7 MB, 15 MB goal, 4 P
gc 94 @0.393s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 14->14->4 MB, 15 MB goal, 4 P
gc 95 @0.397s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 96 @0.401s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->2 MB, 8 MB goal, 4 P
gc 97 @0.403s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 98 @0.406s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 99 @0.409s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 100 @0.415s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->5 MB, 12 MB goal, 4 P
gc 101 @0.421s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 102 @0.426s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 103 @0.432s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 13->13->6 MB, 14 MB goal, 4 P
gc 104 @0.438s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->7 MB, 14 MB goal, 4 P
gc 105 @0.443s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->4 MB, 14 MB goal, 4 P
gc 106 @0.448s 0%: 0+0+1.0 ms clock, 0+0/0/0+4.0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 107 @0.453s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 108 @0.456s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 109 @0.459s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 6->6->2 MB, 7 MB goal, 4 P
gc 110 @0.461s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 111 @0.465s 0%: 0+0.50+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->2 MB, 7 MB goal, 4 P
gc 112 @0.468s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 113 @0.472s 0%: 0+0.15+0 ms clock, 0+0/0.15/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 114 @0.477s 0%: 0.51+0.062+0 ms clock, 2.0+0/0/0+0 ms cpu, 11->11->4 MB, 12 MB goal, 4 P
gc 115 @0.481s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 116 @0.487s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->13->6 MB, 13 MB goal, 4 P
gc 117 @0.493s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 13->13->4 MB, 14 MB goal, 4 P
gc 118 @0.498s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->2 MB, 9 MB goal, 4 P
gc 119 @0.501s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 120 @0.502s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 121 @0.505s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 122 @0.509s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->7 MB, 10 MB goal, 4 P
gc 123 @0.515s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->6 MB, 14 MB goal, 4 P
gc 124 @0.520s 0%: 0.061+0.14+0 ms clock, 0.24+0/0/0+0 ms cpu, 13->13->9 MB, 14 MB goal, 4 P
gc 125 @0.528s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 18->18->9 MB, 19 MB goal, 4 P
gc 126 @0.538s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 19->19->2 MB, 20 MB goal, 4 P
gc 127 @0.540s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 128 @0.543s 0%: 0+1.0+0 ms clock, 0+3.0/1.0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 129 @0.545s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 130 @0.549s 0%: 0.90+0.13+0 ms clock, 3.6+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 131 @0.552s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 132 @0.557s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 133 @0.561s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 134 @0.566s 0%: 0+0+0.50 ms clock, 0+0/0/0+2.0 ms cpu, 10->10->5 MB, 11 MB goal, 4 P
gc 135 @0.570s 0%: 0.50+0+0 ms clock, 1.5+0/0/0+0 ms cpu, 11->12->7 MB, 12 MB goal, 4 P
gc 136 @0.578s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 15->15->5 MB, 16 MB goal, 4 P
gc 137 @0.584s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->3 MB, 11 MB goal, 4 P
gc 138 @0.588s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->8->3 MB, 8 MB goal, 4 P
gc 139 @0.590s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 140 @0.596s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 141 @0.600s 0%: 0+1.0+0 ms clock, 0+0/1.0/0+0 ms cpu, 8->8->2 MB, 9 MB goal, 4 P
gc 142 @0.602s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 143 @0.606s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 144 @0.608s 0%: 0+1.0+0 ms clock, 0+1.0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 145 @0.613s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->2 MB, 9 MB goal, 4 P
gc 146 @0.614s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 147 @0.616s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 148 @0.620s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 149 @0.625s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 150 @0.630s 0%: 0+1.0+0 ms clock, 0+0/1.0/0+0 ms cpu, 9->10->6 MB, 10 MB goal, 4 P
gc 151 @0.636s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->3 MB, 13 MB goal, 4 P
gc 152 @0.639s 0%: 0.75+0.036+0 ms clock, 3.0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 153 @0.644s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 154 @0.652s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->5 MB, 13 MB goal, 4 P
gc 155 @0.658s 0%: 0+4.5+0 ms clock, 0+1.9/0/0+0 ms cpu, 10->11->3 MB, 11 MB goal, 4 P
gc 156 @0.668s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 6->7->2 MB, 7 MB goal, 4 P
gc 157 @0.671s 0%: 0+0.50+0 ms clock, 0+1.0/0.50/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 158 @0.674s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 7 MB goal, 4 P
gc 159 @0.675s 0%: 0+0.50+0 ms clock, 0+0/0.50/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 160 @0.681s 0%: 0+3.0+0 ms clock, 0+1.0/0/0+0 ms cpu, 8->9->5 MB, 9 MB goal, 4 P
gc 161 @0.689s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 162 @0.695s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 163 @0.700s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 164 @0.707s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 16->16->8 MB, 17 MB goal, 4 P
gc 165 @0.718s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 16->16->4 MB, 17 MB goal, 4 P
gc 166 @0.722s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 167 @0.725s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 168 @0.730s 0%: 0+0+1.0 ms clock, 0+0/0/0+4.0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 169 @0.734s 0%: 1.0+0+0 ms clock, 4.0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 170 @0.738s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->7 MB, 10 MB goal, 4 P
gc 171 @0.744s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->6 MB, 14 MB goal, 4 P
gc 172 @0.749s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->8 MB, 13 MB goal, 4 P
gc 173 @0.757s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 16->16->8 MB, 17 MB goal, 4 P
gc 174 @0.767s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 17->17->2 MB, 18 MB goal, 4 P
gc 175 @0.770s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 176 @0.772s 0%: 0+0.32+0.19 ms clock, 0+0.64/0/0+0.76 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 177 @0.775s 0%: 0+0.50+0 ms clock, 0+0.56/0.031/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 178 @0.779s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 179 @0.782s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 180 @0.789s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->3 MB, 13 MB goal, 4 P
gc 181 @0.792s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 182 @0.798s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->5 MB, 12 MB goal, 4 P
gc 183 @0.804s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->6 MB, 11 MB goal, 4 P
gc 184 @0.809s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->5 MB, 13 MB goal, 4 P
gc 185 @0.815s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->2 MB, 11 MB goal, 4 P
gc 186 @0.817s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->3 MB, 7 MB goal, 4 P
gc 187 @0.821s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->1 MB, 7 MB goal, 4 P
gc 188 @0.822s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 189 @0.825s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 190 @0.828s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 191 @0.832s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 192 @0.835s 0%: 0+0.33+0 ms clock, 0+0/0.33/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 193 @0.839s 0%: 0+0.99+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->5 MB, 11 MB goal, 4 P
gc 194 @0.844s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->3 MB, 11 MB goal, 4 P
gc 195 @0.849s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 196 @0.852s 0%: 1.0+0+0 ms clock, 2.0+0/0/0+0 ms cpu, 8->9->4 MB, 9 MB goal, 4 P
gc 197 @0.857s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 198 @0.860s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 199 @0.865s 0%: 0+0.075+0 ms clock, 0+0/0.075/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 200 @0.871s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->3 MB, 11 MB goal, 4 P
gc 201 @0.874s 0%: 0+0+0.50 ms clock, 0+0/0/0+1.5 ms cpu, 8->8->6 MB, 9 MB goal, 4 P
gc 202 @0.879s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->6 MB, 12 MB goal, 4 P
gc 203 @0.885s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->2 MB, 13 MB goal, 4 P
gc 204 @0.887s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 205 @0.890s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 206 @0.893s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 207 @0.898s 0%: 1.0+0+0 ms clock, 2.0+0/0/0+0 ms cpu, 11->11->6 MB, 12 MB goal, 4 P
gc 208 @0.904s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->5 MB, 13 MB goal, 4 P
gc 209 @0.908s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->5 MB, 11 MB goal, 4 P
gc 210 @0.914s 0%: 0+1.0+0 ms clock, 0+0/1.0/0+0 ms cpu, 11->11->4 MB, 12 MB goal, 4 P
gc 211 @0.920s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 212 @0.924s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->6 MB, 11 MB goal, 4 P
gc 213 @0.930s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->4 MB, 14 MB goal, 4 P
gc 214 @0.934s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 215 @0.939s 0%: 0+1.0+0 ms clock, 0+2.0/1.0/0+0 ms cpu, 10->10->3 MB, 11 MB goal, 4 P
gc 216 @0.942s 0%: 0+1.0+0 ms clock, 0+3.0/1.0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 217 @0.946s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->5 MB, 11 MB goal, 4 P
gc 218 @0.952s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 219 @0.955s 0%: 1.0+0+0 ms clock, 4.0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 220 @0.960s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 221 @0.964s 0%: 0+0.18+0 ms clock, 0+0/0.005/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 222 @0.968s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->3 MB, 10 MB goal, 4 P
gc 223 @0.973s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->1 MB, 8 MB goal, 4 P
gc 224 @0.975s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 225 @0.977s 0%: 0+0.49+0 ms clock, 0+0.99/0.49/0+0 ms cpu, 5->5->1 MB, 6 MB goal, 4 P
gc 226 @0.980s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 227 @0.982s 0%: 0.73+0.10+0 ms clock, 2.9+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 228 @0.986s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 229 @0.990s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 230 @0.993s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 231 @0.998s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 232 @1.001s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 233 @1.006s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->4 MB, 12 MB goal, 4 P
gc 234 @1.009s 0%: 0+1.0+0 ms clock, 0+1.0/1.0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 235 @1.013s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 236 @1.017s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 237 @1.020s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 238 @1.024s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 239 @1.029s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->3 MB, 11 MB goal, 4 P
gc 240 @1.032s 0%: 0.44+0.018+0 ms clock, 1.7+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 241 @1.036s 0%: 0.88+0.13+0 ms clock, 3.5+0/0/0+0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 242 @1.040s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 243 @1.044s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 244 @1.047s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 245 @1.050s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->3 MB, 7 MB goal, 4 P
gc 246 @1.053s 0%: 0+1.0+0.99 ms clock, 0+2.0/1.0/0+3.9 ms cpu, 7->7->3 MB, 8 MB goal, 4 P
gc 247 @1.057s 0%: 0+0+1.0 ms clock, 0+0/0/0+4.0 ms cpu, 6->7->4 MB, 7 MB goal, 4 P
gc 248 @1.063s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 249 @1.067s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 250 @1.071s 0%: 0+0+1.5 ms clock, 0+0/0/0+4.5 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 251 @1.074s 0%: 0+0+0.50 ms clock, 0+0/0/0+1.5 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 252 @1.078s 0%: 0.50+0+0 ms clock, 1.5+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 253 @1.084s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 12->12->4 MB, 13 MB goal, 4 P
gc 254 @1.088s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 255 @1.092s 0%: 0+0.46+0 ms clock, 0+0.010/0.46/0+0 ms cpu, 8->8->4 MB, 9 MB goal, 4 P
gc 256 @1.097s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 257 @1.103s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->2 MB, 11 MB goal, 4 P
gc 258 @1.105s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 259 @1.106s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 260 @1.110s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->6 MB, 9 MB goal, 4 P
gc 261 @1.118s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->4 MB, 14 MB goal, 4 P
gc 262 @1.121s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 263 @1.126s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->1 MB, 11 MB goal, 4 P
gc 264 @1.128s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 265 @1.131s 0%: 0+1.0+0 ms clock, 0+0/1.0/0+0 ms cpu, 5->5->2 MB, 6 MB goal, 4 P
gc 266 @1.134s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 267 @1.139s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->4 MB, 10 MB goal, 4 P
gc 268 @1.143s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->8->3 MB, 9 MB goal, 4 P
gc 269 @1.145s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->5 MB, 7 MB goal, 4 P
gc 270 @1.151s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->2 MB, 10 MB goal, 4 P
gc 271 @1.153s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 272 @1.156s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->3 MB, 7 MB goal, 4 P
gc 273 @1.158s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 274 @1.163s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->6 MB, 11 MB goal, 4 P
gc 275 @1.169s 0%: 0+0.50+1.5 ms clock, 0+1.5/0.50/0+4.5 ms cpu, 13->13->6 MB, 14 MB goal, 4 P
gc 276 @1.178s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 12->12->5 MB, 13 MB goal, 4 P
gc 277 @1.182s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->4 MB, 12 MB goal, 4 P
gc 278 @1.185s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 279 @1.189s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 280 @1.195s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->6 MB, 12 MB goal, 4 P
gc 281 @1.202s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->2 MB, 14 MB goal, 4 P
gc 282 @1.205s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 283 @1.205s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 5->6->5 MB, 6 MB goal, 4 P
gc 284 @1.210s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->5 MB, 11 MB goal, 4 P
gc 285 @1.216s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->11->6 MB, 11 MB goal, 4 P
gc 286 @1.222s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->5 MB, 12 MB goal, 4 P
gc 287 @1.227s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 11->11->3 MB, 12 MB goal, 4 P
gc 288 @1.230s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 289 @1.234s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->10->7 MB, 10 MB goal, 4 P
gc 290 @1.240s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->4 MB, 14 MB goal, 4 P
gc 291 @1.245s 0%: 0+0+1.0 ms clock, 0+0/0/0+3.0 ms cpu, 8->8->2 MB, 9 MB goal, 4 P
gc 292 @1.248s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 293 @1.250s 0%: 0+0.60+0 ms clock, 0+1.2/0.60/0+0 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 294 @1.252s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 295 @1.255s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 8->9->5 MB, 9 MB goal, 4 P
gc 296 @1.260s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 297 @1.267s 0%: 0+0.50+0 ms clock, 0+1.0/0.50/0+0 ms cpu, 15->15->6 MB, 16 MB goal, 4 P
gc 298 @1.273s 0%: 0.50+0+0 ms clock, 1.5+0/0/0+0 ms cpu, 13->13->6 MB, 14 MB goal, 4 P
gc 299 @1.279s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->3 MB, 12 MB goal, 4 P
gc 300 @1.282s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 6->6->4 MB, 7 MB goal, 4 P
gc 301 @1.286s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 7->7->5 MB, 8 MB goal, 4 P
gc 302 @1.289s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 9->9->5 MB, 10 MB goal, 4 P
gc 303 @1.295s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 304 @1.302s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 14->14->7 MB, 15 MB goal, 4 P
gc 305 @1.308s 0%: 0.82+0.12+0 ms clock, 3.3+0/0/0+0 ms cpu, 15->15->7 MB, 16 MB goal, 4 P
gc 306 @1.314s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 14->14->6 MB, 15 MB goal, 4 P
gc 307 @1.321s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->1 MB, 12 MB goal, 4 P
gc 308 @1.323s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 309 @1.327s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->3 MB, 6 MB goal, 4 P
gc 310 @1.327s 0%: 1.0+0+0 ms clock, 3.0+0/0/0+0 ms cpu, 6->6->5 MB, 7 MB goal, 4 P
gc 311 @1.333s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 10->10->4 MB, 11 MB goal, 4 P
gc 312 @1.337s 0%: 0.45+0.070+0 ms clock, 1.8+0/0/0+0 ms cpu, 9->9->6 MB, 10 MB goal, 4 P
gc 313 @1.344s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->7 MB, 14 MB goal, 4 P
gc 314 @1.350s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 13->13->2 MB, 14 MB goal, 4 P
gc 315 @1.352s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 316 @1.355s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 5->5->2 MB, 6 MB goal, 4 P
gc 317 @1.357s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 318 @1.444s 0%: 0+0.99+0 ms clock, 0+0/0.99/0+0 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 319 @1.446s 0%: 1.0+0.98+0 ms clock, 4.0+0/0/0+0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 320 @1.461s 0%: 0+1.0+0 ms clock, 0+3.0/1.0/0+0 ms cpu, 7->7->4 MB, 8 MB goal, 4 P
gc 321 @1.475s 0%: 0+1.0+0 ms clock, 0+3.0/1.0/0+0 ms cpu, 8->8->5 MB, 9 MB goal, 4 P
gc 322 @1.489s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 11->11->7 MB, 12 MB goal, 4 P
gc 323 @1.501s 0%: 0+1.0+0 ms clock, 0+3.0/1.0/0+0 ms cpu, 14->14->8 MB, 15 MB goal, 4 P
gc 324 @1.514s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 17->17->11 MB, 18 MB goal, 4 P
gc 325 @1.525s 0%: 0+1.0+0 ms clock, 0+0/1.0/0+0 ms cpu, 22->22->14 MB, 23 MB goal, 4 P
gc 326 @1.538s 0%: 0+1.0+0 ms clock, 0+3.0/1.0/0+0 ms cpu, 28->28->18 MB, 29 MB goal, 4 P
gc 327 @1.553s 0%: 0+1.0+0 ms clock, 0+0/1.0/0+0 ms cpu, 36->36->24 MB, 37 MB goal, 4 P
gc 328 @1.575s 0%: 0+0.50+0 ms clock, 0+1.0/0.50/0+0 ms cpu, 48->48->31 MB, 49 MB goal, 4 P
gc 329 @1.603s 0%: 0+1.0+0 ms clock, 0+0/0/0+0 ms cpu, 61->61->40 MB, 63 MB goal, 4 P
gc 330 @1.638s 0%: 0+0+0 ms clock, 0+0/0/0+0 ms cpu, 80->80->53 MB, 81 MB goal, 4 P
gc 331 @1.690s 0%: 1.0+0+0 ms clock, 1.0+0/0/0+0 ms cpu, 104->104->68 MB, 107 MB goal, 4 P
gc 332 @1.756s 0%: 0+0.99+0 ms clock, 0+1.9/0.99/0+0 ms cpu, 134->134->89 MB, 137 MB goal, 4 P
gc 333 @1.844s 0%: 0+1.0+0 ms clock, 0+1.0/1.0/0+0 ms cpu, 174->174->74 MB, 178 MB goal, 4 P
gc 334 @1.914s 0%: 1.0+0+0 ms clock, 1.0+0/0/0+0 ms cpu, 144->144->75 MB, 148 MB goal, 4 P
gc 335 @1.978s 0%: 0+0.50+1.0 ms clock, 0+0/0.50/0+1.0 ms cpu, 148->148->97 MB, 151 MB goal, 4 P
gc 336 @2.060s 0%: 0+1.0+0 ms clock, 0+1.0/1.0/0+0 ms cpu, 190->190->126 MB, 195 MB goal, 4 P
gc 337 @2.167s 0%: 0+0.50+0 ms clock, 0+1.5/0.50/0+0 ms cpu, 245->246->162 MB, 252 MB goal, 4 P
gc 338 @2.303s 0%: 0+1.0+0 ms clock, 0+1.0/1.0/0+0 ms cpu, 317->317->210 MB, 325 MB goal, 4 P
gc 339 @2.479s 0%: 0+1.0+0 ms clock, 0+0/1.0/0.50+0 ms cpu, 409->410->272 MB, 420 MB goal, 4 P
gc 340 @2.719s 0%: 0+6.0+0 ms clock, 0+0/2.0/0+0 ms cpu, 530->531->341 MB, 544 MB goal, 4 P
gc 341 @3.019s 0%: 0+2.5+0 ms clock, 0+0.50/2.5/0+0 ms cpu, 666->667->431 MB, 683 MB goal, 4 P
gc 342 @3.406s 0%: 0+3.0+0 ms clock, 0+0.50/2.5/0+0 ms cpu, 841->841->438 MB, 862 MB goal, 4 P
gc 343 @3.818s 0%: 0+2.5+0 ms clock, 0+1.0/2.5/0+0 ms cpu, 855->855->311 MB, 877 MB goal, 4 P
gc 344 @4.023s 0%: 0+1.5+0 ms clock, 0+0.50/1.4/0+0 ms cpu, 537->537->339 MB, 623 MB goal, 4 P (forced)
GC forced
gc 345 @124.956s 0%: 0+1.5+0 ms clock, 0+0/1.5/3.5+0 ms cpu, 347->347->0 MB, 678 MB goal, 4 P
scvg0: inuse: 1, idle: 855, sys: 857, released: 0, consumed: 857 (MB)
GC forced
gc 346 @244.978s 0%: 0+1.0+0 ms clock, 0+0/0/1.0+0 ms cpu, 0->0->0 MB, 4 MB goal, 4 P
5 minutes passed
scvg1: 8 MB released
scvg1: inuse: 1, idle: 855, sys: 857, released: 8, consumed: 849 (MB)
GC forced
gc 347 @424.055s 0%: 0+0.99+0 ms clock, 0+0/0/0.99+0 ms cpu, 0->0->0 MB, 4 MB goal, 4 P
GC forced
scvg2: 754 MB released
scvg2: inuse: 1, idle: 855, sys: 857, released: 762, consumed: 94 (MB)
gc 348 @544.077s 0%: 0+66+0 ms clock, 0+0/0/0+0 ms cpu, 0->0->0 MB, 4 MB goal, 4 P

Alex

[randall77]

The Go runtime claims it returned all but 94MB to the OS (the scvg2 lines).
Maybe my hunch earlier was correct, or maybe the "Memory" reported is virtual, not physical.
In any case, I suspect the error is with the observations, not with Go. I think we need an expert familiar with the Windows virtual memory system to know for sure.

[alexbrainman]

I downloaded VMMap program to see what is going on with this process. And it does uses a lot of memory. This particular program creates quite a few threads, and OS allocates 2MB for each thread stack space. @aclements merged CL 49331 recently, that changed oh64.SizeOfStackCommit from 0x00001000 to 0x00200000. I think it is a mistake (and I did not notice at the time). We should change it back to make thread initial stack size small again.

It would be nice to have a test to prevent mistakes like that in the future. I could, probably, write a test that measures committed memory of an external program. But what should I compare that value with?

Alex

[randall77]

Ah, I see, this might be Ms, not Gs or the heap, that are using up all the memory.
In CL 49331, Austin claimed large M stacks just use virtual memory, not physical memory. Are you disputing that?

[alexbrainman]

In CL 49331, Austin claimed large M stacks just use virtual memory, not physical memory. Are you disputing that?

CL 49331 intended to change just the use of virtual memory, but, I think, there is a mistake in CL 49331 - change of oh64.SizeOfStackCommit from 0x00001000 to 0x00200000 actually affects physical memory.

Windows memory management is quite complicated, but, for the purpose of this discussion, each page of process addressed memory could be one of three: free, reserved and committed (see https://msdn.microsoft.com/en-us/library/windows/desktop/aa366794(v=vs.85).aspx ) Only "committed"
memory require actual physical memory to back it up.

When process starts, EXE file describes to OS how stacks should be managed. In particular PE file format specifies the maximum size of the stack to be used (stored in oh64.SizeOfStackReserve). When process creates new thread, it "reserves" oh64.SizeOfStackReserve bytes for each stack. PE file also specify how much of oh64.SizeOfStackReserve bytes should be "committed" at start of each thread (this is stored in oh64.SizeOfStackCommit). So normal stacks should start with large "reserved" stack, with some small part of it "committed" at the beginning. As stack grows, "committed" part grows too - when program grows beyond "committed" area, it tries to read / write memory, this causes "system exception", and memory manager handles these exceptions by making more "committed" memory and restarting failed code again.

So for a particular case of non-cgo windows/amd64 we had:

oh64.SizeOfStackReserve = 0x00020000
oh64.SizeOfStackCommit = 0x00001000

before CL 49331, and:

oh64.SizeOfStackReserve = 0x00200000
oh64.SizeOfStackCommit = 0x00200000 - 0x2000 // account for 2 guard pages

after CL 49331. So the max stack size got increased from 132K to 2M, but "committed" part of the stack also was increased from 4K to 2M. I think we should not have done the second change, because now every new thread cost us 2M of physical memory comparing to 4K before CL 49331. And once "committed", stack memory cannot be freed - I suspect only exiting thread will free its stack memory.

I hope I explained it well enough.

Alex

[randall77]

Yes, that all makes sense, thanks.
Can someone test such a change on a Windows machine, and see if it helps this case?

And once "committed", stack memory cannot be freed - I suspect only exiting thread will free its > stack memory.

Are we ever exiting Ms that have been idle for a long time? If not, then doing that might fix the issue. Maybe an additional task for the scavenger to do.

[aclements]

I see. It looks like I just did what we were already doing in the cgo case. I don't know why we were committing basically the whole stack under cgo in the first place. I'm certainly fine with reducing the commit if that works.

Are we ever exiting Ms that have been idle for a long time? If not, then doing that might fix the issue. Maybe an additional task for the scavenger to do.

I recently added the framework necessary to do this, but right now we only exit locked Ms (when their Gs exit without unlocking). We don't use this for exiting idle Ms currently, but we could.

[alexbrainman]

Can someone test such a change on a Windows machine, and see if it helps this case?

I did test that yesterday. Setting oh64.SizeOfStackCommit back to 0x00001000 helps with memory usage significantly. We can get @6degreeshealth check that it helps too to be sure. I am worried that we have broken this thing without anyone noticing. I wonder if I could write some test to stop this happening in the future.

Are we ever exiting Ms that have been idle for a long time?

I don't think so. But Austin will know.

If not, then doing that might fix the issue. Maybe an additional task for the scavenger to do.

Yes, the fact that thread stacks consume memory (even when threads are idle) might be a good reason to exit them.

I see. It looks like I just did what we were already doing in the cgo case. I don't know why we were committing basically the whole stack under cgo in the first place.

cgo case is very different from non-cgo case as far as I am concerned. I hope not many people use cgo. Especially on Windows, because we have syscall.Syscall to easily call into Windows C code without cgo. And cgo executables are created by external linker, so I am not sure if we can control SizeOfStackReserve and SizeOfStackCommit fields in the PE exe. Also we use _beginthead function to start threads with cgo. I do not know if _beginthread allow us control "commit" stack size. I probably dropped the ball with cgo. Do we want to try and improve this for cgo case too?

I'm certainly fine with reducing the commit if that works.

Cool. I will send the change. The change should be simple, I just wonder about the test.

Alex

[aclements]

And cgo executables are created by external linker, so I am not sure if we can control SizeOfStackReserve and SizeOfStackCommit fields in the PE exe.

That's true. Though I would expect the external linker to set reasonable "normal" stack sizes for Windows, which presumably have a small commit?

Also we use _beginthead function to start threads with cgo. I do not know if _beginthread allow us control "commit" stack size.

We pass 0 for the stack size, which MSDN says means to "the same value as the stack that's specified for the main thread", which I expect means to use both the reservation and commit from the PE header.

The change should be simple, I just wonder about the test.

Start lots of threads and if the system crashes the test fails? :)

[robarchibald]

I would be happy to rest, but I'm on a business trip away from my Windows computer. I won't be able to test until Saturday. I assume that to test I'll need to build Go from source using the latest source. Never done that before, but I'll give it a whirl.

[alexbrainman]

That's true. Though I would expect the external linker to set reasonable "normal" stack sizes for Windows, which presumably have a small commit?

I will see what we get with external linker.

Start lots of threads and if the system crashes the test fails? :)

I was actually hoping you will be helpful. ;-)

I would be happy to rest

That would be nice, if you test when my change is ready. Thank you.

but I'm on a business trip away from my Windows computer. I won't be able to test until Saturday.

The change is not ready, so do not worry.

I assume that to test I'll need to build Go from source using the latest source. Never done that before, but I'll give it a whirl.

Yes, you will need to build Go from source. Here https://golang.org/doc/install/source are the instructions. We will help you if you get into trouble.

Alex

[aclements]

For the test, I was thinking the Windows equivalent of this:

package main

import (
	"fmt"
	"io/ioutil"
	"runtime"
	"strconv"
	"strings"
	"sync"
	"syscall"
)

func main() {
	var wg sync.WaitGroup
	for i := 0; i < 1000; i++ {
		wg.Add(1)
		go func() {
			runtime.LockOSThread()
			wg.Done()
			select {}
		}()
	}
	wg.Wait()

	vsize, rss := mem()
	fmt.Printf("%d bytes RSS (%d bytes virtual)\n", rss, vsize)
}

func mem() (vsize, rss uintptr) {
	stat, err := ioutil.ReadFile("/proc/self/stat")
	if err != nil {
		panic(err)
	}
	parts := strings.Fields(string(stat))
	parseInt := func(x string) uintptr {
		y, err := strconv.ParseInt(x, 10, 64)
		if err != nil {
			panic(err)
		}
		return uintptr(y)
	}
	vsize = parseInt(parts[22])
	rss = parseInt(parts[23]) * uintptr(syscall.Getpagesize())
	return
}

E.g., on Linux/amd64, I get a mere "3973120 bytes RSS (52129792 bytes virtual)".

I'm not sure what the Windows equivalent of /proc/self/stat's RSS is. Maybe PROCESS_MEMORY_COUNTERS_EX.PrivateUsage?

Unfortunately, this probably has to be a runtime/testdata/testprog thing rather than a regular test to avoid interference from other tests' memory usage.