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@xxxxxxxxxxxx>
[ 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@xxxxxxxxxx
[ 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
--
libvir-list mailing list
libvir-list@xxxxxxxxxx
https://www.redhat.com/mailman/listinfo/libvir-list