osd: terminate called after throwing an instance of 'std::bad_alloc'

osd: terminate called after throwing an instance of 'std::bad_alloc'

[Andre Noll]

[-- Attachment #1: Type: text/plain, Size: 3295 bytes --]

Hi,

we're trying to give ceph a try on our compute cluster Initial stress
tests passed without problems, but over the weekend a couple of cosd
processes died and now access to the ceph mount point blocks and
mounting the ceph dir fails with

	mount: 192.168.1.141:6789,192.168.1.145:6789,192.168.1.150:6789:/: can't read superblock

Attempts to restart the cosd on the affected storage nodes fails with

	# /usr/local/bin/cosd -f -i 6 -c /etc/ceph/ceph.conf
	 ** WARNING: Ceph is still under heavy development, and is only suitable for **
	 **          testing and review.  Do not trust it with important data.       **
	starting osd6 at 0.0.0.0:6800/2685 osd_data /var/ceph/osd6 /var/ceph/osd6/journal
	terminate called after throwing an instance of 'std::bad_alloc'
	  what():  std::bad_alloc
	Aborted

Stracing the cosd process shows that it calls mmap() with silly values
for the "fd" and the "length" parameter:

	mmap(NULL, 18446744073709436928, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)

I briefly looked at the source code and noticed that raw_mmap_pages()
in include/buffer.h of seems to call mmap() with an unsigned int
rather than with a size_t as the second (length) parameter. Since

	18446744073709436928 = 0xfffffffffffe4000

this looks like an integer overflow. But maybe it is just uninitialized
garbage.

I've tried the v0.20.2 and the testing branch of the ceph git
repo. Both versions of cosd show the same behaviour.

Our ceph file system 5.5T large, we have 7 cosds, 3 cmons and 3 cmds,
see the ceph.conf below for details.

Any idea how to get back the data? If you need further debugging info,
don't hesitate to ask.

Thanks
Andre
---

[global]
	; enable secure authentication
	auth supported = cephx
	osd journal size = 100    ; measured in MB 

; You need at least one monitor. You need at least three if you want to
; tolerate any node failures. Always create an odd number.
[mon]
	mon data = /var/ceph/mon$id
	; some minimal logging (just message traffic) to aid debugging
	debug ms = 1
[mon0]
	host = node141
	mon addr = 192.168.1.141:6789
[mon1]
	host = node145
	mon addr = 192.168.1.145:6789
[mon2]
	host = node150
	mon addr = 192.168.1.150:6789

; You need at least one mds. Define two to get a standby.
[mds]
	; where the mds keeps it's secret encryption keys
	keyring = /var/ceph/keyring.$name
[mds0]
	host = node141
[mds1]
	host = node145
[mds2]
	host = node150

; osd
;  You need at least one.  Two if you want data to be replicated.
;  Define as many as you like.
[osd]
	; This is where the btrfs volume will be mounted.
	osd data = /var/ceph/osd$id

	; Ideally, make this a separate disk or partition.  A few GB
 	; is usually enough; more if you have fast disks.  You can use
 	; a file under the osd data dir if need be
 	; (e.g. /data/osd$id/journal), but it will be slower than a
 	; separate disk or partition.
	osd journal = /var/ceph/osd$id/journal

[osd0]
	host = node141
[osd1]
	host = node145
[osd2]
	host = node150
[osd3]
	host = node146
[osd4]
	host = node147
[osd5]
	host = node149
[osd6]
	host = node142
-- 
The only person who always got his work done by Friday was Robinson Crusoe

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Sage Weil]

Hi Andre,

On Mon, 31 May 2010, Andre Noll wrote:
> we're trying to give ceph a try on our compute cluster Initial stress
> tests passed without problems,

Cool!

> but over the weekend a couple of cosd processes died and now access to 
> the ceph mount point blocks and mounting the ceph dir fails with

Hmm :(

> Stracing the cosd process shows that it calls mmap() with silly values
> for the "fd" and the "length" parameter:
> 
> 	mmap(NULL, 18446744073709436928, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)

So, the mmap code in buffer.h is actually never called, so my guess is 
that posix_memalign() or some other library implementation is doing it.  
Can you get a stack trace?  Either look at the core file with gdb or run 
cosd via gdb?  Alternatively, the osd startup log with

	debug osd = 20
	debug filestore = 20

in the [osd] section of ceph.conf would help narrow it down.  There is 
probably a missing check in the osd mount/initialization code but it's 
hard to guess where.

Thanks!
sage



> 
> I briefly looked at the source code and noticed that raw_mmap_pages()
> in include/buffer.h of seems to call mmap() with an unsigned int
> rather than with a size_t as the second (length) parameter. Since
> 
> 	18446744073709436928 = 0xfffffffffffe4000
> 
> this looks like an integer overflow. But maybe it is just uninitialized
> garbage.
> 
> I've tried the v0.20.2 and the testing branch of the ceph git
> repo. Both versions of cosd show the same behaviour.
> 
> Our ceph file system 5.5T large, we have 7 cosds, 3 cmons and 3 cmds,
> see the ceph.conf below for details.
> 
> Any idea how to get back the data? If you need further debugging info,
> don't hesitate to ask.
> 
> Thanks
> Andre
> ---
> 
> [global]
> 	; enable secure authentication
> 	auth supported = cephx
> 	osd journal size = 100    ; measured in MB 
> 
> ; You need at least one monitor. You need at least three if you want to
> ; tolerate any node failures. Always create an odd number.
> [mon]
> 	mon data = /var/ceph/mon$id
> 	; some minimal logging (just message traffic) to aid debugging
> 	debug ms = 1
> [mon0]
> 	host = node141
> 	mon addr = 192.168.1.141:6789
> [mon1]
> 	host = node145
> 	mon addr = 192.168.1.145:6789
> [mon2]
> 	host = node150
> 	mon addr = 192.168.1.150:6789
> 
> ; You need at least one mds. Define two to get a standby.
> [mds]
> 	; where the mds keeps it's secret encryption keys
> 	keyring = /var/ceph/keyring.$name
> [mds0]
> 	host = node141
> [mds1]
> 	host = node145
> [mds2]
> 	host = node150
> 
> ; osd
> ;  You need at least one.  Two if you want data to be replicated.
> ;  Define as many as you like.
> [osd]
> 	; This is where the btrfs volume will be mounted.
> 	osd data = /var/ceph/osd$id
> 
> 	; Ideally, make this a separate disk or partition.  A few GB
>  	; is usually enough; more if you have fast disks.  You can use
>  	; a file under the osd data dir if need be
>  	; (e.g. /data/osd$id/journal), but it will be slower than a
>  	; separate disk or partition.
> 	osd journal = /var/ceph/osd$id/journal
> 
> [osd0]
> 	host = node141
> [osd1]
> 	host = node145
> [osd2]
> 	host = node150
> [osd3]
> 	host = node146
> [osd4]
> 	host = node147
> [osd5]
> 	host = node149
> [osd6]
> 	host = node142
> -- 
> The only person who always got his work done by Friday was Robinson Crusoe
> 

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Andre Noll]

[-- Attachment #1: Type: text/plain, Size: 2965 bytes --]

On 10:28, Sage Weil wrote:

> So, the mmap code in buffer.h is actually never called, so my guess is 
> that posix_memalign() or some other library implementation is doing it.  
> Can you get a stack trace?  Either look at the core file with gdb or run 
> cosd via gdb?

Sure. Here we go:

	root@node142:~# gdb /usr/local/bin/cosd
	GNU gdb 6.8-debian
	Copyright (C) 2008 Free Software Foundation, Inc.
	License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
	This is free software: you are free to change and redistribute it.
	There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
	and "show warranty" for details.
	This GDB was configured as "x86_64-linux-gnu"...
	(gdb) run -f -i 6 -c /etc/ceph/ceph.conf
	Starting program: /usr/local/bin/cosd -f -i 6 -c /etc/ceph/ceph.conf
	[Thread debugging using libthread_db enabled]
	 ** WARNING: Ceph is still under heavy development, and is only suitable for **
	 **          testing and review.  Do not trust it with important data.       **
	starting osd6 at 0.0.0.0:6800/3869 osd_data /var/ceph/osd6 /var/ceph/osd6/journal
	[New Thread 0x7f995df606f0 (LWP 3869)]
	[New Thread 0x4227e950 (LWP 3872)]
	[New Thread 0x41896950 (LWP 3873)]
	[New Thread 0x42a7f950 (LWP 3874)]
	[New Thread 0x43280950 (LWP 3875)]
	[New Thread 0x43a81950 (LWP 3876)]
	[New Thread 0x40dd1950 (LWP 3877)]
	[New Thread 0x44282950 (LWP 3878)]
	[New Thread 0x44a83950 (LWP 3879)]
	[New Thread 0x45284950 (LWP 3880)]
	[New Thread 0x45a85950 (LWP 3881)]
	terminate called after throwing an instance of 'std::bad_alloc'
	  what():  std::bad_alloc

	Program received signal SIGABRT, Aborted.
	[Switching to Thread 0x7f995df606f0 (LWP 3869)]
	0x00007f995caf3095 in raise () from /lib/libc.so.6
	(gdb)  bt
	#0  0x00007f995caf3095 in raise () from /lib/libc.so.6
	#1  0x00007f995caf4af0 in abort () from /lib/libc.so.6
	#2  0x00007f995d3780e4 in __gnu_cxx::__verbose_terminate_handler () from /usr/lib/libstdc++.so.6
	#3  0x00007f995d376076 in ?? () from /usr/lib/libstdc++.so.6
	#4  0x00007f995d3760a3 in std::terminate () from /usr/lib/libstdc++.so.6
	#5  0x00007f995d37618a in __cxa_throw () from /usr/lib/libstdc++.so.6
	#6  0x00007f995d376649 in operator new () from /usr/lib/libstdc++.so.6
	#7  0x00007f995d376709 in operator new[] () from /usr/lib/libstdc++.so.6
	#8  0x0000000000540920 in PG::read_log (this=0x7f995845be60, store=<value optimized out>) at ./include/cstring.h:120
	#9  0x0000000000543187 in PG::read_state (this=0x7f995845be60, store=0x8a4840) at osd/PG.cc:2294
	#10 0x00000000004ec1f9 in OSD::load_pgs (this=0x8a04b0) at osd/OSD.cc:884
	#11 0x00000000004ecb00 in OSD::init (this=0x8a04b0) at osd/OSD.cc:462
	#12 0x000000000045f2cc in main (argc=<value optimized out>, argv=<value optimized out>) at cosd.cc:171

Thanks for looking into this.
Andre
-- 
The only person who always got his work done by Friday was Robinson Crusoe

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Sage Weil]

Hi Andre,

On Wed, 2 Jun 2010, Andre Noll wrote:
> On 10:28, Sage Weil wrote:
> 
> > So, the mmap code in buffer.h is actually never called, so my guess is 
> > that posix_memalign() or some other library implementation is doing it.  
> > Can you get a stack trace?  Either look at the core file with gdb or run 
> > cosd via gdb?
> 
> Sure. Here we go:

Okay, it looks like there is a corrupt PG log.  Can you tar up the 
$osd_data/current/meta directory, and then 'f 8' and 'p /x info.pgid' from 
gdb (to figure out which pg it's loading)?

There is an open bug for pglog corruption, but I haven't been able to 
identify where it's actually happening.

Generally speaking, once you identify the bad pg, you can just delete the 
offending pglog and data directory from the osd, restart, and it will 
recover.  Provided you haven't corrupted both copies of the same pg on 
different osds.  Or more often than not, there is more than one corrupted 
log, and you have to repeat the process a few times.

This is probably the sort of corruption that we should log but not crash 
on, so that the osd can continue to start up (and just skip the offending 
pg).  I'll open an issue for that in the tracker.

Thanks-
sage



 > 
> 	root@node142:~# gdb /usr/local/bin/cosd
> 	GNU gdb 6.8-debian
> 	Copyright (C) 2008 Free Software Foundation, Inc.
> 	License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
> 	This is free software: you are free to change and redistribute it.
> 	There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
> 	and "show warranty" for details.
> 	This GDB was configured as "x86_64-linux-gnu"...
> 	(gdb) run -f -i 6 -c /etc/ceph/ceph.conf
> 	Starting program: /usr/local/bin/cosd -f -i 6 -c /etc/ceph/ceph.conf
> 	[Thread debugging using libthread_db enabled]
> 	 ** WARNING: Ceph is still under heavy development, and is only suitable for **
> 	 **          testing and review.  Do not trust it with important data.       **
> 	starting osd6 at 0.0.0.0:6800/3869 osd_data /var/ceph/osd6 /var/ceph/osd6/journal
> 	[New Thread 0x7f995df606f0 (LWP 3869)]
> 	[New Thread 0x4227e950 (LWP 3872)]
> 	[New Thread 0x41896950 (LWP 3873)]
> 	[New Thread 0x42a7f950 (LWP 3874)]
> 	[New Thread 0x43280950 (LWP 3875)]
> 	[New Thread 0x43a81950 (LWP 3876)]
> 	[New Thread 0x40dd1950 (LWP 3877)]
> 	[New Thread 0x44282950 (LWP 3878)]
> 	[New Thread 0x44a83950 (LWP 3879)]
> 	[New Thread 0x45284950 (LWP 3880)]
> 	[New Thread 0x45a85950 (LWP 3881)]
> 	terminate called after throwing an instance of 'std::bad_alloc'
> 	  what():  std::bad_alloc
> 
> 	Program received signal SIGABRT, Aborted.
> 	[Switching to Thread 0x7f995df606f0 (LWP 3869)]
> 	0x00007f995caf3095 in raise () from /lib/libc.so.6
> 	(gdb)  bt
> 	#0  0x00007f995caf3095 in raise () from /lib/libc.so.6
> 	#1  0x00007f995caf4af0 in abort () from /lib/libc.so.6
> 	#2  0x00007f995d3780e4 in __gnu_cxx::__verbose_terminate_handler () from /usr/lib/libstdc++.so.6
> 	#3  0x00007f995d376076 in ?? () from /usr/lib/libstdc++.so.6
> 	#4  0x00007f995d3760a3 in std::terminate () from /usr/lib/libstdc++.so.6
> 	#5  0x00007f995d37618a in __cxa_throw () from /usr/lib/libstdc++.so.6
> 	#6  0x00007f995d376649 in operator new () from /usr/lib/libstdc++.so.6
> 	#7  0x00007f995d376709 in operator new[] () from /usr/lib/libstdc++.so.6
> 	#8  0x0000000000540920 in PG::read_log (this=0x7f995845be60, store=<value optimized out>) at ./include/cstring.h:120
> 	#9  0x0000000000543187 in PG::read_state (this=0x7f995845be60, store=0x8a4840) at osd/PG.cc:2294
> 	#10 0x00000000004ec1f9 in OSD::load_pgs (this=0x8a04b0) at osd/OSD.cc:884
> 	#11 0x00000000004ecb00 in OSD::init (this=0x8a04b0) at osd/OSD.cc:462
> 	#12 0x000000000045f2cc in main (argc=<value optimized out>, argv=<value optimized out>) at cosd.cc:171
> 
> Thanks for looking into this.
> Andre
> -- 
> The only person who always got his work done by Friday was Robinson Crusoe
> 

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Andre Noll]

[-- Attachment #1: Type: text/plain, Size: 1752 bytes --]

On Wed, Jun 02, 11:19, Sage Weil Wrote
> Okay, it looks like there is a corrupt PG log.  Can you tar up the 
> $osd_data/current/meta directory, and then 'f 8' and 'p /x info.pgid' from 
> gdb (to figure out which pg it's loading)?

It's in decode_nohead():

	...
	Program received signal SIGABRT, Aborted.
	[Switching to Thread 0x7ff115b566f0 (LWP 5045)]
	0x00007ff1146e9095 in raise () from /lib/libc.so.6
	(gdb) f 8
	#8  0x0000000000540920 in PG::read_log (this=0x7ff1104b6460,
	store=<value optimized out>) at ./include/cstring.h:120
	120         _data = new char[_len + 1];
	(gdb) p /x info.pgid
	$1 = {v = {preferred = {v = 0xffff}, ps = {v = 0x1bf}, pool = {v = 0x0}}}

> There is an open bug for pglog corruption, but I haven't been able to 
> identify where it's actually happening.

How can one determine the pg from the above output? BTW: cosd has
/var/ceph/osd6/current/commit_op_seq open and this file contains the
number 1103797. Does that tell us anything?

> Generally speaking, once you identify the bad pg, you can just delete the 
> offending pglog and data directory from the osd, restart, and it will 
> recover.  Provided you haven't corrupted both copies of the same pg on 
> different osds.  Or more often than not, there is more than one corrupted 
> log, and you have to repeat the process a few times.

That's valuable information, thanks. It should probably be documented
somewhere.

> This is probably the sort of corruption that we should log but not crash 
> on, so that the osd can continue to start up (and just skip the offending 
> pg).  I'll open an issue for that in the tracker.

Thanks
Andre
-- 
The only person who always got his work done by Friday was Robinson Crusoe

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Sage Weil]

On Fri, 4 Jun 2010, Andre Noll wrote:
> On Wed, Jun 02, 11:19, Sage Weil Wrote
> > Okay, it looks like there is a corrupt PG log.  Can you tar up the 
> > $osd_data/current/meta directory, and then 'f 8' and 'p /x info.pgid' from 
> > gdb (to figure out which pg it's loading)?
> 
> It's in decode_nohead():
> 
> 	...
> 	Program received signal SIGABRT, Aborted.
> 	[Switching to Thread 0x7ff115b566f0 (LWP 5045)]
> 	0x00007ff1146e9095 in raise () from /lib/libc.so.6
> 	(gdb) f 8
> 	#8  0x0000000000540920 in PG::read_log (this=0x7ff1104b6460,
> 	store=<value optimized out>) at ./include/cstring.h:120
> 	120         _data = new char[_len + 1];
> 	(gdb) p /x info.pgid
> 	$1 = {v = {preferred = {v = 0xffff}, ps = {v = 0x1bf}, pool = {v = 0x0}}}

The pgid's format like $pool.$ps[p$preferred] (where the preferred bit 
only shows up if >= 0).  In hex.  So the pgid above is 0.1bf, and the 
corrupted log should be current/meta/pglog_0.1bf_0.  If you send me that 
file (off list) I can see what the corruption looks like.

If you want to try to bring the osd up without that pg, you can move that 
pglog file and current/0.1bf to some other temp directory and restart 
cosd.

Thanks!
sage

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Andre Noll]

[-- Attachment #1: Type: text/plain, Size: 1664 bytes --]

On Fri, Jun 04, 09:48, Sage Weil Wrote
> On Fri, 4 Jun 2010, Andre Noll wrote:
> > On Wed, Jun 02, 11:19, Sage Weil Wrote
> > > Okay, it looks like there is a corrupt PG log.  Can you tar up the 
> > > $osd_data/current/meta directory, and then 'f 8' and 'p /x info.pgid' from 
> > > gdb (to figure out which pg it's loading)?
> > 
> > It's in decode_nohead():
> > 
> > 	...
> > 	Program received signal SIGABRT, Aborted.
> > 	[Switching to Thread 0x7ff115b566f0 (LWP 5045)]
> > 	0x00007ff1146e9095 in raise () from /lib/libc.so.6
> > 	(gdb) f 8
> > 	#8  0x0000000000540920 in PG::read_log (this=0x7ff1104b6460,
> > 	store=<value optimized out>) at ./include/cstring.h:120
> > 	120         _data = new char[_len + 1];
> > 	(gdb) p /x info.pgid
> > 	$1 = {v = {preferred = {v = 0xffff}, ps = {v = 0x1bf}, pool = {v = 0x0}}}
> 
> The pgid's format like $pool.$ps[p$preferred] (where the preferred bit 
> only shows up if >= 0).  In hex.  So the pgid above is 0.1bf, and the 
> corrupted log should be current/meta/pglog_0.1bf_0.  If you send me that 
> file (off list) I can see what the corruption looks like.

Thanks for the explanation. I'll send it off-list in a minute.
It's 361K large.

> If you want to try to bring the osd up without that pg, you can move that 
> pglog file and current/0.1bf to some other temp directory and restart 
> cosd.

Did not work. It recreated that file and then crashed for the same
reason. The gdb output is identical, but the file contents have
changed. I'll send the new pglog_0.1bf_0 as well.

Thanks
Andre
-- 
The only person who always got his work done by Friday was Robinson Crusoe

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Sage Weil]

Hmm, okay.  Unfortunately the logs don't have any clues.  I'm giving on up 
solving the mystery this time around.  You can go ahead and stop all the 
daemons and re-run mkcephfs. 

I've added a 'scripts/check_pglog.sh $osddatadir' script that will just 
look for any corruption.  Running that periodically will let you verify 
that you haven't hit the same corruption without having to restart cosd.  
Ideally we can figure out what kind of workloads are triggering the 
problem, and then reproduce it with sufficient logging enabled to find 
where the race is taking place.

If you have any details about the workload or any failure/recovery 
activity that may have been going on at the time that may shed some light 
on it...

FYI, this is http://tracker.newdream.net/issues/114

Thanks!
sage


On Tue, 8 Jun 2010, Andre Noll wrote:

> On Mon, Jun 07, 10:20, Sage Weil wrote:
> 
> > Do you have osd logs?
> 
> Should all be there. At least I did not remove anything.
> 
> > This is the same corruption I've seen previously, but I've just
> > reaudited the code I suspect and it looks ok.  Some insight into what
> > happened to the cluster would help.  Which osd is it?
> 
> It's osd6 running on node142. I was running osd from ceph-v0.20.2 but
> also tried the osd compiled from the "testing" branch of the git repo.
> 
> > Do you still have the logs (/var/log/ceph/osd$n*)?  The osdmap
> > sequence (tarball of $mon_data/osdmap) would be helpful too.
> 
> I created a tarball of the full /var/log/ceph directory of node142
> (which is only a storage node) and will send it to you off-line.
> 
> We have three monitors. I'll send a tarball of /var/ceph/mon0/monmap/
> of mon0 (node141) as well.
> 
> Thanks
> Andre
> -- 
> The only person who always got his work done by Friday was Robinson Crusoe
> 

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Andre Noll]

[-- Attachment #1: Type: text/plain, Size: 1673 bytes --]

On Tue, Jun 08, 22:54, Sage Weil wrote:
> Hmm, okay.  Unfortunately the logs don't have any clues.  I'm giving on up 
> solving the mystery this time around.  You can go ahead and stop all the 
> daemons and re-run mkcephfs. 

OK, there was only stress-test data on the cephfs anyway. I'll start
from scratch and run another set of tests. Fortunately we haven't
told the users about the shiny new file systems yet, so we are in no
hurry ;)

> I've added a 'scripts/check_pglog.sh $osddatadir' script that will just 
> look for any corruption.  Running that periodically will let you verify 
> that you haven't hit the same corruption without having to restart cosd.  

Goodie. I'll set up a cron job to run this automatically. Should I
do this on each osd?

> Ideally we can figure out what kind of workloads are triggering the 
> problem, and then reproduce it with sufficient logging enabled to find 
> where the race is taking place.
>
> If you have any details about the workload or any failure/recovery 
> activity that may have been going on at the time that may shed some light 
> on it...

Funny enough, the problem occurred while the fs was idle. I ran
some simple tests a few days earlier and these completed with no
problems. From that point on, nobody ever accessed it.

I'll let you know if I can trigger it reliably. If you have any
suggestions for a workload that is likely to trigger the race, I'm
happy to give it a try. Otherwise, I'll just use "stress" again to
write to the cephfs from a couple of clients simultaneously.

Thanks
Andre
-- 
The only person who always got his work done by Friday was Robinson Crusoe

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Sage Weil]

> > I've added a 'scripts/check_pglog.sh $osddatadir' script that will just 
> > look for any corruption.  Running that periodically will let you verify 
> > that you haven't hit the same corruption without having to restart cosd.  
> 
> Goodie. I'll set up a cron job to run this automatically. Should I
> do this on each osd?

Yeah, that would be ideal.

> > Ideally we can figure out what kind of workloads are triggering the 
> > problem, and then reproduce it with sufficient logging enabled to find 
> > where the race is taking place.
> >
> > If you have any details about the workload or any failure/recovery 
> > activity that may have been going on at the time that may shed some light 
> > on it...
> 
> Funny enough, the problem occurred while the fs was idle. I ran
> some simple tests a few days earlier and these completed with no
> problems. From that point on, nobody ever accessed it.
>
> I'll let you know if I can trigger it reliably. If you have any
> suggestions for a workload that is likely to trigger the race, I'm
> happy to give it a try. Otherwise, I'll just use "stress" again to
> write to the cephfs from a couple of clients simultaneously.

I think the corruption can happen when the osd map updates.  The problem 
is that the corrupt data is never read until cosd is restarted, usually a 
long time after the actual problem occurred, so adding that cron job 
should help narrow it down.

I would just proceed with your usual testing and see what happens.

Thanks!
sage

Re: osd: terminate called after throwing an instance of 'std::bad_alloc'

[Andre Noll]

[-- Attachment #1: Type: text/plain, Size: 3579 bytes --]

On Wed, Jun 09, 10:29, Sage Weil wrote:

> > I'll let you know if I can trigger it reliably.

I recreated the cephfs using the same setup (7 osds, 3 mons, 3 mds),
and the problem happened again, this time while running "stress"
from two clients over the weekend.

This morning all stress processes were stuck in state D and access
to the ceph fs blocks. Not even ls -l works.  I rebooted one machine
that was running stress, cosd, cmds and cmon. Had to power cycle it
as reboot was unable to kill the stress processes.

On reboot, cosd crashes after a few seconds due to hitting

	assert(recovering_oids.count(soid) == 0

in start_recovery_op(). gdb output:


	osd/PG.cc: In function 'void PG::start_recovery_op(const sobject_t&)':
	osd/PG.cc:1833: FAILED assert(recovering_oids.count(soid) == 0)
	 1: (ReplicatedPG::issue_repop(ReplicatedPG::RepGather*, utime_t, eversion_t, bool, unsigned long, eversion_t)+0x84e) [0x49c88e]
	 2: (ReplicatedPG::do_op(MOSDOp*)+0xa9a) [0x4a22ba]
	 3: (OSD::dequeue_op(PG*)+0x402) [0x4e4dc2]
	 4: (ThreadPool::worker()+0x1fc) [0x5ec64c]
	 5: (ThreadPool::WorkThread::entry()+0xd) [0x50480d]
	 6: (Thread::_entry_func(void*)+0x7) [0x476f57]
	 7: /lib/libpthread.so.0 [0x7fc9556523f7]
	 8: (clone()+0x6d) [0x7fc9548a7b4d]
	 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
	terminate called after throwing an instance of 'ceph::FailedAssertion*'

	Program received signal SIGABRT, Aborted.

	(gdb) bt
	#0  0x00007fc954802095 in raise () from /lib/libc.so.6
	#1  0x00007fc954803af0 in abort () from /lib/libc.so.6
	#2  0x00007fc9550870e4 in __gnu_cxx::__verbose_terminate_handler () from /usr/lib/libstdc++.so.6
	#3  0x00007fc955085076 in ?? () from /usr/lib/libstdc++.so.6
	#4  0x00007fc9550850a3 in std::terminate () from /usr/lib/libstdc++.so.6
	#5  0x00007fc95508518a in __cxa_throw () from /usr/lib/libstdc++.so.6
	#6  0x00000000005eb22f in ceph::__ceph_assert_fail (assertion=0x6211d0 "recovering_oids.count(soid) == 0", file=0x620113 "osd/PG.cc", line=1833, 
	    func=0x622140 "void PG::start_recovery_op(const sobject_t&)") at common/assert.cc:30
	#7  0x0000000000546b68 in PG::start_recovery_op (this=0xa846d0, soid=@0x12ceb98) at osd/PG.cc:1833
	#8  0x000000000049c88e in ReplicatedPG::issue_repop (this=0xa846d0, repop=0x1296d70, now=<value optimized out>, old_last_update=
	      {version = 249, epoch = 137, __pad = 0}, old_exists=true, old_size=4194304, old_version={version = 249, epoch = 137, __pad = 0})
	    at osd/ReplicatedPG.cc:2280
	#9  0x00000000004a22ba in ReplicatedPG::do_op (this=0xa846d0, op=<value optimized out>) at osd/ReplicatedPG.cc:637
	#10 0x00000000004e4dc2 in OSD::dequeue_op (this=0x8a9fc0, pg=0xa846d0) at osd/OSD.cc:4456
	#11 0x00000000005ec64c in ThreadPool::worker (this=0x8aa478) at common/WorkQueue.cc:44
	#12 0x000000000050480d in ThreadPool::WorkThread::entry (this=<value optimized out>) at ./common/WorkQueue.h:113
	#13 0x0000000000476f57 in Thread::_entry_func (arg=0xa63) at ./common/Thread.h:39
	#14 0x00007fc9556523f7 in start_thread () from /lib/libpthread.so.0
	#15 0x00007fc9548a7b4d in clone () from /lib/libc.so.6
	#16 0x0000000000000000 in ?? ()

I also ran the checkpg script as you suggested, but this did not find
any corrupted pgs. The tip of the git branch this cosd was compiled
from is

	214a42798b4a5cd57d09c6a13b39b17c4f616aa3 (mds: handle dup anchorclient ACKs gracefully)

Any hints?
Andre
-- 
The only person who always got his work done by Friday was Robinson Crusoe

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]