[BUG] 50MB/min logspam: dma: unregistered DMA channel used nchan=0 dma_pos=0 dma_len=1

[BUG] 50MB/min logspam: dma: unregistered DMA channel used nchan=0 dma_pos=0 dma_len=1

[Philipp Hahn]

[-- Attachment #1: Type: text/plain, Size: 1807 bytes --]

Hello,

a Xen-4.1-3 host system filled its log file with the message
 dma: unregistered DMA channel used nchan=0 dma_pos=0 dma_len=1

The happened two times was a Windows Server 2003 with GPLPV 0.11.0.372:
one VM was migrated to that host and one was directly started there.
After a restart of the VM the message no longer gets printed.

Looking at both xen-4.1.3/tools/ioemu-qemu-xen/hw/dma.c and
qemu-git/hw/dma/i8257.c the message is printed by dma_phony_handler(),
which is the default is no other transfer_handler is registered.

The function gets run through DMA_run_bh -> DMA_run -> channel_run.
In DMA_run() the code checks both the 'mask' and 'status' registers:
383   if ((0 == (d->mask & mask)) && (0 != (d->status & (mask << 4)))) {
384       channel_run (icont, ichan);
385       rearm = 1;
386    }

So the messages is printed with maximum frequency, as the BH gets
executed each time leading to massive log spam.

Looking further I analyzed the following case, which *might* be responsible:

While 'mask' is included in the VMStateDescription, 'status' is not.
Before the conversion to VMSTATE* the code was commented out from day-one:
512     /* qemu_put_8s (f, &d->status); */
540     /* qemu_get_8s (f, &d->status); */

1. Might it be that 'status' is uninitialized after migration?
2. Has someone other seen that message?
3. Could the rate of the message please be limited? See attached patch.
4. Some other ideas or comments?

Sincerely
Philipp
-- 
Philipp Hahn
Open Source Software Engineer

Univention GmbH
be open.
Mary-Somerville-Str. 1
D-28359 Bremen
Tel.: +49 421 22232-0
Fax : +49 421 22232-99
hahn@univention.de

http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876

[-- Attachment #2: 0001-hw-dma-Print-error-message-only-once.patch --]
[-- Type: text/x-patch, Size: 1316 bytes --]

>From 5e54adc8f53df4b8c8e8b802049964b2054ad829 Mon Sep 17 00:00:00 2001
Message-Id: <5e54adc8f53df4b8c8e8b802049964b2054ad829.1399625721.git.hahn@univention.de>
From: Philipp Hahn <hahn@univention.de>
Date: Fri, 9 May 2014 10:53:57 +0200
Subject: [PATCH] hw/dma: Print error message only once
Organization: Univention GmbH, Bremen, Germany
To: qemu-devel@nongnu.org

otherwise the message
	dma: unregistered DMA channel used nchan=0 dma_pos=0 dma_len=1
gets printed every time and fills up the log-file with 50 MiB / minute.

Signed-off-by: Philipp Hahn <hahn@univention.de>
---
 hw/dma/i8257.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/hw/dma/i8257.c b/hw/dma/i8257.c
index 4490372..cd710a9 100644
--- a/hw/dma/i8257.c
+++ b/hw/dma/i8257.c
@@ -473,8 +473,14 @@ static void dma_reset(void *opaque)
 
 static int dma_phony_handler (void *opaque, int nchan, int dma_pos, int dma_len)
 {
-    dolog ("unregistered DMA channel used nchan=%d dma_pos=%d dma_len=%d\n",
-           nchan, dma_pos, dma_len);
+    static int once = 0;
+    int mask = 1 << nchan;
+
+    if (0 == (once & mask)) {
+        once |= mask;
+        dolog ("unregistered DMA channel used nchan=%d dma_pos=%d dma_len=%d\n",
+               nchan, dma_pos, dma_len);
+    }
     return dma_pos;
 }
 
-- 
1.9.1