[Bug 221804] page fault during shutdown on a server with gjournaled partitions
bugzilla-noreply at freebsd.org
bugzilla-noreply at freebsd.org
Fri Aug 25 14:55:38 UTC 2017
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=221804
Bug ID: 221804
Summary: page fault during shutdown on a server with gjournaled
partitions
Product: Base System
Version: 10.3-STABLE
Hardware: Any
OS: Any
Status: New
Severity: Affects Some People
Priority: ---
Component: kern
Assignee: freebsd-bugs at FreeBSD.org
Reporter: longwitz at incore.de
I am running FreeBSD 10.3-STABLE #1 r317936 using gjournal/gmirror and got
a page fault of the process g_journal switcher during shutdown:
...
GEOM_JOURNAL: Shutting down geom gjournal 1247376231.
GEOM_JOURNAL: Shutting down geom gjournal 1068288894.
Fatal trap 12: page fault while in kernel mode
cpuid = 0; apic id = 00
fault virtual address = 0x378
fault code = supervisor read data, page not present
instruction pointer = 0x20:0xffffffff806aa1ea
stack pointer = 0x28:0xfffffe104445fa10
frame pointer = 0x28:0xfffffe104445fab0
code segment = base 0x0, limit 0xfffff, type 0x1b
= DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags = interrupt enabled, resume, IOPL = 0
current process = 6 (g_journal switcher)
[ thread pid 6 tid 100132 ]
Stopped at __mtx_lock_sleep+0x1da: movl 0x378(%rbx),%eax
(kgdb) where
...
#10 0xffffffff80954abc in calltrap () at
/usr/src/sys/amd64/amd64/exception.S:238
#11 0xffffffff806aa1ea in __mtx_lock_sleep (c=0xfffff8003823d030,
tid=18446735278556155904, opts=0, file=0x0, line=1145437376)
at /usr/src/sys/kern/kern_mutex.c:506
#12 0xffffffff806a9ff7 in __mtx_lock_flags (c=<value optimized out>,
opts=<value optimized out>, file=0x0, line=0)
at /usr/src/sys/kern/kern_mutex.c:256
#13 0xffffffff811686bf in g_journal_switcher (arg=0xffffffff81170e48)
at
/usr/src/sys/modules/geom/geom_journal/../../../geom/journal/g_journal.c:2945
#14 0xffffffff8068daba in fork_exit (callout=0xffffffff81167a50
<g_journal_switcher>, arg=0xffffffff81170e48,
frame=0xfffffe104445fc00) at /usr/src/sys/kern/kern_fork.c:1030
#15 0xffffffff80954ffe in fork_trampoline () at
/usr/src/sys/amd64/amd64/exception.S:613
(kgdb) f 13
#13 0xffffffff811686bf in g_journal_switcher (arg=0xffffffff81170e48)
at
/usr/src/sys/modules/geom/geom_journal/../../../geom/journal/g_journal.c:2945
2945 mtx_lock(&sc->sc_mtx);
(kgdb) list
2940 g_topology_lock();
2941 LIST_FOREACH(gp, &g_journal_class.geom, geom) {
2942 sc = gp->softc;
2943 if (sc == NULL)
2944 continue;
2945 mtx_lock(&sc->sc_mtx);
2946 if ((sc->sc_type & GJ_TYPE_COMPLETE) ==
GJ_TYPE_COMPLETE &&
2947 !(sc->sc_flags & GJF_DEVICE_DESTROY) &&
2948 (sc->sc_flags & GJF_DEVICE_BEFORE_SWITCH))
{
2949 break;
(kgdb) p *g_journal_class.geom->lh_first
$1 = {name = 0xfffff80038239560 "gjournal 1068288894", class =
0xffffffff81170e48, geom = {le_next = 0x0,
le_prev = 0xffffffff81170ef0}, consumer = {lh_first = 0xfffff800382c5900},
provider = {lh_first = 0x0}, geoms = {
tqe_next = 0xfffff8003822a300, tqe_prev = 0xfffff8003826c330}, rank = 4,
start = 0xffffffff8116bcd0 <g_journal_start>,
spoiled = 0, attrchanged = 0, dumpconf = 0xffffffff811674e0
<g_journal_dumpconf>, access = 0xffffffff8116bfe0 <g_journal_access>,
orphan = 0xffffffff8116be30 <g_journal_orphan>, ioctl = 0, providergone = 0,
resize = 0, spare0 = 0x0, spare1 = 0x0,
softc = 0xfffff8003823d000, flags = 2}
(kgdb) p *(struct g_journal_softc *)((g_journal_class.geom->lh_first))->softc
$2 = {sc_id = 1068288894, sc_type = 3 '\003', sc_orig_type = 1 '\001', sc_geom
= 0xfffff800380bce00, sc_flags = 144, sc_mtx = {
lock_object = {lo_name = 0xffffffff8116f916 "gjournal", lo_flags =
16908288, lo_data = 0, lo_witness = 0x0}, mtx_lock = 6},
sc_mediasize = 1073741312, sc_sectorsize = 512, sc_bio_flush = 3,
sc_journal_id = 1627568564, sc_journal_next_id = 163691452,
sc_journal_copying = 0, sc_journal_offset = 59226624, sc_journal_previous_id
= 3706521218, sc_back_queue = {queue = {
tqh_first = 0x0, tqh_last = 0xfffff8003823d068}, last_offset = 805502976,
insert_point = 0x0}, sc_regular_queue = {queue = {
tqh_first = 0x0, tqh_last = 0xfffff8003823d088}, last_offset = 65536,
insert_point = 0x0}, sc_delayed_queue = {queue = {
tqh_first = 0x0, tqh_last = 0xfffff8003823d0a8}, last_offset = 0,
insert_point = 0x0}, sc_delayed_count = 0,
sc_current_queue = 0x0, sc_current_count = 0, sc_flush_queue = 0x0,
sc_flush_count = 0, sc_flush_in_progress = 0,
sc_copy_queue = 0x0, sc_copy_in_progress = 0, sc_dconsumer =
0xfffff800382c5900, sc_jconsumer = 0xfffff8003822f900,
sc_inactive = {jj_queue = 0x0, jj_offset = 59142656}, sc_active = {jj_queue =
0x0, jj_offset = 59226112}, sc_jstart = 0,
sc_jend = 8589934080, sc_callout = {c_links = {le = {le_next = 0x0, le_prev =
0xfffffe0000803f00}, sle = {sle_next = 0x0}, tqe = {
tqe_next = 0x0, tqe_prev = 0xfffffe0000803f00}}, c_time = 33825373681,
c_precision = 1342177187,
c_arg = 0xfffff8003823d000, c_func = 0xffffffff8116c190
<g_journal_timeout>, c_lock = 0x0, c_flags = 0, c_iflags = 16,
c_cpu = 0}, sc_worker = 0x0, sc_rootmount = 0x0}
(kgdb) f 11
#11 0xffffffff806aa1ea in __mtx_lock_sleep (c=0xfffff8003823d030,
tid=18446735278556155904, opts=0, file=0x0, line=1145437376)
at /usr/src/sys/kern/kern_mutex.c:506
506 owner = (struct thread *)(v & ~MTX_FLAGMASK);
(kgdb) list
501 * If the owner is running on another CPU, spin until
the
502 * owner stops running or the state of the lock
changes.
503 */
504 v = m->mtx_lock;
505 if (v != MTX_UNOWNED) {
506 owner = (struct thread *)(v & ~MTX_FLAGMASK);
507 if (TD_IS_RUNNING(owner)) {
508 if (LOCK_LOG_TEST(&m->lock_object, 0))
509 CTR3(KTR_LOCK,
510 "%s: spinning on %p held by
%p",
(kgdb) p *c
$2 = 6
(kgdb) p lda
$3 = {config = 0xffffffff80d70e48, delay = 0, spin_cnt = 1}
The first parameter on call of __mtx_lock_sleep is the address of
sc->sc_mtx->mtx_lock with value MTX_DESTROYED (=6), and so we have v =
m->mtx_lock = 6, v & ~MTX_FLAGMASK) = 0 with page fault in line 506. The leak
here ist that the case v = MTX_DESTROYED is not handled in this function
__mtx_lock_sleep().
I think we have a race condition between g_journal_switcher and the process
"PID 1" who calls g_journal_shutdown() for every gjournaled partition on
shutdown.
(kgdb) proc 1
[Switching to thread 301 (Thread 100002)]#0 sched_switch
(td=0xfffff8000d2ff500, newtd=<value optimized out>,
flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1956
1956 cpuid = PCPU_GET(cpuid);
(kgdb) where
#0 sched_switch (td=0xfffff8000d2ff500, newtd=<value optimized out>,
flags=<value optimized out>)
at /usr/src/sys/kern/sched_ule.c:1956
#1 0xffffffff806cb316 in mi_switch (flags=0, newtd=0x0) at
/usr/src/sys/kern/kern_synch.c:473
#2 0xffffffff80710c1a in sleepq_wait (wchan=0x0, pri=0) at
/usr/src/sys/kern/subr_sleepqueue.c:632
#3 0xffffffff806cacea in _sleep (ident=<value optimized out>, lock=<value
optimized out>, priority=<value optimized out>,
wmesg=<value optimized out>, sbt=<value optimized out>, pr=<value optimized
out>, flags=<value optimized out>)
at /usr/src/sys/kern/kern_synch.c:242
#4 0xffffffff8075e950 in biowait (bp=<value optimized out>, wchan=<value
optimized out>) at /usr/src/sys/kern/vfs_bio.c:3674
#5 0xffffffff8064a0b5 in g_write_data (cp=<value optimized out>,
offset=146815737344, ptr=0xfffff80609429c00, length=512)
at /usr/src/sys/geom/geom_io.c:937
#6 0xffffffff8118c8df in g_mirror_write_metadata (disk=0xfffff800380b4100,
md=<value optimized out>)
at
/usr/src/sys/modules/geom/geom_mirror/../../../geom/mirror/g_mirror.c:675
#7 0xffffffff8118c495 in g_mirror_update_metadata (disk=0xfffff800380b4100)
at
/usr/src/sys/modules/geom/geom_mirror/../../../geom/mirror/g_mirror.c:774
#8 0xffffffff8118ea6e in g_mirror_idle (sc=0xfffff80038059c00, acw=<value
optimized out>)
at
/usr/src/sys/modules/geom/geom_mirror/../../../geom/mirror/g_mirror.c:860
#9 0xffffffff8118f058 in g_mirror_access (pp=<value optimized out>, acr=<value
optimized out>, acw=<value optimized out>,
ace=<value optimized out>) at
/usr/src/sys/modules/geom/geom_mirror/../../../geom/mirror/g_mirror.c:2914
#10 0xffffffff8064c16e in g_access (cp=0xfffff80038261700, dcr=-1, dcw=-1,
dce=-2) at /usr/src/sys/geom/geom_subr.c:919
#11 0xffffffff8064c16e in g_access (cp=0xfffff800382c5900, dcr=-1, dcw=-1,
dce=-1) at /usr/src/sys/geom/geom_subr.c:919
#12 0xffffffff81169295 in g_journal_destroy (sc=0xfffff8003823d000)
at
/usr/src/sys/modules/geom/geom_journal/../../../geom/journal/g_journal.c:2431
#13 0xffffffff81167741 in g_journal_shutdown (arg=<value optimized out>,
howto=0)
at
/usr/src/sys/modules/geom/geom_journal/../../../geom/journal/g_journal.c:2658
#14 0xffffffff806c11bc in kern_reboot (howto=16384) at
/usr/src/sys/kern/kern_shutdown.c:483
#15 0xffffffff806c0acf in sys_reboot (td=<value optimized out>, uap=<value
optimized out>) at /usr/src/sys/kern/kern_shutdown.c:229
#16 0xffffffff80970cd2 in amd64_syscall (td=0xfffff8000d2ff500, traced=0) at
subr_syscall.c:141
#17 0xffffffff80954dab in Xfast_syscall () at
/usr/src/sys/amd64/amd64/exception.S:398
(kgdb) f 12
#12 0xffffffff81169295 in g_journal_destroy (sc=0xfffff8003823d000)
at
/usr/src/sys/modules/geom/geom_journal/../../../geom/journal/g_journal.c:2431
2431 g_access(cp, -1, -1, -1);
(kgdb) list
2426 sc->sc_current_count);
2427 }
2428
2429 LIST_FOREACH(cp, &gp->consumer, consumer) {
2430 if (cp->acr + cp->acw + cp->ace > 0)
2431 g_access(cp, -1, -1, -1);
2432 /*
2433 * We keep all consumers open for writting, so if I'll
detach
2434 * and destroy consumer here, I'll get providers for
taste, so
2435 * journal will be started again.
(kgdb) p *sc
$4 = {sc_id = 1068288894, sc_type = 3 '\003', sc_orig_type = 1 '\001', sc_geom
= 0xfffff800380bce00, sc_flags = 144, sc_mtx = {
lock_object = {lo_name = 0xffffffff8116f916 "gjournal", lo_flags =
16908288, lo_data = 0, lo_witness = 0x0}, mtx_lock = 6},
sc_mediasize = 1073741312, sc_sectorsize = 512, sc_bio_flush = 3,
sc_journal_id = 1627568564, sc_journal_next_id = 163691452,
sc_journal_copying = 0, sc_journal_offset = 59226624, sc_journal_previous_id
= 3706521218, sc_back_queue = {queue = {
tqh_first = 0x0, tqh_last = 0xfffff8003823d068}, last_offset = 805502976,
insert_point = 0x0}, sc_regular_queue = {queue = {
tqh_first = 0x0, tqh_last = 0xfffff8003823d088}, last_offset = 65536,
insert_point = 0x0}, sc_delayed_queue = {queue = {
tqh_first = 0x0, tqh_last = 0xfffff8003823d0a8}, last_offset = 0,
insert_point = 0x0}, sc_delayed_count = 0,
sc_current_queue = 0x0, sc_current_count = 0, sc_flush_queue = 0x0,
sc_flush_count = 0, sc_flush_in_progress = 0,
sc_copy_queue = 0x0, sc_copy_in_progress = 0, sc_dconsumer =
0xfffff800382c5900, sc_jconsumer = 0xfffff8003822f900,
sc_inactive = {jj_queue = 0x0, jj_offset = 59142656}, sc_active = {jj_queue =
0x0, jj_offset = 59226112}, sc_jstart = 0,
sc_jend = 8589934080, sc_callout = {c_links = {le = {le_next = 0x0, le_prev =
0xfffffe0000803f00}, sle = {sle_next = 0x0}, tqe = {
tqe_next = 0x0, tqe_prev = 0xfffffe0000803f00}}, c_time = 33825373681,
c_precision = 1342177187,
c_arg = 0xfffff8003823d000, c_func = 0xffffffff8116c190
<g_journal_timeout>, c_lock = 0x0, c_flags = 0, c_iflags = 16,
c_cpu = 0}, sc_worker = 0x0, sc_rootmount = 0x0}
Thats the same "struct g_journal_softc" as seen above for the
g_journal_switcher.
Now the story is complete: "PID 1" calls g_journal_shutdown() and loops through
the gjournaled partitions to destroy them. Last partition has sc_id =
1068288894 which is printed to console. Then in g_journal_destroy() we see
mtx_unlock(&sc->sc_mtx);
g_topology_lock();
mtx_destroy(&sc->sc_mtx); (That is mtx_lock = MTX_DESTROYED)
....
g_topology_unlock(); (in g_mirror_access)
At this moment g_journal_switcher gets the topology_lock and starts running to
the page fault described above.
--
You are receiving this mail because:
You are the assignee for the bug.
More information about the freebsd-bugs
mailing list