* xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used @ 2010-01-05 20:55 Frank Van Der Linden 2010-01-05 21:02 ` Keir Fraser 2010-01-06 1:55 ` Wei, Gang 0 siblings, 2 replies; 5+ messages in thread From: Frank Van Der Linden @ 2010-01-05 20:55 UTC (permalink / raw) To: xen-devel I've been looking at Xen (3.4.2) power management, and have been trying out different settings. One machine I tried was a Toshiba M30 laptop, which has an Intel Core 2 Duo CPU: CPU0: Intel(R) Core(TM)2 Duo CPU P8400 @ 2.26GHz stepping 06 CPU1: Intel(R) Core(TM)2 Duo CPU P8400 @ 2.26GHz stepping 06 When dom0 initialized power management, the messages printed are as follows: Set CPU acpi_id(0) cpuid(0) Px State info: _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 _PSS: state_count=4 State0: 2261MHz 35000mW 10us 10us 0x927 0x927 State1: 2260MHz 35000mW 10us 10us 0x4822 0x4822 State2: 1600MHz 16000mW 10us 10us 0x617 0x617 State3: 800MHz 14300mW 10us 10us 0x8611 0x8611 _PSD: num_entries=5 rev=0 domain=0 coord_type=252 num_processors=1 _PPC: 0 xen_pminfo: @acpi_cpufreq_cpu_init,HARDWARE addr space CPU 0 initialization completed Set CPU acpi_id(1) cpuid(1) Px State info: _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 _PSS: state_count=4 State0: 2261MHz 35000mW 10us 10us 0x927 0x927 State1: 2260MHz 35000mW 10us 10us 0x4822 0x4822 State2: 1600MHz 16000mW 10us 10us 0x617 0x617 State3: 800MHz 14300mW 10us 10us 0x8611 0x8611 _PSD: num_entries=5 rev=0 domain=1 coord_type=252 num_processors=1 _PPC: 0 xen_pminfo: @acpi_cpufreq_cpu_init,HARDWARE addr space CPU 1 initialization completed cpuid.MWAIT[.eax=40, .ebx=40, .ecx=3, .edx=3122220] Monitor-Mwait will be used to enter C-1 state cpuid.MWAIT[.eax=40, .ebx=40, .ecx=3, .edx=3122220] Monitor-Mwait will be used to enter C-1 state It seems to mostly work ok, except that an OpenSolaris HVM domU slows down to a crawl. When I examined it, I noticed that it wasn't getting any timer interrupts. Or, almost none; occasionally the interrupt count for the timer jumps, but mostly it stays frozen. If I limit the maximum C state to C2, things seem ok, but when C3 is used, the problems pops up pretty quickly, though not immediately: if I initialize the maximum C state to 1, but then change it to C3 when the domU is already running, it won't immediately slow down, it might take about a minute, during which time the xenpm utility already is showing that C3 is being used. So a switch to C3 isn't guaranteed to cause the problem, but it eventually will. I tried other HVM domains, such as Windows, and they don't seem to have the problem. But, they might be more "tickless" than OpenSolaris is. I haven't looked at the PM code much yet, and I haven't tried -unstable, but there don't seem to be any changes in -unstable that would fix this. Is this a known problem? Any hints for diagnosing the problem? - Frank ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used 2010-01-05 20:55 xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used Frank Van Der Linden @ 2010-01-05 21:02 ` Keir Fraser 2010-01-06 1:55 ` Wei, Gang 1 sibling, 0 replies; 5+ messages in thread From: Keir Fraser @ 2010-01-05 21:02 UTC (permalink / raw) To: Frank Van Der Linden, xen-devel@lists.xensource.com On 05/01/2010 20:55, "Frank Van Der Linden" <Frank.Vanderlinden@Sun.COM> wrote: > I tried other HVM domains, such as Windows, and they don't seem to have > the problem. But, they might be more "tickless" than OpenSolaris is. > > I haven't looked at the PM code much yet, and I haven't tried -unstable, > but there don't seem to be any changes in -unstable that would fix this. > > Is this a known problem? Any hints for diagnosing the problem? Perhaps CPUs are not being woken from C3 in a timely manner? Could check how late timers are fired in timer_softirq_action(), perhaps printing largest missed deadline every few seconds or soemthing like that. -- Keir ^ permalink raw reply [flat|nested] 5+ messages in thread
* RE: xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used 2010-01-05 20:55 xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used Frank Van Der Linden 2010-01-05 21:02 ` Keir Fraser @ 2010-01-06 1:55 ` Wei, Gang 2010-01-06 2:29 ` Frank Van Der Linden 1 sibling, 1 reply; 5+ messages in thread From: Wei, Gang @ 2010-01-06 1:55 UTC (permalink / raw) To: Frank Van Der Linden, xen-devel@lists.xensource.com Frank Van Der Linden wrote: > I haven't looked at the PM code much yet, and I haven't tried > -unstable, but there don't seem to be any changes in -unstable that > would fix this. > > Is this a known problem? Any hints for diagnosing the problem? > > - Frank To make sure whether it is problem of the xen time sub-system, can you try some "while true; do date; sleep 1; done" loop from dom0 directly, w/o creating HVM domain? BTW, could you also do "xm debug c; xm dmesg > xmdmesg.log" in dom0 only case and attach the entire xmdmesg.log? More platform related information can be got from it. Jimmy ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used 2010-01-06 1:55 ` Wei, Gang @ 2010-01-06 2:29 ` Frank Van Der Linden 2010-01-06 4:01 ` Wei, Gang 0 siblings, 1 reply; 5+ messages in thread From: Frank Van Der Linden @ 2010-01-06 2:29 UTC (permalink / raw) To: Wei, Gang; +Cc: xen-devel@lists.xensource.com Wei, Gang wrote: > Frank Van Der Linden wrote: > >> I haven't looked at the PM code much yet, and I haven't tried >> -unstable, but there don't seem to be any changes in -unstable that >> would fix this. >> >> Is this a known problem? Any hints for diagnosing the problem? >> >> - Frank >> > > To make sure whether it is problem of the xen time sub-system, can you try some "while true; do date; sleep 1; done" loop from dom0 directly, w/o creating HVM domain? > > BTW, could you also do "xm debug c; xm dmesg > xmdmesg.log" in dom0 only case and attach the entire xmdmesg.log? More platform related information can be got from it. > > Jimmy > I tested dom0, and time on dom0 is working just fine. This is the Solaris dom0, but that shouldn't matter in this case. Here is the xm dmesg output (plus the c debug key output), with dom0 having been up for a while, but no domUs had ever been run: (xVM) xVM version 3.4.2-xvm-debug (xVM) Command line: console=com1 com1=115200,8n1 dom0_mem=1536M (xVM) Video information: (xVM) VGA is text mode 80x25, font 8x16 (xVM) VBE/DDC methods: none; EDID transfer time: 0 seconds (xVM) EDID info not retrieved because no DDC retrieval method detected (xVM) Disc information: (xVM) Found 1 MBR signatures (xVM) Found 1 EDD information structures (xVM) Xen-e820 RAM map: (xVM) 0000000000000000 - 000000000009bc00 (usable) (xVM) 000000000009bc00 - 00000000000a0000 (reserved) (xVM) 00000000000e8000 - 00000000000eee00 (reserved) (xVM) 00000000000eee00 - 00000000000ef000 (ACPI NVS) (xVM) 00000000000ef000 - 0000000000100000 (reserved) (xVM) 0000000000100000 - 00000000bfba0000 (usable) (xVM) 00000000bfba0000 - 00000000c0000000 (reserved) (xVM) 00000000fec00000 - 00000000fec28000 (reserved) (xVM) 00000000fed00000 - 00000000fed00500 (reserved) (xVM) 00000000fed10000 - 00000000fed1a000 (reserved) (xVM) 00000000fed1c000 - 00000000fed94000 (reserved) (xVM) 00000000fee00000 - 00000000fee01000 (reserved) (xVM) 00000000ffa00000 - 00000000ffc00000 (reserved) (xVM) 00000000ffd00000 - 0000000100000000 (reserved) (xVM) 0000000100000000 - 000000013c000000 (usable) (xVM) System RAM: 4027MB (4123884kB) (xVM) ACPI: RSDP 000F00B0, 0014 (r0 TOSHIB) (xVM) ACPI: RSDT BFBA0000, 0058 (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: FACP BFBA0084, 0084 (r2 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: DSDT BFBA0108, 82BF (r2 TOSHIB A0066 20080603 MSFT 3000000) (xVM) ACPI: FACS 000EEE00, 0040 (xVM) ACPI: SSDT BFBA83C7, 0506 (r2 TOSHIB A0066 20070720 MSFT 3000000) (xVM) ACPI: BOOT BFBA005C, 0028 (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: APIC BFBA8EA1, 0068 (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: MCFG BFBA8F09, 003C (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: HPET BFBA8F45, 0038 (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: TCPA BFBA924A, 0032 (r2 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: SLIC BFBA927C, 0176 (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: ASF! BFBA8FB1, 0075 (r16 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: DMAR BFBA9026, 00C8 (r1 TOSHIB A0066 20080603 TASM 4010000) (xVM) ACPI: SSDT BFBA9E91, 01A3 (r2 TOSHIB A0066 20080317 MSFT 3000000) (xVM) ACPI: SSDT BFBA93F2, 0076 (r2 TOSHIB A0066 20080310 MSFT 3000000) (xVM) ACPI: SSDT BFBA9468, 0A29 (r2 TOSHIB A0066 20080411 MSFT 3000000) (xVM) NUMA turned off (xVM) Faking a node at 0000000000000000-000000013c000000 (xVM) Domain heap initialised (xVM) DMI 2.5 present. (xVM) Using APIC driver default (xVM) ACPI: PM-Timer IO Port: 0xd808 (xVM) ACPI: ACPI SLEEP INFO: pm1x_cnt[d804,0], pm1x_evt[d800,0] (xVM) ACPI: wakeup_vec[eee0c], vec_size[20] (xVM) ACPI: Local APIC address 0xfee00000 (xVM) ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled) (xVM) Processor #0 7:7 APIC version 20 (xVM) ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled) (xVM) Processor #1 7:7 APIC version 20 (xVM) ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1]) (xVM) ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1]) (xVM) ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0]) (xVM) IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23 (xVM) ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) (xVM) ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) (xVM) ACPI: IRQ0 used by override. (xVM) ACPI: IRQ2 used by override. (xVM) ACPI: IRQ9 used by override. (xVM) Enabling APIC mode: Flat. Using 1 I/O APICs (xVM) ACPI: HPET id: 0x8086a301 base: 0xfed00000 (xVM) Using ACPI (MADT) for SMP configuration information (xVM) Using scheduler: SMP Credit Scheduler (credit) (xVM) Initializing CPU#0 (xVM) Detected 2261.053 MHz processor. (xVM) CPU: L1 I cache: 32K, L1 D cache: 32K (xVM) CPU: L2 cache: 3072K (xVM) CPU: Physical Processor ID: 0 (xVM) CPU: Processor Core ID: 0 (xVM) VMX: Supported advanced features: (xVM) - APIC MMIO access virtualisation (xVM) - APIC TPR shadow (xVM) - Virtual NMI (xVM) - MSR direct-access bitmap (xVM) HVM: VMX enabled (xVM) Intel machine check reporting enabled on CPU#0. (xVM) mce_init: init bank1 (xVM) mce_init: init bank2 (xVM) mce_init: init bank3 (xVM) mce_init: init bank4 (xVM) mce_init: init bank5 (xVM) CPU0: Thermal monitoring handled by SMI (xVM) CMCI: CPU0 has no CMCI support (xVM) CPU0: Intel(R) Core(TM)2 Duo CPU P8400 @ 2.26GHz stepping 06 (xVM) Booting processor 1/1 eip 8c000 (xVM) Initializing CPU#1 (xVM) CPU: L1 I cache: 32K, L1 D cache: 32K (xVM) CPU: L2 cache: 3072K (xVM) CPU: Physical Processor ID: 0 (xVM) CPU: Processor Core ID: 1 (xVM) Intel machine check reporting enabled on CPU#1. (xVM) mce_init: init bank1 (xVM) mce_init: init bank2 (xVM) mce_init: init bank4 (xVM) mce_init: init bank5 (xVM) CPU1: Thermal monitoring enabled (TM2) (xVM) CMCI: CPU1 has no CMCI support (xVM) CPU1: Intel(R) Core(TM)2 Duo CPU P8400 @ 2.26GHz stepping 06 (xVM) Total of 2 processors activated. (xVM) ENABLING IO-APIC IRQs (xVM) -> Using new ACK method (xVM) ..TIMER: vector=0xF0 apic1=0 pin1=2 apic2=-1 pin2=-1 (xVM) checking TSC synchronization across 2 CPUs: passed. (xVM) Platform timer is 14.318MHz HPET (xVM) Brought up 2 CPUs (xVM) microcode.c:73:d32767 microcode: CPU1 resumed (xVM) I/O virtualisation disabled (xVM) HPET: 4 timers in total, 0 timers will be used for broadcast (xVM) ACPI sleep modes: S3 (xVM) mcheck_poll: Machine check polling timer started. (xVM) *** LOADING DOMAIN 0 *** (xVM) elf_parse_binary: phdr: paddr=0x40800000 memsz=0x273e8 (xVM) elf_parse_binary: phdr: paddr=0x40000000 memsz=0x1a916c (xVM) elf_parse_binary: phdr: paddr=0x40400000 memsz=0xd97f0 (xVM) elf_parse_binary: memory: 0x40000000 -> 0x408273e8 (xVM) elf_xen_parse_note: LOADER = "generic" (xVM) elf_xen_parse_note: XEN_VERSION = "xen-3.0" (xVM) elf_xen_parse_note: GUEST_OS = "Solaris" (xVM) elf_xen_parse_note: VIRT_BASE = 0x40000000 (xVM) elf_xen_parse_note: PADDR_OFFSET = 0x40000000 (xVM) elf_xen_addr_calc_check: addresses: (xVM) virt_base = 0x40000000 (xVM) elf_paddr_offset = 0x40000000 (xVM) virt_offset = 0x0 (xVM) virt_kstart = 0x40000000 (xVM) virt_kend = 0x408273e8 (xVM) virt_entry = 0x40800000 (xVM) p2m_base = 0xffffffffffffffff (xVM) Xen kernel: 64-bit, lsb, compat32 (xVM) Dom0 kernel: 64-bit, lsb, paddr 0x40000000 -> 0x408273e8 (xVM) PHYSICAL MEMORY ARRANGEMENT: (xVM) Dom0 alloc.: 0000000134000000->0000000138000000 (376832 pages to be allocated) (xVM) VIRTUAL MEMORY ARRANGEMENT: (xVM) Loaded kernel: 0000000040000000->00000000408273e8 (xVM) Init. ramdisk: 0000000040828000->0000000043548000 (xVM) Phys-Mach map: 0000000043548000->0000000043848000 (xVM) Start info: 0000000043848000->00000000438484b4 (xVM) Page tables: 0000000043849000->000000004386a000 (xVM) Boot stack: 000000004386a000->000000004386b000 (xVM) TOTAL: 0000000040000000->0000000043c00000 (xVM) ENTRY ADDRESS: 0000000040800000 (xVM) Dom0 has maximum 2 VCPUs (xVM) elf_load_binary: phdr 1 at 0x0000000040800000 -> 0x00000000408273e8 (xVM) elf_load_binary: phdr 2 at 0x0000000040000000 -> 0x00000000401a916c (xVM) elf_load_binary: phdr 3 at 0x0000000040400000 -> 0x00000000404136ff (xVM) Scrubbing Free RAM: ........................done. (xVM) Xen trace buffers: disabled (xVM) Std. Loglevel: All (xVM) Guest Loglevel: All (xVM) *** Serial input -> DOM0 (type \047CTRL-a\047 three times to switch input to Xen) (xVM) Freed 156kB init memory. (xVM) grant_table.c:808:d0 Expanding dom (0) grant table from (4) to (32) frames. (xVM) PCI add device 00:1f.2 (xVM) Set CPU acpi_id(0) cpuid(0) Px State info: (xVM) _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 (xVM) _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 (xVM) _PSS: state_count=4 (xVM) State0: 2261MHz 35000mW 10us 10us 0x927 0x927 (xVM) State1: 2260MHz 35000mW 10us 10us 0x4822 0x4822 (xVM) State2: 1600MHz 16000mW 10us 10us 0x617 0x617 (xVM) State3: 800MHz 14300mW 10us 10us 0x8611 0x8611 (xVM) _PSD: num_entries=5 rev=0 domain=0 coord_type=252 num_processors=1 (xVM) _PPC: 0 (xVM) xen_pminfo: @acpi_cpufreq_cpu_init,HARDWARE addr space (xVM) CPU 0 initialization completed (xVM) Set CPU acpi_id(1) cpuid(1) Px State info: (xVM) _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 (xVM) _PCT: descriptor=0, length=0, space_id=127, bit_width=0, bit_offset=0, reserved=0, address=0 (xVM) _PSS: state_count=4 (xVM) State0: 2261MHz 35000mW 10us 10us 0x927 0x927 (xVM) State1: 2260MHz 35000mW 10us 10us 0x4822 0x4822 (xVM) State2: 1600MHz 16000mW 10us 10us 0x617 0x617 (xVM) State3: 800MHz 14300mW 10us 10us 0x8611 0x8611 (xVM) _PSD: num_entries=5 rev=0 domain=1 coord_type=252 num_processors=1 (xVM) _PPC: 0 (xVM) xen_pminfo: @acpi_cpufreq_cpu_init,HARDWARE addr space (xVM) CPU 1 initialization completed (xVM) cpuid.MWAIT[.eax=40, .ebx=40, .ecx=3, .edx=3122220] (xVM) Monitor-Mwait will be used to enter C-1 state (xVM) cpuid.MWAIT[.eax=40, .ebx=40, .ecx=3, .edx=3122220] (xVM) Monitor-Mwait will be used to enter C-1 state (xVM) PCI add device 00:19.0 (xVM) PCI add device 00:1b.0 (xVM) Xen trace buffers: initialized (xVM) *** Serial input -> Xen (type \047CTRL-a\047 three times to switch input to DOM0) (xVM) ==cpu0== (xVM) active state: C3 (xVM) max_cstate: C7 (xVM) states: (xVM) C1: type[C1] latency[001] usage[00005351] duration[16709386] (xVM) C2: type[C2] latency[001] usage[00072721] duration[48331319757] (xVM) *C3: type[C3] latency[057] usage[05261685] duration[32698354952269] (xVM) C0: usage[05339757] duration[337842300997] (xVM) ==cpu1== (xVM) active state: C3 (xVM) max_cstate: C7 (xVM) states: (xVM) C1: type[C1] latency[001] usage[00000050] duration[1916444] (xVM) C2: type[C2] latency[001] usage[00039050] duration[77772952140] (xVM) *C3: type[C3] latency[057] usage[05592302] duration[32757362666651] (xVM) C0: usage[05631402] duration[249407777117] - Frank ^ permalink raw reply [flat|nested] 5+ messages in thread
* RE: xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used 2010-01-06 2:29 ` Frank Van Der Linden @ 2010-01-06 4:01 ` Wei, Gang 0 siblings, 0 replies; 5+ messages in thread From: Wei, Gang @ 2010-01-06 4:01 UTC (permalink / raw) To: Frank Van Der Linden; +Cc: xen-devel@lists.xensource.com [-- Attachment #1: Type: text/plain, Size: 678 bytes --] Frank Van Der Linden wrote: > I tested dom0, and time on dom0 is working just fine. This is the > Solaris dom0, but that shouldn't matter in this case. Here is the xm > dmesg output (plus the c debug key output), with dom0 having been up > for > a while, but no domUs had ever been run: Can't see any problem from the serial output. Let's take a further step. Attached patch is a __draft__ patch to collect statistics related with timer interrupts & timer fns. Can you apply it, rebuild the xen hypervisor code, then do "xm debug 9; sleep 20; xm debug 9; xm dmesg > xmdmesg.log" in both dom0 only & 1 HVM cases. Let's have a look on the timer statistics first. Jimmy [-- Attachment #2: timer_fn_stat_v1.patch --] [-- Type: application/octet-stream, Size: 11847 bytes --] diff -r a7b2d4e03a1f xen/arch/x86/apic.c --- a/xen/arch/x86/apic.c Mon Jan 04 09:09:27 2010 +0000 +++ b/xen/arch/x86/apic.c Wed Jan 06 11:37:28 2010 +0800 @@ -1225,6 +1225,9 @@ int reprogram_timer(s_time_t timeout) fastcall void smp_apic_timer_interrupt(struct cpu_user_regs * regs) { + extern void timer_stat_apic_inc( void ); + timer_stat_apic_inc(); + ack_APIC_irq(); perfc_incr(apic_timer); raise_softirq(TIMER_SOFTIRQ); diff -r a7b2d4e03a1f xen/arch/x86/hpet.c --- a/xen/arch/x86/hpet.c Mon Jan 04 09:09:27 2010 +0000 +++ b/xen/arch/x86/hpet.c Wed Jan 06 11:37:28 2010 +0800 @@ -181,6 +181,11 @@ static void handle_hpet_broadcast(struct int cpu; spin_lock_irq(&ch->lock); + + { + extern void timer_stat_hpet_inc (void); + timer_stat_hpet_inc(); + } again: ch->next_event = STIME_MAX; diff -r a7b2d4e03a1f xen/arch/x86/time.c --- a/xen/arch/x86/time.c Mon Jan 04 09:09:27 2010 +0000 +++ b/xen/arch/x86/time.c Wed Jan 06 11:37:28 2010 +0800 @@ -186,6 +186,11 @@ static void smp_send_timer_broadcast_ipi { int cpu = smp_processor_id(); cpumask_t mask; + + { + extern void timer_stat_pit_inc (void); + timer_stat_pit_inc(); + } cpus_and(mask, cpu_online_map, pit_broadcast_mask); diff -r a7b2d4e03a1f xen/common/timer.c --- a/xen/common/timer.c Mon Jan 04 09:09:27 2010 +0000 +++ b/xen/common/timer.c Wed Jan 06 11:37:28 2010 +0800 @@ -18,6 +18,7 @@ #include <xen/timer.h> #include <xen/keyhandler.h> #include <xen/percpu.h> +#include <xen/guest_access.h> #include <asm/system.h> #include <asm/desc.h> @@ -37,6 +38,136 @@ struct timers { } __cacheline_aligned; static DEFINE_PER_CPU(struct timers, timers); + +struct timer_stat{ + u64 nr_executed_timer; + u64 nr_timer_softirq; + u64 nr_timer_softirq_add_timer; + u64 nr_timer_softirq_stop_timer; + u64 nr_local_apic_intr; + u64 nr_hpet_intr; /* received HEPT interrupt */ + u64 nr_pit_intr; /* received PIT interrupt */ + u64 nr_broadcast_IPI; /* received broadcast EVENT_CHECK IPI + Issued by cpumask_raise_softirq()*/ +}; + +static DEFINE_PER_CPU(struct timer_stat, timer_stat)={0UL}; +static DEFINE_PER_CPU(struct timer_stat, saved_timer_stat) = {0UL}; + +static s_time_t timer_stat_now = 0; + +#define TIMER_STAT_INC(_field) do { \ + this_cpu(timer_stat)._field++; \ + }while(0) + +#define TIMER_STAT_INC_CPU(_field, _cpu) do {\ + per_cpu(timer_stat, _cpu)._field++;\ + }while(0) + +void timer_stat_apic_inc( void ) +{ + TIMER_STAT_INC(nr_local_apic_intr); +} + +void timer_stat_hpet_inc (void) +{ + TIMER_STAT_INC(nr_hpet_intr); +} + +void timer_stat_pit_inc (void) +{ + TIMER_STAT_INC(nr_pit_intr); +} + +void timer_stat_broadcast_IPI_inc(cpumask_t mask) +{ + int cpu; + for_each_cpu_mask(cpu, mask) + { + TIMER_STAT_INC_CPU(nr_broadcast_IPI, cpu); + } +} + +static void timer_stat_dump_per_cpu( int cpu, s_time_t now) +{ +#define S_DIFF(_saved,_current,_field) (_current->_field - _saved->_field) + struct timer_stat *t, *saved_t; + u64 nr_all_intr; + u64 HZ_all_intr; + + t = &per_cpu( timer_stat, cpu ); + saved_t = &per_cpu( saved_timer_stat, cpu ); + + nr_all_intr = S_DIFF( saved_t, t, nr_local_apic_intr ) + + S_DIFF( saved_t, t, nr_hpet_intr ) + + S_DIFF( saved_t, t, nr_pit_intr ) + + S_DIFF( saved_t, t, nr_broadcast_IPI ); + + if (now > timer_stat_now){ + HZ_all_intr = nr_all_intr * 10000 / ((now-timer_stat_now)/100000); + }else{ + HZ_all_intr = 0; + } + + printk("%d", cpu); + printk("\t"); + printk("\t%"PRIu64, S_DIFF( saved_t, t, nr_executed_timer )); + printk("\t%"PRIu64, S_DIFF( saved_t, t, nr_local_apic_intr )); + printk("\t%"PRIu64, S_DIFF( saved_t, t, nr_hpet_intr )); + printk("\t%"PRIu64, S_DIFF( saved_t, t, nr_pit_intr )); + printk("\t%"PRIu64, S_DIFF( saved_t, t, nr_broadcast_IPI )); + printk("\t%"PRIu64, HZ_all_intr ); + if (nr_all_intr != 0) { + printk("\t%"PRIu64, 100 * S_DIFF( saved_t, t, nr_executed_timer ) / nr_all_intr ); + } + else { + printk("\t0"); + } + + printk("\n"); + + memcpy(saved_t, t, sizeof(struct timer_stat)); +} + +static void timer_stat_dump(unsigned char key) +{ + int i; + s_time_t now; + + printk("Dump timer statistic\n"); + printk("CPU"); + /* number of executed timer, i.e. calling number of execute_timer() */ + printk("\ttimer"); + + printk("\tlapic"); + printk("\thpet"); + printk("\tpit"); + + /* number of received broadcast IPI */ + printk("\tIPI"); + + /* interrupt frequency : (lapic_intr + hpet_intr + bc_IPI) / period */ + printk("\tHZ"); + + /* number of executed timer per interrupt */ + printk("\t100*timer/all_intr"); + printk("\n"); + + now = NOW(); + for_each_cpu ( i ) + { + timer_stat_dump_per_cpu(i, now); + } + + printk("Period: %"PRId64" seconds\n", (now - timer_stat_now)/1000000000); + timer_stat_now = now; + + { + void timer_stat_dump_1(void); + timer_stat_dump_1(); + } +} + DEFINE_PER_CPU(s_time_t, timer_deadline); @@ -211,14 +342,20 @@ static inline void __add_timer(struct ti { int cpu = timer->cpu; if ( add_entry(&per_cpu(timers, cpu), timer) ) + { + TIMER_STAT_INC_CPU(nr_timer_softirq_add_timer, cpu); cpu_raise_softirq(cpu, TIMER_SOFTIRQ); + } } static inline void __stop_timer(struct timer *timer) { int cpu = timer->cpu; if ( remove_entry(&per_cpu(timers, cpu), timer) ) + { + TIMER_STAT_INC_CPU(nr_timer_softirq_stop_timer, cpu); cpu_raise_softirq(cpu, TIMER_SOFTIRQ); + } } static inline void timer_lock(struct timer *timer) @@ -353,7 +490,10 @@ static void execute_timer(struct timers void (*fn)(void *) = t->function; void *data = t->data; + TIMER_STAT_INC(nr_executed_timer); + ts->running = t; + timer_stat_inc(t); spin_unlock_irq(&ts->lock); (*fn)(data); spin_lock_irq(&ts->lock); @@ -366,6 +506,8 @@ static void timer_softirq_action(void) struct timer *t, **heap, *next; struct timers *ts; s_time_t now; + + TIMER_STAT_INC(nr_timer_softirq); ts = &this_cpu(timers); heap = ts->heap; @@ -505,7 +647,6 @@ static void dump_timerq(unsigned char ke } } - void __init timer_init(void) { static struct timer *dummy_heap; @@ -527,7 +668,86 @@ void __init timer_init(void) } register_keyhandler('a', dump_timerq, "dump timer queues"); + register_keyhandler('9', timer_stat_dump, "dump timer statistics"); } + +#ifdef CONFIG_TIMER_STAT + +static struct timers_stat stat_data; +static struct timers_stat stat_data_saved; +static s_time_t now_saved; +spinlock_t timers_stat_lock = SPIN_LOCK_UNLOCKED; + +void timer_stat_dump_1(void) +{ + int i, cpu; + s_time_t ms,now; + + now = NOW(); + ms = (now - now_saved)/1000000; + if (ms == 0) return; + + printk("%20s", "timer_fn"); + for_each_online_cpu (cpu) + printk("\tCPU%d", cpu); + printk("\n"); + + for (i=0; i<stat_data.nr_timer; i++) + { + printk("%20s",stat_data.data[i].fn_name); + for_each_online_cpu (cpu) + { + printk("\t%ld", (stat_data.data[i].count[cpu] - + stat_data_saved.data[i].count[cpu]) * 1000 / ms); + } + printk("\n"); + } + now_saved = now; + memcpy(&stat_data_saved, &stat_data, sizeof(stat_data)); +} + +void timer_stat_inc(struct timer* t) +{ + if ( t->stat_index > 0 && t->stat_index <= MAX_NR_TIMER ){ + stat_data.data[t->stat_index-1].count[t->cpu]++; + } +} + +void timer_stat_register(struct timer* t, char* fn_name) +{ + int i; + + spin_lock( &timers_stat_lock ); + + if ( stat_data.nr_timer < MAX_NR_TIMER ) + { + for ( i=0; i < stat_data.nr_timer; i++ ) + { + if ( stat_data.data[i].fn_addr == (u64)t->function ) + { + t->stat_index = i+1; + goto out; /* already registered */ + } + } + + stat_data.nr_timer++; + t->stat_index = stat_data.nr_timer; + strlcpy( stat_data.data[t->stat_index-1].fn_name , fn_name, + XEN_TIMER_NAME_MAX_LEN); + stat_data.data[t->stat_index-1].fn_addr = (u64)t->function; + } + else + { + printk( KERN_WARNING "Warning: Timer statistics array overflow," + "please enlarge MAX_NR_TIMER\n" ); + t->stat_index = 0; + } + +out: + spin_unlock( &timers_stat_lock ); +} + +#endif /* CONFIG_TIMER_STAT */ /* * Local variables: diff -r a7b2d4e03a1f xen/include/xen/softirq.h --- a/xen/include/xen/softirq.h Mon Jan 04 09:09:27 2010 +0000 +++ b/xen/include/xen/softirq.h Wed Jan 06 11:37:28 2010 +0800 @@ -37,6 +37,12 @@ static inline void cpumask_raise_softirq { if ( test_and_set_bit(nr, &softirq_pending(cpu)) ) cpu_clear(cpu, mask); + } + + if (nr == TIMER_SOFTIRQ) + { + extern void timer_stat_broadcast_IPI_inc(cpumask_t mask); + timer_stat_broadcast_IPI_inc(mask); } smp_send_event_check_mask(mask); diff -r a7b2d4e03a1f xen/include/xen/timer.h --- a/xen/include/xen/timer.h Mon Jan 04 09:09:27 2010 +0000 +++ b/xen/include/xen/timer.h Wed Jan 06 11:37:28 2010 +0800 @@ -11,6 +11,9 @@ #include <xen/spinlock.h> #include <xen/time.h> #include <xen/string.h> +#include <public/sysctl.h> + +#define CONFIG_TIMER_STAT /* timer statistics, default is off */ struct timer { /* System time expiry value (nanoseconds since boot). */ @@ -38,6 +41,10 @@ struct timer { #define TIMER_STATUS_in_heap 2 /* In use; on timer heap. */ #define TIMER_STATUS_in_list 3 /* In use; on overflow linked list. */ uint8_t status; + +#ifdef CONFIG_TIMER_STAT + uint16_t stat_index; /* index in timer statistics array */ +#endif }; /* @@ -60,7 +67,7 @@ static inline int active_timer(struct ti * time (and multiple times) on an inactive timer. It must *never* execute * concurrently with any other operation on the same timer. */ -static inline void init_timer( +static inline void raw_init_timer( struct timer *timer, void (*function)(void *), void *data, @@ -71,6 +78,20 @@ static inline void init_timer( timer->data = data; timer->cpu = cpu; } + +#ifdef CONFIG_TIMER_STAT + +#define init_timer(x1,x2,x3,x4) do{\ + raw_init_timer(x1,x2,x3,x4);\ + timer_stat_register(x1, STR(x2));\ + }while(0) + +#else + +#define init_timer(x1,x2,x3,x4) raw_init_timer(x1,x2,x3,x4) + +#endif /* CONFIG_TIMER_STAT */ + /* * Set the expiry time and activate a timer. The timer must *previously* have @@ -119,6 +140,37 @@ extern int reprogram_timer(s_time_t time /* calculate the aligned first tick time for a given periodic timer */ extern s_time_t align_timer(s_time_t firsttick, uint64_t period); +#ifdef CONFIG_TIMER_STAT /* timer execution count */ +#define XEN_TIMER_NAME_MAX_LEN 20 +#define MAX_NR_TIMER 64 + +struct timer_stat_v2{ + char fn_name[XEN_TIMER_NAME_MAX_LEN]; + u64 fn_addr; + u64 count[NR_CPUS]; +}; + +struct timers_stat{ + u32 nr_timer; + struct timer_stat_v2 data[MAX_NR_TIMER]; +}; + +void timer_stat_register(struct timer* t,char* fn_name); +void timer_stat_inc(struct timer* t); +int timer_stat_get(struct xen_sysctl_pm_op *op); + +#else + +#define timer_stat_register(x,y) ((void)0) +#define timer_stat_inc(x) ((void)0) + +static inline int timer_stat_get(truct xen_sysctl_pm_op *op) +{ + return -ENODATA; +} + +#endif /* CONFIG_TIMER_STAT */ + #endif /* _TIMER_H_ */ /* [-- Attachment #3: Type: text/plain, Size: 138 bytes --] _______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel ^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2010-01-06 4:01 UTC | newest] Thread overview: 5+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2010-01-05 20:55 xenpm: opensolaris HVM domU stops getting timer interrupts when C3 used Frank Van Der Linden 2010-01-05 21:02 ` Keir Fraser 2010-01-06 1:55 ` Wei, Gang 2010-01-06 2:29 ` Frank Van Der Linden 2010-01-06 4:01 ` Wei, Gang
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.