Heap is not cleaned automatically after mass SET

[amorskoy]

So, I have 73K Point objects poi
I am inserting people withing rate ~ 1000 SET msgs/sec (POINT as well, EX is 10 seconds)

There is just one HTTP hook

127.0.0.1:9852> hooks *
{"ok":true,"hooks":[{"name":"poi_hook","key":"people","endpoints":["http://geocases:9999/"],"command":["NEARBY","people","FENCE","COMMANDS","set","ROAM","pois","*","300"]}],"elapsed":"15.449µs"}

1. Initial memory consumption is 100 MB
2. During ingestion it reaches 320 MB
3. After ingestion it stays at 320 MB
4. After manual GC command it backs to 100 MB

Before GC:

127.0.0.1:9852> server
{"ok":true,"stats":{"aof_size":42984795,"avg_item_size":795,"heap_released":0,"heap_size":62322712,"http_transport":true,"id":"e2dbdf1893535b2cd2020f405018026f","in_memory_size":2810610,"max_heap_size":0,"mem_alloc":62322712,"num_collections":1,"num_hooks":1,"num_objects":78381,"num_points":78381,"num_strings":0,"pid":7459,"pointer_size":8,"read_only":false},"elapsed":"1.08897ms"}

After GC

127.0.0.1:9852> gc
{"ok":true,"elapsed":"471ns"}
127.0.0.1:9852> server
{"ok":true,"stats":{"aof_size":42984795,"avg_item_size":794,"heap_released":260014080,"heap_size":62265040,"http_transport":true,"id":"e2dbdf1893535b2cd2020f405018026f","in_memory_size":2810610,"max_heap_size":0,"mem_alloc":62265040,"num_collections":1,"num_hooks":1,"num_objects":78381,"num_points":78381,"num_strings":0,"pid":7459,"pointer_size":8,"read_only":false},"elapsed":"579.457µs"}

Approximate hook calling rate (measured from endpoint) seems to be OK:

RATE IS 1350 msg/sec
RATE IS 1538 msg/sec
RATE IS 1498 msg/sec
RATE IS 1349 msg/sec

[tidwall]

The Go runtime hangs on to memory for as long as possible. As I understand, the memory will eventually be released. But when this happens depends on factors like how often the Go memory allocator reuses the memory pages, the ratio of unused/used memory in the Go process, and how much system memory is available. Go is greedy with memory.

Ideally Tile38 would have the GC command automatically executed in the background every 30 seconds or so, but right now the Go garbage collector is a stop-the-world operation that can take up to 10 milliseconds to perform. This is too slow for my taste.

The new 1.8 Go runtime (which should be available sometime in February) will have sub-millisecond pauses. This will allow for us to have an automated background GC.

In the meantime I recommend sending a GC following a mass insert.

[m1ome]

@tidwall maybe we can add some kind of GC [interval] ?

[tidwall]

@m1ome I think it may better to add a background garbage collection routine.

Something that executes every ~5 minutes. I don't want it to run more often than it needs, in case the Go garbage collector takes too long to complete. Just often enough to help keep overall system resources in check.

There's currently a routine that does some very basic memory bookkeeping and also watches the maxmemory config setting (#15).

https://github.com/tidwall/tile38/blob/master/controller/controller.go#L180
https://github.com/tidwall/tile38/blob/master/controller/controller.go#L229-L260

These can be used as a template.

The only code that needs to execute is:

runtime.GC()
debug.FreeOSMemory()

With Go 1.7 and below, this operation might take upwards of 10ms. In 1.8+ it should be less than a millisecond.

[m1ome]

@tidwall maybe we should add some configuration option for it? Response time may be crucial in some cases, and let's say 10ms in some time it's pretty important.

[tidwall]

@m1ome good idea. Perhaps autogc where the value is an integer that is the number of seconds between GC calls. Zero would disable it and could be the default.

[m1ome]

@tidwall if you wish i can implement this one :)

[tidwall]

@m1ome Sure, that would be great. 👍

[m1ome]

@tidwall awesome! I am on it!

[tidwall]

I just merged the change that include the autogc config option to master.