https://tracker.ceph.com/https://tracker.ceph.com/favicon.ico2016-07-07T17:44:32ZCeph CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=740402016-07-07T17:44:32ZPatrick Donnellypdonnell@redhat.com
<ul></ul><p>Log is now here: /ceph/post/i16610/client.log</p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=742042016-07-11T18:46:21ZPatrick Donnellypdonnell@redhat.com
<ul></ul><p>Just as a quick update, we're waiting on some more information from Goncalo concerning the possibility of nodes running out of memory (causing the segfault).</p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=742472016-07-12T11:25:37ZGoncalo Borgesgoncalo.borges@sydney.edu.au
<ul><li><strong>File</strong> <a href="/attachments/download/2408/gdb.txt">gdb.txt</a> <a class="icon-only icon-magnifier" title="View" href="/attachments/2408/gdb.txt">View</a> added</li><li><strong>File</strong> <a href="/attachments/download/2410/debug.out.gz">debug.out.gz</a> added</li></ul><p>Just another update after further investigation and discussion in the mailing list.</p>
<p>1. I have tried to run the application giving origin to this segfault in different kinds of resources. <br />a./ The segfault is always appearing in a set of VMs with 16 GB of RAM and 4 cores. <br />b./ The segfault is not appearing in a set of VMs (in principle identical to the 16 GB ones) but with 16 cores and 64 GB of RAM.<br />c./ the segfault is not appearing in a physicall cluster with machines with 96 GB of RAM and 12 cores (24 because of hyperthreading)</p>
<p>2./ When I was running the application in situation 1c) I was seing ceph-fuse consuming more than 10gb of virtual memory. That made me think that the problem could be machines 1a) running out of memory. However, further discussion demonstrated that the virtual memory footprint is a consequence of the arenas mechanism enabled by glibc > 1.10. It is possible to tune the maximum number of arenas per cpu by setting MALLOC_ARENA_MAX env variables. If I set MALLOC_ARENA_MAX to 4 (the default value is 8), the virtual memory footprint decreases tremendously.</p>
<p>3./ After understanding point 2 it became obvious that the virtual memory footprint of ceph-fuse in scenario 1a) should be much less that the 10gb seen in situation 1c) because it scales with the number of cpus. Nevertheless, I did try to run ceph-fuse with MALLOC_ARENA_MAX = 4 and 2 but the segfaults continues to appear.</p>
<p>4./ At this point I do not have a clear idea of what is triggering the segfault. To allow further debugging, I am appending:</p>
<p>- The gdb.txt I get after running <br /> $ gdb /path/to/ceph-fuse core.XXXX<br /> (gdb) set pag off<br /> (gdb) set log on<br /> (gdb) thread apply all bt<br /> (gdb) thread apply all bt full</p>
<p>- The debug.out (gzipped) I get after running ceph-fuse in debug mode with 'debug client 20' and 'debug objectcacher = 20'</p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=743272016-07-12T23:23:50ZGreg Farnumgfarnum@redhat.com
<ul><li><strong>Category</strong> changed from <i>45</i> to <i>Correctness/Safety</i></li><li><strong>Component(FS)</strong> <i>Client, ceph-fuse, osdc</i> added</li></ul> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=746972016-07-13T06:13:54ZBrad Hubbardbhubbard@redhat.com
<ul></ul><p>Alas, the gdb log does not give us much more to go on.</p>
<p>Thread 1 (Thread 0x7f891cdfa700 (LWP 5467)):<br />#0 0x00007f8928c3f6ab in raise () from /lib64/libpthread.so.0<br /><a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: gpf in tcp_sendpage (Closed)" href="https://tracker.ceph.com/issues/1">#1</a> 0x00007f892a2000a5 in handle_fatal_signal(int) () at global/signal_handler.cc:71<br /><a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: BUG at fs/ceph/caps.c:2178 (Closed)" href="https://tracker.ceph.com/issues/2">#2</a> <signal handler called><br /><a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: leaked dentry ref on umount (Closed)" href="https://tracker.ceph.com/issues/3">#3</a> ObjectCacher::Object::get() () at osdc/ObjectCacher.h:359<br /><a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: lockdep warning in socket code (Closed)" href="https://tracker.ceph.com/issues/4">#4</a> 0x00007f892a1b0097 in ObjectCacher::bh_write_scattered(std::list<ObjectCacher::BufferHead*, std::allocator<ObjectCacher::BufferHead*> >&) () at osdc/ObjectCacher.cc:929<br /><a class="issue tracker-1 status-5 priority-3 priority-lowest closed" title="Bug: ./rados lspools sometimes hangs after listing all pools? (Closed)" href="https://tracker.ceph.com/issues/5">#5</a> 0x00007f892a1b0a3c in ObjectCacher::bh_write_adjacencies(ObjectCacher::BufferHead*, std::chrono::time_point<ceph::time_detail::real_clock, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> > >, long*, int*) () at osdc/ObjectCacher.cc:921<br /><a class="issue tracker-2 status-6 priority-3 priority-lowest closed" title="Feature: libceph could use a backward-compatible-to function (Rejected)" href="https://tracker.ceph.com/issues/6">#6</a> 0x00007f892a1b0cef in ObjectCacher::flush(long) () at osdc/ObjectCacher.cc:1142<br /><a class="issue tracker-6 status-3 priority-3 priority-lowest closed" title="Documentation: Document Monitor Commands (Resolved)" href="https://tracker.ceph.com/issues/7">#7</a> 0x00007f892a1b1a34 in ObjectCacher::flusher_entry() () at osdc/ObjectCacher.cc:1741<br /><a class="issue tracker-3 status-5 priority-4 priority-default closed" title="Support: Document differences from S3 (Closed)" href="https://tracker.ceph.com/issues/8">#8</a> 0x00007f892a1bdc6d in ObjectCacher::FlusherThread::entry() () at osdc/ObjectCacher.h:427<br /><a class="issue tracker-2 status-8 priority-3 priority-lowest closed" title="Feature: Access unimported data (Won't Fix)" href="https://tracker.ceph.com/issues/9">#9</a> 0x00007f8928c37aa1 in start_thread () from /lib64/libpthread.so.0<br /><a class="issue tracker-2 status-3 priority-4 priority-default closed" title="Feature: osd: Replace ALLOW_MESSAGES_FROM macro (Resolved)" href="https://tracker.ceph.com/issues/10">#10</a> 0x00007f8927eb093d in clone () from /lib64/libc.so.6</p>
<p>The additional information you provided is interesting though. I wonder if this is indicative of some sort of memory allocation failure?</p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=747932016-07-14T13:44:56ZZheng Yanukernel@gmail.com
<ul></ul><p>looks like ObjectCacher::bh_write_adjacencies() passed an empty list to ObjectCacher::bh_write_scattered(). Maybe the precision of VM's clock is low. Could you please try below patch</p>
<pre>
diff --git a/src/osdc/ObjectCacher.cc b/src/osdc/ObjectCacher.cc
index 90c8329..67d16de 100644
--- a/src/osdc/ObjectCacher.cc
+++ b/src/osdc/ObjectCacher.cc
@@ -1156,7 +1156,7 @@ void ObjectCacher::flush(loff_t amount)
BufferHead *bh = static_cast<BufferHead*>(
bh_lru_dirty.lru_get_next_expire());
if (!bh) break;
- if (bh->last_write > cutoff) break;
+ if (bh->last_write >= cutoff) break;
if (scattered_write) {
bh_write_adjacencies(bh, cutoff, amount > 0 ? &left : NULL, NULL);
</pre> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=749462016-07-19T05:07:45ZGoncalo Borgesgoncalo.borges@sydney.edu.au
<ul></ul><p>Just to keep the full history in this issue, we have understood that the segfault only appears in VM with AMD62xx processors and does not appear in VMs with AMD63XX or Intel processor (details how we found this correlation are provided in the mailing list thread).</p>
<p>It also turns out that Zheng's patch is the solution.</p>
<p>To convince ourselves that the problem was really solved, we executed 40 jobs (with the user application where the ObjectCacher segfault was seen for the first time) in a dozen of AMD 62XX VMs, and none failed. Before, ceph-fuse was always segfaulting a couple of minutes after job startup.</p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=749852016-07-19T13:32:15ZZheng Yanukernel@gmail.com
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Fix Under Review</i></li></ul> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=749862016-07-19T13:32:43ZZheng Yanukernel@gmail.com
<ul></ul><p><a class="external" href="https://github.com/ceph/ceph/pull/10304">https://github.com/ceph/ceph/pull/10304</a></p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=772422016-08-25T01:11:57ZGreg Farnumgfarnum@redhat.com
<ul><li><strong>Status</strong> changed from <i>Fix Under Review</i> to <i>Pending Backport</i></li></ul><p>This got merged to master forever ago. Guess it should get backported too.</p> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=772482016-08-25T06:26:24ZLoïc Dacharyloic@dachary.org
<ul><li><strong>Backport</strong> set to <i>jewel</i></li></ul> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=772512016-08-25T06:27:11ZLoïc Dacharyloic@dachary.org
<ul><li><strong>Copied to</strong> <i><a class="issue tracker-9 status-3 priority-4 priority-default closed" href="/issues/17131">Backport #17131</a>: jewel: Jewel: segfault in ObjectCacher::FlusherThread</i> added</li></ul> CephFS - Bug #16610: Jewel: segfault in ObjectCacher::FlusherThreadhttps://tracker.ceph.com/issues/16610?journal_id=798342016-10-15T09:34:15ZNathan Cutlerncutler@suse.cz
<ul><li><strong>Status</strong> changed from <i>Pending Backport</i> to <i>Resolved</i></li></ul>