* 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. @ 2003-06-28 21:31 Valdis.Kletnieks 2003-06-29 0:10 ` Andrew Morton 2003-07-01 0:25 ` john stultz 0 siblings, 2 replies; 7+ messages in thread From: Valdis.Kletnieks @ 2003-06-28 21:31 UTC (permalink / raw) To: linux-kernel [-- Attachment #1: Type: text/plain, Size: 1570 bytes --] 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? [-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --] ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. 2003-06-28 21:31 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking Valdis.Kletnieks @ 2003-06-29 0:10 ` Andrew Morton 2003-06-29 18:10 ` Valdis.Kletnieks 2003-07-01 0:25 ` john stultz 1 sibling, 1 reply; 7+ messages in thread From: Andrew Morton @ 2003-06-29 0:10 UTC (permalink / raw) To: Valdis.Kletnieks; +Cc: linux-kernel Valdis.Kletnieks@vt.edu 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; _ ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. 2003-06-29 0:10 ` Andrew Morton @ 2003-06-29 18:10 ` Valdis.Kletnieks 2003-06-29 20:33 ` Alan Cox 0 siblings, 1 reply; 7+ messages in thread From: Valdis.Kletnieks @ 2003-06-29 18:10 UTC (permalink / raw) To: Andrew Morton; +Cc: linux-kernel, davej [-- Attachment #1: Type: text/plain, Size: 4936 bytes --] 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.... cset-davej@codemonkey.org.uk|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 */ [-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --] ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. 2003-06-29 18:10 ` Valdis.Kletnieks @ 2003-06-29 20:33 ` Alan Cox 2003-06-29 20:56 ` Valdis.Kletnieks 0 siblings, 1 reply; 7+ messages in thread From: Alan Cox @ 2003-06-29 20:33 UTC (permalink / raw) To: Valdis.Kletnieks; +Cc: Andrew Morton, Linux Kernel Mailing List, davej On Sul, 2003-06-29 at 19:10, Valdis.Kletnieks@vt.edu 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. ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. 2003-06-29 20:33 ` Alan Cox @ 2003-06-29 20:56 ` Valdis.Kletnieks 0 siblings, 0 replies; 7+ messages in thread From: Valdis.Kletnieks @ 2003-06-29 20:56 UTC (permalink / raw) To: Alan Cox; +Cc: Andrew Morton, Linux Kernel Mailing List, davej [-- Attachment #1: Type: text/plain, Size: 382 bytes --] 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. ;) [-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --] ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. 2003-06-28 21:31 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking Valdis.Kletnieks 2003-06-29 0:10 ` Andrew Morton @ 2003-07-01 0:25 ` john stultz 2003-07-01 0:41 ` Valdis.Kletnieks 1 sibling, 1 reply; 7+ messages in thread From: john stultz @ 2003-07-01 0:25 UTC (permalink / raw) To: Valdis.Kletnieks; +Cc: lkml, Andrew Morton On Sat, 2003-06-28 at 14:31, Valdis.Kletnieks@vt.edu 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking. 2003-07-01 0:25 ` john stultz @ 2003-07-01 0:41 ` Valdis.Kletnieks 0 siblings, 0 replies; 7+ messages in thread From: Valdis.Kletnieks @ 2003-07-01 0:41 UTC (permalink / raw) To: john stultz; +Cc: lkml, Andrew Morton [-- Attachment #1: Type: text/plain, Size: 895 bytes --] On Mon, 30 Jun 2003 17:25:48 PDT, john stultz said: > On Sat, 2003-06-28 at 14:31, Valdis.Kletnieks@vt.edu 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... [-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --] ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2003-07-01 0:26 UTC | newest] Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2003-06-28 21:31 2.5.73-mm2 - odd audio problem, bad intel8x0/ac97 clocking Valdis.Kletnieks 2003-06-29 0:10 ` Andrew Morton 2003-06-29 18:10 ` Valdis.Kletnieks 2003-06-29 20:33 ` Alan Cox 2003-06-29 20:56 ` Valdis.Kletnieks 2003-07-01 0:25 ` john stultz 2003-07-01 0:41 ` Valdis.Kletnieks
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).