pool is busy,can not get new client in 5 seconds,wait count is 1

[zut]

错误: Trace:pool is busy,can not get new client in 5 seconds,wait count is 1

我应该如何来解决这个问题？

谢谢

[seefan]

暂时没有发现你说的情况，你可以在显示错误信息时，调用goerr.Error(err).Trace()来显示更多的内容，我们可以根据仔细的信息来分析。

[zut]

暂时没有发现你说的情况，你可以在显示错误信息时，调用goerr.Error(err).Trace()来显示更多的内容，我们可以根据仔细的信息来分析。

详细错误是: Trace:pool is busy,can not get new client in 5 seconds,wait count is 1

本地测试, 基本没有并发.配置也是默认的.

c := &conf.Config{
		Host:      host,
		Port:      port,
		AutoClose: true,
	}

client info信息我打印出一些. 请看最后的回复

[seefan]

把你的代码发我一份吧，我测试一下

[zut]

把你的代码发我一份吧，我测试一下

在一个项目中用了. 无法单独出来发.

[zut]

为了方便测试,我timeout设置成2s
最后的回复,有 client info 更详细的信息.

是不是应为 AutoClose 导致的.你看这张图, cc.index 18 的时候没有自动关闭.

这时候响应时间变成了2s.

这个请求之后的 3分钟都没有问题.

---

3分钟后继续出现

再过1分钟,报错

如果可以,只指导排查方向,谢谢

[zut]

有更详细的信息了:

特征是:

1. 时间变长,
2. 再过一会,就会错误. Trace:pool is busy,can not get new client in 2 seconds,wait count is 1

GetClient true 19 available is 8,active is 60,wait is 0,connection count is 60,status is 1
Close 1 true 19 available is 8,active is 60,wait is 0,connection count is 60,status is 1
Close 2 false 19 available is 8,active is 59,wait is 0,connection count is 60,status is 1
GetClient true 19 available is 9,active is 60,wait is 0,connection count is 60,status is 1
2020-06-23 16:15:42.866 [WARN] [elapsed > 100ms] 200 /api/meas/dashboard 2.002142606s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:15:42.867 [DEBU] 200 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:17 
GetClient true 19 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 19 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 19 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:15:49.364 [DEBU] 200 OPTIONS /api/meas/dashboard                   < 1.middleware.Log mwLog.go:17 
GetClient true 19 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 19 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 19 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:15:51.418 [WARN] [elapsed > 100ms] 401 /api/meas/dashboard 2.000636574s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:15:51.418 [WARN] 401 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:15 
GetClient true 0 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 0 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 0 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:15:56.840 [DEBU] 200 OPTIONS /api/meas/dashboard                   < 1.middleware.Log mwLog.go:17 
GetClient true 0 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 0 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 0 available is 2,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:15:58.865 [WARN] [elapsed > 100ms] 401 /api/meas/dashboard 2.001977589s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:15:58.865 [WARN] 401 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:15 
GetClient true 1 available is 1,active is 61,wait is 0,connection count is 80,status is 1
Close 1 true 1 available is 1,active is 61,wait is 0,connection count is 80,status is 1
Close 2 false 1 available is 1,active is 60,wait is 0,connection count is 80,status is 1
2020-06-23 16:16:04.832 [DEBU] 200 OPTIONS /api/meas/dashboard                   < 1.middleware.Log mwLog.go:17 
GetClient true 2 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 2 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 2 available is 1,active is 60,wait is 0,connection count is 100,status is 1
GetClient true 1 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 1 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 1 available is 2,active is 60,wait is 0,connection count is 100,status is 1
GetClient true 3 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 3 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 3 available is 1,active is 60,wait is 0,connection count is 100,status is 1
GetClient true 2 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 2 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 2 available is 2,active is 60,wait is 0,connection count is 100,status is 1
GetClient true 4 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 4 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 4 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:10.863 [WARN] [elapsed > 100ms] 200 /api/meas/dashboard 4.007022137s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:16:10.863 [DEBU] 200 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:17 
GetClient true 3 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 3 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 3 available is 2,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:12.899 [DEBU] T2 elapsed =  2.00168s                            < 1.db.HGetTo hash.go:51  2.s.GetPlotData sMeas.go:157  3.handler.(*Handler).GetImg aImg.go:16 
2020-06-23 16:16:12.900 [ERRO] Text: Hget PlotData/100001_101__1_S2401_EIRP_20_LCH_1_1M__NTNV_SISO_2_0_0 error   Trace:pool is busy,can not get new client in 2 seconds,wait count is 1 < 1.db.HGetTo hash.go:53  2.s.GetPlotData sMeas.go:157  3.handler.(*Handler).GetImg aImg.go:16 
2020-06-23 16:16:12.901 [WARN] Hget PlotData/100001_101__1_S2401_EIRP_20_LCH_1_1M__NTNV_SISO_2_0_0 error < 1.handler.(*Handler).GetImg aImg.go:17  2.middleware.Auth mwAuth.go:24  3.middleware.ProcessTime middleware.go:11 
2020-06-23 16:16:12.902 [WARN] [elapsed > 100ms] 400 /api/img/100001_101__1_S2401_EIRP_20_LCH_1_1M__NTNV_SISO_2_0_0 2.004009257s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:16:12.902 [WARN] 400 GET /api/img/100001_101__1_S2401_EIRP_20_LCH_1_1M__NTNV_SISO_2_0_0 < 1.middleware.Log mwLog.go:15 
GetClient true 5 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 5 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 5 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:18.108 [DEBU] 200 OPTIONS /api/meas/dashboard                   < 1.middleware.Log mwLog.go:17 
GetClient true 4 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 4 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 4 available is 2,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:20.183 [WARN] [elapsed > 100ms] 401 /api/meas/dashboard 2.003259654s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:16:20.183 [WARN] 401 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:15 
GetClient true 6 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 6 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 6 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:25.514 [DEBU] 200 OPTIONS /api/meas/dashboard                   < 1.middleware.Log mwLog.go:17 
GetClient true 5 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 5 available is 2,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 5 available is 2,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:27.558 [WARN] [elapsed > 100ms] 401 /api/meas/dashboard 2.001992644s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:16:27.558 [WARN] 401 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:15 
GetClient true 7 available is 1,active is 61,wait is 0,connection count is 80,status is 1
Close 1 true 7 available is 1,active is 61,wait is 0,connection count is 80,status is 1
Close 2 false 7 available is 1,active is 60,wait is 0,connection count is 80,status is 1
2020-06-23 16:16:32.844 [DEBU] 200 OPTIONS /api/meas/dashboard                   < 1.middleware.Log mwLog.go:17 
GetClient true 6 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 6 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 6 available is 1,active is 60,wait is 0,connection count is 100,status is 1
2020-06-23 16:16:36.894 [DEBU] T2 elapsed =  2.000896s                           < 1.db.HGetTo hash.go:51  2.s.GetMeas sMeas.go:18  3.handler.(*Handler).GetMeasDashboard aMeas.go:48 
2020-06-23 16:16:36.895 [ERRO] Text: Hget Meas/100001 error      Trace:pool is busy,can not get new client in 2 seconds,wait count is 1 < 1.db.HGetTo hash.go:53  2.s.GetMeas sMeas.go:18  3.handler.(*Handler).GetMeasDashboard aMeas.go:48 
2020-06-23 16:16:36.896 [WARN] Hget Meas/100001 error                            < 1.handler.(*Handler).GetMeasDashboard aMeas.go:49  2.middleware.Auth mwAuth.go:24  3.middleware.ProcessTime middleware.go:11 
2020-06-23 16:16:36.896 [WARN] [elapsed > 100ms] 200 /api/meas/dashboard 2.003202975s < 1.middleware.ProcessTime middleware.go:14  2.middleware.CORS mwCors.go:7  3.middleware.Limit mwLimit.go:17 
2020-06-23 16:16:36.896 [DEBU] 200 GET /api/meas/dashboard                       < 1.middleware.Log mwLog.go:17 
GetClient true 8 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 1 true 8 available is 1,active is 61,wait is 0,connection count is 100,status is 1
Close 2 false 8 available is 1,active is 60,wait is 0,connection count is 100,status is 1

然后
我用简单代码测试发现, active 和 connection count 都不会上涨

[seefan]

我刚测试了一个小时，10个纯程在跑，并没有出现你说的问题。
我想确认以下内容，
1、你是如何获取连接的，是用NewClient还是GetClient
2、是否持有了获取的连接。

[zut]

@seefan 用了GetClient (是调用gossdb.Client())

请看代码：

func HSet(name, key, value interface{}) error {
	name2, err := cc(name)
	if err != nil {
		return err
	}
	key2, err := cc(key)
	if err != nil {
		return err
	}
	b, err := xx.Pack(value)
	if err != nil {
		return err
	}
	return gossdb.Client().HSet(name2, key2, b)
}


func HGetTo(name, key, value interface{}) error {
	name2, err := cc(name)
	if err != nil {
		return err
	}
	key2, err := cc(key)
	if err != nil {
		return err
	}
	xx.IsPointer(value)
	vPack, err := gossdb.Client().HGet(name2, key2)
	if err != nil {
		xlog.Error(goerr.Error(err).Trace())
		return err
	} else if len(vPack.Bytes()) == 0 {
		return ErrNotFound
	}
	return xx.UnpackTo(vPack.Bytes(), &value)
}

1. 用单个测试没有这样的问题,
2. 我是 GoFrame 的ghttp 搭建的 API服务, 你看我打印的日志, active 和 connection count 都不断上涨.

[seefan]

1、我看每次出错附近都这类似这样[WARN] [elapsed > 100ms]的提示，能大概描述一下这个错误是什么吗。
2、从日志中可以看到，每秒并发不高，只有1到2个，但有大量的active连接，这个说明连接是直在用，且没有被回收，是有这样的业务逻辑么。还是说是因为连接无法回收导致的active居高不下。
3、每一次获取范围保存的kv的值有多大，是否达到几M

Trace:pool is busy,can not get new client in 5 seconds,wait count is 1
这个提示是说连接池内没有可以使用的连接了，所以我们需要检查一下为什么连接在使用后无法回收。

[zut]

1 这个错误是每个请求的处理时间，你可以忽略。

2没有长时间连接的业务。

3 大约几百KB？我可以具体打印出来看看。而且是slob/zstd 压缩过的。

[zut]

请问你是如何判断回收的？
@seefan

[seefan]

通过Avaliable来控制，它是一个队列，我会把连接的位置放到队列里管理

[zut]

通过Avaliable来控制，它是一个队列，我会把连接的位置放到队列里管理

我看了一段时间log, 还没能解决.
目前已经关闭AutoClose, 还没有发现问题.