Project

General

Profile

Bug #9558

Both op threads and dispatcher threads get hung even for few minutes during peering stage

Added by Zhi Zhang over 9 years ago. Updated almost 7 years ago.

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

0%

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

Description

During peering stage, op threads will handle peering event and check the missing objects in this function: bool PG::MissingLoc::add_source_info(...). The loop in this function could take long time if this OSD has been down for a long time. From my observation, some op threads and dispatcher threads are likely to get hung if there are some other op threads being in this loop to check the missing objects. When this happens, user traffic will get impact until peering is finished.

For example, we have 8 op threads and 2 dispatcher threads. 4 of 8 op threads are checking the missing objects of one pg for 3 min at peering stage.

See below two op threads log:
-----------------------------------------------------
7fe37f423700

2014-09-21 08:32:40.938082 7fe37f423700 10 osd.28 pg_epoch: 4781 pg[4.29as0( v 4778'21495 lc 4739'19488 (2445'16487,4778'21495] local-les=4781 n=21494 ec=179 les/c 4745/4749 4780/4780/4780) [28,39,63,33,157,41,61,43,115,172,10] r=0 lpr=4780 pi=179-4779/2 crt=4778'21495 lcod 0'0 mlcod 0'0 inactive m=2007 u=2007] needs_recovery primary has 2007 missing
2014-09-21 08:32:40.940536 7fe37f423700 10 osd.28 pg_epoch: 4781 pg[4.29as0( v 4778'21495 lc 4739'19488 (2445'16487,4778'21495] local-les=4781 n=21494 ec=179 les/c 4745/4749 4780/4780/4780) [28,39,63,33,157,41,61,43,115,172,10] r=0 lpr=4780 pi=179-4779/2 crt=4778'21495 lcod 0'0 mlcod 0'0 inactive m=2007 u=2007] search_for_missing b310029a/default.5210.84_ef07342af3a60c5755ca6d5545afa9a7/head//4 4764'20343 also missing on osd.28(0)
...
2014-09-21 08:35:06.367426 7fe37f423700 20 osd.28 pg_epoch: 4781 pg[4.29as0( v 4778'21495 lc 4739'19488 (2445'16487,4778'21495] local-les=4781 n=21494 ec=179 les/c 4745/4749 4780/4780/4780) [28,39,63,33,157,41,61,43,115,172,10] r=0 lpr=4780 pi=179-4779/2 crt=4778'21495 lcod 0'0 mlcod 0'0 inactive m=2007] needs_recovery_map missing ...
...
2014-09-21 08:35:06.403067 7fe37f423700 10 osd.28 pg_epoch: 4781 pg[4.29as0( v 4778'21495 lc 4739'19488 (2445'16487,4778'21495] local-les=4781 n=21494 ec=179 les/c 4745/4749 4780/4780/4780) [28,39,63,33,157,41,61,43,115,172,10] r=0 lpr=4780 pi=179-4779/2 crt=4778'21495 lcod 0'0 mlcod 0'0 inactive m=2007] state<Started/Primary/Active>: Activate Finished

7fe37ec22700

2014-09-21 08:32:40.795282 7fe37ec22700 10 osd.28 pg_epoch: 4781 pg[4.3f0s0( v 4778'21406 lc 4739'19433 (2411'16432,4778'21406] local-les=4781 n=21403 ec=179 les/c 4743/4746 4780/4780/4780) [28,96,100,31,165,19,49,98,51,124,123] r=0 lpr=4780 pi=179-4779/2 crt=4778'21406 lcod 0'0 mlcod 0'0 inactive m=1973 u=1973] needs_recovery primary has 1973 missing
2014-09-21 08:32:40.798003 7fe37ec22700 10 osd.28 pg_epoch: 4781 pg[4.3f0s0( v 4778'21406 lc 4739'19433 (2411'16432,4778'21406] local-les=4781 n=21403 ec=179 les/c 4743/4746 4780/4780/4780) [28,96,100,31,165,19,49,98,51,124,123] r=0 lpr=4780 pi=179-4779/2 crt=4778'21406 lcod 0'0 mlcod 0'0 inactive m=1973 u=1973] search_for_missing b47003f0/default.5206.700_c3ab5902ec6abc1141342cb6bba482ac/head//4 4764'19475 also missing on osd.28(0)
...
2014-09-21 08:35:00.552196 7fe37ec22700 20 osd.28 pg_epoch: 4781 pg[4.3f0s0( v 4778'21406 lc 4739'19433 (2411'16432,4778'21406] local-les=4781 n=21403 ec=179 les/c 4743/4746 4780/4780/4780) [28,96,100,31,165,19,49,98,51,124,123] r=0 lpr=4780 pi=179-4779/2 crt=4778'21406 lcod 0'0 mlcod 0'0 inactive m=1973] needs_recovery_map missing ...
...
2014-09-21 08:35:00.588682 7fe37ec22700 10 osd.28 pg_epoch: 4781 pg[4.3f0s0( v 4778'21406 lc 4739'19433 (2411'16432,4778'21406] local-les=4781 n=21403 ec=179 les/c 4743/4746 4780/4780/4780) [28,96,100,31,165,19,49,98,51,124,123] r=0 lpr=4780 pi=179-4779/2 crt=4778'21406 lcod 0'0 mlcod 0'0 inactive m=1973] state<Started/Primary/Active>: Activate Finished
-----------------------------------------------------

During this time, some other op threads and dispatcher threads get hung at around 08:32:41.

See below two op threads log:
-----------------------------------------------------
7fe380c26700

2014-09-21 08:32:41.013130 7fe380c26700 20 -- 10.193.207.112:6800/43992 submit_message osd_pgtemp(e4781 {5.3a0=[33,62]} v4781) v1 remote, 10.193.207.55:6789/0, have pipe.
2014-09-21 08:35:00.645582 7fe380c26700 10 osd.28 pg_epoch: 4781 pg[6.71( empty local-les=4781 n=0 ec=269 les/c 4743/4743 4780/4780/4780) [28,79,155] r=0 lpr=4780 pi=269-4779/2 crt=0'0 mlcod 0'0 inactive] handle_peering_event: epoch_sent: 4781 epoch_requested: 4781 FlushedEvt
...
2014-09-21 08:37:40.661077 7fe380c26700 10 osd.28 pg_epoch: 4785 pg[4.934s0( v 4778'21363 lc 4739'19394 (2437'16393,4778'21363] local-les=4785 n=21361 ec=179 les/c 4743/4744 4780/4780/4780) [28,156,50,10,20,132,91,16,1,149,71] r=0 lpr=4780 pi=1790-4779/2 crt=4778'21363 lcod 0'0 mlcod 0'0 inactive m=1969 u=1969] needs_recovery primary has 1969 missing
...
2014-09-21 08:38:36.956887 7fe380c26700 10 osd.28 pg_epoch: 4785 pg[4.934s0( v 4778'21363 lc 4739'19394 (2437'16393,4778'21363] local-les=4785 n=21361 ec=179 les/c 4743/4744 4780/4780/4780) [28,156,50,10,20,132,91,16,1,149,71] r=0 lpr=4780 pi=1790-4779/2 crt=4778'21363 lcod 0'0 mlcod 0'0 inactive m=1969 u=1969] search_for_missing 3a005934/default.5207.323_f28745b0eaeb60427213ca988382613e/head//4 4764'19903 is on osd.50(2)
...

7fe380425700

2014-09-21 08:32:40.996011 7fe380425700 20 -- 10.193.207.112:6800/43992 submit_message osd_pgtemp(e4781 {5.3a0=[33,62]} v4781) v1 remote, 10.193.207.55:6789/0, have pipe.
2014-09-21 08:37:33.184623 7fe380425700 10 osd.28 pg_epoch: 4781 pg[7.297( v 280'6 (0'0,280'6] local-les=272 n=6 ec=271 les/c 4743/4743 4780/4780/271) [96,28,164] r=1 lpr=4780 pi=271-4779/2 crt=280'4 lcod 0'0 inactive NOTIFY] handle_peering_event: epoch_sent: 4781 epoch_requested: 4781 MInfoRec from 96 info: 7.297( v 280'6 (0'0,280'6] local-les=4781 n=6 ec=271 les/c 4743/4743 4780/4780/271)
...
2014-09-21 08:37:39.670059 7fe380425700 10 osd.28 pg_epoch: 4785 pg[4.921s0( v 4778'21405 lc 4739'19426 (2427'16425,4778'21405] local-les=4785 n=21402 ec=179 les/c 4743/4743 4780/4780/4780) [28,122,167,80,74,42,29,27,62,54,41] r=0 lpr=4780 pi=4728-4779/2 crt=4778'21405 lcod 0'0 mlcod 0'0 inactive m=1979 u=1979] needs_recovery primary has 1979 missing
...
2014-09-21 08:38:36.956036 7fe380425700 10 osd.28 pg_epoch: 4785 pg[4.921s0( v 4778'21405 lc 4739'19426 (2427'16425,4778'21405] local-les=4785 n=21402 ec=179 les/c 4743/4743 4780/4780/4780) [28,122,167,80,74,42,29,27,62,54,41] r=0 lpr=4780 pi=4728-4779/2 crt=4778'21405 lcod 0'0 mlcod 0'0 inactive m=1979 u=1979] search_for_missing 497e3921/default.5207.337_7a0b4dda6d1468977d3c82eeb34e155a/head//4 4764'20378 is on osd.54(9)
...
-----------------------------------------------------

See below two dispatcher threads log:
-----------------------------------------------------
7fe388c36700

2014-09-21 08:32:42.367682 7fe388c36700 1 -- 10.193.207.112:6800/43992 <== client.25368 10.193.244.203:0/1005057 1 ==== osd_op(client.25368.0:11052443 default.5208.270_osd9.ceph.mobstor.bf1.yahoo.com_1b52bc5d8e3946e5a324f50fd7a007fa [getxattrs,stat,read 0~5898240] 4.509edc63 ack+read e4783) v4 ==== 308+0+0 (1007697035 0 0) 0x3b31a900 con 0x3e124840
2014-09-21 08:37:33.180772 7fe388c36700 10 osd.28 4781 do_waiters -- start
2014-09-21 08:37:33.180782 7fe388c36700 10 osd.28 4781 do_waiters -- finish
2014-09-21 08:37:33.180784 7fe388c36700 20 osd.28 4781 _dispatch 0x3b31a900 osd_op(client.25368.0:11052443 default.5208.270_1b52bc5d8e3946e5a324f50fd7a007fa [getxattrs,stat,read 0~5898240] 4.509edc63 ack+read e4783) v4

7fe387c34700

2014-09-21 08:32:40.590328 7fe387c34700 7 osd.28 4781 handle_pg_notify from osd.127
2014-09-21 08:32:40.590332 7fe387c34700 15 osd.28 4781 require_same_or_newer_map 4781 (i am 4781) 0x3b12f180
2014-09-21 08:34:58.790976 7fe387c34700 10 osd.28 4781 do_waiters -- start
2014-09-21 08:34:58.790980 7fe387c34700 10 osd.28 4781 do_waiters -- finish
2014-09-21 08:34:58.790986 7fe387c34700 10 -- 10.193.207.112:6801/43992 dispatch_throttle_release 2873 to dispatch throttler 104585312/104857600
-----------------------------------------------------

History

#1 Updated by Zhi Zhang over 9 years ago

More info:

When OSD daemon/host is down, some PGs becomes active+degrade, while others are still active+clean. As long as PG is active, it can serve requests normally.

When OSD daemon/host is rejoined, those active+degraded PGs will start to peering. Their states could be inactive, peering, remapped, remapped+peering, etc, before it becomes active. When PG is not active, it can still receive requests but can't process them as normal. It will queue the request into wait_for_active list for retrying until this PG is active at least.

But as mentioned in original description, peering will take long time to finish if the missing object's gap is large, e.g, being down for a long time. And even some PGs is still inactive for a long time because previous PGs are not finished.

So more and more requests will be in wait_for_active list and can't reply to rgw. More and more rgw threads will get hung because of this so that user will get 500 error. And finally all the rgw threads will time out.

#2 Updated by Guang Yang about 9 years ago

A pull request to improve the search for missing process - https://github.com/ceph/ceph/pull/3919

#3 Updated by Sage Weil almost 7 years ago

  • Status changed from New to Can't reproduce

Also available in: Atom PDF