From owner-freebsd-mips@freebsd.org Tue Nov 10 18:05:47 2015 Return-Path: Delivered-To: freebsd-mips@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 67DCCA2B034 for ; Tue, 10 Nov 2015 18:05:47 +0000 (UTC) (envelope-from eugen@grosbein.net) Received: from hz.grosbein.net (hz.grosbein.net [78.47.246.247]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (Client CN "hz.grosbein.net", Issuer "hz.grosbein.net" (not verified)) by mx1.freebsd.org (Postfix) with ESMTPS id 147951324; Tue, 10 Nov 2015 18:05:46 +0000 (UTC) (envelope-from eugen@grosbein.net) Received: from eg.sd.rdtc.ru (root@eg.sd.rdtc.ru [62.231.161.221]) by hz.grosbein.net (8.14.9/8.14.9) with ESMTP id tAAI5VXe017397 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NOT); Tue, 10 Nov 2015 19:05:33 +0100 (CET) (envelope-from eugen@grosbein.net) X-Envelope-From: eugen@grosbein.net X-Envelope-To: adrian@freebsd.org Received: from eg.sd.rdtc.ru (eugen@localhost [127.0.0.1]) by eg.sd.rdtc.ru (8.15.2/8.15.2) with ESMTP id tAAI5I9c076738; Wed, 11 Nov 2015 01:05:18 +0700 (KRAT) (envelope-from eugen@grosbein.net) Subject: Re: USB-related problem To: Adrian Chadd References: <56348063.3090508@grosbein.net> <563707A0.3040700@grosbein.net> <56370E1D.3040801@grosbein.net> <563F5630.2000407@grosbein.net> <563F6F6F.1010807@grosbein.net> <563F91A8.9080702@grosbein.net> <5640C0FD.2040803@grosbein.net> <5640F315.5020303@grosbein.net> <56410214.3070901@grosbein.net> Cc: "freebsd-mips@freebsd.org" From: Eugene Grosbein Message-ID: <564231DE.7090308@grosbein.net> Date: Wed, 11 Nov 2015 01:05:18 +0700 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:38.0) Gecko/20100101 Thunderbird/38.2.0 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit X-Spam-Status: No, score=2.5 required=5.0 tests=BAYES_00, DATE_IN_FUTURE_48_96, LOCAL_FROM autolearn=no version=3.3.2 X-Spam-Report: * 2.2 DATE_IN_FUTURE_48_96 Date: is 48 to 96 hours after Received: date * -2.3 BAYES_00 BODY: Bayes spam probability is 0 to 1% * [score: 0.0000] * 2.6 LOCAL_FROM From my domains X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on hz.grosbein.net X-Spam-Level: ** X-BeenThere: freebsd-mips@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: Porting FreeBSD to MIPS List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 10 Nov 2015 18:05:47 -0000 On 10.11.2015 04:43, Adrian Chadd wrote: > Hi, > > How much C do you know? Are you able to add some debugging to > sched_sync() (which IIRC is the syncer thread) and work out where it's > getting stuck and spinning? I did. I've added new global kernel symbol, variable schedstat so I can check its value using ddb. And it's always equals to 5 when deadlock occurs, discovering the loop: --- sys/kern/vfs_subr.c.orig 2015-10-08 23:33:53.935440000 +0700 +++ sys/kern/vfs_subr.c 2015-11-11 01:01:06.248144000 +0700 @@ -1786,169 +1786,199 @@ sync_vnode(struct synclist *slp, struct * Put us back on the worklist. The worklist * routine will remove us from our current * position and then add us back in at a later * position. */ vn_syncer_add_to_worklist(*bo, syncdelay); } BO_UNLOCK(*bo); vdrop(vp); mtx_lock(&sync_mtx); return (0); } static int first_printf = 1; +volatile unsigned schedstate = 0; + /* * System filesystem synchronizer daemon. */ static void sched_sync(void) { struct synclist *next, *slp; struct bufobj *bo; long starttime; struct thread *td = curthread; int last_work_seen; int net_worklist_len; int syncer_final_iter; int error; last_work_seen = 0; syncer_final_iter = 0; syncer_state = SYNCER_RUNNING; starttime = time_uptime; td->td_pflags |= TDP_NORUNNINGBUF; EVENTHANDLER_REGISTER(shutdown_pre_sync, syncer_shutdown, td->td_proc, SHUTDOWN_PRI_LAST); + schedstate = 0; mtx_lock(&sync_mtx); for (;;) { + schedstate = 1; + if (syncer_state == SYNCER_FINAL_DELAY && syncer_final_iter == 0) { mtx_unlock(&sync_mtx); kproc_suspend_check(td->td_proc); mtx_lock(&sync_mtx); } + schedstate = 2; + net_worklist_len = syncer_worklist_len - sync_vnode_count; if (syncer_state != SYNCER_RUNNING && starttime != time_uptime) { if (first_printf) { printf("\nSyncing disks, vnodes remaining..."); first_printf = 0; } printf("%d ", net_worklist_len); } starttime = time_uptime; /* * Push files whose dirty time has expired. Be careful * of interrupt race on slp queue. * * Skip over empty worklist slots when shutting down. */ do { + schedstate = 3; slp = &syncer_workitem_pending[syncer_delayno]; syncer_delayno += 1; if (syncer_delayno == syncer_maxdelay) syncer_delayno = 0; next = &syncer_workitem_pending[syncer_delayno]; /* * If the worklist has wrapped since the * it was emptied of all but syncer vnodes, * switch to the FINAL_DELAY state and run * for one more second. */ if (syncer_state == SYNCER_SHUTTING_DOWN && net_worklist_len == 0 && last_work_seen == syncer_delayno) { syncer_state = SYNCER_FINAL_DELAY; syncer_final_iter = SYNCER_SHUTDOWN_SPEEDUP; } } while (syncer_state != SYNCER_RUNNING && LIST_EMPTY(slp) && syncer_worklist_len > 0); + schedstate = 4; + /* * Keep track of the last time there was anything * on the worklist other than syncer vnodes. * Return to the SHUTTING_DOWN state if any * new work appears. */ if (net_worklist_len > 0 || syncer_state == SYNCER_RUNNING) last_work_seen = syncer_delayno; if (net_worklist_len > 0 && syncer_state == SYNCER_FINAL_DELAY) syncer_state = SYNCER_SHUTTING_DOWN; while (!LIST_EMPTY(slp)) { + schedstate = 5; + error = sync_vnode(slp, &bo, td); if (error == 1) { LIST_REMOVE(bo, bo_synclist); LIST_INSERT_HEAD(next, bo, bo_synclist); continue; } + schedstate = 6; if (first_printf == 0) { + schedstate = 7; /* * Drop the sync mutex, because some watchdog * drivers need to sleep while patting */ mtx_unlock(&sync_mtx); wdog_kern_pat(WD_LASTVAL); mtx_lock(&sync_mtx); } + schedstate = 8; } + schedstate = 9; + if (syncer_state == SYNCER_FINAL_DELAY && syncer_final_iter > 0) syncer_final_iter--; /* * The variable rushjob allows the kernel to speed up the * processing of the filesystem syncer process. A rushjob * value of N tells the filesystem syncer to process the next * N seconds worth of work on its queue ASAP. Currently rushjob * is used by the soft update code to speed up the filesystem * syncer process when the incore state is getting so far * ahead of the disk that the kernel memory pool is being * threatened with exhaustion. */ if (rushjob > 0) { rushjob -= 1; continue; } /* * Just sleep for a short period of time between * iterations when shutting down to allow some I/O * to happen. * * If it has taken us less than a second to process the * current work, then wait. Otherwise start right over * again. We can still lose time if any single round * takes more than two seconds, but it does not really * matter as we are just trying to generally pace the * filesystem activity. */ + + schedstate = 10; + if (syncer_state != SYNCER_RUNNING || time_uptime == starttime) { + schedstate = 11; thread_lock(td); sched_prio(td, PPAUSE); thread_unlock(td); } - if (syncer_state != SYNCER_RUNNING) + schedstate = 12; + + if (syncer_state != SYNCER_RUNNING) { + schedstate = 13; + cv_timedwait(&sync_wakeup, &sync_mtx, hz / SYNCER_SHUTDOWN_SPEEDUP); - else if (time_uptime == starttime) + } + else if (time_uptime == starttime) { + schedstate = 14; cv_timedwait(&sync_wakeup, &sync_mtx, hz); + } + schedstate = 15; } + schedstate = 16; } /* * Request the syncer daemon to speed up its work. * We never push it to speed up more than half of its * normal turn time, otherwise it could take over the cpu. */ int speedup_syncer(void) { int ret = 0; mtx_lock(&sync_mtx); if (rushjob < syncdelay / 2) { rushjob += 1;