[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

[libvirt] [sandbox] random hang in g_poll



Hello,
I am building a tool on top of libvirt-sandbox and I've noticed that
there are random hangs in the g_main_loop_run call. Normally, only
very rarely does it actually hang, the problem appears let's say 4 out
of 5 times when I run the program under valgrind or when I am using an
LD_PRELOAD for checking gobject ref counts (gobject-list). I ran these
directly on virt-sandbox to ensure that it's not from my code and it
still happens.
Attached is the output of a run that hangs followed by the backtrace.
As I'm new to the gmainloop mechanisms I don't really know where to
start debugging. Any ideas would be appreciated.

Thanks,
Radu Caragea.
G_MAIN_POLL_DEBUG=1 valgrind --tool=helgrind  virt-sandbox -c qemu:///system /bin/uname 
==501== Helgrind, a thread error detector
==501== Copyright (C) 2007-2011, and GNU GPL'd, by OpenWorks LLP et al.
==501== Using Valgrind-3.7.0 and LibVEX; rerun with -h for copyright info
==501== Command: virt-sandbox -c qemu:///system /bin/uname
==501== 
created context=0xcf46ec0
default context=0xcf46ec0
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0028090000 seconds [4 :i] [5 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002150000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002150000 seconds [4 :i] [5 :i]
polling context=0xcf46ec0 n=4 timeout=0
g_main_poll(4) timeout: 0 - elapsed 0.0002190000 seconds [4 :i] [2 :o]
[    0.167719] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    0.190387] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.213602] 00:05: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.214829] Linux agpgart interface v0.103
[    0.215720] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    0.216848] ACPI: Power Button [PWRF]
[    0.219364] ioatdma: Intel(R) QuickData Technology Driver 4.00
[    0.220538] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
[    0.221443] virtio-pci 0000:00:03.0: setting latency timer to 64
[    0.222514] virtio-pci 0000:00:04.0: setting latency timer to 64
[    0.223658] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
[    0.224540] PCI: setting IRQ 10 as level-triggered
[    0.225305] virtio-pci 0000:00:05.0: setting latency timer to 64
[    0.226473] virtio-pci 0000:00:05.0: irq 40 for MSI/MSI-X
[    0.227482] virtio-pci 0000:00:05.0: irq 41 for MSI/MSI-X
[    0.261510] [drm] Initialized drm 1.1.0 20060810
[    0.312087] brd: module loaded
[    0.340053] loop: module loaded
[    0.360062] ata_piix 0000:00:01.1: version 2.13
[    0.360825] ata_piix 0000:00:01.1: setting latency timer to 64
[    0.376041] scsi0 : ata_piix
[    0.380039] scsi1 : ata_piix
[    0.384045] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0c0 irq 14
[    0.385126] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0c8 irq 15
[    0.396057] tun: Universal TUN/TAP device driver, 1.6
[    0.396818] tun: (C) 1999-2004 Max Krasnyansky <maxk qualcomm com>
[    0.397830] jme: JMicron JMC2XX ethernet driver version 1.0.8
[    0.401044] PPP generic driver version 2.4.2
[    0.405045] PPP BSD Compression module registered
[    0.405739] PPP Deflate Compression module registered
[    0.406506] NET: Registered protocol family 24
[    0.413069] Generic UIO driver for PCI 2.3 devices version: 0.01.0
[    0.417055] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.424207] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.438052] Initializing USB Mass Storage driver...
[    0.440044] usbcore: registered new interface driver usb-storage
[    0.441122] USB Mass Storage support registered.
[    0.443043] usbcore: registered new interface driver ums_eneub6250
[    0.445043] usbcore: registered new interface driver ums-realtek
[    0.449044] usbcore: registered new interface driver usbserial
[    0.451044] usbcore: registered new interface driver usbserial_generic
[    0.453460] USB Serial support registered for generic
[    0.454235] usbserial: USB Serial Driver core
[    0.457044] usbcore: registered new interface driver aircable
[    0.459043] USB Serial support registered for aircable
[    0.461043] usbcore: registered new interface driver opticon
[    0.463044] USB Serial support registered for opticon
[    0.465043] usbcore: registered new interface driver siemens_mpi
[    0.469042] USB Serial support registered for siemens_mpi
[    0.473048] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    0.475209] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.475963] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.482043] mousedev: PS/2 mouse device common for all mice
[    0.491093] rtc_cmos 00:01: RTC can wake from S4
[    0.493057] rtc_cmos 00:01: rtc core: registered rtc_cmos as rtc0
[    0.494042] rtc0: alarms up to one day, 114 bytes nvram, hpet irqs
[    0.495626] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[    0.501004] applesmc: supported laptop not found!
[    0.501728] applesmc: driver init failed (ret=-19)!
[    0.502788] f71882fg: Not a Fintek device
[    0.503434] f71882fg: Not a Fintek device
[    0.505356] pc87360: PC8736x not detected, module not inserted
[    0.506384] sch56xx_common: Unsupported device id: 0xff
[    0.507203] sch56xx_common: Unsupported device id: 0xff
[    0.508786] device-mapper: ioctl: 4.22.0-ioctl (2011-10-19) initialised: dm-devel redhat com
[    0.510159] cpuidle: using governor ladderpolling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002170000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002040000 seconds
polling context=0xcf46ec0 n=4 timeout=0
g_main_poll(4) timeout: 0 - elapsed 0.0002180000 seconds [4 :i] [2 :o]
[    0.511339] usbcore: registered new interface driver usbhid
[    0.512185] usbhid: USB HID core driver
[    0.512888] IPv4 over IPv4 tunneling driver
[    0.513695] TCP: cubic registered
[    0.514417] NET: Registered protocol family 10
[    0.515779] Mobile IPv6
[    0.516270] IPv6 over IPv4 tunneling driver
[    0.517667] NET: Registered protocol family 17
[    0.518369] Bridge firewalling registered
[    0.518964] Ebtables v2.0 registered
[    0.519560] lec:lane_module_init: lec.c: initialized
[    0.520320] lib80211: common routines for IEEE802.11 drivers
[    0.521182] lib80211_crypt: registered algorithm 'NULL'
[    0.522145] registered taskstats version 1
[    0.523063] rtc_cmos 00:01: setting system clock to 2012-06-16 11:08:10 UTC (1339844890)
[    0.539717] Freeing unused kernel memory: 500k freed
[    0.542360] FS-Cache: Loaded
[    0.543387] 9pnet: Installing 9P2000 support
[    0.544722] 9p: Installing v9fs 9p2000 file system support
[    0.546774] virtio-pci 0000:00:03.0: irq 42 for MSI/MSI-X
[    0.547680] virtio-pci 0000:00:03.0: irq 43 for MSI/MSI-X
[    0.558902] virtio-pci 0000:00:04.0: irq 44 for MSI/MSI-X
[    0.560380] virtio-pci 0000:00:04.0: irq 45 for MSI/MSI-X
[    0.704556] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
[    1.140052] Switching to clocksource tsc
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002120000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 4.9118620000 seconds [5 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002120000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 0.0002110000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 4.9851280000 seconds [5 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002110000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 0.0002110000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 4.9852270000 seconds [5 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002100000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 0.0002140000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 4.9846530000 seconds [5 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002100000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 0.0002120000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 4.9851540000 seconds [5 :i]
polling context=0xcf46ec0 n=3 timeout=0
g_main_poll(3) timeout: 0 - elapsed 0.0002780000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
g_main_poll(3) timeout: -1 - elapsed 0.0002120000 seconds [4 :i]
polling context=0xcf46ec0 n=3 timeout=-1
==501== 
==501== For counts of detected and suppressed errors, rerun with: -v
==501== Use --history-level=approx or =none to gain increased speed, at
==501== the cost of reduced accuracy of conflicting-access information
==501== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
Terminated



(gdb) cont
Continuing.
^C
Program received signal SIGTRAP, Trace/breakpoint trap.
0x00000000097152b8 in __GI___poll (fds=0xcfc5400, nfds=3, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:83
83          return INLINE_SYSCALL (poll, 3, CHECK_N (fds, nfds), nfds, timeout);
(gdb) bt
#0  0x00000000097152b8 in __GI___poll (fds=0xcfc5400, nfds=3, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:83
#1  0x000000000935faef in g_poll (fds=0xcfc5400, nfds=3, timeout=-1) at gpoll.c:132
#2  0x000000000934f217 in g_main_context_poll (context=0xcf46ec0, timeout=-1, priority=2147483647, fds=0xcfc5400, n_fds=3)
    at gmain.c:3440
#3  0x000000000934eb6c in g_main_context_iterate (context=0xcf46ec0, block=1, dispatch=1, self=0xcfec630) at gmain.c:3141
#4  0x000000000934efc0 in g_main_loop_run (loop=0xcf35320) at gmain.c:3340
#5  0x0000000000402b9d in main (argc=1, argv=0x7fefffa18) at virt-sandbox.c:249




[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]