From owner-freebsd-current@FreeBSD.ORG Wed Nov 10 09:54:00 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 D284916A4CE; Wed, 10 Nov 2004 09:54:00 +0000 (GMT) Received: from hotmail.com (bay2-dav1.bay2.hotmail.com [65.54.246.105]) by mx1.FreeBSD.org (Postfix) with ESMTP id A14B943D2F; Wed, 10 Nov 2004 09:54:00 +0000 (GMT) (envelope-from tssajo@hotmail.com) Received: from mail pickup service by hotmail.com with Microsoft SMTPSVC; Wed, 10 Nov 2004 01:54:00 -0800 Received: from 24.24.201.219 by BAY2-DAV1.phx.gbl with DAV; Wed, 10 Nov 2004 09:53:12 +0000 X-Originating-IP: [24.24.201.219] X-Originating-Email: [tssajo@hotmail.com] X-Sender: tssajo@hotmail.com From: "Zoltan Frombach" To: "Robert Watson" , =?iso-8859-1?Q?S=F8ren_Schmidt?= References: Date: Wed, 10 Nov 2004 01:53:17 -0800 MIME-Version: 1.0 Content-Type: text/plain; format=flowed; charset="iso-8859-1"; reply-type=original Content-Transfer-Encoding: 8bit X-Priority: 3 X-MSMail-Priority: Normal X-Mailer: Microsoft Outlook Express 6.00.2900.2180 X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.2180 Message-ID: X-OriginalArrivalTime: 10 Nov 2004 09:54:00.0556 (UTC) FILETIME=[3414C2C0:01C4C70B] 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:54:00 -0000 I'm on FreeBSD 5.3-RELEASE. I get this when I try to patch the file: # patch subr_taskqueue.c Zoltan Frombach wrote: > > I just upgraded to 5.3-RELEASE a few days ago. This morning this line > > got into my system log file: > > Nov 9 06:14:03 www kernel: ad0: WARNING - WRITE_DMA interrupt was seen > > but timeout fired LBA=2491143 > > > > I've never seen this message before. Can someone please explain what it > > means? With Thanks, > > 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. > > 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. > > Either way its a WARNING not a FAILURE :) 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 =================================================================== 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 5 Oct 2004 04:16:00 -0000 1.25 +++ kern/subr_taskqueue.c 23 Oct 2004 19:18:26 -0000 @@ -36,9 +36,16 @@ #include #include #include +#include #include +#include #include +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 *taskqueue_giant_ih; static void *taskqueue_ih; @@ -140,6 +147,9 @@ return 0; } + getnanotime(&task->ta_queuetime); + tq_in++; + /* * Optimise the case when all tasks have the same priority. */ @@ -172,6 +182,7 @@ taskqueue_run(struct taskqueue *queue) { struct task *task; + struct timespec tv; int owned, pending; owned = mtx_owned(&queue->tq_mutex); @@ -187,8 +198,16 @@ pending = task->ta_pending; task->ta_pending = 0; task->ta_flags |= TAF_PENDING; + tq_out++; mtx_unlock(&queue->tq_mutex); + getnanotime(&tv); + timespecsub(&tv, &task->ta_queuetime); + if (tv.tv_nsec >= 0500000000) { + printf("taskqueue_run: warning, queue time of %d.%09ld " + "for context %p\n", tv.tv_sec, tv.tv_nsec, + task->ta_func); + } task->ta_func(task->ta_context, pending); mtx_lock(&queue->tq_mutex); Index: sys/_task.h =================================================================== RCS file: /home/ncvs/src/sys/sys/_task.h,v retrieving revision 1.3 diff -u -r1.3 _task.h --- sys/_task.h 5 Oct 2004 04:16:01 -0000 1.3 +++ sys/_task.h 23 Oct 2004 19:38:16 -0000 @@ -46,6 +46,7 @@ task_fn_t *ta_func; /* task handler */ void *ta_context; /* argument for handler */ int ta_flags; /* Flags */ + struct timespec ta_queuetime; /* time enqueued */ }; #define TAF_PENDING 0x1 /* Task is being run now */