2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by Valdis.Kletni.. » Sun, 29 Jun 2003 23:40:04



2.5.73-mm1 is fine.

This is *not* the "clock runs really really fas"t issue - I left -mm2 running overnight and
in some 8 hours the system clock only drifted a few seconds versus wall clock (and it's
possible it was off a few seconds when it booted, as it didn't get an NTP sync at boot).

Audio plays "too fast" - a 4 minute .ogg goes through in about 3:40, sounding a bit
high-pitched in the process.

lspci -v:
00:1f.5 Multimedia audio controller: Intel Corp. 82801CA/CAM AC'97 Audio (rev 02)
        Subsystem: Cirrus Logic: Unknown device 5959
        Flags: bus master, medium devsel, latency 0, IRQ 11
        I/O ports at d800 [size=256]
        I/O ports at dc80 [size=64]

relevant dmesg output:
Advanced Linux Sound Architecture Driver Version 0.9.4 (Mon Jun 09 12:01:18 2003 UTC).
request_module: failed /sbin/modprobe -- snd-card-0. error = -16
PCI: Setting latency timer of device 0000:00:1f.5 to 64
intel8x0: clocking to 51084
ALSA sound/pci/intel8x0.c:2520: joystick(s) found
ALSA device list:
  #0: Intel 82801CA-ICH3 at 0xd800, irq 11

The 'clocking to 51084' is *VERY* suspicious, as previously this value was
*always* 48000. Something very strange obviously happened in
intel8x0_measure_ac97_clock(), but I can't figure out what.  I don't
think the mdelay(50) is off - the Bogomips value hasn't changed from 3185.04.
The problem is deterministic - on 3 reboots, I've gotten 51084 twice and 51085
once. Unless an odd latency is hitting spin_lock_irq(save,restore), I don't
see how that code can break?

Any ideas?

  application_pgp-signature_part
< 1K Download
 
 
 

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by Andrew Morto » Mon, 30 Jun 2003 02:20:04



> This is *not* the "clock runs really really fas"t issue - I left -mm2 running overnight and
>  in some 8 hours the system clock only drifted a few seconds versus wall clock (and it's
>  possible it was off a few seconds when it booted, as it didn't get an NTP sync at boot).

>  Audio plays "too fast" - a 4 minute .ogg goes through in about 3:40, sounding a bit
>  high-pitched in the process.

>  lspci -v:
>  00:1f.5 Multimedia audio controller: Intel Corp. 82801CA/CAM AC'97 Audio (rev 02)
>          Subsystem: Cirrus Logic: Unknown device 5959
>          Flags: bus master, medium devsel, latency 0, IRQ 11
>          I/O ports at d800 [size=256]
>          I/O ports at dc80 [size=64]

>  relevant dmesg output:
>  Advanced Linux Sound Architecture Driver Version 0.9.4 (Mon Jun 09 12:01:18 2003 UTC).
>  request_module: failed /sbin/modprobe -- snd-card-0. error = -16
>  PCI: Setting latency timer of device 0000:00:1f.5 to 64
>  intel8x0: clocking to 51084
>  ALSA sound/pci/intel8x0.c:2520: joystick(s) found
>  ALSA device list:
>    #0: Intel 82801CA-ICH3 at 0xd800, irq 11

>  The 'clocking to 51084' is *VERY* suspicious

It could be that do_gettimeofday() has gone silly.  Could you
add this patch and see what it says?

 sound/pci/intel8x0.c |    6 ++----
 1 files changed, 2 insertions(+), 4 deletions(-)

diff -puN sound/pci/intel8x0.c~intel8x0-cleanup sound/pci/intel8x0.c
--- 25/sound/pci/intel8x0.c~intel8x0-cleanup    2003-06-28 17:07:43.000000000 -0700

        t = stop_time.tv_sec - start_time.tv_sec;
        t *= 1000000;
-       if (stop_time.tv_usec < start_time.tv_usec)
-               t -= start_time.tv_usec - stop_time.tv_usec;
-       else
-               t += stop_time.tv_usec - start_time.tv_usec;
+       t += stop_time.tv_usec - start_time.tv_usec;
+       printk(KERN_INFO "%s: measured %lu usecs\n", __FUNCTION__, t);
        if (t == 0) {
                snd_printk(KERN_ERR "?? calculation error..\n");
                return;

_

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in

More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

 
 
 

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by Valdis.Kletni.. » Mon, 30 Jun 2003 20:20:10


On Sat, 28 Jun 2003 17:10:36 PDT, Andrew Morton said:

Quote:> >  The 'clocking to 51084' is *VERY* suspicious

> It could be that do_gettimeofday() has gone silly.  Could you
> add this patch and see what it says?

Woo woo.  Good catch, Andrew.  It says:

intel8x0_measure_ac97_clock: measured 39909 usecs

Hmm.. wonder why it's 40K rather than the expected 50K...

Turns out we're running at 1.2G rather than 1.6G.. Or at least /proc/cpuinfo
says we are.  However, things are not always what they seem....

Some testing indicates it's probably b0rkage in Dave Jone's recent work
splitting/reorging the speedstep driver....


(although the comments in the cset say Dominik Brodowski did the cleanups?)

after enabling debugging in arch/i386/kernel/cpu/cpufreq/cpufreq-ich.c
(which required the attached patch), we have this (annotated) dmesg output:

Machine check exception polling timer started.
  OK, so we know approx where in boot we are now..
speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0x10300410 0x0
    from speedstep_get_freqs()

speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0x10300410 0x0
cpufreq: read at pmbase 0x800 + 0x50 returned 0x0
cpufreq: writing 0x1 to pmbase 0x800 + 0x50
cpufreq: read at pmbase 0x800 + 0x50 returned 0x1
cpufreq: change to 0 MHz succeeded
   all this from first call from get_freqs() to set_state(SPEEDSTEP_LOW,0);
   Does that 'to 0mz' give you warm-n-fuzzies? Not me....  freqs.new isn't initialized yet...

speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0xc300410 0x0
   speedstep_get_freqs() checking that we actually went low

speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0xc300410 0x0
cpufreq: read at pmbase 0x800 + 0x50 returned 0x1
cpufreq: writing 0x0 to pmbase 0x800 + 0x50
cpufreq: read at pmbase 0x800 + 0x50 returned 0x0
cpufreq: change to 1200 MHz succeeded
   set_state(SPEEDSTEP_HIGH,0);  and again we got the wrong value in
  the message.  We went *from* 1200 *to* 1600.

speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0x10300410 0x0
speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0x10300410 0x0
cpufreq: currently at high speed setting - 1600 MHz
   speedstep_cpu_init();
cpufreq: speed=1600000 low=1200000 high=1600000
  my debugging to make sure low/high were set right.  All is good at this point,
  and we return from speedstep_cpu_init().

speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0x10300410 0x0
cpufreq: read at pmbase 0x800 + 0x50 returned 0x0
cpufreq: writing 0x0 to pmbase 0x800 + 0x50
  (remember - LOW is 1 and HIGH is 0 here)
cpufreq: read at pmbase 0x800 + 0x50 returned 0x0
cpufreq: change to 1200 MHz succeeded
  Umm.. No.  We went from 1.6G to 1.6G.

OK.. Who's the wise guy? ;)

Looks to me like cpufreq_add_device() calls cpufreq_set_policy(), which ends up
calling speedstep_set_state() with notify=1.  Rememer the missing warm-n-fuzzies?

      freqs.old = speedstep_get_processor_frequency(speedstep_processor);
        freqs.new = speedstep_freqs[SPEEDSTEP_LOW].frequency;
        freqs.cpu = 0; /* speedstep.c is UP only driver */

        if (notify)
                cpufreq_notify_transition(&freqs, CPUFREQ_PRECHANGE);

which ends up calling notify_transition() ends up calling adjust_jiffies(),
and things get pear-shaped ;)

If we're going from 1200 to 1600,  this Does The Wrong Thing because
adjust_jiffies will be passed old == new == 1200 and fail to actually change
the loops_per_jiffy because the tests are > and <.

More subtly evil, when cpu_set_policy() runs, we go from 1600 to 1600, and
notify_transition is called with bogus values.  So as a result,
adjust_jiffies() gets called with old=1600 new=1200, and we reset the jiffies
inappropriately. Meanwhile, similar evil happens in time_cpufreq_notifier(),
where cpu_khz will be incorrectly set to 1200.  So cat /proc/cpuinfo
says we're at 1.2G when we're really still at 1.6G.

End result?  Processor is running at 1.6G, /proc/cpuinfo *says* 1.2G, and
jiffies_per_loop is set for 1.2G.  We call mdelay(50) at 1.6G and enough loops
for 1.2G, and end up at 80%. So the 50ms is really 40ms, and i810 gets the wrong
clocking.

And there's this remaining nit in speedstep_set_state():
        if (state == (value & 0x1)) {
                dprintk (KERN_INFO "cpufreq: change to %u MHz succeeded\n", (freqs.new / 1000));
        } else {

Not initialized the first call, and even after will print the SPEEDSTEP_LOW number no matter what.

Oh, and the debugging patch:

--- arch/i386/kernel/cpu/cpufreq/speedstep-ich.c.dist   2003-06-29 10:34:17.949264614 -0400

                return -EIO;

        dprintk(KERN_INFO "cpufreq: currently at %s speed setting - %i MHz\n",
-               (speed == speedstep_low_freq) ? "low" : "high",
+               (speed == speedstep_freqs[SPEEDSTEP_LOW].frequency) ? "low" : "high",
                (speed / 1000));

        /* cpuinfo and default policy values */

  application_pgp-signature_part
< 1K Download
 
 
 

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by Alan Co » Mon, 30 Jun 2003 22:40:09



Quote:> > It could be that do_gettimeofday() has gone silly.  Could you
> > add this patch and see what it says?

> Woo woo.  Good catch, Andrew.  It says:

> intel8x0_measure_ac97_clock: measured 39909 usecs

> Hmm.. wonder why it's 40K rather than the expected 50K...

Lots of laptops clock the i810 audio off an existing clock and software
fix up the difference. Saves components.

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in

More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

 
 
 

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by Valdis.Kletni.. » Mon, 30 Jun 2003 23:10:29


On Sun, 29 Jun 2003 21:33:33 BST, Alan Cox said:

Quote:> > Hmm.. wonder why it's 40K rather than the expected 50K...

> Lots of laptops clock the i810 audio off an existing clock and software
> fix up the difference. Saves components.

And works fine until the speedstep stuff leaves you running at 1.6G
but jiffies_per_loop set for 1.2G, which is why mdelay(50) only
waited 40ms.  ;)

  application_pgp-signature_part
< 1K Download
 
 
 

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by john stult » Wed, 02 Jul 2003 02:30:20



> 2.5.73-mm1 is fine.

> This is *not* the "clock runs really really fas"t issue - I left -mm2 running overnight and
> in some 8 hours the system clock only drifted a few seconds versus wall clock (and it's
> possible it was off a few seconds when it booted, as it didn't get an NTP sync at boot).

> Audio plays "too fast" - a 4 minute .ogg goes through in about 3:40, sounding a bit
> high-pitched in the process.
> Any ideas?

Hrmmm. Are you seeing something like:

Loosing too many ticks!
TSC cannot be used as a timesource. (Are you running with SpeedStep?)
Falling back to a sane timesource.

in your dmesg?

I just realized that in clock_fallback() from my lost-tick-speedstep-fix
we don't re-calibrate loops_per_jiffies. The conversion from cycles to
loops should be pretty close, but that might need some additional work.

Hrmmm..
-john

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in

More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

 
 
 

2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking.

Post by Valdis.Kletni.. » Wed, 02 Jul 2003 02:50:10


On Mon, 30 Jun 2003 17:25:48 PDT, john stultz said:


> > 2.5.73-mm1 is fine.

> > This is *not* the "clock runs really really fas"t issue - I left -mm2 runni
ng overnight and
> > in some 8 hours the system clock only drifted a few seconds versus wall clo
ck (and it's
> > possible it was off a few seconds when it booted, as it didn't get an NTP s
ync at boot).

> > Audio plays "too fast" - a 4 minute .ogg goes through in about 3:40, soundi
ng a bit
> > high-pitched in the process.

> > Any ideas?

> Hrmmm. Are you seeing something like:

> Loosing too many ticks!
> TSC cannot be used as a timesource. (Are you running with SpeedStep?)
> Falling back to a sane timesource.

Nope, it's a pretty clear bug in the Speedstep code leaving loops_per_jiffies bogus.

I posted a follow-up note explaining in more detail...

  application_pgp-signature_part
< 1K Download
 
 
 

1. 2.5.73-mm2 drivers/net/pcmcia/nmclan_cs compile problem

drivers/net/pcmcia/nmclan_cs.c: In function `nmclan_config':
drivers/net/pcmcia/nmclan_cs.c:714: parse error before `*'
drivers/net/pcmcia/nmclan_cs.c:723: `tuple' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:723: (Each undeclared identifier is reported only once
drivers/net/pcmcia/nmclan_cs.c:723: for each function it appears in.)
drivers/net/pcmcia/nmclan_cs.c:724: `buf' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:728: `last_ret' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:728: `last_fn' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:730: `parse' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:741: `i' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:747: `ioaddr' undeclared (first use in this function)
drivers/net/pcmcia/nmclan_cs.c:783: `lp' undeclared (first use in this function)
make[3]: *** [drivers/net/pcmcia/nmclan_cs.o] Error 1
make[2]: *** [drivers/net/pcmcia] Error 2

Regards
Michael
--
Powered by linux-2.5.73-mm1, compiled with gcc-2.95-3 - not fancy but rock solid

My current linux related activities:
- Test development and testing of swsusp
- Everyday usage of 2.5 kernel

More info on the 2.5 kernel: http://www.codemonkey.org.uk/post-halloween-2.5.txt

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in

More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

2. 2.2.0-pre7, ppp, telnet

3. Oops in __change_page_attr Re: (was 2.5.73-mm2)

4. ppp->ssh->ppp

5. 2.5.73-mm2

6. Problem with getservbyname on AIX 4.3.2.0

7. 2.5.73-mm2 ftp conntrack/nat not working

8. Help What does patch format diskette mean.

9. 2.5.73-bk6, -bk7, -bk8, -mm2 regression test results

10. BadRAM for 2.5.73-mm2

11. Hotplug/PPP oddness n 2.5.73-mm1 - scripts not running, bad event

12. 2.5.73 problem with ALSA (ESS Allegro)

13. Advansys SCSI compile problems in 2.5.73