From owner-freebsd-current@FreeBSD.ORG Wed Nov 10 09:18:57 2004 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 717DE16A4CE for ; Wed, 10 Nov 2004 09:18:57 +0000 (GMT) Received: from fledge.watson.org (fledge.watson.org [204.156.12.50]) by mx1.FreeBSD.org (Postfix) with ESMTP id 005F143D2D for ; Wed, 10 Nov 2004 09:18:57 +0000 (GMT) (envelope-from robert@fledge.watson.org) Received: from fledge.watson.org (localhost [127.0.0.1]) by fledge.watson.org (8.13.1/8.13.1) with ESMTP id iAA9HeRj072713; Wed, 10 Nov 2004 04:17:40 -0500 (EST) (envelope-from robert@fledge.watson.org) Received: from localhost (robert@localhost)iAA9HdXt072710; Wed, 10 Nov 2004 09:17:40 GMT (envelope-from robert@fledge.watson.org) Date: Wed, 10 Nov 2004 09:17:39 +0000 (GMT) From: Robert Watson X-Sender: robert@fledge.watson.org To: =?ISO-8859-1?Q?S=F8ren_Schmidt?= In-Reply-To: <4191CD35.9040000@DeepCore.dk> Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=ISO-8859-1 Content-Transfer-Encoding: QUOTED-PRINTABLE cc: Zoltan Frombach cc: freebsd-current@freebsd.org Subject: Re: Re: 5.3-RELEASE: WARNING - WRITE_DMA interrupt timout - what does it mean? X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 10 Nov 2004 09:18:57 -0000 On Wed, 10 Nov 2004, S=F8ren Schmidt wrote: > Zoltan Frombach wrote: > > I just upgraded to 5.3-RELEASE a few days ago. This morning this line= =20 > > got into my system log file: > > Nov 9 06:14:03 www kernel: ad0: WARNING - WRITE_DMA interrupt was seen= =20 > > but timeout fired LBA=3D2491143 > >=20 > > I've never seen this message before. Can someone please explain what it= =20 > > means? With Thanks, >=20 > It means that the disk has processed the write request (interrupt seen), > but that the system (the bio_taskqueue) hasn't been able to get the > result returned to the kernel.=20 >=20 > Your disk is not involved in this problem since it has done its part, > but the rest of the system is either busy with something else, or there > are bugs lurking that prohibits the bio_taskqueue from running.=20 >=20 > Either way its a WARNING not a FAILURE :)=20 I'm still a bit skeptical that the task queue is at fault -- I run my notebook with continuous measurement of the latency to schedule tasks, generating a warning for any latency > .5 seconds, and the only time I ever see that sort of latency is during the boot process when ACPI has scheduled a task to run, but the task queue thread has not yet been allowed to run: ipfw2 initialized, divert loadable, rule-based forwarding disabled, default to deny, logging disabled taskqueue_run: warning, queue time of 0.900011314 for context 0xc045638c ad0: 19077MB [38760/16/63] at ata0-master UDMA33 It would be quite interesting to have someone run with this timing code on a system reporting the warning to see what they find. What is the threshold to generate the ATA timeout warning? My impression was that it was several seconds, which is quite a long time. The attached patch checks for .5 second or above latency. If the task queue is really getting stalled for several seconds, we should figure out what task it is. There's KTR tracing in the taskqueue code that we can use to dump a trace stream to see what task is taking so long. Robert N M Watson FreeBSD Core Team, TrustedBSD Projects robert@fledge.watson.org Principal Research Scientist, McAfee Research Index: kern/subr_taskqueue.c =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D RCS file: /home/ncvs/src/sys/kern/subr_taskqueue.c,v retrieving revision 1.25 diff -u -r1.25 subr_taskqueue.c --- kern/subr_taskqueue.c=095 Oct 2004 04:16:00 -0000=091.25 +++ kern/subr_taskqueue.c=0923 Oct 2004 19:18:26 -0000 @@ -36,9 +36,16 @@ #include #include #include +#include #include +#include #include =20 +int tq_in; +SYSCTL_INT(_kern, OID_AUTO, tq_in, CTLFLAG_RD, &tq_in, 0, ""); +int tq_out; +SYSCTL_INT(_kern, OID_AUTO, tq_out, CTLFLAG_RD, &tq_out, 0, ""); + static MALLOC_DEFINE(M_TASKQUEUE, "taskqueue", "Task Queues"); static void=09*taskqueue_giant_ih; static void=09*taskqueue_ih; @@ -140,6 +147,9 @@ =09=09return 0; =09} =20 +=09getnanotime(&task->ta_queuetime); +=09tq_in++; + =09/* =09 * Optimise the case when all tasks have the same priority. =09 */ @@ -172,6 +182,7 @@ taskqueue_run(struct taskqueue *queue) { =09struct task *task; +=09struct timespec tv; =09int owned, pending; =20 =09owned =3D mtx_owned(&queue->tq_mutex); @@ -187,8 +198,16 @@ =09=09pending =3D task->ta_pending; =09=09task->ta_pending =3D 0; =09=09task->ta_flags |=3D TAF_PENDING; +=09=09tq_out++; =09=09mtx_unlock(&queue->tq_mutex); =20 +=09=09getnanotime(&tv); +=09=09timespecsub(&tv, &task->ta_queuetime); +=09=09if (tv.tv_nsec >=3D 0500000000) { +=09=09=09printf("taskqueue_run: warning, queue time of %d.%09ld " +=09=09=09 "for context %p\n", tv.tv_sec, tv.tv_nsec, +=09=09=09 task->ta_func); +=09=09} =09=09task->ta_func(task->ta_context, pending); =20 =09=09mtx_lock(&queue->tq_mutex); Index: sys/_task.h =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D RCS file: /home/ncvs/src/sys/sys/_task.h,v retrieving revision 1.3 diff -u -r1.3 _task.h --- sys/_task.h=095 Oct 2004 04:16:01 -0000=091.3 +++ sys/_task.h=0923 Oct 2004 19:38:16 -0000 @@ -46,6 +46,7 @@ =09task_fn_t *ta_func;=09=09/* task handler */ =09void=09*ta_context;=09=09/* argument for handler */ =09int=09ta_flags;=09=09/* Flags */ +=09struct timespec ta_queuetime;=09/* time enqueued */ }; =20 #define TAF_PENDING=090x1=09=09/* Task is being run now */