喜迎
元旦
解决一次rgw线程数不足引发的问题 | 奋斗的松鼠 - Blog

解决一次rgw线程数不足引发的问题

字数统计: 3.4k字   |   阅读时长≈ 16分

最近ceph集群发生了一些比较奇怪的现象，搬去另外一个机房的那套集群在恢复正常业务之后，一直有一些问题

写在前面

松鼠哥的ceph专业课程上线啦！
面向新手同学，从0实战，全面入门ceph安装部署与运维，有需要的同学赶紧扫码订购吧：

完成测试后接入实际的业务流量，测试时未能发现的问题在业务运行过程中出现了。

问题现象

问题是由前端业务写入不顺利开始的，前端大量写入图片的程序开始频繁出现TCP连接超时的报错，并伴有不少HTTP 500的错误，目前我们的写行为比较单纯，两套集群写入量是五五开的，但是，一旦有某套集群写入有问题，就会自动剔除该集群的写入，写入量会全部转移到另外一个无问题的集群

排查过程

刚开始，怀疑是两端服务器tcp连接数不够导致，其中ceph这边的tcp连接数被设置成很大，而且搬迁前后并没有发生改动，使用命令统计了一下tcp的连接，未见有超出的现象

在搬迁完成后，我们趁着机器重新开机前，加装了64G内存，从而设备内存增长到314G，由于设备此前使用的是单根64G的内存，所以就直接加装了一根64G的内存，排查发现，numa的内存分布及其不合理，未加内存的node内存被耗尽，另外一个node则空闲很多，会不会是因为部分跑在未加内存的node上，跨node访问引发了性能问题？

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
[root@ceph-52-204 tanweijie]# numactl -H
available: 2 nodes (0-1)
node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 28 29 30 31 32 33 34 35 36 37 38 39 40 41
node 0 size: 196287 MB
node 0 free: 55018 MB
node 1 cpus: 14 15 16 17 18 19 20 21 22 23 24 25 26 27 42 43 44 45 46 47 48 49 50 51 52 53 54 55
node 1 size: 131072 MB
node 1 free: 258 MB
node distances:
node   0   1
  0:  10  21
  1:  21  10
[root@ceph-52-204 tanweijie]# numastat -s

Per-node numastat info (in MBs):
                          Node 0          Node 1           Total
                 --------------- --------------- ---------------
Numa_Hit             53338359.98     15053454.36     68391814.34
Local_Node           53335831.25     15053010.53     68388841.78
Other_Node             792211.51          519.39       792730.90
Numa_Miss              789682.78           75.56       789758.34
Numa_Foreign               75.56       789682.78       789758.34
Interleave_Hit            421.43          422.21          843.64

不管是不是这原因，内存分布如果不均匀导致numa的miss很高，也是异常情况，所以做出了调整，将跑在node1上的5个osd调到node0上跑，均衡一下内存使用，确认每个node都剩余超过20G内存后，跑了一晚，竟然好了！没有再出现500错误和连接超时。

在我们要举杯欢庆的时候，白天10点后业务高峰来到后，又开始陆续出现http 500和connection timeout的问题，看来高兴得太早了

后来又陆续怀疑是不是网络问题，我们写入客户端到集群使用了专线，专线最近一直也不稳定，有可能大量的丢包导致上传文件失败引发？而且，出问题的客户端使用的是aws-nodejs的客户端，会不会根这个sdk有关系？

经过排查，使用python boto持续长时间写入竟然不会有问题，那么很可能跟网络没有关系了，况且tcp通信正常的情况下，数据包不容易出现问题，那么是sdk的问题吗？有可能，不同的sdk使用的tcp方式可能有差异，python boto只需要一次连接，使用该连接就可以持续传输数据，看起来是用的长连接，如果nodejs使用的tcp是短连接的话，有可能是并发太高导致rgw扛不住，但是我们测试过，这种并发还是小儿科的，不会扛不住

求助社区

rgw的日志、系统、网络及内存配置等都排查过无果后，笔者将打开的rgw日志中，http 500的完整处理日志提交到了社区

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
2018-11-15 16:32:25.897665 7f187d57d700  1 ====== starting new request req=0x7f187d577110 =====
2018-11-15 16:32:25.897677 7f187d57d700  2 req 67835212:0.000011::PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665::initializing for trans_id = tx0000000000000040b154c-005bed2f19-4a9157-tupu-201-zone1
2018-11-15 16:32:25.897683 7f187d57d700 10 rgw api priority: s3=5 s3website=4
2018-11-15 16:32:25.897684 7f187d57d700 10 host=192.26.2.58
2018-11-15 16:32:25.897685 7f187d57d700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2018-11-15 16:32:25.897687 7f187d57d700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665
2018-11-15 16:32:25.897694 7f187d57d700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2018-11-15 16:32:25.897697 7f187d57d700 10 meta>> HTTP_X_AMZ_DATE
2018-11-15 16:32:25.897699 7f187d57d700 10 x>> x-amz-content-sha256:dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
2018-11-15 16:32:25.897701 7f187d57d700 10 x>> x-amz-date:20181115T083208Z
2018-11-15 16:32:25.897709 7f187d57d700 20 get_handler handler=22RGWHandler_REST_Obj_S3
2018-11-15 16:32:25.897711 7f187d57d700 10 handler=22RGWHandler_REST_Obj_S3
2018-11-15 16:32:25.897713 7f187d57d700  2 req 67835212:0.000047:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665::getting op 1
2018-11-15 16:32:25.897720 7f187d57d700 10 op=21RGWPutObj_ObjStore_S3
2018-11-15 16:32:25.897721 7f187d57d700  2 req 67835212:0.000055:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying requester
2018-11-15 16:32:25.897723 7f187d57d700 20 rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2018-11-15 16:32:25.897724 7f187d57d700 20 rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2018-11-15 16:32:25.897726 7f187d57d700 20 rgw::auth::s3::S3AnonymousEngine denied with reason=-1
2018-11-15 16:32:25.897727 7f187d57d700 20 rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::LocalEngine
2018-11-15 16:32:25.897732 7f187d57d700 10 v4 signature format = 7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897735 7f187d57d700 10 v4 credential format = HEREISMYACCESSKEY/20181115/us-east-1/s3/aws4_request
2018-11-15 16:32:25.897736 7f187d57d700 10 access key id = HEREISMYACCESSKEY
2018-11-15 16:32:25.897737 7f187d57d700 10 credential scope = 20181115/us-east-1/s3/aws4_request
2018-11-15 16:32:25.897749 7f187d57d700 10 canonical headers format = host:192.26.2.58:7480
x-amz-content-sha256:dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
x-amz-date:20181115T083208Z

2018-11-15 16:32:25.897751 7f187d57d700 10 payload request hash = dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
2018-11-15 16:32:25.897761 7f187d57d700 10 canonical request = PUT
/2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665

host:192.26.2.58:7480
x-amz-content-sha256:dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
x-amz-date:20181115T083208Z

host;x-amz-content-sha256;x-amz-date
dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
2018-11-15 16:32:25.897762 7f187d57d700 10 canonical request hash = bc606bfc44d01f8db7d94686ff02abf3a642af84a885c5ae7936bc319ecd006a
2018-11-15 16:32:25.897772 7f187d57d700 10 string to sign = AWS4-HMAC-SHA256
20181115T083208Z
20181115/us-east-1/s3/aws4_request
bc606bfc44d01f8db7d94686ff02abf3a642af84a885c5ae7936bc319ecd006a
2018-11-15 16:32:25.897783 7f187d57d700 10 delaying v4 auth
2018-11-15 16:32:25.897849 7f187d57d700 10 date_k    = ad45895410fc6277d9a3a70b2ed71d32e9834037482c2b6868f1fbf56f05b025
2018-11-15 16:32:25.897854 7f187d57d700 10 region_k  = 60ed98f8c01c34bc2d806e1eb7f48c57961117dd9a7aa3f4a64d1e32b426a0a1
2018-11-15 16:32:25.897859 7f187d57d700 10 service_k = 7c782408bcdcc759be1f83d973ce833243076e707ec1422584b7f81b8c012f17
2018-11-15 16:32:25.897864 7f187d57d700 10 signing_k = b26c41194026c05feaf64bb514440e07d4ac2598fec27c13a9e41aca1babf4a1
2018-11-15 16:32:25.897886 7f187d57d700 10 generated signature = 7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897887 7f187d57d700 15 string_to_sign=AWS4-HMAC-SHA256
20181115T083208Z
20181115/us-east-1/s3/aws4_request
bc606bfc44d01f8db7d94686ff02abf3a642af84a885c5ae7936bc319ecd006a
2018-11-15 16:32:25.897897 7f187d57d700 15 server signature=7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897898 7f187d57d700 15 client signature=7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897899 7f187d57d700 15 compare=0
2018-11-15 16:32:25.897903 7f187d57d700 20 rgw::auth::s3::LocalEngine granted access
2018-11-15 16:32:25.897904 7f187d57d700 20 rgw::auth::s3::AWSAuthStrategy granted access
2018-11-15 16:32:25.897907 7f187d57d700  2 req 67835212:0.000242:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:normalizing buckets and tenants
2018-11-15 16:32:25.897910 7f187d57d700 10 s->object=599a5b2f483442afa8fa65d8/15422706636870.6152642808670665 s->bucket=2018-11-15-16
2018-11-15 16:32:25.897912 7f187d57d700  2 req 67835212:0.000246:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:init permissions
2018-11-15 16:32:25.897925 7f187d57d700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>tupubi</ID><DisplayName>tupu-s3-system</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>tupubi</ID><DisplayName>tupu-s3-system</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2018-11-15 16:32:25.897939 7f187d57d700  2 req 67835212:0.000274:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:recalculating target
2018-11-15 16:32:25.897941 7f187d57d700  2 req 67835212:0.000276:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:reading permissions
2018-11-15 16:32:25.897943 7f187d57d700  2 req 67835212:0.000278:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:init op
2018-11-15 16:32:25.897945 7f187d57d700  2 req 67835212:0.000279:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying op mask
2018-11-15 16:32:25.897946 7f187d57d700 20 required_mask= 2 user.op_mask=7
2018-11-15 16:32:25.897947 7f187d57d700  2 req 67835212:0.000282:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying op permissions
2018-11-15 16:32:25.897949 7f187d57d700 20 -- Getting permissions begin with perm_mask=50
2018-11-15 16:32:25.897951 7f187d57d700  5 Searching permissions for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=tupubi, acct_name=tupu-s3-system, subuser=, perm_mask=15, is_admin=0) mask=50
2018-11-15 16:32:25.897954 7f187d57d700  5 Searching permissions for uid=tupubi
2018-11-15 16:32:25.897955 7f187d57d700  5 Found permission: 15
2018-11-15 16:32:25.897958 7f187d57d700  5 Searching permissions for group=1 mask=50
2018-11-15 16:32:25.897959 7f187d57d700  5 Permissions for group not found
2018-11-15 16:32:25.897960 7f187d57d700  5 Searching permissions for group=2 mask=50
2018-11-15 16:32:25.897961 7f187d57d700  5 Permissions for group not found
2018-11-15 16:32:25.897962 7f187d57d700  5 -- Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=tupubi, acct_name=tupu-s3-system, subuser=, perm_mask=15, is_admin=0), owner=tupubi, perm=2
2018-11-15 16:32:25.897964 7f187d57d700 10  identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=tupubi, acct_name=tupu-s3-system, subuser=, perm_mask=15, is_admin=0) requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
2018-11-15 16:32:25.897966 7f187d57d700  2 req 67835212:0.000300:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying op params
2018-11-15 16:32:25.897968 7f187d57d700  2 req 67835212:0.000302:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:pre-executing
2018-11-15 16:32:25.897969 7f187d57d700  2 req 67835212:0.000303:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:executing
2018-11-15 16:32:25.981901 7f184450b700  2 req 67833405:165.197798:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:completing
2018-11-15 16:32:25.981915 7f184450b700  0 WARNING: set_req_state_err err_no=5 resorting to 500
2018-11-15 16:32:25.982003 7f184450b700  2 req 67833405:165.197902:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:op status=-5
2018-11-15 16:32:25.982011 7f184450b700  2 req 67833405:165.197910:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:http status=500
2018-11-15 16:32:25.982025 7f184450b700  1 ====== req done req=0x7f1844505110 op status=-5 http_status=500 ======
2018-11-15 16:32:25.982049 7f184450b700 20 process_request() returned -5
2018-11-15 16:32:25.983337 7f184450b700  1 civetweb: 0x7f18fc366000: 192.25.52.186 - - [15/Nov/2018:16:29:40 +0800] "PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779 HTTP/1.1" 500 0 - aws-sdk-nodejs/2.262.1 linux/v8.9.3 promise
2018-11-15 16:32:25.983467 7f184450b700 20 CONTENT_LENGTH=373584
2018-11-15 16:32:25.983474 7f184450b700 20 CONTENT_TYPE=application/octet-stream
2018-11-15 16:32:25.983476 7f184450b700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=HEREISMYACCESSKEY/20181115/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=a7ad9fcf05040259956f952696f8f56ea2acdd32fffce0c9325f0b9ba405f7f6
2018-11-15 16:32:25.983480 7f184450b700 20 HTTP_CONNECTION=close
2018-11-15 16:32:25.983482 7f184450b700 20 HTTP_HOST=192.26.2.58:7480
2018-11-15 16:32:25.983485 7f184450b700 20 HTTP_USER_AGENT=aws-sdk-nodejs/2.262.1 linux/v8.9.3 promise
2018-11-15 16:32:25.983488 7f184450b700 20 HTTP_VERSION=1.1
2018-11-15 16:32:25.983490 7f184450b700 20 HTTP_X_AMZ_CONTENT_SHA256=2909e9c16ef46bc688b9a248a4885bc304b0168e56f4932d0b0b94d865c8b104
2018-11-15 16:32:25.983494 7f184450b700 20 HTTP_X_AMZ_DATE=20181115T083214Z
2018-11-15 16:32:25.983498 7f184450b700 20 REMOTE_ADDR=172.25.52.187
2018-11-15 16:32:25.983500 7f184450b700 20 REQUEST_METHOD=PUT
2018-11-15 16:32:25.983502 7f184450b700 20 REQUEST_URI=/2018-11-15-16/5b572e82878b01abf107dd7f/15422706736040.4062170427445626.jpg
2018-11-15 16:32:25.983505 7f184450b700 20 SCRIPT_URI=/2018-11-15-16/5b572e82878b01abf107dd7f/15422706736040.4062170427445626.jpg
2018-11-15 16:32:25.983506 7f184450b700 20 SERVER_PORT=7480

社区当晚就给了答复，The '165.197798' in this log output shows that it took over two minutes to complete. It's likely the client timed out and closed the connection. This doesn't look like a bug.，噢，在put_obj:completing中，165.197798表示该部分处理花费的时间，是的，花费了超过2分半钟，这导致客户端连接超时，断开连接，从而引发http 500

发现解决办法

其实从上面的分析，已经可以大致分析出问题，rgw处理请求太慢，这会导致连接超时或者现有连接出现http 500的现象，实际上，在运行了几个月后，写入的业务量相对于早期已经提高很多，所以在配置上已经跟不上处理的要求了

前端写入业务此前一直使用短连接进行写入，目的是优化每次的读写，然后实际使用时，长连接会使得http 500和timeout问题变得更严重，这里的问题暂时还没查清楚，但可以确定的是rgw的处理能力跟不上了，要调整的参数应该就是num_threads，关于这个参数，redhat和官方具体的解释是：

1
2
3
4
5
6
7
8
9
num_threads
官方解释：
Description:    Sets the number of threads spawned by Civetweb to handle incoming HTTP connections. This effectively limits the number of concurrent connections that the frontend can service.
Type:    Integer
Default:    rgw_thread_pool_size


redhat解释：
Number of worker threads. Civetweb handles each incoming connection in a separate thread. Therefore, the value of this option is effectively the number of concurrent HTTP connections Civetweb can handle.

这样看来，每个线程单独处理一个进来的连接，这就意味着，如果当前连接数已经饱和，新的连接则需要等待，如果一直等不到，就timeout，但即使等到了连接，因为线程的饱和，在处理请求的时候也可能因为资源的不足或者其他资源的占用导致无法即使响应，而引发http 500

为什么不是一开始就调大

在参数调优阶段，这个num_threads是经过笔者调整多次的，当时定的值是160，为什么不在一开始就调大呢？原因是调优阶段时使用的是cosbench和python bto来进行验证调试结果，cosbench在实际测试的时候，即使ops很高，也只能在一小段时间内得出结果，笔者对该参数设置为100、200、300、400的时候进行过对比发现在200左右，再调大该值，对性能没有贡献了，再调整几次，发现160左右能达到最佳性能，所以定了这个值，而boto使用的是长连接，对高并发的连接请求更是不能覆盖到。

现在看来，调优的测试工具也应该对场景覆盖多一些，另外，针对该值的调优可以看看这篇干货Ceph Rados Gateway Tuning

最终的解决

我们的解决方法就是

  • 1、将rgw的num_threads调大，最终调整到768
  • 2、给radosgw进程分配更多的cpu核，从原来的8核增加到12核
  • 3、针对tcp连接，优化net.ipv4.tcp_timestamps和net.ipv4.tcp_tw_recycle，使得连接能快速被回收

修改配置并全部生效后，未再发现http 500和timeout的问题

参考资料

Civetweb Configuration Options
HTTP FRONTENDS

赏

谢谢你请我吃糖果

支付宝
微信
  • 本文作者： 奋斗的松鼠
  • 本文链接： http://www.strugglesquirrel.com/2018/11/28/解决一次rgw线程数不足引发的问题/
  • 版权声明： 本博客所有文章除特别声明外，创作版权均为作者个人所有，未经允许禁止转载！

扫一扫，分享到微信

tag:

    缺失模块。
    1、请确保node版本大于6.2
    2、在博客根目录（注意不是yilia-plus根目录）执行以下命令：
    npm i hexo-generator-json-content --save

    3、在根目录_config.yml里添加配置： 

      jsonContent:
    meta: false
    pages: false
    posts:
      title: true
      date: true
      path: true
      text: false
      raw: false
      content: false
      slug: false
      updated: false
      comments: false
      link: false
      permalink: false
      excerpt: false
      categories: false
      tags: true

松鼠哥，存储研发专家
曾就职于深信服北京研发中心，负责存储相关产品的调研测试
在分布式存储领域深耕近十年，实战经验和理论经验功力深厚
累计管理及上线生产集群超过600个，机器超3万台，磁盘总数超过80万块，总容量达到EB级别。