{"action":"created","issue":{"url":"https://api.github.com/repos/ceph/ceph/issues/21566","repository_url":"https://api.github.com/repos/ceph/ceph","labels_url":"https://api.github.com/repos/ceph/ceph/issues/21566/labels{/name}","comments_url":"https://api.github.com/repos/ceph/ceph/issues/21566/comments","events_url":"https://api.github.com/repos/ceph/ceph/issues/21566/events","html_url":"https://github.com/ceph/ceph/pull/21566","id":316329026,"node_id":"MDExOlB1bGxSZXF1ZXN0MTgzMTA4Nzk3","number":21566,"title":"mds: add drop_cache command","user":{"login":"rishabh-d-dave","id":10697359,"node_id":"MDQ6VXNlcjEwNjk3MzU5","avatar_url":"https://avatars1.githubusercontent.com/u/10697359?v=4","gravatar_id":"","url":"https://api.github.com/users/rishabh-d-dave","html_url":"https://github.com/rishabh-d-dave","followers_url":"https://api.github.com/users/rishabh-d-dave/followers","following_url":"https://api.github.com/users/rishabh-d-dave/following{/other_user}","gists_url":"https://api.github.com/users/rishabh-d-dave/gists{/gist_id}","starred_url":"https://api.github.com/users/rishabh-d-dave/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rishabh-d-dave/subscriptions","organizations_url":"https://api.github.com/users/rishabh-d-dave/orgs","repos_url":"https://api.github.com/users/rishabh-d-dave/repos","events_url":"https://api.github.com/users/rishabh-d-dave/events{/privacy}","received_events_url":"https://api.github.com/users/rishabh-d-dave/received_events","type":"User","site_admin":false},"labels":[{"id":144329802,"node_id":"MDU6TGFiZWwxNDQzMjk4MDI=","url":"https://api.github.com/repos/ceph/ceph/labels/cephfs","name":"cephfs","color":"b192ff","default":false},{"id":340048817,"node_id":"MDU6TGFiZWwzNDAwNDg4MTc=","url":"https://api.github.com/repos/ceph/ceph/labels/needs-review","name":"needs-review","color":"d4c5f9","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":18,"created_at":"2018-04-20T16:15:46Z","updated_at":"2018-07-19T21:47:24Z","closed_at":null,"author_association":"CONTRIBUTOR","pull_request":{"url":"https://api.github.com/repos/ceph/ceph/pulls/21566","html_url":"https://github.com/ceph/ceph/pull/21566","diff_url":"https://github.com/ceph/ceph/pull/21566.diff","patch_url":"https://github.com/ceph/ceph/pull/21566.patch"},"body":"Adds the command `drop cache` for MDS and an extra message so that client acknowledge to MDS that cache has been released. See - http://tracker.ceph.com/issues/23362"},"comment":{"url":"https://api.github.com/repos/ceph/ceph/issues/comments/406424526","html_url":"https://github.com/ceph/ceph/pull/21566#issuecomment-406424526","issue_url":"https://api.github.com/repos/ceph/ceph/issues/21566","id":406424526,"node_id":"MDEyOklzc3VlQ29tbWVudDQwNjQyNDUyNg==","user":{"login":"batrick","id":548304,"node_id":"MDQ6VXNlcjU0ODMwNA==","avatar_url":"https://avatars3.githubusercontent.com/u/548304?v=4","gravatar_id":"","url":"https://api.github.com/users/batrick","html_url":"https://github.com/batrick","followers_url":"https://api.github.com/users/batrick/followers","following_url":"https://api.github.com/users/batrick/following{/other_user}","gists_url":"https://api.github.com/users/batrick/gists{/gist_id}","starred_url":"https://api.github.com/users/batrick/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/batrick/subscriptions","organizations_url":"https://api.github.com/users/batrick/orgs","repos_url":"https://api.github.com/users/batrick/repos","events_url":"https://api.github.com/users/batrick/events{/privacy}","received_events_url":"https://api.github.com/users/batrick/received_events","type":"User","site_admin":false},"created_at":"2018-07-19T21:47:24Z","updated_at":"2018-07-19T21:47:24Z","author_association":"MEMBER","body":"@rishabh-d-dave it now works:\r\n\r\n````\r\n$ bin/ceph daemon mds.a cache drop\r\n*** DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***\r\n{\r\n    \"flush_journal\": {\r\n        \"message\": \"\",\r\n        \"return_code\": 0\r\n    },\r\n    \"cache\": {\r\n        \"pool\": {\r\n            \"items\": 169,\r\n            \"bytes\": 48936\r\n        }\r\n    }\r\n}\r\n````\r\n\r\nand from the log:\r\n\r\n````\r\n2018-07-19 17:41:43.418 7fad9f9ba700  1 mds.a asok_command: cache drop (starting...)\r\n2018-07-19 17:41:43.418 7fad9f9ba700  0 mds.0.server max_caps_per_client 0 < min_caps_per_client 100\r\n2018-07-19 17:41:43.418 7fad9f9ba700 10 mds.0.server recall_client_state 1, caps per client 100-101\r\n2018-07-19 17:41:43.418 7fad9f9ba700  0 mds.0.4  Sleeper r is 0\r\n2018-07-19 17:41:43.418 7fad9f9ba700  7 mds.0.cache trim bytes_used=47kB limit=1GB reservation=0.05% count=18446744073709551615\r\n2018-07-19 17:41:43.418 7fad9f9ba700  7 mds.0.cache trim_lru trimming 18446744073709551615 items from LRU size=10 mid=0 pintail=0 pinned=10\r\n2018-07-19 17:41:43.418 7fad9f9ba700  7 mds.0.cache trim_lru trimmed 0 items\r\n2018-07-19 17:41:43.418 7fad9f9ba700  7 mds.0.log _prepare_new_segment seq 2\r\n2018-07-19 17:41:43.418 7fad9f9ba700 10 mds.0.log Advancing to next stray directory on mds 0\r\n2018-07-19 17:41:43.418 7fad9f9ba700  7 mds.0.log _journal_segment_subtree_map\r\n2018-07-19 17:41:43.418 7fad9f9ba700 10 mds.0.cache create_subtree_map 2 subtrees, 2 fullauth\r\n2018-07-19 17:41:43.418 7fad9f9ba700 15 mds.0.cache show_subtrees\r\n2018-07-19 17:41:43.418 7fad9f9ba700 10 mds.0.cache |__ 0    auth [dir 0x1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741825|complete f() n() hs=0+0,ss=0+0 | subtree=1 dirty=0 authpin=0 0x701fcc6d00]\r\n2018-07-19 17:41:43.418 7fad9f9ba700 10 mds.0.cache |__ 0    auth [dir 0x100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741825|complete f(v0 10=0+10) n(v0 10=0+10) hs=10+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x701fcc7200]\r\n2018-07-19 17:41:43.418 7fad9f9ba700 15 mds.0.cache  subtree [dir 0x1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741825|complete f() n() hs=0+0,ss=0+0 | subtree=1 dirty=0 authpin=0 0x701fcc6d00]\r\n2018-07-19 17:41:43.418 7fad9f9ba700 15 mds.0.cache  subtree [dir 0x100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741825|complete f(v0 10=0+10) n(v0 10=0+10) hs=10+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x701fcc7200]\r\n2018-07-19 17:41:43.418 7fad9f9ba700 20 mds.0.journal EMetaBlob::add_dir_context final:\r\n2018-07-19 17:41:43.418 7fad9f9ba700 20 mds.0.journal EMetaBlob::add_dir_context final:\r\n2018-07-19 17:41:43.418 7fad9f9ba700 15 mds.0.cache  subtrees {0x1=[],0x100=[]}\r\n2018-07-19 17:41:43.418 7fad9f9ba700 15 mds.0.cache  ambiguous_subtrees\r\n2018-07-19 17:41:43.418 7fad969a8700  5 mds.0.log _submit_thread 4195196~872 : ESubtreeMap 2 subtrees , 0 ambiguous [metablob 0x1, 2 dirs]\r\n2018-07-19 17:41:43.418 7fad969a8700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6836/17378 -- osd_op(unknown.0.4:40 2.4 2:2e2fa760:::200.00000001:head [write 892~892 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e16) v8 -- 0x7020061a80 con 0\r\n2018-07-19 17:41:43.418 7fad969a8700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6836/17378 -- osd_op(unknown.0.4:41 2.4 2:292cf221:::200.00000000:head [writefull 0~90 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e16) v8 -- 0x702005e680 con 0\r\n2018-07-19 17:41:43.434 7fada01bb700  1 -- 127.0.0.1:6846/1607993607 <== osd.1 127.0.0.1:6836/17378 31 ==== osd_op_reply(40 200.00000001 [write 892~892 [fadvise_dontneed]] v16'9 uv9 ondisk = 0) v8 ==== 156+0+0 (1456679394 0 0) 0x702005e9c0 con 0x701fff1800\r\n2018-07-19 17:41:43.434 7fad971a9700 10 MDSIOContextBase::complete: 13C_MDL_Flushed\r\n2018-07-19 17:41:43.434 7fad971a9700 10 MDSIOContextBase::complete: 13C_MDL_Flushed\r\n2018-07-19 17:41:43.434 7fad971a9700 10 MDSInternalContextBase::complete: 25MDSInternalContextWrapper\r\n2018-07-19 17:41:43.434 7fad971a9700 10 MDSIOContextBase::complete: 12C_IO_Wrapper\r\n2018-07-19 17:41:43.434 7fad971a9700 10 MDSInternalContextBase::complete: 25MDSInternalContextWrapper\r\n2018-07-19 17:41:43.434 7fad9f9ba700  5 mds.0.4 _command_flush_journal: beginning segment expiry\r\n2018-07-19 17:41:43.434 7fad9f9ba700 10 mds.0.log trim_all: 2/0/0\r\n2018-07-19 17:41:43.434 7fad9f9ba700 10 mds.0.openfiles commit log_seq 2\r\n2018-07-19 17:41:43.434 7fad9f9ba700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6836/17378 -- osd_op(unknown.0.4:42 2.6 2:654134d2:::mds0_openfiles.0:head [omap-set-header] snapc 0=[] ondisk+write+known_if_redirected+full_force e16) v8 -- 0x70200f2000 con 0\r\n2018-07-19 17:41:43.434 7fad9f9ba700  6 mds.0.journal LogSegment(1/4194304).try_to_expire\r\n2018-07-19 17:41:43.434 7fad9f9ba700  4 mds.0.sessionmap save_if_dirty: writing 0\r\n2018-07-19 17:41:43.434 7fad9f9ba700  6 mds.0.journal LogSegment(1/4194304).try_to_expire success\r\n2018-07-19 17:41:43.434 7fad9f9ba700 10 mds.0.log try_expire expired segment 1/4194304\r\n2018-07-19 17:41:43.434 7fad9f9ba700  5 mds.0.log _expired segment 1/4194304, 1 events\r\n2018-07-19 17:41:43.434 7fad9f9ba700 10 mds.0.log _trim_expired_segments open file table committedseq 1 <= 1/4194304\r\n2018-07-19 17:41:43.434 7fad9f9ba700  5 mds.0.4 _command_flush_journal: waiting for 0 segments to expire\r\n2018-07-19 17:41:43.434 7fad9f9ba700  5 mds.0.4 _command_flush_journal: expiry complete, expire_pos/trim_pos is now 400000/400000\r\n2018-07-19 17:41:43.434 7fad9f9ba700 10 mds.0.log _trim_expired_segments open file table committedseq 1 <= 1/400000\r\n2018-07-19 17:41:43.434 7fad9f9ba700  5 mds.0.4 _command_flush_journal: trim complete, expire_pos/trim_pos is now 400000/400000\r\n2018-07-19 17:41:43.434 7fad9f9ba700  1 -- 127.0.0.1:6846/5fd80907 --> 127.0.0.1:6836/43e2 -- osd_op(unknown.0.4:2b 2.4 2:292cf221:::200.00000000:head [writefull 0~90 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e16) v8 -- 0x70200f2340 con 0\r\n2018-07-19 17:41:43.442 7fada01bb700  1 -- 127.0.0.1:6846/1607993607 <== osd.1 127.0.0.1:6836/17378 32 ==== osd_op_reply(41 200.00000000 [writefull 0~90 [fadvise_dontneed]] v16'10 uv10 ondisk = 0) v8 ==== 156+0+0 (3736483682 0 0) 0x702005e680 con 0x701fff1800\r\n2018-07-19 17:41:43.450 7fada01bb700  1 -- 127.0.0.1:6846/1607993607 <== osd.1 127.0.0.1:6836/17378 33 ==== osd_op_reply(43 200.00000000 [writefull 0~90 [fadvise_dontneed]] v16'11 uv11 ondisk = 0) v8 ==== 156+0+0 (2855701686 0 0) 0x702005e680 con 0x701fff1800\r\n2018-07-19 17:41:43.450 7fada01bb700  1 -- 127.0.0.1:6846/1607993607 <== osd.1 127.0.0.1:6836/17378 34 ==== osd_op_reply(42 mds0_openfiles.0 [omap-set-header] v16'5 uv5 ondisk = 0) v8 ==== 160+0+0 (3953806500 0 0) 0x702005e680 con 0x701fff1800\r\n2018-07-19 17:41:43.450 7fad971a9700 10 MDSIOContextBase::complete: 13C_IO_OFT_Save\r\n2018-07-19 17:41:43.450 7fad971a9700 10 mds.0.openfiles _commit_finish log_seq 2\r\n2018-07-19 17:41:43.450 7fad971a9700 10 MDSInternalContextBase::complete: 15C_OFT_Committed\r\n2018-07-19 17:41:43.450 7fad971a9700 10 mds.0.log _trim_expired_segments trimming expired 1/0x400000\r\n2018-07-19 17:41:43.450 7fad971a9700 10 mds.0.log _trim_expired_segments waiting for 2/4195196 to expire\r\n2018-07-19 17:41:43.450 7fad971a9700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6836/17378 -- osd_op(unknown.0.4:44 2.4 2:292cf221:::200.00000000:head [writefull 0~90 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e16) v8 -- 0x70200f2000 con 0\r\n2018-07-19 17:41:43.450 7fad9f9ba700  5 mds.0.4 _command_flush_journal: write_head complete, all done!\r\n2018-07-19 17:41:43.450 7fad9f9ba700  1 mds.a asok_command: cache drop (complete)\r\n````\r\n\r\nHOWEVER, if we're doing I/O from a client (`cp -av /usr .`), I've observed some form of deadlock:\r\n\r\n````\r\n2018-07-19 17:43:01.101 7fad9d1b5700  3 mds.0.server handle_client_session client_session(flushmsg_ack seq 55) v1 from client.4213\r\n2018-07-19 17:43:01.101 7fad9d1b5700  7 mds.0.4 mds has 1 queued contexts\r\n2018-07-19 17:43:01.101 7fad9d1b5700 10 mds.0.4 0x701fca06a0\r\n2018-07-19 17:43:01.101 7fad9d1b5700 10 mds.0.4  finish 0x701fca06a0\r\n2018-07-19 17:43:01.101 7fad9f9ba700  0 mds.0.4  Sleeper r is 0\r\n2018-07-19 17:43:01.101 7fad9f9ba700  7 mds.0.cache trim bytes_used=1MB limit=1GB reservation=0.05% count=18446744073709551615\r\n2018-07-19 17:43:01.101 7fad9f9ba700  7 mds.0.cache trim_lru trimming 18446744073709551615 items from LRU size=28 mid=0 pintail=10 pinned=28\r\n2018-07-19 17:43:01.101 7fad9f9ba700  7 mds.0.cache trim_lru trimmed 0 items\r\n2018-07-19 17:43:01.101 7fad9f9ba700  7 mds.0.log _prepare_new_segment seq 593\r\n2018-07-19 17:43:01.101 7fad9f9ba700 10 mds.0.log Advancing to next stray directory on mds 0\r\n2018-07-19 17:43:01.101 7fad9f9ba700  7 mds.0.log _journal_segment_subtree_map\r\n2018-07-19 17:43:01.101 7fad9f9ba700 10 mds.0.cache create_subtree_map 2 subtrees, 2 fullauth\r\n2018-07-19 17:43:01.101 7fad9f9ba700 15 mds.0.cache show_subtrees\r\n2018-07-19 17:43:01.101 7fad9f9ba700 10 mds.0.cache |__ 0    auth [dir 0x1 / [2,head] auth pv=17 v=13 cv=1/1 REP dir_auth=0 ap=2+269+270 state=1610874881|complete f(v0 m2018-07-19 17:42:57.617196 1=0+1)->f(v0 m2018-07-19 17:42:57.617196 1=0+1) n(v0 rc2018-07-19 17:42:57.768478 8=4+4)/n()->n(v0 rc2018-07-19 17:43:00.263541 b9 185=146+39)/n() hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x701fcc6d00]\r\n2018-07-19 17:43:01.101 7fad9f9ba700 10 mds.0.cache |__ 0    auth [dir 0x100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741825|complete f(v0 10=0+10) n(v0 10=0+10) hs=10+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x701fcc7200]\r\n2018-07-19 17:43:01.101 7fad9f9ba700 15 mds.0.cache  subtree [dir 0x1 / [2,head] auth pv=17 v=13 cv=1/1 REP dir_auth=0 ap=2+269+270 state=1610874881|complete f(v0 m2018-07-19 17:42:57.617196 1=0+1)->f(v0 m2018-07-19 17:42:57.617196 1=0+1) n(v0 rc2018-07-19 17:42:57.768478 8=4+4)/n()->n(v0 rc2018-07-19 17:43:00.263541 b9 185=146+39)/n() hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x701fcc6d00]\r\n2018-07-19 17:43:01.101 7fad9f9ba700 15 mds.0.cache  subtree [dir 0x100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741825|complete f(v0 10=0+10) n(v0 10=0+10) hs=10+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x701fcc7200]\r\n2018-07-19 17:43:01.101 7fad9f9ba700 20 mds.0.journal EMetaBlob::add_dir_context final:\r\n2018-07-19 17:43:01.101 7fad9f9ba700 20 mds.0.journal EMetaBlob::add_dir_context final:\r\n2018-07-19 17:43:01.101 7fad9f9ba700 15 mds.0.cache  subtrees {0x1=[],0x100=[]}\r\n2018-07-19 17:43:01.101 7fad9f9ba700 15 mds.0.cache  ambiguous_subtrees\r\n2018-07-19 17:43:01.101 7fad969a8700  5 mds.0.log _submit_thread 5056869~872 : ESubtreeMap 2 subtrees , 0 ambiguous [metablob 0x1, 2 dirs]\r\n2018-07-19 17:43:01.105 7fad969a8700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6836/17378 -- osd_op(unknown.0.4:50 2.4 2:2e2fa760:::200.00000001:head [write 75885~787572 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e16) v8 -- 0x70200f3040 con 0\r\n2018-07-19 17:43:01.105 7fad9d1b5700  1 -- 127.0.0.1:6846/1607993607 <== client.4213 127.0.0.1:0/2662882739 349 ==== client_request(client.4213:296 getattr pAsLsXsFs #0x1 2018-07-19 17:43:01.108858 caller_uid=0, caller_gid=0{0,}) v4 ==== 144+0+0 (1198522490 0 0) 0x70200f3040 con 0x7020066700\r\n2018-07-19 17:43:01.105 7fad9d1b5700  4 mds.0.server handle_client_request client_request(client.4213:296 getattr pAsLsXsFs #0x1 2018-07-19 17:43:01.108858 caller_uid=0, caller_gid=0{0,}) v4\r\n2018-07-19 17:43:01.105 7fad9d1b5700 20 mds.0.4 get_session have 0x70200cae00 client.4213 127.0.0.1:0/2662882739 state open\r\n2018-07-19 17:43:01.105 7fad9d1b5700 15 mds.0.server  oldest_client_tid=27\r\n2018-07-19 17:43:01.105 7fad9d1b5700  7 mds.0.cache request_start request(client.4213:296 cr=0x70200f3040)\r\n2018-07-19 17:43:01.105 7fad9d1b5700  7 mds.0.server dispatch_client_request client_request(client.4213:296 getattr pAsLsXsFs #0x1 2018-07-19 17:43:01.108858 caller_uid=0, caller_gid=0{0,}) v4\r\n2018-07-19 17:43:01.105 7fad9d1b5700 10 mds.0.server rdlock_path_pin_ref request(client.4213:296 cr=0x70200f3040) #0x1\r\n2018-07-19 17:43:01.105 7fad9d1b5700  7 mds.0.cache traverse: opening base ino 0x1 snap head\r\n2018-07-19 17:43:01.105 7fad9d1b5700 10  mds.0.cache.snaprealm(0x1 seq 1 0x701fecd900) have_past_parents_open [1,head]\r\n2018-07-19 17:43:01.105 7fad9d1b5700 10 mds.0.cache path_traverse finish on snapid head\r\n2018-07-19 17:43:01.105 7fad9d1b5700 10 mds.0.server ref is [inode 0x1 [...2,head] / auth v3 pv5 ap=269+0 snaprealm=0x701fecd900 dirtyparent f(v0 m2018-07-19 17:42:57.617196 1=0+1)->f(v0 m2018-07-19 17:42:57.617196 1=0+1) n(v0 1=0+1)->n(v0 1=0+1) (isnap sync r=269) (inest lock w=2 dirty) (ipolicy sync r=195) (ifile mix) (iversion lock w=2 last_client=4213) caps={4213=pAsLsXs/-@2} | dirtyscattered=1 request=0 lock=4 dirfrag=1 caps=1 dirtyparent=1 dirty=1 authpin=1 0x701fe7dc00]\r\n2018-07-19 17:43:01.169 7fada01bb700  1 -- 127.0.0.1:6846/1607993607 <== osd.1 127.0.0.1:6836/17378 41 ==== osd_op_reply(50 200.00000001 [write 75885~787572 [fadvise_dontneed]] v16'17 uv17 ondisk = 0) v8 ==== 156+0+0 (241523181 0 0) 0x702101ed00 con 0x701fff1800\r\n2018-07-19 17:43:01.169 7fad971a9700 10 MDSIOContextBase::complete: 18C_MDS_openc_finish\r\n2018-07-19 17:43:03.109 7fad9a1af700 10 mds.beacon.a _send up:active seq 73\r\n018-07-19 17:43:03.109 7fad9a1af700 10 monclient: _send_mon_message to mon.c at 127.0.0.1:40775/0\r\n2018-07-19 17:43:03.109 7fad9a1af700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:40775/0 -- mdsbeacon(24164/a up:active seq 73 v5) v7 -- 0x701febd100 con 0\r\n2018-07-19 17:43:03.985 7fad9b1b1700 20 mgrc operator() sending 24 counters (of possible 280), 0 new, 0 removed\r\n2018-07-19 17:43:03.985 7fad9b1b1700 20 mgrc _send_report encoded 214 bytes\r\n2018-07-19 17:43:03.985 7fad9b1b1700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6813/16760 -- mgrreport(unknown.a +0-0 packed 214) v6 -- 0x701febc300 con 0\r\n2018-07-19 17:43:07.109 7fad9a1af700 10 mds.beacon.a _send up:active seq 74\r\n2018-07-19 17:43:07.109 7fad9a1af700 10 monclient: _send_mon_message to mon.c at 127.0.0.1:40775/0\r\n2018-07-19 17:43:07.109 7fad9a1af700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:40775/0 -- mdsbeacon(24164/a up:active seq 74 v5) v7 -- 0x701febd480 con 0\r\n2018-07-19 17:43:07.969 7fad9c1b3700 10 monclient: tick\r\n2018-07-19 17:43:07.969 7fad9c1b3700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2018-07-19 17:42:37.970809)\r\n2018-07-19 17:43:07.969 7fad9c1b3700 20 monclient: _un_backoff reopen_interval_multipler now 1\r\n2018-07-19 17:43:08.985 7fad9b1b1700 20 mgrc operator() sending 24 counters (of possible 280), 0 new, 0 removed\r\n2018-07-19 17:43:08.985 7fad9b1b1700 20 mgrc _send_report encoded 214 bytes\r\n2018-07-19 17:43:08.985 7fad9b1b1700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6813/16760 -- mgrreport(unknown.a +0-0 packed 214) v6 -- 0x701febaa80 con 0\r\n2018-07-19 17:43:11.109 7fad9a1af700 10 mds.beacon.a _send up:active seq 75\r\n2018-07-19 17:43:11.109 7fad9a1af700 10 monclient: _send_mon_message to mon.c at 127.0.0.1:40775/0\r\n2018-07-19 17:43:11.109 7fad9a1af700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:40775/0 -- mdsbeacon(24164/a up:active seq 75 v5) v7 -- 0x70200ccd80 con 0\r\n2018-07-19 17:43:13.984 7fad9b1b1700 20 mgrc operator() sending 24 counters (of possible 280), 0 new, 0 removed\r\n2018-07-19 17:43:13.984 7fad9b1b1700 20 mgrc _send_report encoded 214 bytes\r\n2018-07-19 17:43:13.984 7fad9b1b1700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6813/16760 -- mgrreport(unknown.a +0-0 packed 214) v6 -- 0x701febb500 con 0\r\n2018-07-19 17:43:15.108 7fad9a1af700 10 mds.beacon.a _send up:active seq 76\r\n2018-07-19 17:43:15.108 7fad9a1af700 10 monclient: _send_mon_message to mon.c at 127.0.0.1:40775/0\r\n2018-07-19 17:43:15.108 7fad9a1af700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:40775/0 -- mdsbeacon(24164/a up:active seq 76 v5) v7 -- 0x70200cb880 con 0\r\n2018-07-19 17:43:17.968 7fad9c1b3700 10 monclient: tick\r\n2018-07-19 17:43:17.968 7fad9c1b3700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2018-07-19 17:42:47.971074)\r\n2018-07-19 17:43:17.968 7fad9c1b3700 20 monclient: _un_backoff reopen_interval_multipler now 1\r\n2018-07-19 17:43:17.968 7fad9f1b9700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15\r\n2018-07-19 17:43:18.984 7fad9b1b1700 20 mgrc operator() sending 24 counters (of possible 280), 0 new, 0 removed\r\n2018-07-19 17:43:18.984 7fad9b1b1700 20 mgrc _send_report encoded 214 bytes\r\n2018-07-19 17:43:18.984 7fad9b1b1700  1 -- 127.0.0.1:6846/1607993607 --> 127.0.0.1:6813/16760 -- mgrreport(unknown.a +0-0 packed 214) v6 -- 0x701febb880 con 0\r\n2018-07-19 17:43:19.108 7fad9a1af700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15\r\n2018-07-19 17:43:19.108 7fad9a1af700  1 mds.beacon.a _send skipping beacon, heartbeat map not healthy\r\n2018-07-19 17:43:22.968 7fad9f1b9700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15\r\n2018-07-19 17:43:23.108 7fad9a1af700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15\r\n2018-07-19 17:43:23.108 7fad9a1af700  1 mds.beacon.a _send skipping beacon, heartbeat map not healthy\r\n````\r\n\r\nIt appears to be because we trimmed the cache then flushed the journal, causing some kind of problem.\r\n\r\n````\r\n$ sudo gdb -q -p 17862\r\nAttaching to process 17862\r\n[New LWP 17863]\r\n[New LWP 17864]\r\n[New LWP 17865]\r\n[New LWP 17866]\r\n[New LWP 17867]\r\n[New LWP 17868]\r\n[New LWP 17869]\r\n[New LWP 17870]\r\n[New LWP 17871]\r\n[New LWP 17872]\r\n[New LWP 17873]\r\n[New LWP 17875]\r\n[New LWP 17876]\r\n[New LWP 17877]\r\n[New LWP 18081]\r\n[New LWP 18082]\r\n[New LWP 18083]\r\n[New LWP 18084]\r\n[New LWP 18085]\r\n[New LWP 18086]\r\n[New LWP 18087]\r\n[Thread debugging using libthread_db enabled]\r\nUsing host libthread_db library \"/lib/x86_64-linux-gnu/libthread_db.so.1\".\r\npthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n185     ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S: No such file or directory.\r\n(gdb) info threads\r\n  Id   Target Id         Frame \r\n* 1    Thread 0x7fadad9e6440 (LWP 17862) \"ceph-mds\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  2    Thread 0x7fada115a700 (LWP 17863) \"log\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  3    Thread 0x7fad9f1b9700 (LWP 17864) \"service\" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225\r\n  4    Thread 0x7fad9f9ba700 (LWP 17865) \"admin_socket\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  5    Thread 0x7fada01bb700 (LWP 17866) \"msgr-worker-0\" 0x00007fada3980a13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84\r\n  6    Thread 0x7fad9e9b8700 (LWP 17867) \"msgr-worker-1\" 0x00007fada3980a13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84\r\n  7    Thread 0x7fad9e1b7700 (LWP 17868) \"msgr-worker-2\" 0x00007fada3980a13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84\r\n  8    Thread 0x7fad9d9b6700 (LWP 17869) \"signal_handler\" 0x00007fada397474d in poll () at ../sysdeps/unix/syscall-template.S:84\r\n  9    Thread 0x7fad9d1b5700 (LWP 17870) \"ms_dispatch\" 0x00007fada420aa44 in std::_Rb_tree_insert_and_rebalance(bool, std::_Rb_tree_node_base*, std::_Rb_tree_node_base*, std::_Rb_tree_node_base&) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6\r\n  10   Thread 0x7fad9c9b4700 (LWP 17871) \"ms_local\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  11   Thread 0x7fad9c1b3700 (LWP 17872) \"safe_timer\" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225\r\n  12   Thread 0x7fad9b9b2700 (LWP 17873) \"fn_anonymous\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  13   Thread 0x7fad9b1b1700 (LWP 17875) \"safe_timer\" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225\r\n  14   Thread 0x7fad9a9b0700 (LWP 17876) \"safe_timer\" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135\r\n  15   Thread 0x7fad9a1af700 (LWP 17877) \"safe_timer\" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225\r\n  16   Thread 0x7fad999ae700 (LWP 18081) \"ms_dispatch\" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225\r\n  17   Thread 0x7fad991ad700 (LWP 18082) \"OpHistorySvc\" 0x00007fada394530d in nanosleep () at ../sysdeps/unix/syscall-template.S:84\r\n  18   Thread 0x7fad989ac700 (LWP 18083) \"mds_rank_progr\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  19   Thread 0x7fad981ab700 (LWP 18084) \"PQ_Finisher\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  20   Thread 0x7fad979aa700 (LWP 18085) \"safe_timer\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n  21   Thread 0x7fad971a9700 (LWP 18086) \"fn_anonymous\" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135\r\n  22   Thread 0x7fad969a8700 (LWP 18087) \"md_submit\" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185\r\n(gdb) thread 9\r\n[Switching to thread 9 (Thread 0x7fad9d1b5700 (LWP 17870))]\r\n#0  0x00007fada420aa44 in std::_Rb_tree_insert_and_rebalance(bool, std::_Rb_tree_node_base*, std::_Rb_tree_node_base*, std::_Rb_tree_node_base&) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6\r\n(gdb) bt\r\n#0  0x00007fada420aa44 in std::_Rb_tree_insert_and_rebalance(bool, std::_Rb_tree_node_base*, std::_Rb_tree_node_base*, std::_Rb_tree_node_base&) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6\r\n#1  0x000000701df005fb in std::_Rb_tree<SimpleLock*, SimpleLock*, std::_Identity<SimpleLock*>, std::less<SimpleLock*>, std::allocator<SimpleLock*> >::_M_insert_<SimpleLock* const&, std::_Rb_tree<SimpleLock*, SimpleLock*, std::_Identity<SimpleLock*>, std::less<SimpleLock*>, std::allocator<SimpleLock*> >::_Alloc_node> (this=0x7fad9d1b08a0, __x=<optimized out>, __p=0x7021005db0, __v=@0x7fad9d1b0890: 0x701fe7e148, \r\n    __node_gen=...) at /usr/include/c++/7/bits/stl_tree.h:1755\r\n#2  0x000000701df5dace in std::_Rb_tree<SimpleLock*, SimpleLock*, std::_Identity<SimpleLock*>, std::less<SimpleLock*>, std::allocator<SimpleLock*> >::_M_insert_unique<SimpleLock*>(SimpleLock*&&) (this=this@entry=0x7fad9d1b08a0, __v=__v@entry=<unknown type in /home/pdonnell/ceph/build/bin/ceph-mds, CU 0xe1a10f, DIE 0x120b1ab>) at /usr/include/c++/7/bits/stl_tree.h:2096\r\n#3  0x000000701df1b0ed in std::set<SimpleLock*, std::less<SimpleLock*>, std::allocator<SimpleLock*> >::insert(SimpleLock*&&) (__x=<unknown type in /home/pdonnell/ceph/build/bin/ceph-mds, CU 0xe1a10f, DIE 0x12e19b2>, this=0x7fad9d1b08a0) at /usr/include/c++/7/bits/stl_set.h:510\r\n#4  Server::handle_client_getattr (this=0x701fcded10, mdr=..., is_lookup=<optimized out>) at /home/pdonnell/ceph/src/mds/Server.cc:3093\r\n#5  0x000000701df4b15b in Server::handle_client_request (this=this@entry=0x701fcded10, req=req@entry=0x70200f3040) at /home/pdonnell/ceph/src/mds/Server.cc:1771\r\n#6  0x000000701df4ea8b in Server::dispatch (this=0x701fcded10, m=m@entry=0x70200f3040) at /home/pdonnell/ceph/src/mds/Server.cc:260\r\n#7  0x000000701decab4c in MDSRank::handle_deferrable_message (this=this@entry=0x701ffac000, m=m@entry=0x70200f3040) at /home/pdonnell/ceph/src/mds/MDSRank.cc:767\r\n#8  0x000000701deda89b in MDSRank::_dispatch (this=this@entry=0x701ffac000, m=m@entry=0x70200f3040, new_msg=new_msg@entry=true) at /home/pdonnell/ceph/src/mds/MDSRank.cc:604\r\n#9  0x000000701dedaf95 in MDSRankDispatcher::ms_dispatch (this=0x701ffac000, m=m@entry=0x70200f3040) at /home/pdonnell/ceph/src/mds/MDSRank.cc:583\r\n#10 0x000000701dec36d3 in MDSDaemon::ms_dispatch (this=0x701ff04000, m=0x70200f3040) at /home/pdonnell/ceph/src/mds/MDSDaemon.cc:1159\r\n#11 0x00007fada4e95cca in Messenger::ms_deliver_dispatch (m=0x70200f3040, this=0x701fe78000) at /home/pdonnell/ceph/src/msg/Messenger.h:655\r\n#12 DispatchQueue::entry (this=0x701fe78180) at /home/pdonnell/ceph/src/msg/DispatchQueue.cc:201\r\n#13 0x00007fada4f3712d in DispatchQueue::DispatchThread::entry (this=<optimized out>) at /home/pdonnell/ceph/src/msg/DispatchQueue.h:102\r\n#14 0x00007fada46f66ba in start_thread (arg=0x7fad9d1b5700) at pthread_create.c:333\r\n#15 0x00007fada398041d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109\r\n````\r\n\r\nIt doesn't happen if you just use the `flush journal` command. @ukernel any idea? This is pretty trivial to reproduce in my testing."}}
{"actor":{"display_login":"batrick"}}