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?
[email protected] wrote:
>
> 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
+++ 25-akpm/sound/pci/intel8x0.c 2003-06-28 17:09:07.000000000 -0700
@@ -2062,10 +2062,8 @@ static void __devinit intel8x0_measure_a
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;
_
On Sat, 28 Jun 2003 17:10:36 PDT, Andrew Morton said:
> > 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....
[email protected]|ChangeSet|20030626004701|05850.txt
(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
+++ arch/i386/kernel/cpu/cpufreq/speedstep-ich.c 2003-06-29 10:36:34.833000667 -0400
@@ -295,7 +295,7 @@
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 */
On Sul, 2003-06-29 at 19:10, [email protected] wrote:
> > 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.
On Sun, 29 Jun 2003 21:33:33 BST, Alan Cox said:
> > 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. ;)
On Sat, 2003-06-28 at 14:31, [email protected] wrote:
> 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
On Mon, 30 Jun 2003 17:25:48 PDT, john stultz said:
> On Sat, 2003-06-28 at 14:31, [email protected] wrote:
> > 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...