Depended types' encoder/decoder functions are not all computed during pretouch

[bimoadityar]

Describe the bug

Even after pretouching the marshaled type, the latency of marshaling the type takes time of milliseconds order, which may be risk breaking the SLAs of some endpoints. I am wondering what additional things I can do to avoid this risk.

To Reproduce

Can run the following toy program:

package main

import (
	"encoding/xml"
	"fmt"
	"reflect"
	"time"

	"github.com/brianvoe/gofakeit/v5"
	"github.com/bytedance/sonic"
)

type status struct {
	Name        string `xml:"name"`
	ID          int    `xml:"id"`
	Description string `xml:"description"`
	GroupID     int    `xml:"groupId"`
	GroupName   string `xml:"groupName"`
	Action      string `xml:"action"`
}

type message struct {
	MessageID string `xml:"messageId"`
	To        string `xml:"to"`
	SmsCount  int    `xml:"smsCount"`
	Status    status `xml:"status"`
}

type serviceException struct {
	MessageID string `xml:"messageId"`
	Text      string `xml:"text"`
}

type requestError struct {
	ServiceException serviceException `xml:"serviceException"`
}

type infobipResponse struct {
	Name         xml.Name     `xml:"smsResponse"`
	Messages     []message    `xml:"messages>message"`
	RequestError requestError `xml:"requestError"`
}

func generateResponse() *infobipResponse {
	return &infobipResponse{
		Name: xml.Name{Space: gofakeit.URL(), Local: gofakeit.Word()},
		Messages: []message{
			{
				MessageID: gofakeit.UUID(),
				To:        gofakeit.Phone(),
				SmsCount:  gofakeit.Number(1, 10),
				Status: status{
					Name:        gofakeit.Word(),
					ID:          gofakeit.Number(1, 10),
					Description: gofakeit.Sentence(10),
					GroupID:     gofakeit.Number(1, 10),
					GroupName:   gofakeit.Word(),
					Action:      gofakeit.Word(),
				},
			},
		},
		RequestError: requestError{
			ServiceException: serviceException{
				MessageID: gofakeit.UUID(),
				Text:      gofakeit.Sentence(40),
			},
		},
	}
}

func main() {
	totalLen := 0 // just to avoid optimization
	cnt := 0

	t := reflect.TypeOf(generateResponse())
	printTime("pre", func() { sonic.Pretouch(t) })

	for i := 1; i <= 10; i++ {
		payload := generateResponse()
		printTime(fmt.Sprintf("run %d", i), func() {
			out, _ := sonic.Marshal(payload)
			totalLen += len(out)
			cnt++
		})
	}

	fmt.Printf("len\t\t%v\n", totalLen/cnt)
}

func printTime(v string, fn func()) {
	start := time.Now()
	fn()
	fmt.Printf("%s\t\t%v\n", v, time.Since(start))
}

Then, the result will look like this:

pre             13.021132ms
run 1           1.053851ms
run 2           1.911µs
run 3           588ns
run 4           559ns
run 5           487ns
run 6           1.799µs
run 7           476ns
run 8           443ns
run 9           501ns
run 10          460ns
len             731

For reference, here is the output if we use encoding/json, where no latency exceed 100 microseconds:

run 1           85.921µs
run 2           2.042µs
run 3           2.013µs
run 4           1.752µs
run 5           2.07µs
run 6           3.215µs
run 7           2.116µs
run 8           1.989µs
run 9           1.231µs
run 10          2.131µs
len             729

Things I have tried on top of pretouching that does not help:

• adding time.Sleep before marshal
• marshaling other types
• creating a value from the pretouched type, i.e. reflect.New(t.Elem()).Interface(), and marshaling that

Expected behavior

There is no marshaling latency on miliseconds level, even on the first marshal.

Sonic version:

v1.13.3

Environment:

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/bimoadityar/.cache/go-build"
GOENV="/home/bimoadityar/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/bimoadityar/.go/pkg/mod"
GOOS="linux"
GOPATH="/home/bimoadityar/.go"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/bimoadityar/.config/spkit/bin/sdk/go1.17.13"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/bimoadityar/.config/spkit/bin/sdk/go1.17.13/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.13"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/bimoadityar/Documents/bimo-test-2/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1204808054=/tmp/go-build -gno-record-gcc-switches"

[bimoadityar]

From my local debugging, seems that most of the latency comes from inside the compiled Encoder function. I am not sure how to debug further...

[liuq19]

you can try pretouch with larger CompileRecursiveDepth and CompileMaxInlineDepth. https://github.com/bytedance/sonic?tab=readme-ov-file#pretouch

[bimoadityar]

I tried providing the option with larger value:

	t := reflect.TypeOf(generateResponse())
	printTime("pre", func() {
		sonic.Pretouch(t,
			option.WithCompileMaxInlineDepth(100), option.WithCompileRecursiveDepth(100),
		)
	})

but it seems that the first marshal still take 800-1300 microseconds for this example on my side.

[bimoadityar]

By adding some logging on the internal/caching/pcache.go's Compute function:

func (self *ProgramCache) Compute(vt *rt.GoType, compute func(*rt.GoType, ...interface{}) (interface{}, error), ex ...interface{}) (interface{}, error) {
+	start := time.Now()
+	defer func() { fmt.Printf("compute %30s %v\n", vt.Pack().String(), time.Since(start)) }()
	...
}

I can see that the first run still computes the encoder function for the message and requestError type:

compute          *main.infobipResponse 1.299203ms
compute          *main.infobipResponse 7.021477ms
compute           main.infobipResponse 938.944µs
compute           main.infobipResponse 5.740167ms
pre             15.064312ms
compute                   main.message 655.909µs
compute          main.serviceException 414.75µs
run 1           1.130026ms
run 2           5.666µs
run 3           1.149µs
run 4           949ns
run 5           553ns
run 6           510ns
run 7           477ns
run 8           470ns
run 9           482ns
run 10          571ns
len             731

Is there a way I can offload all this computation to the very start? Is it not covered in your provided pretouch options?
Why are not the message and the serviceException types inlined or precomputed in this case?

[AsterDY]

dynamic interface can't be compiled until you give concrete type. So the best practice is use real object to 'unmarshal' as pretouch