possible memory leak using sjson.Set

[saartamir]

Hi @tidwall I'm using this library to enrich event without unmarshalling into Go struct, and there's seems to be a memory problem in sjson.Set(). This is how I use it:

func EnrichEvent(event string, ctx *fasthttp.RequestCtx) string {
	startTime := time.Now().UnixNano() / 1000000

	log := zap.L()

	ua := string(ctx.UserAgent())
	ip := ctx.RemoteIP().String()
	entryTs := strconv.Itoa(int(time.Now().UnixNano() / int64(time.Millisecond)))

	var err error

	// add new fields to events
	event, err = sjson.Set(event, "ua", ua)
	if err != nil {
		log.Error("could not add ua to event", zap.String("event", event), zap.Error(err))
	}

	event, err = sjson.Set(event, "client_ip", ip)
	if err != nil {
		log.Error("could not add client_ip to event", zap.String("event", event), zap.Error(err))
	}

	event, err = sjson.Set(event, "entry_ts", entryTs)
	if err != nil {
		log.Error("could not add entry_ts to event", zap.String("event", event), zap.Error(err))
	}

	endTime := time.Now().UnixNano() / 1000000
	promy.RecordMetric("EnrichTimeHistogram", 0, float64(endTime-startTime), nil)

	return event
}

and when I'm trying to profile the allocs, it looks like sjson keeps growing and growing:

am I doing anything wrong?

[tidwall]

I wrote a program that tried to reproduce the issue, but I wasn't able to see the memory issues that you were seeing.

I took your example function and hardcoded the values that came from the fasthttp and `zap' libraries.

Here's the complete program:

package main

import (
	"fmt"
	"log"
	"runtime"
	"strconv"
	"time"

	"github.com/tidwall/sjson"
)

func main() {
	evs := make(chan string, 100)
	go func() {
		var totalBytes int64
		var totalEvents int64
		ticker := time.NewTicker(time.Second)
		for {
			select {
			case ev := <-evs:
				totalEvents++
				totalBytes += int64(len(ev))
			case <-ticker.C:
				var stats runtime.MemStats
				runtime.ReadMemStats(&stats)
				fmt.Printf(
					"Processes %d Messages (%0.2f GB), Heap Size: %0.2f MB\n",
					totalEvents,
					float64(totalBytes)/1024/1024/1024,
					float64(stats.HeapAlloc)/1024/1024,
				)
			}
		}
	}()

	for i := 0; i < runtime.NumCPU(); i++ {
		go func() {
			for {
				evs <- EnrichEvent("{}")
			}
		}()
	}
	select {}
}

// func EnrichEvent(event string, ctx *fasthttp.RequestCtx) string {
func EnrichEvent(event string) string {
	// startTime := time.Now().UnixNano() / 1000000

	// log := zap.L()

	// ua := string(ctx.UserAgent())
	ua := "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36"
	// ip := ctx.RemoteIP().String()
	ip := "127.10.105.81:98172"
	entryTs := strconv.Itoa(int(time.Now().UnixNano() / int64(time.Millisecond)))

	var err error

	// add new fields to events
	event, err = sjson.Set(event, "ua", ua)
	if err != nil {
		// log.Error("could not add ua to event", zap.String("event", event), zap.Error(err))
		log.Fatal("could not add ua to event", event, err)
	}

	event, err = sjson.Set(event, "client_ip", ip)
	if err != nil {
		// log.Error("could not add client_ip to event", zap.String("event", event), zap.Error(err))
		log.Fatal("could not add client_ip to event", event, err)
	}

	event, err = sjson.Set(event, "entry_ts", entryTs)
	if err != nil {
		// log.Error("could not add entry_ts to event", zap.String("event", event), zap.Error(err))
		log.Fatal("could not add entry_ts to event", event, err)
	}

	// endTime := time.Now().UnixNano() / 1000000
	// promy.RecordMetric("EnrichTimeHistogram", 0, float64(endTime-startTime), nil)

	return event
}

The program processes as many events as possible over a number of goroutines and prints out stats every second.

Here's what I'm seeing:

Processes 1139184 Messages (0.20 GB), Heap Size: 3.57 MB
Processes 2255683 Messages (0.39 GB), Heap Size: 2.86 MB
Processes 3358867 Messages (0.58 GB), Heap Size: 3.63 MB
Processes 4471472 Messages (0.77 GB), Heap Size: 3.48 MB
Processes 5598419 Messages (0.96 GB), Heap Size: 3.21 MB
Processes 6704932 Messages (1.16 GB), Heap Size: 3.65 MB
Processes 7796037 Messages (1.34 GB), Heap Size: 3.30 MB
Processes 8903962 Messages (1.53 GB), Heap Size: 3.61 MB
Processes 9993757 Messages (1.72 GB), Heap Size: 2.71 MB
Processes 11091102 Messages (1.91 GB), Heap Size: 2.02 MB
Processes 12201903 Messages (2.10 GB), Heap Size: 2.97 MB
Processes 13317121 Messages (2.29 GB), Heap Size: 2.09 MB
Processes 14428639 Messages (2.49 GB), Heap Size: 3.58 MB
Processes 15551060 Messages (2.68 GB), Heap Size: 3.53 MB
Processes 16684651 Messages (2.87 GB), Heap Size: 2.57 MB
Processes 17801735 Messages (3.07 GB), Heap Size: 3.52 MB
Processes 18914031 Messages (3.26 GB), Heap Size: 2.24 MB
Processes 20032989 Messages (3.45 GB), Heap Size: 2.07 MB
Processes 21146109 Messages (3.64 GB), Heap Size: 3.67 MB
Processes 22257386 Messages (3.83 GB), Heap Size: 3.54 MB
Processes 23346580 Messages (4.02 GB), Heap Size: 3.36 MB
Processes 24456117 Messages (4.21 GB), Heap Size: 3.04 MB
Processes 25562760 Messages (4.40 GB), Heap Size: 1.73 MB
Processes 26671997 Messages (4.60 GB), Heap Size: 3.61 MB
Processes 27789998 Messages (4.79 GB), Heap Size: 2.33 MB
Processes 28945007 Messages (4.99 GB), Heap Size: 3.31 MB
Processes 30069362 Messages (5.18 GB), Heap Size: 3.49 MB

After about 30 seconds, 30 million sjson.Set calls were processed with amounted to 5 GB of data. Yet the Go heap never goes above 4 MB.