Support #20336
openosd_op_reply Input/output error
0%
Description
When I use cosbench test my rgw cluster.
I found than sometime request got 500 return code.
debug log:
2017-06-19 17:07:55.263045 7fc626cfa700 1 -- 10.26.69.3:0/561515496 <== osd.20 10.26.66.4:6811/4019816 2193 ==== osd_op_reply(431498 .dir.93029d3f-512b-497b-a0bf-b427d6d8b30d.6659035.63.14 [call] v18494'47969
uv47969 ondisk = 0) v7 ==== 175+0+0 (498142069 0 0) 0x7fc3b0002f10 con 0x7fc62c13c470
2017-06-19 17:07:55.263051 7fc2a93ef700 20 cache get: touching lru, lru_counter=92930 promotion_ts=92798
2017-06-19 17:07:55.263055 7fc2a93ef700 10 moving default.rgw.data.root+.bucket.meta.s3test16:93029d3f-512b-497b-a0bf-b427d6d8b30d.6651063.61 to cache LRU end
2017-06-19 17:07:55.263058 7fc2a93ef700 10 cache get: name=default.rgw.data.root+.bucket.meta.s3test16:93029d3f-512b-497b-a0bf-b427d6d8b30d.6651063.61 : hit (requested=22, cached=23)
2017-06-19 17:07:55.263057 7fc2a9bf0700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>ivanwa</ID><DisplayName>Ivan Wong</DisplayName>Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>ivanwa</ID><DisplayName>Ivan Wong</DisplayName></Grantee><Permission>FULL_CONTROL</Per
mission></Grant></AccessControlList></AccessControlPolicy>
2017-06-19 17:07:55.263065 7fc2a93ef700 20 get_system_obj_state: s->obj_tag was set empty
2017-06-19 17:07:55.263068 7fc2a93ef700 10 cache get: name=default.rgw.data.root+.bucket.meta.s3test16:93029d3f-512b-497b-a0bf-b427d6d8b30d.6651063.61 : hit (requested=17, cached=23)
2017-06-19 17:07:55.263070 7fc2a9bf0700 2 req 97362:0.000875:s3:PUT /s3test93/myobjects59:put_obj:recalculating target
2017-06-19 17:07:55.263075 7fc2a9bf0700 2 req 97362:0.000881:s3:PUT /s3test93/myobjects59:put_obj:reading permissions
2017-06-19 17:07:55.263078 7fc2a9bf0700 2 req 97362:0.000884:s3:PUT /s3test93/myobjects59:put_obj:init op
2017-06-19 17:07:55.263081 7fc2a9bf0700 2 req 97362:0.000887:s3:PUT /s3test93/myobjects59:put_obj:verifying op mask
2017-06-19 17:07:55.263084 7fc2a9bf0700 20 required_mask= 2 user.op_mask=7
2017-06-19 17:07:55.263070 7fc435cdc700 1 -- 10.26.69.3:0/561515496 <== osd.150 10.26.66.26:6804/3185772 4996 ==== osd_op_reply(431503 .dir.93029d3f-512b-497b-a0bf-b427d6d8b30d.6651063.50.14 [call] v0'0 uv0 on
disk = 5 ((5) Input/output error)) v7 ==== 175+0+0 (111091176 0 0) 0x7fc58c02f220 con 0x7fc62c13b100
2017-06-19 17:07:55.263086 7fc2a93ef700 20 bucket index object: .dir.93029d3f-512b-497b-a0bf-b427d6d8b30d.6651063.61.11
2017-06-19 17:07:55.263086 7fc2a9bf0700 2 req 97362:0.000892:s3:PUT /s3test93/myobjects59:put_obj:verifying op permissions
2017-06-19 17:07:55.263090 7fc2a9bf0700 5 Searching permissions for uid=ivanwa mask=50
2017-06-19 17:07:55.263092 7fc2a9bf0700 5 Found permission: 15
2017-06-19 17:07:55.263094 7fc2a9bf0700 5 Searching permissions for group=1 mask=50
2017-06-19 17:07:55.263095 7fc2a9bf0700 5 Permissions for group not found
2017-06-19 17:07:55.263097 7fc2a9bf0700 5 Searching permissions for group=2 mask=50
2017-06-19 17:07:55.263099 7fc2a9bf0700 5 Permissions for group not found
2017-06-19 17:07:55.263100 7fc2a9bf0700 5 Getting permissions id=ivanwa owner=ivanwa perm=2
2017-06-19 17:07:55.263102 7fc2a9bf0700 10 uid=ivanwa requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
2017-06-19 17:07:55.263104 7fc2a9bf0700 2 req 97362:0.000910:s3:PUT /s3test93/myobjects59:put_obj:verifying op params
2017-06-19 17:07:55.263109 7fc2a9bf0700 2 req 97362:0.000915:s3:PUT /s3test93/myobjects59:put_obj:pre-executing
2017-06-19 17:07:55.263112 7fc2a9bf0700 2 req 97362:0.000918:s3:PUT /s3test93/myobjects59:put_obj:executing
2017-06-19 17:07:55.263114 7fc2a93ef700 1 - 10.26.69.3:0/561515496 --> 10.26.66.2:6800/4184025 -- osd_op(client.6659035.0:431508 141.563bc7c6 .dir.93029d3f-512b-497b-a0bf-b427d6d8b30d.6651063.61.11 [call rgw.
bucket_prepare_op] snapc 0=[] ondisk+write+known_if_redirected e18494) v7 -- ?+0 0x7fc56c045f80 con 0x7fc62c1fb4c0
2017-06-19 17:07:55.263164 7fc2ae3f9700 2 req 97361:0.002756:s3:PUT /s3test90/myobjects94:put_obj:completing
2017-06-19 17:07:55.263171 7fc2ae3f9700 0 WARNING: set_req_state_err err_no=5 resorting to 500
2017-06-19 17:07:55.263239 7fc2ae3f9700 2 req 97361:0.002834:s3:PUT /s3test90/myobjects94:put_obj:op status=-5
2017-06-19 17:07:55.263242 7fc2ae3f9700 2 req 97361:0.002837:s3:PUT /s3test90/myobjects94:put_obj:http status=500
2017-06-19 17:07:55.263249 7fc2ae3f9700 1 ====== req done req=0x7fc2ae3f37e0 op status=-5 http_status=500 ======
2017-06-19 17:07:55.263264 7fc2ae3f9700 20 process_request() returned -5
2017-06-19 17:07:55.263291 7fc2ae3f9700 1 civetweb: 0x7fc54400a520: 10.26.69.3 - - [19/Jun/2017:17:07:55 +0800] "PUT /s3test90/myobjects94 HTTP/1.1" 500 0 - aws-sdk-java/1.10.76 Linux/3.13.0-106-generic Java_H
otSpot(TM)_64-Bit_Server_VM/24.45-b08/1.7.0_45
*I used smartctl check the osd disk.The test pass without any error.
Otherwise,I used 1M object size test the cluster.Run after a period of time will appear a lot of slow request, then the interval after 30 s recovery.*
Timestamp Op-Count Byte-Count Avg-ResTime Avg-ProcTime Throughput Bandwidth Succ-Ratio
(Version)
write write write write write write
18:27:14 3.27 kops 3.27 GB 186.75 ms 140.87 ms 647.48 op/s 647.48 MB/S 100%
18:27:19 2.37 kops 2.37 GB 211.71 ms 163.14 ms 434.8 op/s 434.8 MB/S 100%
18:27:24 120 ops 120 MB 219.16 ms 183.84 ms 41.9 op/s 41.9 MB/S 100%
18:27:29 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:27:34 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:27:39 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:27:44 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:27:49 4.42 kops 4.42 GB 1416.33 ms 1389.55 ms 848.16 op/s 848.16 MB/S 100%
18:27:54 2.64 kops 2.64 GB 481.14 ms 436.87 ms 517.77 op/s 517.77 MB/S 100%
18:27:59 914 ops 914 MB 285.94 ms 241.94 ms 278.84 op/s 278.84 MB/S 100%
18:28:04 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:28:09 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:28:14 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:28:19 0 ops 0 B N/A N/A 0 op/s 0 B/S N/A
18:28:24 248 ops 248 MB 2761.53 ms 2719.27 ms 49 op/s 49 MB/S 100%
18:28:29 1.53 kops 1.53 GB 3686.56 ms 3660.71 ms 331.32 op/s 331.32 MB/S 100%
18:28:34 2.86 kops 2.86 GB 329.32 ms 289.53 ms 540.57 op/s 540.57 MB/S 100%