Project

General

Profile

Actions
Copy link

Bug #17201

closed

helgrind: false positive lock order violation between journal and librbd

Added by Jason Dillaman over 7 years ago. Updated over 7 years ago.

Status:
Won't Fix
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
other
Tags:
Backport:
jewel
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

2016-09-01T20:25:58.599 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Thread #21: lock order "0x7CA9070 before 0x7CF3C28" violated
2016-09-01T20:25:58.599 INFO:tasks.workunit.client.0.vpm041.stderr:==21289==
2016-09-01T20:25:58.600 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Observed (incorrect) order is: acquisition of lock at 0x7CF3C28
2016-09-01T20:25:58.600 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== at 0x4C32536: pthread_mutex_lock (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.601 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135EF387: Mutex::Lock(bool) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.602 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135D9211: journal::JournalRecorder::flush(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.602 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135C3C04: journal::Journaler::stop_append(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.602 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350D737: librbd::Journal<librbd::ImageCtx>::close(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.603 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353A953: librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>::send_close_journal() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.603 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353AC93: librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>::handle_flush_notifies(int*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.604 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353AE3A: librbd::util::detail::C_StateCallbackAdapter<librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>, &librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>::handle_flush_notifies, true>::complete(int) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.604 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134C3623: ContextWQ::process(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.604 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13617B94: ThreadPool::worker(ThreadPool::WorkThread*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.605 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13618B7F: ThreadPool::WorkThread::entry() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.609 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x4C30FA6: ? (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.610 INFO:tasks.workunit.client.0.vpm041.stderr:==21289==
2016-09-01T20:25:58.610 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== followed by a later acquisition of lock at 0x7CA9070
2016-09-01T20:25:58.611 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== at 0x4C32536: pthread_mutex_lock (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.611 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135EF387: Mutex::Lock(bool) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.612 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135E5B66: journal::ObjectRecorder::cancel_append_task() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.612 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135E84F4: journal::ObjectRecorder::flush(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.613 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135D9298: journal::JournalRecorder::flush(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.613 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135C3C04: journal::Journaler::stop_append(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.614 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350D737: librbd::Journal<librbd::ImageCtx>::close(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.614 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353A953: librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>::send_close_journal() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.615 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353AC93: librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>::handle_flush_notifies(int*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.615 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353AE3A: librbd::util::detail::C_StateCallbackAdapter<librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>, &librbd::exclusive_lock::ReleaseRequest<librbd::ImageCtx>::handle_flush_notifies, true>::complete(int) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.616 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134C3623: ContextWQ::process(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.616 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13617B94: ThreadPool::worker(ThreadPool::WorkThread*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.617 INFO:tasks.workunit.client.0.vpm041.stderr:==21289==
2016-09-01T20:25:58.617 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Lock at 0x7CA9070 was first observed
2016-09-01T20:25:58.618 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== at 0x4C321AA: pthread_mutex_init (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.618 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135EF088: Mutex::Mutex(std::string const&, bool, bool, bool, CephContext*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.618 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134BF950: librbd::ImageCtx::get_timer_instance(CephContext*, SafeTimer**, Mutex**) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.621 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1355B258: librbd::journal::CreateRequest<librbd::ImageCtx>::create_journal() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.622 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1355C9C7: librbd::journal::CreateRequest<librbd::ImageCtx>::get_pool_id() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.622 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1355CC39: librbd::journal::CreateRequest<librbd::ImageCtx>::send() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.622 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353FF21: librbd::image::CreateRequest<librbd::ImageCtx>::journal_create() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.622 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1354079A: librbd::image::CreateRequest<librbd::ImageCtx>::handle_fetch_mirror_mode(int*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13541E7D: void librbd::util::detail::rados_state_callback<librbd::image::CreateRequest<librbd::ImageCtx>, &librbd::image::CreateRequest<librbd::ImageCtx>::handle_fetch_mirror_mode, true>(void*, void*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x82FD69C: librados::C_AioComplete::finish(int) (in /usr/lib/librados.so.2.0.0)
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x82E1738: Context::complete(int) (in /usr/lib/librados.so.2.0.0)
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x838EB55: Finisher::finisher_thread_entry() (in /usr/lib/librados.so.2.0.0)
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Address 0x7ca9070 is 224 bytes inside a block of size 296 alloc'd
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== at 0x4C2C500: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.623 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134BF8F1: librbd::ImageCtx::get_timer_instance(CephContext*, SafeTimer**, Mutex**) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1355B258: librbd::journal::CreateRequest<librbd::ImageCtx>::create_journal() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1355C9C7: librbd::journal::CreateRequest<librbd::ImageCtx>::get_pool_id() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1355CC39: librbd::journal::CreateRequest<librbd::ImageCtx>::send() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1353FF21: librbd::image::CreateRequest<librbd::ImageCtx>::journal_create() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1354079A: librbd::image::CreateRequest<librbd::ImageCtx>::handle_fetch_mirror_mode(int*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13541E7D: void librbd::util::detail::rados_state_callback<librbd::image::CreateRequest<librbd::ImageCtx>, &librbd::image::CreateRequest<librbd::ImageCtx>::handle_fetch_mirror_mode, true>(void*, void*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x82FD69C: librados::C_AioComplete::finish(int) (in /usr/lib/librados.so.2.0.0)
2016-09-01T20:25:58.624 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x82E1738: Context::complete(int) (in /usr/lib/librados.so.2.0.0)
2016-09-01T20:25:58.625 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x838EB55: Finisher::finisher_thread_entry() (in /usr/lib/librados.so.2.0.0)
2016-09-01T20:25:58.625 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x4C30FA6: ? (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.625 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Block was alloc'd by thread #14
2016-09-01T20:25:58.625 INFO:tasks.workunit.client.0.vpm041.stderr:==21289==
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Lock at 0x7CF3C28 was first observed
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== at 0x4C321AA: pthread_mutex_init (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135EF088: Mutex::Mutex(std::string const&, bool, bool, bool, CephContext*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135DC366: journal::JournalRecorder::JournalRecorder(librados::IoCtx&, std::string const&, boost::intrusive_ptr<journal::JournalMetadata> const&, unsigned int, unsigned long, double) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135C2740: journal::Journaler::start_append(int, unsigned long, double) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350C05B: librbd::Journal<librbd::ImageCtx>::start_append() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350C261: librbd::Journal<librbd::ImageCtx>::handle_flushing_replay() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350C467: librbd::Journal<librbd::ImageCtx>::handle_replay_complete(int)::{lambda(int)#1}::operator()(int) const (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.626 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134B49D9: FunctionContext::finish(int) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.627 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1347A5E8: Context::complete(int) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.627 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134C3623: ContextWQ::process(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.627 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13617B94: ThreadPool::worker(ThreadPool::WorkThread*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.627 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13618B7F: ThreadPool::WorkThread::entry() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.627 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Address 0x7cf3c28 is 104 bytes inside a block of size 248 alloc'd
2016-09-01T20:25:58.627 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== at 0x4C2C500: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.628 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x135C271C: journal::Journaler::start_append(int, unsigned long, double) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.630 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350C05B: librbd::Journal<librbd::ImageCtx>::start_append() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350C261: librbd::Journal<librbd::ImageCtx>::handle_flushing_replay() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1350C467: librbd::Journal<librbd::ImageCtx>::handle_replay_complete(int)::{lambda(int)#1}::operator()(int) const (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134B49D9: FunctionContext::finish(int) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x1347A5E8: Context::complete(int) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x134C3623: ContextWQ::process(Context*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13617B94: ThreadPool::worker(ThreadPool::WorkThread*) (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x13618B7F: ThreadPool::WorkThread::entry() (in /usr/lib/librbd.so.1.0.0)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x4C30FA6: ??? (in /usr/lib/valgrind/vgpreload_helgrind-amd64-linux.so)
2016-09-01T20:25:58.631 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== by 0x4E45183: start_thread (pthread_create.c:312)
2016-09-01T20:25:58.632 INFO:tasks.workunit.client.0.vpm041.stderr:==21289== Block was alloc'd by thread #21
2016-09-01T20:25:58.632 INFO:tasks.workunit.client.0.vpm041.stderr:==21289==

Actions
Copy link

Also available in: Atom PDF