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

Marshal Takes too much time #331

Closed
shahriar350 opened this issue Feb 1, 2022 · 24 comments · Fixed by #368
Closed

Marshal Takes too much time #331

shahriar350 opened this issue Feb 1, 2022 · 24 comments · Fixed by #368
Labels
enhancement New feature or request performance

Comments

@shahriar350
Copy link

shahriar350 commented Feb 1, 2022

I have a product struct when to make it to json using Marshal, It takes too time around 10s-20s to convert. Is there any problem with my code or its a bug?

fmt.Println("Data is: ", products)
fmt.Println("Marshal start at: ", time.Now())
data, dataErr := gojson.Marshal(products)
fmt.Println("Marshal end at: ", time.Now())
if dataErr != nil {
	fmt.Println(dataErr)
}
fmt.Println("data is: ",fmt.Sprintf("%s",data))
Data is:  [SellerProduct(id=1, name=samsung, slug=samsung, selling_price=40000, product_price=0, quantity=0, active=false, offer_price=0, created_a
t=Mon Jan  1 00:00:00 0001, updated_at=Mon Jan  1 00:00:00 0001) SellerProduct(id=2, name=samsung s10, slug=samsung-s10, selling_price=40000, produ
ct_price=0, quantity=0, active=false, offer_price=0, created_at=Mon Jan  1 00:00:00 0001, updated_at=Mon Jan  1 00:00:00 0001) SellerProduct(id=3,
name=samsung s10, slug=samsung-s10-7943, selling_price=50000, product_price=0, quantity=0, active=false, offer_price=50, offer_price_start=Tue Feb
 1 06:00:00 2022, offer_price_end=Mon Feb  7 06:00:00 2022, created_at=Mon Jan  1 00:00:00 0001, updated_at=Mon Jan  1 00:00:00 0001) SellerProduct
(id=4, name=nokia 7, slug=nokia-7, selling_price=50000, product_price=0, quantity=0, active=false, offer_price=50, offer_price_start=Tue Feb  1 06:
00:00 2022, offer_price_end=Mon Feb  7 06:00:00 2022, created_at=Mon Jan  1 00:00:00 0001, updated_at=Mon Jan  1 00:00:00 0001)]

**Marshal start at:  2022-02-01 13:46:41.6443916 +0600 +06 m=+11.061040001**

13:46:41 | 200 |     5ms |       127.0.0.1 | GET     | /api/user/cart/count
13:46:41 | 200 |    84ms |       127.0.0.1 | GET     | /api/nonuser/all/main/categories

**Marshal end at:  2022-02-01 13:46:54.1005208 +0600 +06 m=+23.517169201**

data is:  [{"id":1,"name":"samsung","slug":"samsung","selling_price":"40000","product_price":"0","created_at":"0001-01-01T00:00:00Z","updated_at":"
0001-01-01T00:00:00Z","edges":{"seller_product_images":[{"id":1,"display":true,"image":"e8f49d7d15c54bd0b2d05f8c4bc4ab9a.jpeg","created_at":"0001-0
1-01T00:00:00Z","updated_at":"0001-01-01T00:00:00Z","edges":{}}]}},{"id":2,"name":"samsung s10","slug":"samsung-s10","selling_price":"40000","produ
ct_price":"0","created_at":"0001-01-01T00:00:00Z","updated_at":"0001-01-01T00:00:00Z","edges":{"seller_product_images":[{"id":4,"display":true,"ima
ge":"ac013a294da14320a8f991ed91db1d5f.jpg","created_at":"0001-01-01T00:00:00Z","updated_at":"0001-01-01T00:00:00Z","edges":{}}]}},{"id":3,"name":"s
amsung s10","slug":"samsung-s10-7943","selling_price":"50000","product_price":"0","offer_price":50,"offer_price_start":"2022-02-01T06:00:00+06:00",
"offer_price_end":"2022-02-07T06:00:00+06:00","created_at":"0001-01-01T00:00:00Z","updated_at":"0001-01-01T00:00:00Z","edges":{"seller_product_imag
es":[{"id":7,"display":true,"image":"fb5d1fa7e2834d2fbe2f725b509a7bf2.jpg","created_at":"0001-01-01T00:00:00Z","updated_at":"0001-01-01T00:00:00Z",
"edges":{}}]}},{"id":4,"name":"nokia 7","slug":"nokia-7","selling_price":"50000","product_price":"0","offer_price":50,"offer_price_start":"2022-02-
01T06:00:00+06:00","offer_price_end":"2022-02-07T06:00:00+06:00","created_at":"0001-01-01T00:00:00Z","updated_at":"0001-01-01T00:00:00Z","edges":{"
seller_product_images":[{"id":10,"display":true,"image":"65cd5529119640e09d85acf76f88ebaa.jpg","created_at":"0001-01-01T00:00:00Z","updated_at":"00
01-01-01T00:00:00Z","edges":{}}]}}]
@shahriar350
Copy link
Author

shahriar350 commented Feb 1, 2022

type AutoGenerated []struct {
	ID           int       `json:"id"`
	Name         string    `json:"name"`
	Slug         string    `json:"slug"`
	SellingPrice string    `json:"selling_price"`
	ProductPrice string    `json:"product_price"`
	CreatedAt    time.Time `json:"created_at"`
	UpdatedAt    time.Time `json:"updated_at"`
	Edges        struct {
		SellerProductImages []struct {
			ID        int       `json:"id"`
			Display   bool      `json:"display"`
			Image     string    `json:"image"`
			CreatedAt time.Time `json:"created_at"`
			UpdatedAt time.Time `json:"updated_at"`
			Edges     struct {
			} `json:"edges"`
		} `json:"seller_product_images"`
	} `json:"edges"`
	OfferPrice      int       `json:"offer_price,omitempty"`
	OfferPriceStart time.Time `json:"offer_price_start,omitempty"`
	OfferPriceEnd   time.Time `json:"offer_price_end,omitempty"`
}
my auto generated struct.

@orisano
Copy link
Contributor

orisano commented Feb 1, 2022

I can't reproduce this issue...

@orisano
Copy link
Contributor

orisano commented Feb 1, 2022

func TestIssue331(t *testing.T) {
	type SellerProductImage struct {
		ID        int       `json:"id"`
		Display   bool      `json:"display"`
		Image     string    `json:"image"`
		CreatedAt time.Time `json:"created_at"`
		UpdatedAt time.Time `json:"updated_at"`
		Edges     struct{}  `json:"edges"`
	}
	type Edges struct {
		SellerProductImages []SellerProductImage `json:"seller_product_images"`
	}
	type Product struct {
		ID              int       `json:"id"`
		Name            string    `json:"name"`
		Slug            string    `json:"slug"`
		SellingPrice    string    `json:"selling_price"`
		ProductPrice    string    `json:"product_price"`
		CreatedAt       time.Time `json:"created_at"`
		UpdatedAt       time.Time `json:"updated_at"`
		Edges           Edges     `json:"edges"`
		OfferPrice      int       `json:"offer_price,omitempty"`
		OfferPriceStart time.Time `json:"offer_price_start,omitempty"`
		OfferPriceEnd   time.Time `json:"offer_price_end,omitempty"`
	}
	products := []Product{
		{ID: 1, Name: "samsung", Slug: "samsung", SellingPrice: "40000", ProductPrice: "0", Edges: Edges{SellerProductImages: []SellerProductImage{{ID: 1, Display: true, Image: "e8f49d7d15c54bd0b2d05f8c4bc4ab9a.jpeg"}}}},
		{ID: 2, Name: "samsung s10", Slug: "samsung-s10", SellingPrice: "40000", ProductPrice: "0", Edges: Edges{SellerProductImages: []SellerProductImage{{ID: 4, Display: true, Image: "ac013a294da14320a8f991ed91db1d5f.jpg"}}}},
		{ID: 3, Name: "samsung s10", Slug: "samsung-s10-7943", SellingPrice: "50000", ProductPrice: "0", OfferPrice: 50, OfferPriceStart: time.Date(2022, 2, 1, 6, 0, 0, 0, time.UTC), OfferPriceEnd: time.Date(2022, 2, 7, 6, 0, 0, 0, time.UTC), Edges: Edges{SellerProductImages: []SellerProductImage{{ID: 7, Display: true, Image: "fb5d1fa7e2834d2fbe2f725b509a7bf2.jpg"}}}},
		{ID: 4, Name: "nokia 7", Slug: "nokia-7", SellingPrice: "50000", ProductPrice: "0", OfferPrice: 50, OfferPriceStart: time.Date(2022, 2, 1, 6, 0, 0, 0, time.UTC), OfferPriceEnd: time.Date(2022, 2, 7, 6, 0, 0, 0, time.UTC), Edges: Edges{SellerProductImages: []SellerProductImage{{ID: 10, Display: true, Image: "65cd5529119640e09d85acf76f88ebaa.jpg"}}}},
	}
	begin := time.Now()
	b, err := json.Marshal(products)
	if err != nil {
		t.Fatal(err)
	}
	_ = b
	t.Log(time.Now().Sub(begin)) // output: 495.218µs
}
  • go-json 0.9.4
  • go 1.17.5
  • darwin
  • amd64
  • 2.3 GHz Quad-Core
  • Memory 32GB

@goccy
Copy link
Owner

goccy commented Feb 1, 2022

I didn't understand why the following output was from the code. Are any other programs running in parallel ? I would like to know if the same thing happens with only json.Marshal running .

13:46:41 | 200 |     5ms |       127.0.0.1 | GET     | /api/user/cart/count
13:46:41 | 200 |    84ms |       127.0.0.1 | GET     | /api/nonuser/all/main/categories

@shahriar350
Copy link
Author

I didn't understand why the following output was from the code. Are any other programs running in parallel ? I would like to know if the same thing happens with only json.Marshal running .

13:46:41 | 200 |     5ms |       127.0.0.1 | GET     | /api/user/cart/count
13:46:41 | 200 |    84ms |       127.0.0.1 | GET     | /api/nonuser/all/main/categories

This is another request which is made by frontend. Ignore this.

@shahriar350
Copy link
Author

i dont know why it takes too much time for me. I use ent for sql. But other package like std package, gojay, json-iterator works fine but this package works fine but takes too time.

@orisano
Copy link
Contributor

orisano commented Feb 1, 2022

If CPU usage is high, can you get the pprof?

@shahriar350
Copy link
Author

If CPU usage is high, can you get the pprof?

image
0.1% cpu use for my project. why only go-json takes too much time? other package of json work normally.

@goccy
Copy link
Owner

goccy commented Feb 2, 2022

It is not reproducible and may be an environment dependent issue. I can't investigate as it is, so could you measure it with pprof and attach a capture of the go-json part?

@efectn
Copy link

efectn commented Feb 2, 2022

If CPU usage is high, can you get the pprof?

image 0.1% cpu use for my project. why only go-json takes too much time? other package of json work normally.

You should use Fiber's https://github.com/gofiber/fiber/tree/master/middleware/pprof middleware and go tool pprof for more detailed output

@shahriar350
Copy link
Author

It is not reproducible and may be an environment dependent issue. I can't investigate as it is, so could you measure it with pprof and attach a capture of the go-json part?

actually i dont know about that package.

@shahriar350
Copy link
Author

with go-json

1537.50kB 26.28% 26.28%  1537.50kB 26.28%  runtime.allocm
  727.78kB 12.44% 38.72%   727.78kB 12.44%  github.com/gofiber/fiber/v2/internal/go-json/encoder.init.0
  512.34kB  8.76% 47.48%   512.34kB  8.76%  github.com/volatiletech/inflect.(*Ruleset).AddSingularExact (inline)
  512.22kB  8.76% 56.23%   512.22kB  8.76%  regexp.onePassCopy
  512.20kB  8.76% 64.99%   512.20kB  8.76%  runtime.malg
  512.06kB  8.75% 73.74%   512.06kB  8.75%  github.com/zclconf/go-cty/cty/function/stdlib.init
  512.04kB  8.75% 82.50%   512.04kB  8.75%  github.com/gofiber/fiber/v2.(*routeParser).analyseConstantPart
  512.02kB  8.75% 91.25%   512.02kB  8.75%  strings.makeCutsetFunc
  512.02kB  8.75%   100%   512.02kB  8.75%  text/template/parse.(*ChainNode).String (inline)

with other json

flat  flat%   sum%        cum   cum%
 1537.50kB 17.21% 17.21%  1537.50kB 17.21%  runtime.allocm
 1166.01kB 13.05% 30.26%  1166.01kB 13.05%  compress/flate.newDeflateFast (inline)
  982.73kB 11.00% 41.26%   982.73kB 11.00%  github.com/gofiber/fiber/v2/internal/go-json/decoder.init.0
  902.59kB 10.10% 51.36%  2613.27kB 29.25%  compress/flate.NewWriter
  727.78kB  8.15% 59.51%   727.78kB  8.15%  github.com/gofiber/fiber/v2/internal/go-json/encoder.init.0
  544.67kB  6.10% 65.60%  1710.68kB 19.15%  compress/flate.(*compressor).init
     513kB  5.74% 71.34%      513kB  5.74%  github.com/klauspost/compress/flate.newHuffmanEncoder (inline)
  512.20kB  5.73% 77.08%   512.20kB  5.73%  runtime.malg
  512.10kB  5.73% 82.81%   512.10kB  5.73%  net.init
  512.02kB  5.73% 88.54%   512.02kB  5.73%  regexp/syntax.(*Regexp).CapNames
  512.01kB  5.73% 94.27%   512.01kB  5.73%  text/template/parse.(*Tree).newText (inline)
  512.01kB  5.73%   100%   512.01kB  5.73%  time.Time.Format

@goccy is this type of pprof you need?

@orisano
Copy link
Contributor

orisano commented Feb 18, 2022

Maybe it is a memory profile. I think that we need a CPU profile.
Could you get a CPU profile?

@shahriar350
Copy link
Author

shahriar350 commented Feb 19, 2022

Maybe it is a memory profile. I think that we need a CPU profile. Could you get a CPU profile?

with ffjson:
Type: cpu
Time: Feb 19, 2022 at 5:47am (+06)
Duration: 30.01s, Total samples = 270ms ( 0.9%)

      flat  flat%   sum%        cum   cum%
      60ms 22.22% 22.22%       60ms 22.22%  runtime.cgocall
      20ms  7.41% 29.63%       30ms 11.11%  runtime.mallocgc
      20ms  7.41% 37.04%      100ms 37.04%  runtime.schedule
      20ms  7.41% 44.44%       20ms  7.41%  runtime.stdcall1
      20ms  7.41% 51.85%       20ms  7.41%  runtime.stdcall6
      10ms  3.70% 55.56%       30ms 11.11%  github.com/mattn/go-sqlite3._Cfunc__sqlite3_step_internal
      10ms  3.70% 59.26%       10ms  3.70%  github.com/pquerna/ffjson/ffjson.Marshal
      10ms  3.70% 62.96%       10ms  3.70%  runtime.gogo
      10ms  3.70% 66.67%       30ms 11.11%  runtime.netpoll
      10ms  3.70% 70.37%       10ms  3.70%  runtime.nextFreeFast (inline)

With go-json
Type: cpu
Time: Feb 19, 2022 at 5:44am (+06)
Duration: 30.02s, Total samples = 49.21s (163.94%)

      flat  flat%   sum%        cum   cum%
     1.24s  2.52% 83.26%      1.33s  2.70%  runtime.heapBits.next (inline)
     0.94s  1.91% 85.17%      0.94s  1.91%  indexbody
     0.83s  1.69% 86.85%      0.83s  1.69%  github.com/gofiber/fiber/v2/internal/go-json/encoder.(*Opcode).IsEnd
     0.79s  1.61% 88.46%      0.85s  1.73%  runtime.heapBitsSetType
     0.74s  1.50% 89.96%      0.74s  1.50%  runtime.duffcopy
     0.49s     1% 90.96%      1.53s  3.11%  strings.Index
     0.43s  0.87% 91.83%      0.81s  1.65%  runtime.bulkBarrierPreWrite
     0.31s  0.63% 92.46%      0.66s  1.34%  runtime.findObject

@orisano
Copy link
Contributor

orisano commented Feb 19, 2022

Thanks!
Could you also upload the profile file?

@shahriar350
Copy link
Author

go-json
gojson-pprof.samples.cpu.003.pb.gz

ffjson

ffjson.pprof.samples.cpu.004.pb.gz

Issue project:
https://github.com/shahriar350/eCommerceGolangNuxt-backend

@orisano
Copy link
Contributor

orisano commented Feb 19, 2022

I reproduced this issue.
Does this problem occur only on the first request?

@orisano
Copy link
Contributor

orisano commented Feb 19, 2022

My request's logs:

18:47:08 | 200 |  6.702s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:09 | 200 |     1ms |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:10 | 200 |     1ms |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:11 | 200 |     1ms |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:14 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:19 | 200 |     1ms |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:20 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:21 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:21 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:22 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:23 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:24 | 200 |     1ms |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:25 | 200 |     1ms |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:25 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:26 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products
18:47:27 | 200 |      0s |       127.0.0.1 | GET     | /api/nonuser/all/products

@shahriar350
Copy link
Author

shahriar350 commented Feb 19, 2022

I reproduced this issue. Does this problem occur only on the first request?

yes. first time when the server starts and idle for a long time. later it caches data and returns that.

@orisano
Copy link
Contributor

orisano commented Feb 19, 2022

My repro repo:
https://github.com/orisano/eCommerceGolangNuxt-backend

I think the reason is that when linkRecursiveCode is applied to recursiveCodes of length 2522, copyCode is executed 2522 times, which causes a lot of memory allocation and GC.

pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz

The performance of go-json may be poor for entc-generated types.

@goccy how should we solve this problem?

@shahriar350
Copy link
Author

shahriar350 commented Feb 19, 2022

My repro repo: https://github.com/orisano/eCommerceGolangNuxt-backend

I think the reason is that when linkRecursiveCode is applied to recursiveCodes of length 2522, copyCode is executed 2522 times, which causes a lot of memory allocation and GC.

The performance of go-json may be poor for entc-generated types.

@goccy how should we solve this problem?

I also tried with GORM orm. I faced the same problem. I thought about the problem with GORM but later after I changed my orm to EntGo, the issue still existed. but other json packages like ffjson, easyjson, std json all work good.

@goccy
Copy link
Owner

goccy commented Mar 4, 2022

I was able to figure out the problem. thank you :)
Also, I will think about how to resolve this problem 🤔

@goccy goccy added enhancement New feature or request performance labels Mar 4, 2022
@shahriar350
Copy link
Author

I was able to figure out the problem. thank you :) Also, I will think about how to resolve this problem 🤔

Great. @goccy . I hope you resolve that problem soon but could you please what is the issue occur in this problem?

@goccy
Copy link
Owner

goccy commented Mar 26, 2022

@shahriar350

This cause is mentioned by @orisano . Dedicated processing is performed when encoding a struct type with a recursive structure. At this time, the copy process runs, so if you target a struct type with many fields, it will take a long time to copy at first time only.

goccy added a commit that referenced this issue May 3, 2022
Improve performance on linkRecursiveCode
- cache linked recursive codes for compile
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request performance
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants