[wallet] sqlite write slow(>=200ms) somtime when read/write parallel / sqlite 数据库在并发读写的时候会有一定概率超过 200ms

[LinZexiao]

链服务模块 / Chain Service Components

• venus
• venus-auth
• venus-gateway
• venus-messager
• venus-miner
• 文档 / docs

订单服务模块 / Deal Service Components

• venus-market
• 文档 / docs

算力服务模块 / Storage Power Service Components

• venus-sector-manager
• venus-worker
• 文档 / docs

版本 / Version

v1.11.0

描述 / Describe the Bug

wallet 重启的时候会一直有 sql 执行 超过 200ms 的 log:

通过 benchmark 测试, 发现如果并发读写 sqlite 的时候, 就会有一定概率会遇到这个问题

func BenchmarkSignRecord(b *testing.B) {
	type StructA struct {
		ID        string `gorm:"primaryKey;type:varchar(256);not null"`
		CreatedAt time.Time
		Type      types.MsgType
		Signer    string            `gorm:"type:varchar(256);not null"`
		Err       string            `gorm:"type:varchar(256);default:null"`
		RawMsg    []byte            `gorm:"type:blob;default:null"`
		Signature *crypto.Signature `gorm:"embedded;embeddedPrefix:signature_"`
	}

	tempFile := os.TempDir() + "/sign_record.db"
	db, err := gorm.Open(sqlite.Open(tempFile), &gorm.Config{})
	assert.NoError(b, err)

	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		r := StructA{
			ID:        uuid.New().String(),
			RawMsg:    []byte("hellosagsyoudgfuaoweygfuaygswefahwsefgasidughfiuagsdoiufgauisod"),
			Err:       "error",
			Type:      types.MTVerifyAddress,
			CreatedAt: time.Now(),
		}
		db.Create(&r)
	}

}

func BenchmarkSignRecordParallel(b *testing.B) {
	type StructA struct {
		ID        string `gorm:"primaryKey;type:varchar(256);not null"`
		CreatedAt time.Time
		Type      types.MsgType
		Signer    string            `gorm:"type:varchar(256);not null"`
		Err       string            `gorm:"type:varchar(256);default:null"`
		RawMsg    []byte            `gorm:"type:blob;default:null"`
		Signature *crypto.Signature `gorm:"embedded;embeddedPrefix:signature_"`
	}

	tempFile := os.TempDir() + "/sign_record.db"
	db, err := gorm.Open(sqlite.Open(tempFile), &gorm.Config{})
	assert.NoError(b, err)

	db.AutoMigrate(&StructA{})

	b.ResetTimer()
	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			r := StructA{
				ID:        uuid.New().String(),
				RawMsg:    []byte("hellosagsyoudgfuaoweygfuaygswefahwsefgasidughfiuagsdoiufgauisod"),
				Err:       "error",
				Type:      types.MTVerifyAddress,
				CreatedAt: time.Now(),
			}
			db.Create(&r)
		}
	})
}

https://filecoinproject.slack.com/archives/C028PCH8L31/p1685271917299359

日志 / Logging Information

2023/05/28 18:58:19 /root/venus-wallet/storage/sqlite/sign_record.go:89 SLOW SQL >= 200ms
[1049.987ms] [rows:1] INSERT INTO `sign_record` (`id`,`created_at`,`type`,`signer`,`signature_type`,`signature_data`,`raw_msg`) VALUES ("3c8e223e-5570-45c3-aa7c-b204e6beb72d","2023-05-28 18:58:18.657","drawrandomparam","f3vztcuqxjpfhojsflilz3roqznqkvv5zczjxuqcmxgr7mhyeam757adpfuuukfybtf52yiqwkz6x6vr6aybca",NULL,NULL,"<binary>")

2023/05/28 18:58:48 /root/venus-wallet/storage/sqlite/sign_record.go:89 SLOW SQL >= 200ms
[541.314ms] [rows:1] INSERT INTO `sign_record` (`id`,`created_at`,`type`,`signer`,`signature_type`,`signature_data`,`raw_msg`) VALUES ("ff5a34a3-537c-4aed-9ace-d4bb5f4ce97f","2023-05-28 18:58:48.045","drawrandomparam","f3vztcuqxjpfhojsflilz3roqznqkvv5zczjxuqcmxgr7mhyeam757adpfuuukfybtf52yiqwkz6x6vr6aybca",NULL,NULL,"<binary>")

重现步骤 / Repo Steps

• https://filecoinproject.slack.com/archives/C028PCH8L31/p1685271917299359 (Slack)

[Fatman13]

这种无法复现的，要不咱们直接关了？可以用 close as not planned。估计之后也不太会看了。已经有结论的话，下次需求会再撸一遍也浪费时间。这个 close as not planned 里面本身包含了 cant repo 的 case。CC @elvin-du

[elvin-du]

签名的时候这个错误一直都有。

[LinZexiao]

在签名记录比较多，并且签名比较频繁的情形下，会出现慢查询的情况。

增加了 SignRecorder 配置项。

[SignRecorder]
  # 签名记录器，用于记录签名数据
Enable = true
KeepDuration = "168h"