Re: on starting HVM-domU whole system freezes with "soft lockup - CPU X stuck for XXs! [qemu-dm:...]"

[Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>]

[-- Attachment #1: Type: text/plain, Size: 6079 bytes --]

On Wed, Apr 13, 2011 at 09:30:51AM +0200, MadLoisae@gmx.net wrote:
> Hi xen-devel,
> 
> ----
> I already posted this on xen-users - Todd Deshane asked me to post
> this here for feedback.
> He also asked if I can test xen 4.1 - I am looking if I can find and
> install backports but if not I'm afraid I think I'm not able to
> compiling on myself.
> ----
> 
> I am trying since a few days my first steps with xen.
> Hardware: Core2 T7200, Intel 945GME, 2GB RAM
> Software: debian squeeze, i686, with debian delivered xen 4.0.1
> CPU and BIOS support hardware virtualisation: (XEN) HVM: VMX enabled
> 
> I can successfully boot with xen my dom0 with squeeze-delivered i686 kernel.
> As soon as I start a HVM (paravirtualisation works without problems)
> my dom0 stucks immediately.
> I can see about 10 seconds after starting domU "nothing", then the
> first messages like "hrtimer: interrupt took 1739955444 ns" messages
> appear, then my disk gets timeouts. then kernel panics like below
> are starting - normally they are not written to messages-log, one
> time i had "luck":

That is indeed "lucky" as it looks as all the interrupts got disabled
on your machine. And all the drivers started to hit their error handling
code as they hit their timeouts.

But the weird part is that this message got written to disk so the interrupts
did get re-enabled.. Is this happening only on this machine?
Can you run the attached code and see what happens when the
guest starts?

Also, how much memory do you give to your domain?

> 
> kernel: : [ 4815.144473] saa7146 (0) vpeirq: used 3 times >80% of
> buffer (1049604 bytes now)
> kernel: : [ 4815.144473] Modules linked in: tun xt_physdev loop
> ipt_REJECT ip6table_filter ip6_tables ebtable_nat ebtables bridge
> stp xen_evtchn xenfs nfsd lockd nfs_acl auth_rpcgss sunrpc exportfs
> xt_recent ipt_MASQUERADE xt_tcpudp xt_state iptable_nat nf_nat
> nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 iptable_filter
> ip_tables x_tables fuse ext4 jbd2 crc16 it87 hwmon_vid coretemp
> tda10021 snd_hda_codec_via budget_av snd_hda_intel snd_hda_codec
> saa7146_vv snd_hwdep videodev v4l1_compat snd_pcm_oss snd_mixer_oss
> videobuf_dma_sg videobuf_core snd_pcm snd_seq_midi snd_rawmidi
> snd_seq_midi_event snd_seq budget_core i915 drm_kms_helper dvb_core
> snd_timer saa7146 snd_seq_device ttpci_eeprom drm rng_core pcspkr
> evdev i2c_i801 i2c_algo_bit snd i2c_core soundcore video output
> button snd_page_alloc processor acpi_processor ext3 jbd mbcache
> dm_mod sd_mod crc_t10dif ata_generic uhci_hcd ata_piix fan ehci_hcd
> libata scsi_mod e1000e usbcore nls_base thermal thermal_sys [last
> unloaded: scsi_wait_scan]
> kernel: : [ 4815.144473]
> kernel: : [ 4815.324579] saa7146 (0) saa7146_i2c_writeout [irq]:
> timed out waiting for end of xfer
> kernel: : [ 4815.324722] ata1: lost interrupt (Status 0x50)
> kernel: : [ 4815.324772] sd 0:0:0:0: [sda] Unhandled error code
> kernel: : [ 4815.324775] sd 0:0:0:0: [sda] Result: hostbyte=DID_OK
> driverbyte=DRIVER_TIMEOUT
> kernel: : [ 4815.324780] sd 0:0:0:0: [sda] CDB: Write(10): 2a 00 00
> d3 41 9f 00 00 28 00
> kernel: : [ 4815.324806] lost page write due to I/O error on sda1
> kernel: : [ 4815.324817] lost page write due to I/O error on sda1
> kernel: : [ 4815.324826] lost page write due to I/O error on sda1
> kernel: : [ 4815.324834] lost page write due to I/O error on sda1
> kernel: : [ 4815.324843] lost page write due to I/O error on sda1
> kernel: : [ 4815.450483] Pid: 1337, comm: qemu-dm Not tainted
> (2.6.32-5-xen-686 #1) 945GM/E-ITE8712
> kernel: : [ 4815.450483] EIP: 0061:[<c1002227>] EFLAGS: 00200246 CPU: 0
> kernel: : [ 4815.450483] EIP is at hypercall_page+0x227/0x1001
> kernel: : [ 4815.450483] EAX: 00040000 EBX: 00000000 ECX: 00000000
> EDX: c357a7b4
> kernel: : [ 4815.450483] ESI: 00000009 EDI: 00000028 EBP: c13959e4
> ESP: ddb6defc
> kernel: : [ 4815.450483]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0069
> kernel: : [ 4815.450483] CR0: 8005003b CR2: 0807f9d0 CR3: 1da42000
> CR4: 00002660
> kernel: : [ 4815.450483] DR0: 00000000 DR1: 00000000 DR2: 00000000
> DR3: 00000000
> kernel: : [ 4815.450483] DR6: ffff0ff0 DR7: 00000400
> kernel: : [ 4815.450483] Call Trace:
> kernel: : [ 4815.450483]  [<c1006048>] ? xen_force_evtchn_callback+0xc/0x10
> kernel: : [ 4815.450483]  [<c1006778>] ? check_events+0x8/0xc
> kernel: : [ 4815.450483]  [<c1006737>] ? xen_irq_enable_direct_end+0x0/0x1
> kernel: : [ 4815.450483]  [<c103c80b>] ? __do_softirq+0x4b/0x156
> kernel: : [ 4815.450483]  [<c103c947>] ? do_softirq+0x31/0x3c
> kernel: : [ 4815.450483]  [<c103ca21>] ? irq_exit+0x26/0x58
> kernel: : [ 4815.450483]  [<c1199a16>] ? xen_evtchn_do_upcall+0x22/0x2c
> kernel: : [ 4815.653736]  [<c1009b5f>] ? xen_do_upcall+0x7/0xc
> kernel: : [ 4815.653736]  [<c104a74c>] ? sys_clock_gettime+0x46/0x7e
> kernel: : [ 4815.653736]  [<c1008f9c>] ? syscall_call+0x7/0xb
> kernel: : [ 4815.676006] saa7146 (0) vpeirq: used 1 times >80% of
> buffer (1300396 bytes now)
> 
> on monitor I can see frequently messages which look like:
> soft lockup - CPU X stuck for XXs! [qemu-dm:...]
> always i saw qemu-dm is listed with PID in this message. these
> messages I can never find in messages-log, i think the machine is
> too dead to write them down onto disc.
> 
> the only way to get the machine back is to be fast enough after
> starting (means less than about 10 seconds) do a xm destroy <name>.
> otherwise the system needs to be powercycled, rarely ctrl-alt-delete
> on console initiates a reboot, most time this also does not work.
> 
> can anybody tell me where I can search for the issue?
> currently I tried to change architecture to amd64, but as it is not
> only the kernel and xen itself this is not a "fast try", so
> hopefully somebody can help me here.
> attached: xm dmesg (from i686)
> in there I've limited memory of dom0 to 1GB because I tought maybe
> balooning causes the issue. my HVM machines never had more than
> 512MB configured RAM, but nevertheless the problem also occurs with
> 128 or 256MB configured.
> 
> thank you for your investigations.

[-- Attachment #2: read_interrupts.c --]
[-- Type: text/x-csrc, Size: 5129 bytes --]

#include <stdio.h>
#include <string.h>
#include <stdlib.h>
/*
*/
char *interrupts = "/proc/interrupts";
static int DELTA = 30;
static int MAX_CNT = -1;
static int MAX_SLEEP = 5;
#define MAX_CPUS 64
#define MAX_NAME 64
#define MAX_LINE 300
struct irq {
	int nr;
	char name[5];
	int number[MAX_CPUS];
	int avg[MAX_CPUS];
	int max[MAX_CPUS];
	char type[MAX_NAME];
	char drivers[MAX_NAME];
	struct irq *next;
};
struct snapshot {
	int	cpu_cnt;
	int	cnt;
	struct irq *irq;
};
int get_cpu_count()
{
	FILE *fp;
	int cpu_count;
	char buf[MAX_LINE];
	char *s;
	fp = fopen("/proc/cpuinfo","r");
	if (!fp)
		return -1;

	cpu_count = 0;
	// Get CPUs out of the way.
	while (1) {
		s = fgets(buf, MAX_LINE, fp);
		if (!s) {
			if (!feof(fp)) {
				printf("%s: termianted before eof.\n", __FUNCTION__);
			}
			break;
		}
		if (strlen(buf) < 1)
			continue;
		if (buf[strlen(buf)-1] == '\n')
			buf[strlen(buf)-1] = '\0';

		s = strchr(buf, ':');
		if (!s)
			continue;
		if (strncmp(buf,"processor", strlen("processor")) == 0) {
			cpu_count ++;
		}
	}
	fclose(fp);
	return cpu_count;
}

static struct snapshot  *
get_snapshot(int cpu_count)
{
	FILE *fp;
	int i;
	char buf[MAX_LINE];
	char *s,*temp;
	struct snapshot *now;
	struct irq *irq;

	now = malloc(sizeof(struct snapshot));
	now->cpu_cnt = cpu_count;
	now->irq = NULL;	
	fp = fopen(interrupts,"r");
	if (!fp)
		return NULL;

	while (1) {
		s = fgets(buf, MAX_LINE, fp);
		if (!s) {
			if (!feof(fp)) {
				printf("%s: termianted before eof.\n", __FUNCTION__);
			}
			break;
		}
		if (strlen(buf) < 1)
			continue;
		if (buf[strlen(buf)-1] == '\n')
			buf[strlen(buf)-1] = '\0';
		// Skip the CPU0.. CPU1..
		s = buf;
		while (s) {
			char *p;
			p = strstr(s, "CPU");
			if (!p)
				break;
			s = strchr(s+3, ' ');
			while (*s == ' ')
				s++;
		}
		if (*s == '\0')
			continue;
		/* List re-order */
		irq = malloc(sizeof(struct irq));
		memset(irq, 0, sizeof(struct irq));
		irq->next = now->irq;
		now->irq = irq;
	
		//printf("[%s]\n", s);	
		/* Get IRQ, or the string value */
		temp = strchr(s,':');
		strncpy(irq->name, s, 4);
		irq->nr = 0;
		irq->nr = atoi(irq->name);
		s = ++temp;
		// For CPU count write values
		for (i = 0; i <  cpu_count; i++) {
			while (isblank(*s))
				s++;
			/*
			if (i == 0)
				printf("%d:%d<---", irq->nr, atoi(s)); */
			irq->number[i] = atoi(s);
			while (isdigit(*s))
				s++;
		}
		while (isblank(*s))
			s++;
		temp = strchr(s,' ');
		if (!temp)
			temp = s + strlen(s);
		//printf("![%s]\n", s);
		strncpy(irq->type, s, temp-s > MAX_NAME ? MAX_NAME : temp-s);
		s = temp;
		while (isblank(*s))
			s++;
		//printf("[%s]\n",s);
		strncpy(irq->drivers, s, strlen(s) >MAX_NAME ? MAX_NAME : strlen(s));
		
	}
/*            CPU0       CPU1       CPU2       CPU3       
16:          9          0          0          0  xen-pirq-ioapic-level  uhci_hcd:usb3, nouveau, pata_jmicron
274:         47          0          0          0   xen-dyn-event     pcifront
275:          0          0          0          0   xen-dyn-event     vkbd
276:         54          0          0          0   xen-dyn-event     eth0
277:        324         21          0          0   xen-dyn-event     hvc_console
*/
	fclose(fp);

	return now;


}
void cleanup(struct snapshot *now) {

	struct irq *p,*q;

	p = now->irq;
	while (p) {
		q = p->next;
		free(p);
		p = q;
	}
	free(now);
}

static const char *blacklist[] = {"timer", "resched","interrupts", NULL}; 
void get_delta(struct snapshot *b, struct snapshot *n)
{
	struct irq *p_old,*q_old, *p_new, *q_new;
	int i, delta;
	char *p;

	p_old = b->irq;
	p_new = n->irq;
	printf("-----------------------------------------------------------\n");
	printf("irq  cpu: delta avg/s max/s driver\n");
	while (p_new && p_old) {
		q_old = p_old->next;
		q_new = p_new->next;

		for (i = 0; blacklist[i]; i++) {
			if (blacklist[i] == NULL)
				break;
			if (strncmp(blacklist[i],
			 	    p_old->drivers,
				    strlen(blacklist[i])) == 0) {
				goto skip;	
			}
		}
		for (i = 0; i < b->cpu_cnt; i++) {
			p_new->avg[i] = p_old->avg[i];
			p_new->max[i] = p_old->max[i];

			delta = 0;
			delta = p_new->number[i] - p_old->number[i];
			if ((delta == p_old->number[i]) ||
				delta == p_new->number[i])
				continue;

			if (delta < 0) {
				printf("%s CPU%d going backwards (%d)!\n", p_old->name, i, delta);
				continue;
			}
			p_new->avg[i] = (delta + p_old->avg[i]) / 2;
			if (delta > p_new->max[i])
				p_new->max[i] = delta;
			if (delta > DELTA) {
				printf("%-5s %2d: %-5d %-5d %-5d %s\n",
					p_old->name, i, delta,
					p_new->avg[i] / MAX_SLEEP, p_new->max[i] / MAX_SLEEP,
					p_old->drivers);
			}
			
		}
skip:
		p_old = q_old;
		p_new = q_new;
	}
}
int main(int argc, char *argv[])
{
	struct snapshot *before, *now;
	struct irq *p,*q;
	int cnt;
	int cpu_count;

	cpu_count = get_cpu_count();
	if (cpu_count == 0)
		return;

	cnt = MAX_CNT;
	before = get_snapshot(cpu_count);
	while (cnt--) {
		sleep(MAX_SLEEP);
		now = get_snapshot(cpu_count);
		get_delta(before ,now);
		cleanup(before);
		before = now;
		if (cnt - 1 == 0 && MAX_CNT == -1)
			cnt = MAX_CNT;
	}
	cleanup(before);
	return;

	return cnt;
}

[-- Attachment #3: Type: text/plain, Size: 138 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel