Skip to content

osd: avoid two copy with same src cancel each other#39593

Merged
tchaikov merged 1 commit intoceph:masterfrom
mychoxin:fix_promote_dead_loop
Mar 8, 2021
Merged

osd: avoid two copy with same src cancel each other#39593
tchaikov merged 1 commit intoceph:masterfrom
mychoxin:fix_promote_dead_loop

Conversation

@mychoxin
Copy link
Copy Markdown
Contributor

@mychoxin mychoxin commented Feb 21, 2021

osd: avoid two copy with same src cancel each other and run into dead loop

For cache tier, if some head object has two snaps, the two snaps share the same clone object,
and the clone object was flush/evicted from cache pool, when a rollback requests and a read
snap request to these two snaps at the same time will generate two promote requests to the
same clone object, these two promote requests will generate two copy ops with same src, than
the second copy op will cancel the first copy op by calling cancel_copy and kick_object_context_blocked,
but after calling kick_object_context_blocked, a new promote request corresponding to first
copy op will be restarted and generate a new copy op, the new copy op will cancel the second
copy op again, so two promote requests will cancel their copy op each other and run into dead
loop.

Fixes: https://tracker.ceph.com/issues/49409

Signed-off-by: YuanXin yuanxin@didiglobal.com
Signed-off-by: mychoxin mychoxin@gmail.com

Checklist

  • References tracker ticket
  • Updates documentation if necessary
  • Includes tests for new functionality or reproducer for bug

Show available Jenkins commands
  • jenkins retest this please
  • jenkins test classic perf
  • jenkins test crimson perf
  • jenkins test signed
  • jenkins test make check
  • jenkins test make check arm64
  • jenkins test submodules
  • jenkins test dashboard
  • jenkins test api
  • jenkins test docs
  • jenkins render docs
  • jenkins test ceph-volume all
  • jenkins test ceph-volume tox

@github-actions github-actions Bot added the core label Feb 21, 2021
@mychoxin
Copy link
Copy Markdown
Contributor Author

@tchaikov please help to have a look

@mychoxin
Copy link
Copy Markdown
Contributor Author

@liewegas please help to have a look

@liewegas
Copy link
Copy Markdown
Member

I wonder if it would be cleaner to pull the kick_object_context_blocked(cop->obc); into the callers? There are only two:

  • start_copy wouldn't kick
  • cancel_copy_ops would. (It could be renamed cancel_and_kick_copy_ops for clarity)

@mychoxin mychoxin force-pushed the fix_promote_dead_loop branch 2 times, most recently from c24105e to c2318c6 Compare February 23, 2021 04:56
@mychoxin
Copy link
Copy Markdown
Contributor Author

@liewegas good idea, i have done, please help to review.

@liewegas liewegas changed the title avoid two copy with same src cancel each other osd: avoid two copy with same src cancel each other Feb 23, 2021
@liewegas
Copy link
Copy Markdown
Member

Code looks good. Is this a case you can reproduce? It would be great to add a test for it

@mychoxin
Copy link
Copy Markdown
Contributor Author

Let me try it.

@github-actions github-actions Bot added the tests label Feb 26, 2021
@mychoxin mychoxin force-pushed the fix_promote_dead_loop branch from a972035 to 2296f83 Compare February 26, 2021 13:32
@mychoxin
Copy link
Copy Markdown
Contributor Author

@liewegas I reproduced it and modified the description, not two rollback op, the first op is rollback and the second is read snap. Please help to review.

Copy link
Copy Markdown
Member

@liewegas liewegas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks right to me!

@liewegas liewegas requested a review from neha-ojha February 26, 2021 13:54
@mychoxin
Copy link
Copy Markdown
Contributor Author

@neha-ojha Please help to rewiew, thx.

@tchaikov

This comment has been minimized.

@mychoxin mychoxin force-pushed the fix_promote_dead_loop branch from 2296f83 to 88031b5 Compare February 27, 2021 15:40
@mychoxin
Copy link
Copy Markdown
Contributor Author

@tchaikov I have rebased it, is that ok?

@tchaikov
Copy link
Copy Markdown
Contributor

@mychoxin thanks! looks great!

@mychoxin mychoxin force-pushed the fix_promote_dead_loop branch from 80c890c to 9e77de1 Compare March 1, 2021 00:25
Copy link
Copy Markdown
Member

@neha-ojha neha-ojha left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

makes sense to me, @myoungwon @athanatos WDYT?

nit: the description in #39593 (comment) looks great, can we please add the same to the commit description as well?

For cache tier, if some head object has two snaps, the two snaps share the same clone object,
and the clone object was flush/evicted from cache pool, when a rollback requests and a read
snap request to these two snaps at the same time will generate two promote requests to the
same clone object, these two promote requests will generate two copy ops with same src, than
the second copy op will cancel the first copy op by calling cancel_copy and kick_object_context_blocked,
but after calling kick_object_context_blocked, a new promote request corresponding to first
copy op will be restarted and generate a new copy op, the new copy op will cancel the second
copy op again, so two promote requests will cancel their copy op each other and run into dead
loop.

Fixes: https://tracker.ceph.com/issues/49409

Signed-off-by: YuanXin <yuanxin@didiglobal.com>
@mychoxin mychoxin force-pushed the fix_promote_dead_loop branch from 9e77de1 to 617f711 Compare March 1, 2021 23:55
@mychoxin
Copy link
Copy Markdown
Contributor Author

mychoxin commented Mar 1, 2021

makes sense to me, @myoungwon @athanatos WDYT?

nit: the description in #39593 (comment) looks great, can we please add the same to the commit description as well?

done

@athanatos
Copy link
Copy Markdown
Contributor

LGTM

@myoungwon
Copy link
Copy Markdown
Member

lgtm

@mychoxin
Copy link
Copy Markdown
Contributor Author

mychoxin commented Mar 5, 2021

@liewegas Is there any question?

@tchaikov
Copy link
Copy Markdown
Contributor

tchaikov commented Mar 5, 2021

@mychoxin it's just pending on a rados suite run.

@tchaikov tchaikov self-assigned this Mar 7, 2021
@mychoxin
Copy link
Copy Markdown
Contributor Author

mychoxin commented Mar 8, 2021

ok, it tells ceph_test_rados Crashed, but no details show where it crashed at.

@athanatos
Copy link
Copy Markdown
Contributor

@myoungwon Can you help @mychoxin interpret the test failure?

@tchaikov
Copy link
Copy Markdown
Contributor

tchaikov commented Mar 8, 2021

@mychoxin @myoungwon following is an excerpt from /a//kchai-2021-03-07_12:30:50-rados-wip-kefu-testing-2021-03-07-1842-distro-basic-smithi/5944406/teuthology.log

2021-03-07T14:01:07.092 DEBUG:teuthology.orchestra.run.smithi085:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 30 ceph --cluster ceph --admin-daemon /var/run/ceph/ceph-osd.4.asok dump_ops_in_flight
2021-03-07T14:01:07.093 INFO:tasks.rados.rados.0.smithi083.stdout:2716:  finishing copy_from racing read to smithi08322634-40
2021-03-07T14:01:07.093 INFO:tasks.rados.rados.0.smithi083.stdout:2725:  finishing rollback tid 0 to smithi08322634-26
2021-03-07T14:01:07.093 INFO:tasks.rados.rados.0.smithi083.stdout:2716:  finishing copy_from to smithi08322634-40
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr:/build/ceph-17.0.0-1695-gd5f415b9/src/test/osd/RadosModel.h: In function 'virtual void CopyFromOp::_finish(TestOp::CallbackInfo*)' thread 7f5da9b02700 time 2021-03-07T14:01:06.784131+0000
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr:/build/ceph-17.0.0-1695-gd5f415b9/src/test/osd/RadosModel.h: 1938: FAILED ceph_assert(!version || comp->get_version64() == version)
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr: ceph version 17.0.0-1695-gd5f415b9 (d5f415b9b67a6d66ef39db91322ef188bb9f833e) quincy (dev)
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x14b) [0x7f5daff7f29d]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 2: (ceph::__ceph_assertf_fail(char const*, char const*, int, char const*, char const*, ...)+0) [0x7f5daff7f478]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 3: (CopyFromOp::_finish(TestOp::CallbackInfo*)+0x52b) [0x5627f03acefb]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 4: (write_callback(void*, void*)+0x19) [0x5627f03cb9a9]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 5: /usr/lib/librados.so.2(+0x99fc6) [0x7f5db8c6bfc6]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 6: /usr/lib/librados.so.2(+0xb3c25) [0x7f5db8c85c25]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 7: /usr/lib/librados.so.2(+0xb695f) [0x7f5db8c8895f]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 8: /usr/lib/librados.so.2(+0xb6c96) [0x7f5db8c88c96]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 9: /usr/lib/x86_64-linux-gnu/libstdc++.so.6(+0xbd6df) [0x7f5daf8326df]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 10: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f5dafb056db]

@myoungwon
Copy link
Copy Markdown
Member

@athanatos @tchaikov I'll take a look.

@tchaikov
Copy link
Copy Markdown
Contributor

tchaikov commented Mar 8, 2021

@mychoxin @myoungwon i am not able to reproduce the failure when rerunning of the failed test

@tchaikov
Copy link
Copy Markdown
Contributor

tchaikov commented Mar 8, 2021

@tchaikov tchaikov merged commit 1b36d57 into ceph:master Mar 8, 2021
@neha-ojha
Copy link
Copy Markdown
Member

@mychoxin @myoungwon following is an excerpt from /a//kchai-2021-03-07_12:30:50-rados-wip-kefu-testing-2021-03-07-1842-distro-basic-smithi/5944406/teuthology.log

2021-03-07T14:01:07.092 DEBUG:teuthology.orchestra.run.smithi085:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 30 ceph --cluster ceph --admin-daemon /var/run/ceph/ceph-osd.4.asok dump_ops_in_flight
2021-03-07T14:01:07.093 INFO:tasks.rados.rados.0.smithi083.stdout:2716:  finishing copy_from racing read to smithi08322634-40
2021-03-07T14:01:07.093 INFO:tasks.rados.rados.0.smithi083.stdout:2725:  finishing rollback tid 0 to smithi08322634-26
2021-03-07T14:01:07.093 INFO:tasks.rados.rados.0.smithi083.stdout:2716:  finishing copy_from to smithi08322634-40
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr:/build/ceph-17.0.0-1695-gd5f415b9/src/test/osd/RadosModel.h: In function 'virtual void CopyFromOp::_finish(TestOp::CallbackInfo*)' thread 7f5da9b02700 time 2021-03-07T14:01:06.784131+0000
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr:/build/ceph-17.0.0-1695-gd5f415b9/src/test/osd/RadosModel.h: 1938: FAILED ceph_assert(!version || comp->get_version64() == version)
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr: ceph version 17.0.0-1695-gd5f415b9 (d5f415b9b67a6d66ef39db91322ef188bb9f833e) quincy (dev)
2021-03-07T14:01:07.094 INFO:tasks.rados.rados.0.smithi083.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x14b) [0x7f5daff7f29d]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 2: (ceph::__ceph_assertf_fail(char const*, char const*, int, char const*, char const*, ...)+0) [0x7f5daff7f478]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 3: (CopyFromOp::_finish(TestOp::CallbackInfo*)+0x52b) [0x5627f03acefb]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 4: (write_callback(void*, void*)+0x19) [0x5627f03cb9a9]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 5: /usr/lib/librados.so.2(+0x99fc6) [0x7f5db8c6bfc6]
2021-03-07T14:01:07.095 INFO:tasks.rados.rados.0.smithi083.stderr: 6: /usr/lib/librados.so.2(+0xb3c25) [0x7f5db8c85c25]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 7: /usr/lib/librados.so.2(+0xb695f) [0x7f5db8c8895f]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 8: /usr/lib/librados.so.2(+0xb6c96) [0x7f5db8c88c96]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 9: /usr/lib/x86_64-linux-gnu/libstdc++.so.6(+0xbd6df) [0x7f5daf8326df]
2021-03-07T14:01:07.096 INFO:tasks.rados.rados.0.smithi083.stderr: 10: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f5dafb056db]

https://tracker.ceph.com/issues/49726 is showing up in almost every rados run on master after this PR merged. @mychoxin can you please address this?

@tchaikov
Copy link
Copy Markdown
Contributor

#40057 is created before we have a fix.

@athanatos
Copy link
Copy Markdown
Contributor

If it's that common, probably worth just reverting it.

@tchaikov
Copy link
Copy Markdown
Contributor

@athanatos pretty reproducible . see https://pulpito.ceph.com/kchai-2021-03-12_05:42:44-rados-wip-kefu-testing-2021-03-12-1106-distro-basic-smithi/5958481/.

just added Signed-off-by and Fixes tags to #40057. and will test it in my next batch.

@myoungwon
Copy link
Copy Markdown
Member

myoungwon commented Mar 12, 2021

@athanatos @tchaikov @neha-ojha
I think I found the root cause. Can you double-check this?
This seems like the sequence inversion because kick_object_context_blocked is moved to cancel_copy_ops().

Please look at the following.
During copy-from op in ceph_test_rados, it also issues the stat op to check racing read. So,

  1. copy-from to OID A
  2. stat to OID A
  3. The osd receives copy-from, then issue copy request to the target
  4. Stat is received, but it is blocked.
  5. Something happens, so recovery is triggered
  6. cancel_copy_ops() is called, so copy-from is canceled, then re-queued

At this point, the original code invokes kick_object_context_blocked(), then cop->cb->complete() in order.
So, this causes re-queueing blocked op by using enqueue_front(). In other words, kick_object_context_blocked()
enqueue old operation, and cop->cb->complete() enqueue current operation by using enqueue_front(). (note that this is
enqueue_front). But, with this PR, the functions are called in reverse order, which means the stat (as I described above) will be served before handling copy-from because it enqueues the first position in the queue.

So, I think we can avoid this and resolve the issue this PR posted via #40067 ?

@tchaikov
Copy link
Copy Markdown
Contributor

tchaikov commented Mar 12, 2021

@mychoxin just reverted this change in #40057

@myoungwon thanks for looking into this. at first glance, your analysis makes sense to me! but before your fix lands on master, i think we'd better address the test failure first. also, could you include this change in #40067? so we can test them at the same time?

@myoungwon
Copy link
Copy Markdown
Member

@tchaikov ok.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants