Bug #9768
Updated by Loïc Dachary over 9 years ago
<pre>
$ ceph --version
ceph version 0.80.6 (f93610a4421cb670b08e974c6550ee715ac528ae)
$ uname -a
Linux g3 3.14-2-amd64 #1 SMP Debian 3.14.15-2 (2014-08-09) x86_64 GNU/Linux
</pre>
<pre>
$ ceph-disk prepare --mkfs ext4 /dev/sdc
$ ps fauwwwx | grep mkfs
root 366 0.0 0.0 40672 1548 ? Ss Oct10 0:00 udevd --daemon
root 21963 0.0 0.0 40644 1360 ? S 13:57 0:00 \_ udevd --daemon
root 21988 0.0 0.0 4308 636 ? S 13:57 0:00 | \_ /bin/sh /usr/sbin/ceph-disk-activate /dev/sdc1
root 21991 0.2 0.0 48736 9968 ? S 13:57 0:00 | \_ /usr/bin/python /usr/sbin/ceph-disk activate /dev/sdc1
root 22082 0.0 0.0 192040 8820 ? Sl 13:57 0:00 | \_ /usr/bin/ceph-osd --cluster ceph --mkfs --mkkey -i 6 --monmap /var/lib/ceph/tmp/mnt.5mDa2j/activate.monmap --osd-data /var/lib/ceph/tmp/mnt.5mDa2j --osd-journal /var/lib/ceph/tmp/mnt.5mDa2j/journal --osd-uuid 0b27732f-bee9-4212-9395-bad5eaeffc37 --keyring /var/lib/ceph/tmp/mnt.5mDa2j/keyring
</pre>
The log with debug_filestore=20
<pre>
2014-10-14 14:01:41.906165 7fbacf2077c0 0 ceph version 0.80.6 (f93610a4421cb670b08e974c6550ee715ac528ae), process ceph-osd, pid 24349
2014-10-14 14:01:41.908424 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) dump_stop
2014-10-14 14:01:41.908750 7fbacf2077c0 10 -- :/0 ready :/0
2014-10-14 14:01:41.908783 7fbacf2077c0 1 -- :/0 messenger.start
2014-10-14 14:01:41.908817 7fbacf2077c0 10 -- :/24349 shutdown :/24349
2014-10-14 14:01:41.908822 7fbacf2077c0 1 -- :/24349 mark_down_all
2014-10-14 14:01:41.908830 7fbacf2077c0 10 -- :/24349 wait: waiting for dispatch queue
2014-10-14 14:01:41.908841 7fbac9735700 10 -- :/24349 reaper_entry start
2014-10-14 14:01:41.908863 7fbac9735700 10 -- :/24349 reaper
2014-10-14 14:01:41.908868 7fbac9735700 10 -- :/24349 reaper done
2014-10-14 14:01:41.908867 7fbacf2077c0 10 -- :/24349 wait: dispatch queue is stopped
2014-10-14 14:01:41.908882 7fbac9735700 10 -- :/24349 reaper_entry done
2014-10-14 14:01:41.908953 7fbacf2077c0 10 -- :/24349 wait: closing pipes
2014-10-14 14:01:41.908975 7fbacf2077c0 10 -- :/24349 reaper
2014-10-14 14:01:41.908978 7fbacf2077c0 10 -- :/24349 reaper done
2014-10-14 14:01:41.908980 7fbacf2077c0 10 -- :/24349 wait: waiting for pipes to close
2014-10-14 14:01:41.908982 7fbacf2077c0 10 -- :/24349 wait: done.
2014-10-14 14:01:41.908983 7fbacf2077c0 1 -- :/24349 shutdown complete.
2014-10-14 14:01:41.909008 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkfs in /var/lib/ceph/tmp/mnt.CDjohX
2014-10-14 14:01:41.909030 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkfs fsid is already set to 0d11281e-1c65-4a45-952c-c0523675b15f
2014-10-14 14:01:41.968445 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) leveldb db exists/created
2014-10-14 14:01:41.968474 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) open_journal at /var/lib/ceph/tmp/mnt.CDjohX/journal
2014-10-14 14:01:41.970890 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 11: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1
2014-10-14 14:01:41.971213 7fbacf2077c0 -1 journal check: ondisk fsid 0b27732f-bee9-4212-9395-bad5eaeffc37 doesn't match expected 0d11281e-1c65-4a45-952c-c0523675b15f, invalid (someone else's?) journal
2014-10-14 14:01:41.973309 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 11: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1
2014-10-14 14:01:41.983002 7fbacf2077c0 0 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkjournal created journal on /var/lib/ceph/tmp/mnt.CDjohX/journal
2014-10-14 14:01:41.983048 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkfs done in /var/lib/ceph/tmp/mnt.CDjohX
2014-10-14 14:01:41.983064 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) basedir /var/lib/ceph/tmp/mnt.CDjohX journal /var/lib/ceph/tmp/mnt.CDjohX/journal
2014-10-14 14:01:41.983086 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mount fsid is 0d11281e-1c65-4a45-952c-c0523675b15f
2014-10-14 14:01:41.990817 7fbacf2077c0 0 genericfilestorebackend(/var/lib/ceph/tmp/mnt.CDjohX) detect_features: FIEMAP ioctl is supported and appears to work
2014-10-14 14:01:41.990833 7fbacf2077c0 0 genericfilestorebackend(/var/lib/ceph/tmp/mnt.CDjohX) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2014-10-14 14:01:41.996025 7fbacf2077c0 0 genericfilestorebackend(/var/lib/ceph/tmp/mnt.CDjohX) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
2014-10-14 14:01:42.014473 7fbacf2077c0 0 filestore(/var/lib/ceph/tmp/mnt.CDjohX) limited size xattrs
2014-10-14 14:01:42.014581 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mount op_seq is 1
2014-10-14 14:01:42.034149 7fbacf2077c0 20 filestore (init)dbobjectmap: seq is 1
2014-10-14 14:01:42.034177 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) open_journal at /var/lib/ceph/tmp/mnt.CDjohX/journal
2014-10-14 14:01:42.034206 7fbacf2077c0 0 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2014-10-14 14:01:42.034212 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) list_collections
2014-10-14 14:01:42.034321 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000
2014-10-14 14:01:42.036454 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 17: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1
2014-10-14 14:01:42.038633 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 17: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1
2014-10-14 14:01:42.038926 7fbacf2077c0 15 filestore(/var/lib/ceph/tmp/mnt.CDjohX) read meta/23c2fcde/osd_superblock/0//-1 0~0
2014-10-14 14:01:42.038999 7fbacf2077c0 -1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) could not find 23c2fcde/osd_superblock/0//-1 in index: (2) No such file or directory
2014-10-14 14:01:42.039019 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) FileStore::read(meta/23c2fcde/osd_superblock/0//-1) open error: (2) No such file or directory
2014-10-14 14:01:42.039068 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) queue_transactions new osr(default 0x7fbad228cb98)/0x7fbad228cb98
2014-10-14 14:01:42.039082 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) queue_transactions (writeahead) 2 0x7fff05f7dd80
2014-10-14 14:01:47.034856 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry woke after 5.000534
2014-10-14 14:01:47.034895 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000
2014-10-14 14:01:52.035013 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry woke after 5.000115
2014-10-14 14:01:52.035056 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000
2014-10-14 14:01:57.035129 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry woke after 5.000073
2014-10-14 14:01:57.035161 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000
....
</pre>
stack trace
<pre>
(gdb) thread apply all bt
Thread 14 (Thread 0x7f3177cd8700 (LWP 23461)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b67413b in ceph::log::Log::entry() ()
#2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3177cd8700) at pthread_create.c:309
#3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 13 (Thread 0x7f3176d4e700 (LWP 23462)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1 0x00007f317b74021b in CephContextServiceThread::entry() ()
#2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3176d4e700) at pthread_create.c:309
#3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 12 (Thread 0x7f317654d700 (LWP 23463)):
#0 0x00007f3178c370ed in poll () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007f317b726433 in AdminSocket::entry() ()
#2 0x00007f317a4dc0a4 in start_thread (arg=0x7f317654d700) at pthread_create.c:309
#3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 11 (Thread 0x7f317554b700 (LWP 23470)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b595dbf in WBThrottle::get_next_should_flush(boost::tuples::tuple<ghobject_t, std::tr1::shared_ptr<FDCache::FD>, WBThrottle::PendingWB, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type>*) ()
#2 0x00007f317b596c83 in WBThrottle::entry() ()
#3 0x00007f317a4dc0a4 in start_thread (arg=0x7f317554b700) at pthread_create.c:309
#4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 10 (Thread 0x7f3175d4c700 (LWP 23471)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1 0x00007f317b51fc0d in Cond::WaitInterval(CephContext*, Mutex&, utime_t) ()
#2 0x00007f317b4ea490 in FileStore::sync_entry() ()
#3 0x00007f317b52076d in FileStore::SyncThread::entry() ()
#4 0x00007f317a4dc0a4 in start_thread (arg=0x7f3175d4c700) at pthread_create.c:309
#5 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 9 (Thread 0x7f3174d4a700 (LWP 23476)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b613286 in FileJournal::write_thread_entry() ()
#2 0x00007f317b51ee8d in FileJournal::Writer::entry() ()
#3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3174d4a700) at pthread_create.c:309
#4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 8 (Thread 0x7f3174549700 (LWP 23477)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b2bee06 in Cond::Wait(Mutex&) ()
#2 0x00007f317b610eea in FileJournal::write_finish_thread_entry() ()
#3 0x00007f317b51efad in FileJournal::WriteFinisher::entry() ()
#4 0x00007f317a4dc0a4 in start_thread (arg=0x7f3174549700) at pthread_create.c:309
#5 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 7 (Thread 0x7f3173d48700 (LWP 23478)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b6625f8 in Finisher::finisher_thread_entry() ()
#2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3173d48700) at pthread_create.c:309
#3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 6 (Thread 0x7f3173547700 (LWP 23479)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1 0x00007f317b71cb32 in ThreadPool::worker(ThreadPool::WorkThread*) ()
#2 0x00007f317b71dd90 in ThreadPool::WorkThread::entry() ()
#3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3173547700) at pthread_create.c:309
#4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 5 (Thread 0x7f3172d46700 (LWP 23480)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1 0x00007f317b71cb32 in ThreadPool::worker(ThreadPool::WorkThread*) ()
#2 0x00007f317b71dd90 in ThreadPool::WorkThread::entry() ()
#3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3172d46700) at pthread_create.c:309
#4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 4 (Thread 0x7f3172545700 (LWP 23481)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b6625f8 in Finisher::finisher_thread_entry() ()
#2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3172545700) at pthread_create.c:309
#3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 3 (Thread 0x7f3171d44700 (LWP 23482)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b6625f8 in Finisher::finisher_thread_entry() ()
#2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3171d44700) at pthread_create.c:309
#3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 2 (Thread 0x7f3171543700 (LWP 23483)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b717d84 in SafeTimer::timer_thread() ()
#2 0x00007f317b71892d in SafeTimerThread::entry() ()
#3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3171543700) at pthread_create.c:309
#4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thread 1 (Thread 0x7f317b01d7c0 (LWP 23460)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f317b35bbf4 in ObjectStore::apply_transactions(ObjectStore::Sequencer*, std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, Context*) ()
#2 0x00007f317b2c0d08 in ObjectStore::apply_transaction(ObjectStore::Transaction&, Context*) ()
#3 0x00007f317b27374a in OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int) ()
#4 0x00007f317b24a872 in main ()
</pre>