Project

General

Profile

Actions
Copy link

Bug #51023

closed

mds: tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3)

Added by Xiubo Li almost 3 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
High
Assignee:
Xiubo Li
Category:
Correctness/Safety
Target version:
Ceph - v17.0.0
% Done:

0%

Source:
Development
Tags:
Backport:
pacific,octopus
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
fs
Component(FS):
MDS
Labels (FS):
crash
Pull request ID:
41667
Crash signature (v1):
Crash signature (v2):

Description

From https://pulpito.ceph.com/yuriw-2021-05-27_19:31:33-kcephfs-wip-yuri3-testing-2021-05-27-0818-nautilus-distro-basic-smithi/6138429/:

2021-05-27T23:14:13.379 INFO:tasks.ceph.mds.c.smithi104.stderr:tcmalloc: large alloc 94317937795072 bytes == (nil) @  0x7f75fe0ea35f 0x7f75fe109a56 0x55c817ca10f9 0x55c817ca127b 0x55c817ca1340 0x55c817ca141e 0x55c817e90230 0x55c817e904cf 0x55c817d7af8d 0x55c817f33ea4 0x55c817f340ff 0x55c817f34310 0x7f75fe7b151f 0x7f75fc5dbea5 0x7f75fb2889fd
2021-05-27T23:14:13.379 INFO:tasks.ceph.mds.c.smithi104.stderr:terminate called after throwing an instance of 'std::bad_alloc'
2021-05-27T23:14:13.379 INFO:tasks.ceph.mds.c.smithi104.stderr:  what():  std::bad_alloc
2021-05-27T23:14:13.380 INFO:tasks.ceph.mds.c.smithi104.stderr:*** Caught signal (Aborted) **
2021-05-27T23:14:13.380 INFO:tasks.ceph.mds.c.smithi104.stderr: in thread 7f75eec84700 thread_name:fn_anonymous
2021-05-27T23:14:13.381 INFO:tasks.ceph.mds.c.smithi104.stderr: ceph version 14.2.21-281-gb7a4754d941 (b7a4754d941f016678ca17d548fafb10e7444735) nautilus (stable)
2021-05-27T23:14:13.381 INFO:tasks.ceph.mds.c.smithi104.stderr: 1: (()+0xf630) [0x7f75fc5e3630]
2021-05-27T23:14:13.381 INFO:tasks.ceph.mds.c.smithi104.stderr: 2: (gsignal()+0x37) [0x7f75fb1c03d7]
2021-05-27T23:14:13.382 INFO:tasks.ceph.mds.c.smithi104.stderr: 3: (abort()+0x148) [0x7f75fb1c1ac8]
2021-05-27T23:14:13.382 INFO:tasks.ceph.mds.c.smithi104.stderr: 4: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f75fbad0a95]
2021-05-27T23:14:13.382 INFO:tasks.ceph.mds.c.smithi104.stderr: 5: (()+0x5ea06) [0x7f75fbacea06]
2021-05-27T23:14:13.382 INFO:tasks.ceph.mds.c.smithi104.stderr: 6: (()+0x5ea33) [0x7f75fbacea33]
2021-05-27T23:14:13.383 INFO:tasks.ceph.mds.c.smithi104.stderr: 7: (()+0x5ec53) [0x7f75fbacec53]
2021-05-27T23:14:13.383 INFO:tasks.ceph.mds.c.smithi104.stderr: 8: (()+0x1772b) [0x7f75fe0eb72b]
2021-05-27T23:14:13.383 INFO:tasks.ceph.mds.c.smithi104.stderr: 9: (tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3) [0x7f75fe109a03]
2021-05-27T23:14:13.383 INFO:tasks.ceph.mds.c.smithi104.stderr: 10: (std::string::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&)+0x59) [0x55c817ca10f9]
2021-05-27T23:14:13.383 INFO:tasks.ceph.mds.c.smithi104.stderr: 11: (std::string::_Rep::_M_clone(std::allocator<char> const&, unsigned long)+0x1b) [0x55c817ca127b]
2021-05-27T23:14:13.384 INFO:tasks.ceph.mds.c.smithi104.stderr: 12: (std::string::reserve(unsigned long)+0x40) [0x55c817ca1340]
2021-05-27T23:14:13.384 INFO:tasks.ceph.mds.c.smithi104.stderr: 13: (std::string::append(char const*, unsigned long)+0x5e) [0x55c817ca141e]
2021-05-27T23:14:13.384 INFO:tasks.ceph.mds.c.smithi104.stderr: 14: (CDentry::make_path(filepath&, bool) const+0x90) [0x55c817e90230]
2021-05-27T23:14:13.384 INFO:tasks.ceph.mds.c.smithi104.stderr: 15: (operator<<(std::ostream&, CDentry const&)+0x6f) [0x55c817e904cf]
2021-05-27T23:14:13.385 INFO:tasks.ceph.mds.c.smithi104.stderr: 16: (MDCache::_create_system_file_finish(boost::intrusive_ptr<MutationImpl>&, CDentry*, unsigned long, MDSContext*)+0xbd) [0x55c817d7af8d]
2021-05-27T23:14:13.385 INFO:tasks.ceph.mds.c.smithi104.stderr: 17: (MDSContext::complete(int)+0x74) [0x55c817f33ea4]
2021-05-27T23:14:13.385 INFO:tasks.ceph.mds.c.smithi104.stderr: 18: (MDSIOContextBase::complete(int)+0x16f) [0x55c817f340ff]
2021-05-27T23:14:13.385 INFO:tasks.ceph.mds.c.smithi104.stderr: 19: (MDSLogContextBase::complete(int)+0x40) [0x55c817f34310]
2021-05-27T23:14:13.385 INFO:tasks.ceph.mds.c.smithi104.stderr: 20: (Finisher::finisher_thread_entry()+0x16f) [0x7f75fe7b151f]
2021-05-27T23:14:13.386 INFO:tasks.ceph.mds.c.smithi104.stderr: 21: (()+0x7ea5) [0x7f75fc5dbea5]
2021-05-27T23:14:13.386 INFO:tasks.ceph.mds.c.smithi104.stderr: 22: (clone()+0x6d) [0x7f75fb2889fd]
2021-05-27T23:14:13.386 INFO:tasks.ceph.mds.c.smithi104.stderr:2021-05-27 23:14:13.415 7f75eec84700 -1 *** Caught signal (Aborted) **
2021-05-27T23:14:13.386 INFO:tasks.ceph.mds.c.smithi104.stderr: in thread 7f75eec84700 thread_name:fn_anonymous
2021-05-27T23:14:13.387 INFO:tasks.ceph.mds.c.smithi104.stderr: ceph version 14.2.21-281-gb7a4754d941 (b7a4754d941f016678ca17d548fafb10e7444735) nautilus (stable)
2021-05-27T23:14:13.387 INFO:tasks.ceph.mds.c.smithi104.stderr: 1: (()+0xf630) [0x7f75fc5e3630]
2021-05-27T23:14:13.387 INFO:tasks.ceph.mds.c.smithi104.stderr: 2: (gsignal()+0x37) [0x7f75fb1c03d7]
2021-05-27T23:14:13.387 INFO:tasks.ceph.mds.c.smithi104.stderr: 3: (abort()+0x148) [0x7f75fb1c1ac8]
2021-05-27T23:14:13.388 INFO:tasks.ceph.mds.c.smithi104.stderr: 4: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f75fbad0a95]
2021-05-27T23:14:13.388 INFO:tasks.ceph.mds.c.smithi104.stderr: 5: (()+0x5ea06) [0x7f75fbacea06]
2021-05-27T23:14:13.388 INFO:tasks.ceph.mds.c.smithi104.stderr: 6: (()+0x5ea33) [0x7f75fbacea33]
2021-05-27T23:14:13.388 INFO:tasks.ceph.mds.c.smithi104.stderr: 7: (()+0x5ec53) [0x7f75fbacec53]
2021-05-27T23:14:13.389 INFO:tasks.ceph.mds.c.smithi104.stderr: 8: (()+0x1772b) [0x7f75fe0eb72b]
2021-05-27T23:14:13.389 INFO:tasks.ceph.mds.c.smithi104.stderr: 9: (tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3) [0x7f75fe109a03]
2021-05-27T23:14:13.389 INFO:tasks.ceph.mds.c.smithi104.stderr: 10: (std::string::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&)+0x59) [0x55c817ca10f9]
2021-05-27T23:14:13.389 INFO:tasks.ceph.mds.c.smithi104.stderr: 11: (std::string::_Rep::_M_clone(std::allocator<char> const&, unsigned long)+0x1b) [0x55c817ca127b]
2021-05-27T23:14:13.389 INFO:tasks.ceph.mds.c.smithi104.stderr: 12: (std::string::reserve(unsigned long)+0x40) [0x55c817ca1340]
2021-05-27T23:14:13.390 INFO:tasks.ceph.mds.c.smithi104.stderr: 13: (std::string::append(char const*, unsigned long)+0x5e) [0x55c817ca141e]
2021-05-27T23:14:13.390 INFO:tasks.ceph.mds.c.smithi104.stderr: 14: (CDentry::make_path(filepath&, bool) const+0x90) [0x55c817e90230]
2021-05-27T23:14:13.390 INFO:tasks.ceph.mds.c.smithi104.stderr: 15: (operator<<(std::ostream&, CDentry const&)+0x6f) [0x55c817e904cf]
2021-05-27T23:14:13.390 INFO:tasks.ceph.mds.c.smithi104.stderr: 16: (MDCache::_create_system_file_finish(boost::intrusive_ptr<MutationImpl>&, CDentry*, unsigned long, MDSContext*)+0xbd) [0x55c817d7af8d]
2021-05-27T23:14:13.391 INFO:tasks.ceph.mds.c.smithi104.stderr: 17: (MDSContext::complete(int)+0x74) [0x55c817f33ea4]
2021-05-27T23:14:13.391 INFO:tasks.ceph.mds.c.smithi104.stderr: 18: (MDSIOContextBase::complete(int)+0x16f) [0x55c817f340ff]
2021-05-27T23:14:13.391 INFO:tasks.ceph.mds.c.smithi104.stderr: 19: (MDSLogContextBase::complete(int)+0x40) [0x55c817f34310]
2021-05-27T23:14:13.391 INFO:tasks.ceph.mds.c.smithi104.stderr: 20: (Finisher::finisher_thread_entry()+0x16f) [0x7f75fe7b151f]
2021-05-27T23:14:13.391 INFO:tasks.ceph.mds.c.smithi104.stderr: 21: (()+0x7ea5) [0x7f75fc5dbea5]
2021-05-27T23:14:13.392 INFO:tasks.ceph.mds.c.smithi104.stderr: 22: (clone()+0x6d) [0x7f75fb2889fd]
2021-05-27T23:14:13.392 INFO:tasks.ceph.mds.c.smithi104.stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
2021-05-27T23:14:13.392 INFO:tasks.ceph.mds.c.smithi104.stderr:
2021-05-27T23:14:13.392 INFO:tasks.ceph.mds.c.smithi104.stderr:  -405> 2021-05-27 23:14:10.413 7f75eec84700 -1 mds.0.openfiles _load_finish got (2) No such file or directory
2021-05-27T23:14:13.393 INFO:tasks.ceph.mds.c.smithi104.stderr:     0> 2021-05-27 23:14:13.415 7f75eec84700 -1 *** Caught signal (Aborted) **
2021-05-27T23:14:13.393 INFO:tasks.ceph.mds.c.smithi104.stderr: in thread 7f75eec84700 thread_name:fn_anonymous
2021-05-27T23:14:13.393 INFO:tasks.ceph.mds.c.smithi104.stderr:
2021-05-27T23:14:13.393 INFO:tasks.ceph.mds.c.smithi104.stderr: ceph version 14.2.21-281-gb7a4754d941 (b7a4754d941f016678ca17d548fafb10e7444735) nautilus (stable)

Related issues 2 (0 open — 2 closed)

Copied to CephFS - Backport #53163: octopus: mds: tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3)ResolvedXiubo LiActions
Copied to CephFS - Backport #53164: pacific: mds: tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3)ResolvedXiubo LiActions
Actions
Copy link
 #1

Updated by Xiubo Li almost 3 years ago

  • Status changed from New to In Progress

The root cause is that the "~mds0/stray0" dentry has been trimmed before the "C_MDC_CreateSystemFile" finisher callback was called:

   -15> 2021-05-27 23:14:13.412 7f75f0c88700 20 mds.0.cache upkeep thread trimming cache; last trim 1659.41s ago
   -14> 2021-05-27 23:14:13.412 7f75f0c88700 10 mds.0.cache trim_client_leases
   -13> 2021-05-27 23:14:13.412 7f75f0c88700  7 mds.0.cache trim bytes_used=14kB limit=1GB reservation=0.05% count=0
   -12> 2021-05-27 23:14:13.412 7f75f0c88700  7 mds.0.cache trim_lru trimming 0 items from LRU size=1 mid=0 pintail=0 pinned=0
   -11> 2021-05-27 23:14:13.412 7f75f0c88700 12 mds.0.cache trim_dentry [dentry #0x100/stray0 [2,head] auth NULL (dversion lock) pv=4 v=2 ino=(nil) state=1073741888|bottomlru 0x55c81a4f2700]
   -10> 2021-05-27 23:14:13.412 7f75f0c88700 12 mds.0.cache  in container [dir 0x100 ~mds0/ [2,head] auth pv=5 v=2 cv=1/1 dir_auth=0 ap=1+0 state=1610612737|complete f(v0 1=1+0) n() hs=0+1,ss=0+0 | child=1 subtree=1 subtreetemp=0 dirty=1 waiter=0 authpin=1 0x55c81b2a4300]
    -9> 2021-05-27 23:14:13.413 7f75f0c88700 12 mds.0.cache.dir(0x100) remove_dentry [dentry #0x100/stray0 [2,head] auth NULL (dversion lock) pv=4 v=2 ino=(nil) state=1073741888|bottomlru 0x55c81a4f2700]
    -8> 2021-05-27 23:14:13.413 7f75f0c88700  7 mds.0.cache trim_lru trimmed 1 items
    -7> 2021-05-27 23:14:13.413 7f75f0c88700  7 mds.0.server recall_client_state: min=100 max=1048576 total=0 flags=0xa
    -6> 2021-05-27 23:14:13.413 7f75f0c88700  7 mds.0.server recalled 0 client caps.
    -5> 2021-05-27 23:14:13.413 7f75f0c88700 20 mds.0.cache upkeep thread waiting interval 1s
    -4> 2021-05-27 23:14:13.414 7f75f8497700  1 -- [v2:172.21.15.104:6834/737462473,v1:172.21.15.104:6835/737462473] <== osd.3 v2:172.21.15.46:6812/36408 6 ==== osd_op_reply(23 200.00000001 [write 48~1918 [fadvise_dontneed]] v192'32 uv32 ondisk = 0) v8 ==== 156+0+0 (crc 0 0 0) 0x55c81b205b80 con 0x55c81b265800
Actions
Copy link
 #2

Updated by Xiubo Li almost 3 years ago

It was one use-after-free bug, maybe we should lru_pin the stray dentries.

Actions
Copy link
 #3

Updated by Patrick Donnelly almost 3 years ago

Xiubo Li wrote:

It was one use-after-free bug, maybe we should lru_pin the stray dentries.

That's what ultimately should happen but I'm not yet sure what the most coherent way to achieve this is. Calling lru_pin in the Context constructor is not done anywhere else. I also could find a pin type in MDSCacheObject that fits this situation or an analogous bit of code to base this change on. Any idea?

Actions
Copy link
 #4

Updated by Xiubo Li almost 3 years ago

Patrick Donnelly wrote:

Xiubo Li wrote:

It was one use-after-free bug, maybe we should lru_pin the stray dentries.

That's what ultimately should happen but I'm not yet sure what the most coherent way to achieve this is. Calling lru_pin in the Context constructor is not done anywhere else. I also could find a pin type in MDSCacheObject that fits this situation or an analogous bit of code to base this change on. Any idea?

We can just add one "CDentry::PIN_STRAY" or "CDentry::PIN_POPULATE" and then call the "dn->get(CDentry::PIN_STRAY/CDentry::PIN_POPULATE)", the "first_get()" will call the lru_pin() in CDentry class:

174   void get(int by) {
175     if (ref == 0)
176       first_get();                                                                                                                                 
177     ref++;
178 #ifdef MDS_REF_SET
179     if (ref_map.find(by) == ref_map.end()) 
180       ref_map[by] = 0;
181     ref_map[by]++;
182 #endif
183   }

Another approach is that we can just make the cache not trimmable during openning the root, currently when openning the root the mds is already in ACTIVE state which is trimmable for the cache.

Which one is better ?

Actions
Copy link
 #5

Updated by Patrick Donnelly almost 3 years ago

Xiubo Li wrote:

Patrick Donnelly wrote:

Xiubo Li wrote:

It was one use-after-free bug, maybe we should lru_pin the stray dentries.

That's what ultimately should happen but I'm not yet sure what the most coherent way to achieve this is. Calling lru_pin in the Context constructor is not done anywhere else. I also could find a pin type in MDSCacheObject that fits this situation or an analogous bit of code to base this change on. Any idea?

We can just add one "CDentry::PIN_STRAY" or "CDentry::PIN_POPULATE" and then call the "dn->get(CDentry::PIN_STRAY/CDentry::PIN_POPULATE)", the "first_get()" will call the lru_pin() in CDentry class:

[...]

Another approach is that we can just make the cache not trimmable during openning the root, currently when openning the root the mds is already in ACTIVE state which is trimmable for the cache.

Which one is better ?

I think "dn->get(0)" would suffice. There's no PIN that fits this problem AFAICT.

Actions
Copy link
 #6

Updated by Xiubo Li almost 3 years ago

Patrick Donnelly wrote:

Xiubo Li wrote:

Patrick Donnelly wrote:

Xiubo Li wrote:

It was one use-after-free bug, maybe we should lru_pin the stray dentries.

That's what ultimately should happen but I'm not yet sure what the most coherent way to achieve this is. Calling lru_pin in the Context constructor is not done anywhere else. I also could find a pin type in MDSCacheObject that fits this situation or an analogous bit of code to base this change on. Any idea?

We can just add one "CDentry::PIN_STRAY" or "CDentry::PIN_POPULATE" and then call the "dn->get(CDentry::PIN_STRAY/CDentry::PIN_POPULATE)", the "first_get()" will call the lru_pin() in CDentry class:

[...]

Another approach is that we can just make the cache not trimmable during openning the root, currently when openning the root the mds is already in ACTIVE state which is trimmable for the cache.

Which one is better ?

I think "dn->get(0)" would suffice. There's no PIN that fits this problem AFAICT.

Yeah, this also looks good to me. Thanks.

Actions
Copy link
 #7

Updated by Xiubo Li almost 3 years ago

  • Status changed from In Progress to Fix Under Review
  • Pull request ID set to 41667
Actions
Copy link
 #8

Updated by Xiubo Li almost 3 years ago

  • Target version set to v17.0.0
Actions
Copy link
 #9

Updated by Patrick Donnelly over 2 years ago

  • Category set to Correctness/Safety
  • Status changed from Fix Under Review to Pending Backport
  • Source set to Development
  • Backport set to pacific,octopus
Actions
Copy link
 #10

Updated by Backport Bot over 2 years ago

  • Copied to Backport #53163: octopus: mds: tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3) added
Actions
Copy link
 #11

Updated by Backport Bot over 2 years ago

  • Copied to Backport #53164: pacific: mds: tcmalloc::allocate_full_cpp_throw_oom(unsigned long)+0xf3) added
Actions
Copy link
 #12

Updated by Loïc Dachary over 2 years ago

  • Status changed from Pending Backport to Resolved

While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".

Actions
Copy link

Also available in: Atom PDF