Project

General

Profile

Bug #22408

objecter: sent out of order ops

Added by Sage Weil over 6 years ago. Updated over 4 years ago.

Status:
Can't reproduce
Priority:
High
Assignee:
-
Category:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
Objecter
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

2017-12-04 21:46:49.492 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 47 ==== osd_op(client.4156.0:230 2.3c 2.f3bd5ebc (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 237+0+21 (1622976175 0 554963611) 0x5569a1eaad80 con 0x5569a29d7800
2017-12-04 21:46:49.492 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 48 ==== osd_op(client.4156.0:235 2.3e 2.950c2cfe (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 240+0+38 (814723537 0 1640650905) 0x5569a27829c0 con 0x5569a29d7800
2017-12-04 21:46:49.492 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 49 ==== osd_op(client.4156.0:240 2.2 2.5961bc42 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 246+0+0 (3225606758 0 0) 0x5569a2c15400 con 0x5569a29d7800
2017-12-04 21:46:49.492 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 50 ==== osd_op(client.4156.0:241 2.3c 2.f3bd5ebc (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 237+0+44 (3035202442 0 373528411) 0x5569a2c15400 con 0x5569a29d7800
2017-12-04 21:46:49.492 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 51 ==== osd_op(client.4156.0:242 2.3e 2.950c2cfe (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 240+0+20 (443886151 0 500188455) 0x5569a27850c0 con 0x5569a29d7800
2017-12-04 21:46:49.496 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 52 ==== osd_op(client.4156.0:245 2.38 2.ea225af8 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 236+0+0 (1353743976 0 0) 0x5569a22129c0 con 0x5569a29d7800
2017-12-04 21:46:49.496 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 53 ==== osd_op(client.4156.0:251 2.38 2.ea225af8 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 312+0+56 (629625142 0 1571237320) 0x55699f4f36c0 con 0x5569a29d7800
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 54 ==== osd_op(client.4156.0:254 2.b 2.1aa4ad4b (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 246+0+0 (3418490765 0 0) 0x5569a2213d40 con 0x5569a29d7800
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 55 ==== osd_op(client.4156.0:256 2.38 2.ea225af8 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 274+0+43 (186144397 0 2537278725) 0x55699fa24a40 con 0x5569a29d7800
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 1 ==== osd_op(client.4156.0:256 2.38 2.ea225af8 (undecoded) ondisk+retry+read+known_if_redirected e32) v9 ==== 274+0+43 (3458823427 0 2537278725) 0x5569a1ea9040 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 2 ==== osd_op(client.4156.0:260 2.b 2.1aa4ad4b (undecoded) ondisk+retry+read+known_if_redirected e32) v9 ==== 246+0+0 (3414267323 0 0) 0x5569a1ea8d00 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 3 ==== osd_op(client.4156.0:261 2.19 2.4178cd99 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 241+0+0 (1831279878 0 0) 0x5569a2214080 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 4 ==== osd_op(client.4156.0:262 2.26 2.b74753e6 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 230+0+0 (1836394690 0 0) 0x5569a2214700 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 5 ==== osd_op(client.4156.0:263 2.26 2.b74753e6 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 230+0+0 (3618589350 0 0) 0x5569a2215740 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 6 ==== osd_op(client.4156.0:264 2.3e 2.950c2cfe (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 240+0+0 (1522655644 0 0) 0x5569a2bea9c0 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 7 ==== osd_op(client.4156.0:265 2.1c 2.54f4921c (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 240+0+0 (3209458527 0 0) 0x5569a2bec080 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 8 ==== osd_op(client.4156.0:266 2.38 2.ea225af8 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 236+0+0 (1464743724 0 0) 0x5569a2bed0c0 con 0x5569a1a76700
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 9 ==== osd_op(client.4156.0:267 2.3c 2.f3bd5ebc (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 237+0+0 (1296420686 0 0) 0x5569a2becd80 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 10 ==== osd_op(client.4156.0:259 2.3c 2.f3bd5ebc (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 237+0+0 (1296420686 0 0) 0x5569a2beba00 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 11 ==== osd_op(client.4156.0:268 2.38 2.ea225af8 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 236+0+30 (3377207136 0 1005607131) 0x55699f4f36c0 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 12 ==== osd_op(client.4156.0:269 2.1c 2.54f4921c (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 240+0+38 (3019887187 0 2515421301) 0x5569a1ebba80 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 13 ==== osd_op(client.4156.0:270 2.38 2.ea225af8 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 236+0+44 (210015123 0 373528411) 0x5569a2c14080 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 14 ==== osd_op(client.4156.0:271 2.1c 2.54f4921c (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 240+0+20 (3973591687 0 4236338658) 0x5569a2785a80 con 0x5569a1a76700
2017-12-04 21:46:49.508 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 15 ==== osd_op(client.4156.0:272 2.3c 2.f3bd5ebc (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 313+0+56 (2758970976 0 1571237320) 0x5569a22129c0 con 0x5569a1a76700
2017-12-04 21:46:49.508 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 16 ==== osd_op(client.4156.0:273 2.3b 2.53b8a87b (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 245+0+0 (2099043904 0 0) 0x55699fa24a40 con 0x5569a1a76700
2017-12-04 21:46:49.508 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 17 ==== osd_op(client.4156.0:274 2.11 2.cc915e51 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 245+0+0 (1456165968 0 0) 0x5569a1ebba80 con 0x5569a1a76700
2017-12-04 21:46:49.508 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 18 ==== osd_op(client.4156.0:278 2.26 2.b74753e6 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 230+0+242 (1018421343 0 3626819466) 0x5569a253b0c0 con 0x5569a1a76700
2017-12-04 21:46:49.508 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 19 ==== osd_op(client.4156.0:280 2.3b 2.53b8a87b (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 245+0+0 (2099043904 0 0) 0x5569a2213d40 con 0x5569a1a76700
2017-12-04 21:46:49.508 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 20 ==== osd_op(client.4156.0:281 2.11 2.cc915e51 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 245+0+0 (1456165968 0 0) 0x5569a2c15400 con 0x5569a1a76700
2017-12-04 21:46:49.512 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 21 ==== osd_op(client.4156.0:284 2.26 2.b74753e6 (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 230+0+242 (2573483893 0 2785313313) 0x5569a2bec3c0 con 0x5569a1a76700

note the ordering of op client.4156.0:259:
...
2017-12-04 21:46:49.500 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 9 ==== osd_op(client.4156.0:267 2.3c 2.f3bd5ebc (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 237+0+0 (1296420686 0 0) 0x5569a2becd80 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 10 ==== osd_op(client.4156.0:259 2.3c 2.f3bd5ebc (undecoded) ondisk+write+known_if_redirected e32) v9 ==== 237+0+0 (1296420686 0 0) 0x5569a2beba00 con 0x5569a1a76700
2017-12-04 21:46:49.504 7f1ea7d53700  1 -- 172.21.15.30:6805/26859 <== client.4156 172.21.15.41:0/2837864525 11 ==== osd_op(client.4156.0:268 2.38 2.ea225af8 (undecoded) ondisk+read+known_if_redirected e32) v9 ==== 236+0+30 (3377207136 0 1005607131) 0x55699f4f36c0 con 0x5569a1a76700
...

from grep 172.21.15.41:0/2837864525 remote/*/log/cluster1*osd.0* | grep '= osd_op'

/a/sage-2017-12-04_18:01:15-rbd-mimic-dev1-distro-basic-smithi/1927044

rbd/mirror-ha/{base/install.yaml cluster/{2-node.yaml openstack.yaml} msgr-failures/many.yaml objectstore/bluestore.yaml workloads/rbd-mirror-ha-workunit.yaml}

History

#1 Updated by Sage Weil over 6 years ago

/a/yuriw-2017-12-19_20:40:29-rbd-wip-yuri4-testing-2017-12-19-1722-distro-basic-smithi/1981037

rbd/basic/{base/install.yaml cachepool/small.yaml clusters/{fixed-1.yaml openstack.yaml} msgr-failures/many.yaml objectstore/bluestore-comp.yaml tasks/rbd_api_tests_old_format.yaml}

 -1366> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 5 ==== osd_op(client.4160.0:4433 12.7 12.913dbc27 (undecoded) ondisk+retry+read+known_if_redirected e190) v9 ==== 247+0+0 (3623162147 0 0) 0x55f75f3dd400 con 0x55f760a51100
 -1352> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 6 ==== osd_op(client.4160.0:4435 12.7 12.e419ca9f (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 240+0+0 (1814860787 0 0) 0x55f760661400 con 0x55f760a51100
 -1341> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 7 ==== osd_op(client.4160.0:4436 12.1 12.b7322459 (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 240+0+0 (2884958506 0 0) 0x55f762db8340 con 0x55f760a51100
 -1332> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 8 ==== osd_op(client.4160.0:4437 12.6 12.94bbfabe (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 240+0+0 (3567655662 0 0) 0x55f75f558340 con 0x55f760a51100
 -1322> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 9 ==== osd_op(client.4160.0:4438 12.7 12.57b0fa0f (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (3434865760 0 0) 0x55f75f53dd40 con 0x55f760a51100
 -1309> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 10 ==== osd_op(client.4160.0:4439 12.7 12.ee77a3d7 (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (3448361571 0 0) 0x55f760cd23c0 con 0x55f760a51100
 -1301> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 11 ==== osd_op(client.4160.0:4440 12.6 12.3780786 (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 236+0+0 (2671723489 0 0) 0x55f76065fa00 con 0x55f760a51100
 -1293> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 12 ==== osd_op(client.4160.0:4441 12.6 12.52d0400e (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (1008990229 0 0) 0x55f761458d80 con 0x55f760a51100
 -1282> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 13 ==== osd_op(client.4160.0:4442 12.1 12.9c60b219 (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (1543442713 0 0) 0x55f761cbd400 con 0x55f760a51100
 -1273> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 14 ==== osd_op(client.4160.0:4443 12.7 12.57b0fa0f (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (1409167922 0 0) 0x55f761310d00 con 0x55f760a51100
  -795> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 15 ==== osd_op(client.4160.0:4434 12.7 12.ee77a3d7 (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (228387982 0 0) 0x55f75f53f400 con 0x55f760a51100
  -785> 2017-12-19 23:13:47.071 7fa36f044700  1 -- 172.21.15.51:6805/25672 <== client.4160 172.21.15.51:0/3725326423 16 ==== osd_op(client.4160.0:4444 12.7 12.ee77a3d7 (undecoded) ondisk+write+known_if_redirected e190) v9 ==== 237+0+0 (228387982 0 0) 0x55f764191040 con 0x55f760a51100

#2 Updated by Sage Weil over 6 years ago

  • Description updated (diff)

#3 Updated by Josh Durgin almost 6 years ago

  • Priority changed from Urgent to High
  • Component(RADOS) Objecter added

#4 Updated by Neha Ojha over 4 years ago

  • Status changed from 12 to Can't reproduce

Also available in: Atom PDF