Re: oops on resume

["Brian J. Murrell" <brian@interlinx.bc.ca>]

[-- Attachment #1.1: Type: text/plain, Size: 4961 bytes --]

On Thu, 2004-08-05 at 23:09 +0200, Dominik Brodowski wrote:
> 
> My bet is that speedstep_get_processor_frequency() returns something 
> between one and 100000 kHz instead of the proper value _only_ _upon_
> _resuming_.

What do _I_ win?  :-)

>  So it'd be great if you could enable SPEEDSTEP_DEBUG in both
> files mentioned above, re-test the "resume process", and tell us what the
> lines right before the oops say.

OK, enabled, and a boatload of other debug that I inserted in there:

Back to C!
zapping low mappings.
speedstep-lib: P4 - MSR_EBC_FREQUENCY_ID: 0x16300a16 0x0
FSB code = 0, msr_lo = 372247062
fsb = 100000
mult = 372247062
speedstep-lib: P4 - FSB 100000 kHz; Multiplier 22
pentium4_get_frequency() returns = 2200000
Warning: CPU frequency out of sync: cpufreq and timingcore thinks of 1200000, is 2200000 kHz.
here we are in time_cpufreq_notifier 0
here we are in time_cpufreq_notifier 1
here we are in cpufreq_scale 0, old = 2162688, div = 2200000, mult = 2200000
calling do_div(4757913600000, 2200000)
here we are in cpufreq_scale 1, returning 2162688
here we are in cpufreq_scale 0, old = 2193684, div = 2200000, mult = 2200000
calling do_div(4826104800000, 2200000)
here we are in cpufreq_scale 1, returning 2193684
here we are in time_cpufreq_notifier 2, cpu_khz = 2193684
here we are in cpufreq_scale 0, old = 1957878, div = 2200000, mult = 2200000
calling do_div(4307331600000, 2200000)
here we are in cpufreq_scale 1, returning 1957878
here we are in time_cpufreq_notifier 3, fast_gettimeoffset_quotient = 1957878
here we are in set_cyc2ns_scale 0, cpu_mhz = 2193
here we are in time_cpufreq_notifier 4
here we are in time_cpufreq_notifier 5
divide error: 0000 [#1]
Modules linked in: parport_pc(U) lp(U) parport(U) autofs4(U) ds(U) yenta_socket(U) pcmcia_core(U) sunrpc(U) 3c59x(U) floppy(U) sg(U) scsi_mod(U) dm_mod(U) uhci_hcd(U) button(U) battery(U) asus_acpi(U) ac(U) radeon(U) md5(U) ipv6(U) ext3(U)
jbd(U)
CPU:    0
EIP:    0060:[<02111fd6>]    Not tainted
EFLAGS: 00000202   (2.6.7-1.503custom)
EIP is at time_cpufreq_notifier+0x35d/0x36c
eax: 0233f4e8   ebx: 00000891   ecx: 0233d480   edx: 00000000
esi: 00000891   edi: 02302986   ebp: 001ddff6   esp: 204f4eb4
ds: 0068   es: 007b   ss: 0068
Process bash (pid: 4250, threadinfo=204f4000 task=1eca5830)
Stack: 02302a53 e0f84e80 00000000 0233ccc0 204f4ef0 00000008 00000004 0212c929
       204f4ef0 21f6b684 023c1828 02291741 02324f2b 00124f80 002191c0 00000000
       00124f80 002191c0 0210ebc0 0235edb4 023548e0 0222c151 00000000 00000002
Call Trace:
 [<0212c929>] notifier_call_chain+0x17/0x2b
 [<02291741>] cpufreq_resume+0xa9/0xd1
 [<0210ebc0>] mtrr_restore+0x42/0x47
 [<0222c151>] sysdev_resume+0x55/0xa5
 [<0222f17c>] device_power_up+0x5/0xa
 [<021390ae>] suspend_enter+0x25/0x2d
 [<02139131>] enter_state+0x54/0x7f
 [<02139239>] state_store+0x84/0x99
 [<021391b5>] state_store+0x0/0x99
 [<021a56df>] subsys_attr_store+0x19/0x21
 [<021a5852>] flush_write_buffer+0x1d/0x22
 [<021a5879>] sysfs_write_file+0x22/0x35
 [<02160b77>] vfs_write+0xb6/0xe2
 [<02160c11>] sys_write+0x2c/0x42
Code: e8 cd ce 00 00 83 c4 0c 31 c0 5b 5e 5f 5d c3 55 bd a4 cc 33

Here is my printk littered time_cpufreq_notifier to correlate all those
messages above:

static int
time_cpufreq_notifier(struct notifier_block *nb, unsigned long val,
		       void *data)
{
	struct cpufreq_freqs *freq = data;

printk("here we are in time_cpufreq_notifier 0\n");
	write_seqlock_irq(&xtime_lock);
	if (!ref_freq) {
		ref_freq = freq->old;
		loops_per_jiffy_ref = cpu_data[freq->cpu].loops_per_jiffy;
#ifndef CONFIG_SMP
		fast_gettimeoffset_ref = fast_gettimeoffset_quotient;
		cpu_khz_ref = cpu_khz;
#endif
	}

	if ((val == CPUFREQ_PRECHANGE  && freq->old < freq->new) ||
	    (val == CPUFREQ_POSTCHANGE && freq->old > freq->new) ||
	    (val == CPUFREQ_RESUMECHANGE)) {
printk("here we are in time_cpufreq_notifier 1\n");
		if (!(freq->flags & CPUFREQ_CONST_LOOPS))
			cpu_data[freq->cpu].loops_per_jiffy = cpufreq_scale(loops_per_jiffy_ref, ref_freq, freq->new);
#ifndef CONFIG_SMP
		if (cpu_khz)
			cpu_khz = cpufreq_scale(cpu_khz_ref, ref_freq, freq->new);
printk("here we are in time_cpufreq_notifier 2, cpu_khz = %lu\n", cpu_khz);
		if (use_tsc) {
			if (!(freq->flags & CPUFREQ_CONST_LOOPS)) {
				fast_gettimeoffset_quotient = cpufreq_scale(fast_gettimeoffset_ref, freq->new, ref_freq);
printk("here we are in time_cpufreq_notifier 3, fast_gettimeoffset_quotient = %lu\n", fast_gettimeoffset_quotient);
				set_cyc2ns_scale(cpu_khz/1000);
			}
		}
#endif
printk("here we are in time_cpufreq_notifier 4\n");
	}
printk("here we are in time_cpufreq_notifier 5\n");
	write_sequnlock_irq(&xtime_lock);
printk("here we are in time_cpufreq_notifier 6\n");

	return 0;
}

Notice in the debug output, we never get the "here we are in
time_cpufreq_notifier 6" message.

Thots?

b.


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

[-- Attachment #2: Type: text/plain, Size: 143 bytes --]

_______________________________________________
Cpufreq mailing list
Cpufreq@www.linux.org.uk
http://www.linux.org.uk/mailman/listinfo/cpufreq