Re: Linux-next Alsa hda_intel events/0 high CPU usage, bisected

[Takashi Iwai <tiwai@suse.de>]

At Mon, 09 Jun 2008 13:11:43 +0200,
I wrote:
> 
> At Sat, 7 Jun 2008 18:56:33 -0700 (PDT),
> Benjamin Kidwell wrote:
> > 
> > --- Takashi Iwai <> wrote:
> > 
> > > The problem is that your hardware reports the wrong DMA position.
> > > I didn't expect that this delay is so much, (IOW, the hardware is so
> > > buggy).  Maybe it should be put into its own workq.
> > 
> > I've been getting my process timing information from ps, top, and htop, which
> > I know can be unreliable in some ways (I've been using a tickless (NO_HZ=y)
> > kernel). I recompiled the g8a4bd4d kernel with that option off and a few more
> > changes to make my settings more conservative, and rechecked events/0. It
> > still reports at a consistent 2.5%, (down from about 4.3% with previous kernel
> > options) and after a short period of use (uptime 30 minutes) events/0 has had
> > 0:48 of time. In comparison, Xorg and Firefox (usually the biggest users)
> > report 1:12 and 0:44 in the same timeframe. 
> > 
> > So if I understand the purpose of the code, that means that my system has
> > generated 48 seconds worth of timing mistakes in audio playback relative to 25
> > minutes or so of audio stream, so that suggests the timing error of the
> > hardware is about 3%! That seems like huge latency for hardware so I see why
> > you wouldn't expect that.
> 
> Could you check the patch below in addition?  It's against my latest
> git tree and should be applicable as is to linux-next (since it merges
> from my tree), too.

Doh forgot the patch.  Here it is.


thanks,

Takashi


diff --git a/sound/pci/hda/hda_intel.c b/sound/pci/hda/hda_intel.c
index dc68709..c0ae0e8 100644
--- a/sound/pci/hda/hda_intel.c
+++ b/sound/pci/hda/hda_intel.c
@@ -917,6 +917,26 @@ static void azx_init_pci(struct azx *chip)
 }
 
 
+static struct timespec irq_pending_time;
+static long max_delay, avg_delay, avg_count;
+
+static void check_latency(void)
+{
+	struct timespec end_time;
+	long delay;
+
+	getnstimeofday(&end_time);
+	delay = end_time.tv_sec - irq_pending_time.tv_sec;
+	delay *= 1000000000L;
+	delay += end_time.tv_nsec - irq_pending_time.tv_nsec;
+	if (delay > max_delay) {
+		max_delay = delay;
+		printk(KERN_DEBUG "XXX hda: max_delay=%ld ns\n", max_delay);
+	}
+	avg_delay += delay / 1000;
+	avg_count++;
+}
+
 static int azx_position_ok(struct azx *chip, struct azx_dev *azx_dev);
 
 /*
@@ -952,6 +972,7 @@ static irqreturn_t azx_interrupt(int irq, void *dev_id)
 			} else {
 				/* bogus IRQ, process it later */
 				azx_dev->irq_pending = 1;
+				getnstimeofday(&irq_pending_time);
 				schedule_work(&chip->irq_pending_work);
 			}
 		}
@@ -1288,6 +1309,13 @@ static int azx_pcm_close(struct snd_pcm_substream *substream)
 	hinfo->ops.close(hinfo, apcm->codec, substream);
 	snd_hda_power_down(apcm->codec);
 	mutex_unlock(&chip->open_mutex);
+	if (avg_count) {
+		printk(KERN_DEBUG "XXX hda: avg_delay=%ld us\n",
+		       avg_delay / avg_count);
+		avg_count = 0;
+		avg_delay = 0;
+		max_delay = 0;
+	}
 	return 0;
 }
 
@@ -1521,6 +1549,7 @@ static void azx_irq_pending_work(struct work_struct *work)
 				azx_dev->irq_pending = 0;
 				spin_unlock(&chip->reg_lock);
 				snd_pcm_period_elapsed(azx_dev->substream);
+				check_latency();
 				spin_lock(&chip->reg_lock);
 			} else
 				pending++;