Panic on kern_event.c
Sylvain GALLIANO
sg at efficientip.com
Fri Nov 16 14:47:55 UTC 2018
Le jeu. 15 nov. 2018 à 23:10, Mark Johnston <markj at freebsd.org> a écrit :
> On Thu, Nov 08, 2018 at 05:05:03PM +0100, Sylvain GALLIANO wrote:
> > Hi,
> >
> > I replaced
> > << printf("XXX knote %p already in tailq status:%x kq_count:%d [%p %p]
> >
> %u\n",kn,kn->kn_status,kq->kq_count,kn->kn_tqe.tqe_next,kn->kn_tqe.tqe_prev,__LINE__);
> > by
> > >> panic("XXX knote %p already in tailq status:%x kq_count:%d [%p %p]
> >
> %u\n",kn,kn->kn_status,kq->kq_count,kn->kn_tqe.tqe_next,kn->kn_tqe.tqe_prev,__LINE__);
> >
> > Here is the stack during panic:
> > panic: XXX knote 0xfffff801e1c6ddc0 already in tailq status:1 kq_count:2
> > [0 0xfffff8000957a978] 2671
> >
> > cpuid = 0
> > time = 1541688832
> > KDB: stack backtrace:
> > db_trace_self_wrapper() at db_trace_self_wrapper+0x2c/frame
> > 0xfffffe0412258fd0
> > kdb_backtrace() at kdb_backtrace+0x53/frame 0xfffffe04122590a0
> > vpanic() at vpanic+0x277/frame 0xfffffe0412259170
> > doadump() at doadump/frame 0xfffffe04122591d0
> > knote_enqueue() at knote_enqueue+0xf2/frame 0xfffffe0412259210
> > kqueue_register() at kqueue_register+0xaed/frame 0xfffffe0412259340
> > kqueue_kevent() at kqueue_kevent+0x13c/frame 0xfffffe04122595b0
> > kern_kevent_fp() at kern_kevent_fp+0x66/frame 0xfffffe0412259610
> > kern_kevent() at kern_kevent+0x17f/frame 0xfffffe0412259700
> > kern_kevent_generic() at kern_kevent_generic+0xfe/frame
> 0xfffffe0412259780
> > sys_kevent() at sys_kevent+0xaa/frame 0xfffffe0412259810
> > syscallenter() at syscallenter+0x4e3/frame 0xfffffe04122598f0
> > amd64_syscall() at amd64_syscall+0x1b/frame 0xfffffe04122599b0
> > fast_syscall_common() at fast_syscall_common+0x101/frame
> 0xfffffe04122599b0
> > --- syscall (560, FreeBSD ELF64, sys_kevent), rip = 0x406e3bfa, rsp =
> > 0x7fffdf7e9db8, rbp = 0x7fffdf7e9e00 ---
> > KDB: enter: panic
> >
> >
> > you can get kernel.debug + vmcore at:
> >
> https://drive.google.com/drive/folders/1MbqJQm12-KOYDbb4-9uNRTnAdsNqLaIP?usp=sharing
>
> Could you please give the following patch a try?
>
> If possible, could you also ktrace one of the active syslog-ng processes
> for some time, perhaps 15 seconds, and share the kdump? I have been
> trying to reproduce the problem without any luck.
>
> diff --git a/sys/kern/kern_event.c b/sys/kern/kern_event.c
> index d9c670e29d60..9ef7c53361bf 100644
> --- a/sys/kern/kern_event.c
> +++ b/sys/kern/kern_event.c
> @@ -224,6 +224,7 @@ SYSCTL_UINT(_kern, OID_AUTO, kq_calloutmax, CTLFLAG_RW,
> #define KQ_LOCK(kq) do { \
> mtx_lock(&(kq)->kq_lock); \
> } while (0)
> +#define KQ_LOCKPTR(kq) (&(kq)->kq_lock)
> #define KQ_FLUX_WAKEUP(kq) do {
> \
> if (((kq)->kq_state & KQ_FLUXWAIT) == KQ_FLUXWAIT) { \
> (kq)->kq_state &= ~KQ_FLUXWAIT; \
> @@ -687,8 +688,11 @@ filt_timerexpire(void *knx)
> struct kq_timer_cb_data *kc;
>
> kn = knx;
> + KQ_OWNED(kn->kn_kq);
> kn->kn_data++;
> - KNOTE_ACTIVATE(kn, 0); /* XXX - handle locking */
> +
> + if (!kn_in_flux(kn) || (kn->kn_status & KN_SCAN) != 0)
> + KNOTE_ACTIVATE(kn, 1);
>
> if ((kn->kn_flags & EV_ONESHOT) != 0)
> return;
> @@ -753,7 +757,7 @@ filt_timerattach(struct knote *kn)
> kn->kn_flags |= EV_CLEAR; /* automatically set */
> kn->kn_status &= ~KN_DETACHED; /* knlist_add clears it */
> kn->kn_ptr.p_v = kc = malloc(sizeof(*kc), M_KQUEUE, M_WAITOK);
> - callout_init(&kc->c, 1);
> + callout_init_mtx(&kc->c, KQ_LOCKPTR(kn->kn_kq), 0);
> filt_timerstart(kn, to);
>
> return (0);
> @@ -772,8 +776,10 @@ filt_timerstart(struct knote *kn, sbintime_t to)
> kc->next = to + sbinuptime();
> kc->to = to;
> }
> + KQ_LOCK(kn->kn_kq);
> callout_reset_sbt_on(&kc->c, kc->next, 0, filt_timerexpire, kn,
> PCPU_GET(cpuid), C_ABSOLUTE);
> + KQ_UNLOCK(kn->kn_kq);
> }
>
> static void
> @@ -826,7 +832,6 @@ filt_timertouch(struct knote *kn, struct kevent *kev,
> u_long type)
> KQ_LOCK(kq);
> if (kn->kn_status & KN_QUEUED)
> knote_dequeue(kn);
> -
> kn->kn_status &= ~KN_ACTIVE;
> kn->kn_data = 0;
> KQ_UNLOCK(kq);
> @@ -1843,6 +1848,7 @@ kqueue_scan(struct kqueue *kq, int maxevents, struct
> kevent_copyops *k_ops,
> }
>
> TAILQ_INSERT_TAIL(&kq->kq_head, marker, kn_tqe);
> + marker->kn_status |= KN_QUEUED;
> influx = 0;
> while (count) {
> KQ_OWNED(kq);
> @@ -1861,8 +1867,10 @@ kqueue_scan(struct kqueue *kq, int maxevents,
> struct kevent_copyops *k_ops,
> }
>
> TAILQ_REMOVE(&kq->kq_head, kn, kn_tqe);
> + KASSERT((kn->kn_status & KN_QUEUED) != 0,
> + ("knote %p not queued", kn));
> + kn->kn_status &= ~KN_QUEUED;
> if ((kn->kn_status & KN_DISABLED) == KN_DISABLED) {
> - kn->kn_status &= ~KN_QUEUED;
> kq->kq_count--;
> continue;
> }
> @@ -1876,7 +1884,6 @@ kqueue_scan(struct kqueue *kq, int maxevents, struct
> kevent_copyops *k_ops,
> ("knote %p is unexpectedly in flux", kn));
>
> if ((kn->kn_flags & EV_DROP) == EV_DROP) {
> - kn->kn_status &= ~KN_QUEUED;
> kn_enter_flux(kn);
> kq->kq_count--;
> KQ_UNLOCK(kq);
> @@ -1888,7 +1895,6 @@ kqueue_scan(struct kqueue *kq, int maxevents, struct
> kevent_copyops *k_ops,
> KQ_LOCK(kq);
> continue;
> } else if ((kn->kn_flags & EV_ONESHOT) == EV_ONESHOT) {
> - kn->kn_status &= ~KN_QUEUED;
> kn_enter_flux(kn);
> kq->kq_count--;
> KQ_UNLOCK(kq);
> @@ -1910,8 +1916,8 @@ kqueue_scan(struct kqueue *kq, int maxevents, struct
> kevent_copyops *k_ops,
> if (kn->kn_fop->f_event(kn, 0) == 0) {
> KQ_LOCK(kq);
> KQ_GLOBAL_UNLOCK(&kq_global, haskqglobal);
> - kn->kn_status &= ~(KN_QUEUED | KN_ACTIVE |
> - KN_SCAN);
> + /* XXXMJ races with EVFILT_TIMER
> activation. */
> + kn->kn_status &= ~(KN_ACTIVE | KN_SCAN);
> kn_leave_flux(kn);
> kq->kq_count--;
> kn_list_unlock(knl);
> @@ -1937,11 +1943,13 @@ kqueue_scan(struct kqueue *kq, int maxevents,
> struct kevent_copyops *k_ops,
> }
> if (kn->kn_flags & EV_DISPATCH)
> kn->kn_status |= KN_DISABLED;
> - kn->kn_status &= ~(KN_QUEUED | KN_ACTIVE);
> + kn->kn_status &= ~KN_ACTIVE;
> kq->kq_count--;
> - } else
> + } else if ((kn->kn_status & KN_QUEUED) == 0) {
> + kn->kn_status |= KN_QUEUED;
> TAILQ_INSERT_TAIL(&kq->kq_head, kn,
> kn_tqe);
> -
> + }
> +
> kn->kn_status &= ~KN_SCAN;
> kn_leave_flux(kn);
> kn_list_unlock(knl);
>
Unfortunately patched kernel is not stable:
- some processes run at 100% CPU (STOP state) and cannot be killed
- sometime the system completely freeze (need a hard reboot)
I cannot reproduce the issue as soon as syslog-ng is under ktrace (even
after 10GB of ktrace file)
When I stop ktrace, issue come back after few minutes.
More information about the freebsd-current
mailing list