[libvirt] Release of libvirt-0.6.4
The monthly release is out ! There is a number of new things in that release, but as happens in time-based releases some are not fully complete, for example the OpenNebula driver was added but it still need a bit of work on the detection code and a bit of cleanup to avoid a GPL/AFS licencing issue, so please don't enable it except for test builds. We also have a new set of Interface config APIs but they are not yet implemented by a driver and the XML import/export routines are not there yet. Still there is a lot of things to use and discover in this release as you can see below: * New features: - new API virStorageVolCreateXMLFrom (Cole Robinson) - full VBox graphic capabilities (Pritesh Kothari) - Interface config APIs (Laine Stump) - APIs for domain XML conversions (Daniel Berrange) - initial version of OpenNebula driver (Abel Miguez Rodriguez) * Portability: - better compiler warning selection (Daniel Berrange) - Win32 portability fixes (Daniel Berrange) * Documentation: - documentation for <sound> device XML format (Cole Robinson) - storage format documentation fixes (Ryota Ozaki) - docs for XML conversion APIs (Daniel Berrange) - inconsistencies in storage volume docs and schemas (Ryota Ozaki) * Bug fixes: - fix hostdev managed handling (Mark McLoughlin) - lxc_controller should not cash without args (Guido Gunther) - bug fixes in I/O routines (Guido Gunther) - fix migrationsave/restore for QEmu 0.10.0 (Daniel Berrange) - avoid crash on VBox init (Guido Gunther) - fix dev and cgroup init in LXC (Ryota Ozaki) - QEmu startup fix (Cole Robinson) - block node reboots from LXCs (Ryota Ozaki) - QEmu argv detection fix for recent kvm (Daniel Berrange) - fix watch/timer event deletion (Daniel Berrange) - fix XML escaping bug - various locking bugs (Daniel Berrange) - avoid a deadlock in HAL nodedev driver (Cole Robinson) - detection of node device media insert/eject (Cole Robinson) - broken networking with new QEMU/KVM >= 86 (Daniel Berrange) - various fixes in domain and network startup error report (Cole Robinson) - double free on unexpected client disconnect (Daniel Berrange) * Improvements: - cleanups and doc on virExec (Cole Robinson) - error reporting in QEmu migrations (Cole Robinson) - better path and driver detection in VBox (Pritesh Kothari) - avoid caching QEMU driver capabilities(Cole Robinson) - multiple graphics elements definitions (Pritesh Kothari) - LSB init header init.d improvements (Frederik Himpe) - special erro code for invalid operations (Daniel Berrange) - dlopen error logging (Daniel Berrange) - fix UUID and name uniqueness (Daniel Berrange) - improvement on VBox initialization (Pritesh Kothari and Dan Berrange) - "Host only" and "Internal" network in VBox (Pritesh Kothari) - add utility virExecDaemonize (Cole Robinson) - enable bridges without IP (Ludwig Nussel) - 'make -s' silencing (Daniel Berrange) - test case for exercising the event loop (Daniel Berrange) - virsh commands vol-clone and vol-create-from (Cole Robinson) - new xend don't use [] around cpumaps (Tatsuro Enokura) - add the CIL mutex lock checker (Daniel Berrange) - fix some LXC error code (Amy Griffis) - virInterface python bindings (Daniel Berrange) - fix to the example code for event handling (Pritesh Kothari) - always add location informations to logging (Daniel Berrange) - python domain events example and binding (Daniel Berrange) - PPC Qemu Machine Type update (Thomas Baker) * Cleanups: - strings bug in virsh (Daniel Berrange) - various cleanups in storage code (Cole Robinson) - rpm spec cleanups - destructors data cleanups (Laine Stump) - some QEmu code refactoring (Daniel Berrange) - avoid dependancy on libcap (Daniel Berrange) - python import cleanup (Cole Robinson) - virAsprintf based cleanups in storage code (Cole Robinson) - fix some direct stderr logging - OpenNebula driver cleanups (Daniel Berrange) Thanks everybody for the contributions for this new release ! Daniel -- Daniel Veillard | libxml Gnome XML XSLT toolkit http://xmlsoft.org/ daniel@veillard.com | Rpmfind RPM search engine http://rpmfind.net/ http://veillard.com/ | virtualization library http://libvirt.org/
On Fri, 29 May 2009 19:18:05 +0200, Daniel Veillard wrote:
- test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64): 51) QEMU ARGV-2-XML restore-v2 ... OK 52) QEMU ARGV-2-XML restore-v2 ... OK 53) QEMU ARGV-2-XML migrate ... OK PASS: qemuargv2xmltest PASS: seclabeltest 1: Simple write OK 2: Deleted before poll OK 3: Interrupted during poll OK 4: Deleted during dispatch OK 5: Deleted during dispatch OK 6: Firing a timer FAIL Timer 1 should have fired, but didn't FAIL: eventtest 1) Node device XML-2-XML computer ... OK 2) Node device XML-2-XML DVD_GCC_4247N ... OK 3) Node device XML-2-XML net_00_13_02_b9_f9_d3 ... OK 4) Node device XML-2-XML net_00_15_58_2f_e9_55 ... OK 5) Node device XML-2-XML pci_1002_71c4 ... OK 6) Node device XML-2-XML pci_8086_27c5_scsi_host_0 ... OK 7) Node device XML-2-XML pci_8086_27c5_scsi_host_scsi_device_lun0 ... OK 8) Node device XML-2-XML pci_8086_27c5_scsi_host_scsi_host ... OK 9) Node device XML-2-XML pci_8086_27c5_scsi_host ... OK 10) Node device XML-2-XML storage_serial_SATA_HTS721010G9SA00_MPCZ12Y0GNGWSE ... OK 11) Node device XML-2-XML usb_device_1d6b_1_0000_00_1d_0_if0 ... OK 12) Node device XML-2-XML usb_device_1d6b_1_0000_00_1d_0 ... OK PASS: nodedevxml2xmltest ==================== 1 of 34 tests failed ==================== What could be wrong? -- Frederik himpe
On Sat, May 30, 2009 at 12:45:21PM +0000, Frederik Himpe wrote:
On Fri, 29 May 2009 19:18:05 +0200, Daniel Veillard wrote:
- test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64):
51) QEMU ARGV-2-XML restore-v2 ... OK 52) QEMU ARGV-2-XML restore-v2 ... OK 53) QEMU ARGV-2-XML migrate ... OK PASS: qemuargv2xmltest PASS: seclabeltest 1: Simple write OK 2: Deleted before poll OK 3: Interrupted during poll OK 4: Deleted during dispatch OK 5: Deleted during dispatch OK 6: Firing a timer FAIL Timer 1 should have fired, but didn't FAIL: eventtest 1) Node device XML-2-XML computer ... OK 2) Node device XML-2-XML DVD_GCC_4247N ... OK 3) Node device XML-2-XML net_00_13_02_b9_f9_d3 ... OK 4) Node device XML-2-XML net_00_15_58_2f_e9_55 ... OK 5) Node device XML-2-XML pci_1002_71c4 ... OK 6) Node device XML-2-XML pci_8086_27c5_scsi_host_0 ... OK 7) Node device XML-2-XML pci_8086_27c5_scsi_host_scsi_device_lun0 ... OK 8) Node device XML-2-XML pci_8086_27c5_scsi_host_scsi_host ... OK 9) Node device XML-2-XML pci_8086_27c5_scsi_host ... OK 10) Node device XML-2-XML storage_serial_SATA_HTS721010G9SA00_MPCZ12Y0GNGWSE ... OK 11) Node device XML-2-XML usb_device_1d6b_1_0000_00_1d_0_if0 ... OK 12) Node device XML-2-XML usb_device_1d6b_1_0000_00_1d_0 ... OK PASS: nodedevxml2xmltest ==================== 1 of 34 tests failed ====================
What could be wrong?
Strange, this test case works fine for me on both archs with Fedora 9/10/11 and RHEL 5. Could you run the test manually with debugging turned on, eg LIBVIRT_DEBUG=1 ./eventtest And also try and capture an strace log with timings strace -ttt ./eventtest Regards, Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
On Mon, 01 Jun 2009 10:36:36 +0100, Daniel P. Berrange wrote:
On Sat, May 30, 2009 at 12:45:21PM +0000, Frederik Himpe wrote:
On Fri, 29 May 2009 19:18:05 +0200, Daniel Veillard wrote:
- test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64):
What could be wrong?
Strange, this test case works fine for me on both archs with Fedora 9/10/11 and RHEL 5.
Could you run the test manually with debugging turned on, eg
LIBVIRT_DEBUG=1 ./eventtest
And also try and capture an strace log with timings
strace -ttt ./eventtest
Actually I found out the test failure is not 100% reproducible. I have seen it failing in steps 6, 9 and IIRC also step 10 of eventtest. Here's a failed execution: $ LIBVIRT_DEBUG=1 ./eventtest 12:18:52.040: debug : virEventAddHandleImpl:112 : Add handle 13 1 0x404570 (nil) 12:18:52.040: debug : virEventAddHandleImpl:116 : Used 0 handle slots, adding 10 more 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddHandleImpl:112 : Add handle 3 1 0x403750 0x60f480 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddHandleImpl:112 : Add handle 5 1 0x403750 0x60f498 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddHandleImpl:112 : Add handle 7 1 0x403750 0x60f4b0 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddHandleImpl:112 : Add handle 9 1 0x403750 0x60f4c8 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddHandleImpl:112 : Add handle 11 1 0x403750 0x60f4e0 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddTimeoutImpl:209 : Adding timer 1 with -1 ms freq 12:18:52.040: debug : virEventAddTimeoutImpl:217 : Used 0 timeout slots, adding 10 more 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddTimeoutImpl:209 : Adding timer 2 with -1 ms freq 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddTimeoutImpl:209 : Adding timer 3 with -1 ms freq 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddTimeoutImpl:209 : Adding timer 4 with -1 ms freq 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 12:18:52.040: debug : virEventAddTimeoutImpl:209 : Adding timer 5 with -1 ms freq 12:18:52.040: debug : virEventInterruptLocked:636 : Skip interrupt, 0 0 1: Simple write 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=1 w=2, f=3 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=2 w=3, f=5 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=3 w=4, f=7 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=4 w=5, f=9 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=5 w=6, f=11 e=1 12:18:52.041: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 12:18:52.041: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 12:18:52.041: debug : virEventRunOnce:565 : Poll on 6 handles 0x6202f0 timeout -1 12:18:52.041: debug : virEventRunOnce:567 : Poll got 1 event 12:18:52.041: debug : virEventDispatchHandles:450 : Dispatch n=2 f=5 w=3 e=1 0x60f498 OK 12:18:52.041: debug : virEventRemoveHandleImpl:173 : Remove handle 2 12:18:52.041: debug : virEventRemoveHandleImpl:186 : mark delete 1 3 12:18:52.041: debug : virEventInterruptLocked:636 : Skip interrupt, 0 -565913264 2: Deleted before poll 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=1 w=3, f=5 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=2 w=4, f=7 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=3 w=5, f=9 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=4 w=6, f=11 e=1 12:18:52.041: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 12:18:52.041: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 12:18:52.041: debug : virEventRunOnce:565 : Poll on 5 handles 0x6202f0 timeout -1 12:18:52.041: debug : virEventRunOnce:567 : Poll got 1 event 12:18:52.041: debug : virEventDispatchHandles:450 : Dispatch n=1 f=5 w=3 e=1 0x60f498 OK 3: Interrupted during poll 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=1 w=3, f=5 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=2 w=4, f=7 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=3 w=5, f=9 e=1 12:18:52.041: debug : virEventMakePollFDs:365 : Prepare n=4 w=6, f=11 e=1 12:18:52.041: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 12:18:52.041: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 12:18:52.041: debug : virEventRunOnce:565 : Poll on 5 handles 0x620010 timeout -1 12:18:52.147: debug : virEventRemoveHandleImpl:173 : Remove handle 3 12:18:52.147: debug : virEventRemoveHandleImpl:186 : mark delete 1 5 12:18:52.147: debug : virEventInterruptLocked:640 : Interrupting 12:18:52.147: debug : virEventRunOnce:567 : Poll got 1 event 12:18:52.147: debug : virEventDispatchHandles:450 : Dispatch n=0 f=13 w=1 e=1 (nil) 12:18:52.147: debug : virEventDispatchHandles:440 : Skip deleted n=1 w=3 f=5 OK 4: Deleted during dispatch 12:18:52.147: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 12:18:52.147: debug : virEventMakePollFDs:365 : Prepare n=1 w=4, f=7 e=1 12:18:52.147: debug : virEventMakePollFDs:365 : Prepare n=2 w=5, f=9 e=1 12:18:52.147: debug : virEventMakePollFDs:365 : Prepare n=3 w=6, f=11 e=1 12:18:52.147: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 12:18:52.147: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 12:18:52.147: debug : virEventRunOnce:565 : Poll on 4 handles 0x620010 timeout -1 12:18:52.147: debug : virEventRunOnce:567 : Poll got 1 event 12:18:52.147: debug : virEventDispatchHandles:450 : Dispatch n=1 f=7 w=4 e=1 0x60f4b0 12:18:52.147: debug : virEventRemoveHandleImpl:173 : Remove handle 5 12:18:52.147: debug : virEventRemoveHandleImpl:186 : mark delete 2 9 12:18:52.147: debug : virEventInterruptLocked:636 : Skip interrupt, 1 -565913264 12:18:52.147: debug : virEventDispatchHandles:440 : Skip deleted n=2 w=5 f=9 OK 5: Deleted during dispatch 12:18:52.148: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 12:18:52.148: debug : virEventMakePollFDs:365 : Prepare n=1 w=4, f=7 e=1 12:18:52.148: debug : virEventMakePollFDs:365 : Prepare n=2 w=6, f=11 e=1 12:18:52.148: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 12:18:52.148: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 12:18:52.148: debug : virEventRunOnce:565 : Poll on 3 handles 0x6202f0 timeout -1 12:18:52.148: debug : virEventRunOnce:567 : Poll got 1 event 12:18:52.148: debug : virEventDispatchHandles:450 : Dispatch n=1 f=7 w=4 e=1 0x60f4b0 12:18:52.148: debug : virEventRemoveHandleImpl:173 : Remove handle 4 12:18:52.148: debug : virEventRemoveHandleImpl:186 : mark delete 1 7 12:18:52.148: debug : virEventInterruptLocked:636 : Skip interrupt, 1 -565913264 OK 12:18:52.148: debug : virEventUpdateTimeoutImpl:247 : Updating timer 2 timeout with 100 ms freq 12:18:52.148: debug : virEventInterruptLocked:636 : Skip interrupt, 0 -565913264 6: Firing a timer 12:18:52.148: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 12:18:52.148: debug : virEventMakePollFDs:365 : Prepare n=1 w=6, f=11 e=1 12:18:52.148: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 12:18:52.148: debug : virEventCalculateTimeout:319 : Got a timeout scheduled for 1243851532248 12:18:52.148: debug : virEventCalculateTimeout:343 : Timeout at 1243851532248 due in 100 ms 12:18:52.148: debug : virEventRunOnce:565 : Poll on 2 handles 0x6202f0 timeout 100 12:18:52.247: debug : virEventRunOnce:567 : Poll got 0 event FAIL Timer 1 should have fired, but didn't $ strace -ttt ./eventtest 1243851616.289203 execve("./eventtest", ["./eventtest"], [/* 50 vars */]) = 0 1243851616.290638 brk(0) = 0x620000 1243851616.290710 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2add61961000 1243851616.290827 uname({sys="Linux", node="klodia.mandriva.com", ...}) = 0 1243851616.290946 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) 1243851616.291034 open("/etc/ld.so.cache", O_RDONLY) = 3 1243851616.291087 fstat(3, {st_mode=S_IFREG|0644, st_size=259381, ...}) = 0 1243851616.291175 mmap(NULL, 259381, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2add61962000 1243851616.291214 close(3) = 0 1243851616.291266 open("/lib64/librt.so.1", O_RDONLY) = 3 1243851616.291310 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\"\0\257;\0\0\0@"..., 832) = 832 1243851616.291381 fstat(3, {st_mode=S_IFREG|0755, st_size=38664, ...}) = 0 1243851616.291447 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2add619a2000 1243851616.291500 mmap(0x3baf000000, 2132976, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3baf000000 1243851616.291547 mprotect(0x3baf007000, 2097152, PROT_NONE) = 0 1243851616.291594 mmap(0x3baf207000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x3baf207000 1243851616.291652 close(3) = 0 1243851616.291700 open("/lib64/libpthread.so.0", O_RDONLY) = 3 1243851616.291754 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200W\0\256;\0\0\0@"..., 832) = 832 1243851616.291833 fstat(3, {st_mode=S_IFREG|0755, st_size=132560, ...}) = 0 1243851616.291902 mmap(0x3bae000000, 2208592, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3bae000000 1243851616.291956 mprotect(0x3bae016000, 2097152, PROT_NONE) = 0 1243851616.291997 mmap(0x3bae216000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x3bae216000 1243851616.292059 mmap(0x3bae218000, 13136, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3bae218000 1243851616.292102 close(3) = 0 1243851616.292161 open("/lib64/libintl.so.8", O_RDONLY) = 3 1243851616.292210 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \35\200\261;\0\0\0@"..., 832) = 832 1243851616.292262 fstat(3, {st_mode=S_IFREG|0644, st_size=39768, ...}) = 0 1243851616.292324 mmap(0x3bb1800000, 2133640, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3bb1800000 1243851616.292365 mprotect(0x3bb1809000, 2093056, PROT_NONE) = 0 1243851616.292407 mmap(0x3bb1a08000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x8000) = 0x3bb1a08000 1243851616.292470 close(3) = 0 1243851616.292537 open("/lib64/libc.so.6", O_RDONLY) = 3 1243851616.292579 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\345A\255;\0\0\0@"..., 832) = 832 1243851616.292628 fstat(3, {st_mode=S_IFREG|0755, st_size=1442280, ...}) = 0 1243851616.292701 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2add619a3000 1243851616.292767 mmap(0x3bad400000, 3543672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3bad400000 1243851616.292805 mprotect(0x3bad559000, 2093056, PROT_NONE) = 0 1243851616.292846 mmap(0x3bad758000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x158000) = 0x3bad758000 1243851616.292915 mmap(0x3bad75d000, 17016, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3bad75d000 1243851616.292958 close(3) = 0 1243851616.293056 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2add619a4000 1243851616.293217 arch_prctl(ARCH_SET_FS, 0x2add619a4560) = 0 1243851616.293371 mprotect(0x3bad758000, 16384, PROT_READ) = 0 1243851616.293459 mprotect(0x3bae216000, 4096, PROT_READ) = 0 1243851616.293522 mprotect(0x3baf207000, 4096, PROT_READ) = 0 1243851616.293571 mprotect(0x60e000, 4096, PROT_READ) = 0 1243851616.293611 mprotect(0x3bad21b000, 4096, PROT_READ) = 0 1243851616.293649 munmap(0x2add61962000, 259381) = 0 1243851616.293693 set_tid_address(0x2add619a45f0) = 32095 1243851616.293732 set_robust_list(0x2add619a4600, 0x18) = 0 1243851616.293770 futex(0x7fff4914720c, FUTEX_WAKE_PRIVATE, 1) = 0 1243851616.293832 rt_sigaction(SIGRTMIN, {0x3bae005610, [], SA_RESTORER|SA_SIGINFO, 0x3bae00ed30}, NULL, 8) = 0 1243851616.293898 rt_sigaction(SIGRT_1, {0x3bae0056a0, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x3bae00ed30}, NULL, 8) = 0 1243851616.293943 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0 1243851616.293993 getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0 1243851616.294171 pipe([3, 4]) = 0 1243851616.294227 pipe([5, 6]) = 0 1243851616.294274 pipe([7, 8]) = 0 1243851616.294313 pipe([9, 10]) = 0 1243851616.294353 pipe([11, 12]) = 0 1243851616.294399 pipe([13, 14]) = 0 1243851616.294446 fcntl(13, F_GETFL) = 0 (flags O_RDONLY) 1243851616.294483 fcntl(13, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 1243851616.294522 fcntl(14, F_GETFL) = 0x1 (flags O_WRONLY) 1243851616.294559 fcntl(14, F_SETFL, O_WRONLY|O_NONBLOCK) = 0 1243851616.294598 fcntl(13, F_GETFD) = 0 1243851616.294631 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 1243851616.294668 fcntl(14, F_GETFD) = 0 1243851616.294699 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 1243851616.294811 brk(0) = 0x620000 1243851616.294862 brk(0x641000) = 0x641000 1243851616.294935 mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x2add619a5000 1243851616.295023 mprotect(0x2add619a5000, 4096, PROT_NONE) = 0 1243851616.295073 clone(child_stack=0x2add621a5250, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x2add621a59e0, tls=0x2add621a5950, child_tidptr=0x2add621a59e0) = 32096 1243851616.295229 write(2, " 1: Simple write "..., 17 1: Simple write ) = 17 1243851616.295284 futex(0x60f404, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x60f400, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1243851616.295335 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.295394 sched_yield() = 0 1243851616.295436 write(6, "1"..., 1) = 1 1243851616.295507 clock_gettime(CLOCK_REALTIME, {1243851616, 295521816}) = 0 1243851616.295552 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.295595 clock_gettime(CLOCK_REALTIME, {1243851616, 295607183}) = 0 1243851616.295644 futex(0x60f440, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.295695 futex(0x60f444, FUTEX_WAIT_PRIVATE, 1, {4, 999914633}) = -1 EAGAIN (Resource temporarily unavailable) 1243851616.295747 write(2, "OK\n"..., 3OK ) = 3 1243851616.295790 write(2, " 2: Deleted before poll "..., 24 2: Deleted before poll ) = 24 1243851616.295838 futex(0x60f404, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x60f400, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1243851616.295882 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.295929 sched_yield() = 0 1243851616.295966 write(6, "1"..., 1) = 1 1243851616.296015 clock_gettime(CLOCK_REALTIME, {1243851616, 296026215}) = 0 1243851616.296062 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.296118 clock_gettime(CLOCK_REALTIME, {1243851616, 296128425}) = 0 1243851616.296157 futex(0x60f440, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.296205 futex(0x60f444, FUTEX_WAIT_PRIVATE, 3, {4, 999897790}) = -1 EAGAIN (Resource temporarily unavailable) 1243851616.296255 write(2, "OK\n"..., 3OK ) = 3 1243851616.296298 write(2, " 3: Interrupted during poll "..., 28 3: Interrupted during poll ) = 28 1243851616.296358 futex(0x60f404, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x60f400, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1243851616.296407 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.296455 sched_yield() = 0 1243851616.296489 sched_yield() = 0 1243851616.296525 nanosleep({0, 100000000}, NULL) = 0 1243851616.403482 write(14, "\0"..., 1) = 1 1243851616.403538 futex(0x60f580, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.403590 clock_gettime(CLOCK_REALTIME, {1243851616, 403601045}) = 0 1243851616.403635 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.403673 clock_gettime(CLOCK_REALTIME, {1243851616, 403683826}) = 0 1243851616.403717 futex(0x60f440, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.403759 futex(0x60f444, FUTEX_WAIT_PRIVATE, 5, {4, 999917219}) = -1 EAGAIN (Resource temporarily unavailable) 1243851616.403807 write(2, "OK\n"..., 3OK ) = 3 1243851616.403851 write(2, " 4: Deleted during dispatch "..., 28 4: Deleted during dispatch ) = 28 1243851616.403897 futex(0x60f404, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x60f400, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1243851616.403952 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.403992 sched_yield() = 0 1243851616.404025 write(8, "1"..., 1) = 1 1243851616.404073 write(10, "1"..., 1) = 1 1243851616.404113 clock_gettime(CLOCK_REALTIME, {1243851616, 404123651}) = 0 1243851616.404164 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.404212 clock_gettime(CLOCK_REALTIME, {1243851616, 404222412}) = 0 1243851616.404251 futex(0x60f440, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.404294 futex(0x60f444, FUTEX_WAIT_PRIVATE, 7, {4, 999901239}) = -1 EAGAIN (Resource temporarily unavailable) 1243851616.404341 write(2, "OK\n"..., 3OK ) = 3 1243851616.404381 write(2, " 5: Deleted during dispatch "..., 28 5: Deleted during dispatch ) = 28 1243851616.404430 futex(0x60f404, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x60f400, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1243851616.404477 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.404519 sched_yield() = 0 1243851616.404558 write(8, "1"..., 1) = 1 1243851616.404616 clock_gettime(CLOCK_REALTIME, {1243851616, 404627378}) = 0 1243851616.404657 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.404696 clock_gettime(CLOCK_REALTIME, {1243851616, 404706866}) = 0 1243851616.404736 futex(0x60f440, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.404790 futex(0x60f444, FUTEX_WAIT_PRIVATE, 9, {4, 999920512}) = -1 EAGAIN (Resource temporarily unavailable) 1243851616.404836 write(2, "OK\n"..., 3OK ) = 3 1243851616.404880 write(2, " 6: Firing a timer "..., 19 6: Firing a timer ) = 19 1243851616.404926 futex(0x60f404, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x60f400, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1243851616.404971 futex(0x60f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 1243851616.405012 sched_yield() = 0 1243851616.405047 clock_gettime(CLOCK_REALTIME, {1243851616, 405060486}) = 0 1243851616.405087 clock_gettime(CLOCK_REALTIME, {1243851616, 405100814}) = 0 1243851616.405130 futex(0x60f444, FUTEX_WAIT_PRIVATE, 11, {4, 999959672}) = 0 1243851616.503505 write(2, "FAIL Timer 1 should have fired, b"..., 43FAIL Timer 1 should have fired, but didn't ) = 43 1243851616.503591 exit_group(1) = ? -- Frederik Himpe
On Mon, Jun 01, 2009 at 10:26:38AM +0000, Frederik Himpe wrote:
On Mon, 01 Jun 2009 10:36:36 +0100, Daniel P. Berrange wrote:
On Sat, May 30, 2009 at 12:45:21PM +0000, Frederik Himpe wrote:
On Fri, 29 May 2009 19:18:05 +0200, Daniel Veillard wrote:
- test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64):
What could be wrong?
Strange, this test case works fine for me on both archs with Fedora 9/10/11 and RHEL 5.
Could you run the test manually with debugging turned on, eg
LIBVIRT_DEBUG=1 ./eventtest
And also try and capture an strace log with timings
strace -ttt ./eventtest
Actually I found out the test failure is not 100% reproducible. I have seen it failing in steps 6, 9 and IIRC also step 10 of eventtest.
What I think is happening is that poll() is returning much sooner than we anticipate. When you give it a timeout, it'll return upto 1 timeslice before the timeout is due. I suspect that this is what is tripping up the test case on Mandriva. Could you apply the following patch, and re-build & run LIBVIRT_DEBUG=1 ./eventtest again, and also re-run with the 'strace -ttt -f ./eventtest' (i forgot to ask for -f last time). Regards, Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
On Wed, Jun 03, 2009 at 12:00:05PM +0100, Daniel P. Berrange wrote:
On Mon, Jun 01, 2009 at 10:26:38AM +0000, Frederik Himpe wrote:
On Mon, 01 Jun 2009 10:36:36 +0100, Daniel P. Berrange wrote:
On Sat, May 30, 2009 at 12:45:21PM +0000, Frederik Himpe wrote:
On Fri, 29 May 2009 19:18:05 +0200, Daniel Veillard wrote:
- test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64):
What could be wrong?
Strange, this test case works fine for me on both archs with Fedora 9/10/11 and RHEL 5.
Could you run the test manually with debugging turned on, eg
LIBVIRT_DEBUG=1 ./eventtest
And also try and capture an strace log with timings
strace -ttt ./eventtest
Actually I found out the test failure is not 100% reproducible. I have seen it failing in steps 6, 9 and IIRC also step 10 of eventtest.
What I think is happening is that poll() is returning much sooner than we anticipate. When you give it a timeout, it'll return upto 1 timeslice before the timeout is due. I suspect that this is what is tripping up the test case on Mandriva. Could you apply the following patch, and re-build & run LIBVIRT_DEBUG=1 ./eventtest again, and also re-run with the 'strace -ttt -f ./eventtest' (i forgot to ask for -f last time).
The patch in question being this one :-) Index: qemud/event.c =================================================================== RCS file: /data/cvs/libvirt/qemud/event.c,v retrieving revision 1.23 diff -u -p -r1.23 event.c --- qemud/event.c 12 May 2009 16:43:05 -0000 1.23 +++ qemud/event.c 3 Jun 2009 10:57:04 -0000 @@ -401,7 +401,8 @@ static int virEventDispatchTimeouts(void for (i = 0 ; i < ntimeouts ; i++) { if (eventLoop.timeouts[i].deleted || eventLoop.timeouts[i].frequency < 0) continue; - + VIR_INFO("Check timeout %lld against current %lld", + eventLoop.timeouts[i].expiresAt, now); if (eventLoop.timeouts[i].expiresAt <= now) { virEventTimeoutCallback cb = eventLoop.timeouts[i].cb; int timer = eventLoop.timeouts[i].timer; Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
- test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64):
What I think is happening is that poll() is returning much sooner than we anticipate. When you give it a timeout, it'll return upto 1 timeslice before the timeout is due. I suspect that this is what is tripping up the test case on Mandriva. Could you apply the following patch, and re-build & run LIBVIRT_DEBUG=1 ./eventtest again, and also re-run with the 'strace -ttt -f ./eventtest' (i forgot to ask for -f last time).
$ LIBVIRT_DEBUG=1 ./eventtest 21:52:03.725: debug : virEventAddHandleImpl:112 : Add handle 13 1 0x804bc40 (nil) 21:52:03.736: debug : virEventAddHandleImpl:116 : Used 0 handle slots, adding 10 more 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddHandleImpl:112 : Add handle 3 1 0x804ace0 0x80582a0 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddHandleImpl:112 : Add handle 5 1 0x804ace0 0x80582b8 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddHandleImpl:112 : Add handle 7 1 0x804ace0 0x80582d0 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddHandleImpl:112 : Add handle 9 1 0x804ace0 0x80582e8 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddHandleImpl:112 : Add handle 11 1 0x804ace0 0x8058300 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddTimeoutImpl:209 : Adding timer 1 with -1 ms freq 21:52:03.736: debug : virEventAddTimeoutImpl:217 : Used 0 timeout slots, adding 10 more 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddTimeoutImpl:209 : Adding timer 2 with -1 ms freq 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddTimeoutImpl:209 : Adding timer 3 with -1 ms freq 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddTimeoutImpl:209 : Adding timer 4 with -1 ms freq 21:52:03.736: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 21:52:03.736: debug : virEventAddTimeoutImpl:209 : Adding timer 5 with -1 ms freq 21:52:03.737: debug : virEventInterruptLocked:637 : Skip interrupt, 0 0 1: Simple write 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=1 w=2, f=3 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=2 w=3, f=5 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=3 w=4, f=7 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=4 w=5, f=9 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=5 w=6, f=11 e=1 21:52:03.737: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.737: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 21:52:03.737: debug : virEventRunOnce:566 : Poll on 6 handles 0x8068158 timeout -1 21:52:03.737: debug : virEventRunOnce:568 : Poll got 1 event 21:52:03.737: debug : virEventDispatchHandles:451 : Dispatch n=2 f=5 w=3 e=1 0x80582b8 OK 21:52:03.737: debug : virEventRemoveHandleImpl:173 : Remove handle 2 21:52:03.737: debug : virEventRemoveHandleImpl:186 : mark delete 1 3 21:52:03.737: debug : virEventInterruptLocked:637 : Skip interrupt, 0 -1210193008 2: Deleted before poll 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=1 w=3, f=5 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=2 w=4, f=7 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=3 w=5, f=9 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=4 w=6, f=11 e=1 21:52:03.737: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.737: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 21:52:03.737: debug : virEventRunOnce:566 : Poll on 5 handles 0x8068098 timeout -1 21:52:03.737: debug : virEventRunOnce:568 : Poll got 1 event 21:52:03.737: debug : virEventDispatchHandles:451 : Dispatch n=1 f=5 w=3 e=1 0x80582b8 OK 3: Interrupted during poll 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=1 w=3, f=5 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=2 w=4, f=7 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=3 w=5, f=9 e=1 21:52:03.737: debug : virEventMakePollFDs:365 : Prepare n=4 w=6, f=11 e=1 21:52:03.737: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.737: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 21:52:03.737: debug : virEventRunOnce:566 : Poll on 5 handles 0x8068098 timeout -1 21:52:03.837: debug : virEventRemoveHandleImpl:173 : Remove handle 3 21:52:03.837: debug : virEventRemoveHandleImpl:186 : mark delete 1 5 21:52:03.837: debug : virEventInterruptLocked:641 : Interrupting 21:52:03.837: debug : virEventRunOnce:568 : Poll got 1 event 21:52:03.837: debug : virEventDispatchHandles:451 : Dispatch n=0 f=13 w=1 e=1 (nil) 21:52:03.837: debug : virEventDispatchHandles:441 : Skip deleted n=1 w=3 f=5 OK 4: Deleted during dispatch 21:52:03.837: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=1 w=4, f=7 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=2 w=5, f=9 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=3 w=6, f=11 e=1 21:52:03.838: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.838: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 21:52:03.838: debug : virEventRunOnce:566 : Poll on 4 handles 0x80688f0 timeout -1 21:52:03.838: debug : virEventRunOnce:568 : Poll got 2 event 21:52:03.838: debug : virEventDispatchHandles:451 : Dispatch n=1 f=7 w=4 e=1 0x80582d0 21:52:03.838: debug : virEventRemoveHandleImpl:173 : Remove handle 5 21:52:03.838: debug : virEventRemoveHandleImpl:186 : mark delete 2 9 21:52:03.838: debug : virEventInterruptLocked:637 : Skip interrupt, 1 -1210193008 21:52:03.838: debug : virEventDispatchHandles:441 : Skip deleted n=2 w=5 f=9 OK 5: Deleted during dispatch 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=1 w=4, f=7 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=2 w=6, f=11 e=1 21:52:03.838: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.838: debug : virEventCalculateTimeout:343 : Timeout at 0 due in -1 ms 21:52:03.838: debug : virEventRunOnce:566 : Poll on 3 handles 0x8068098 timeout -1 21:52:03.838: debug : virEventRunOnce:568 : Poll got 1 event 21:52:03.838: debug : virEventDispatchHandles:451 : Dispatch n=1 f=7 w=4 e=1 0x80582d0 21:52:03.838: debug : virEventRemoveHandleImpl:173 : Remove handle 4 21:52:03.838: debug : virEventRemoveHandleImpl:186 : mark delete 1 7 21:52:03.838: debug : virEventInterruptLocked:637 : Skip interrupt, 1 -1210193008 OK 21:52:03.838: debug : virEventUpdateTimeoutImpl:247 : Updating timer 2 timeout with 100 ms freq 21:52:03.838: debug : virEventInterruptLocked:637 : Skip interrupt, 0 -1210193008 6: Firing a timer 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=1 w=6, f=11 e=1 21:52:03.838: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.838: debug : virEventCalculateTimeout:319 : Got a timeout scheduled for 1244145123938 21:52:03.838: debug : virEventCalculateTimeout:343 : Timeout at 1244145123938 due in 100 ms 21:52:03.838: debug : virEventRunOnce:566 : Poll on 2 handles 0x8068098 timeout 100 21:52:03.931: debug : virEventRunOnce:568 : Poll got 0 event 21:52:03.931: info : virEventDispatchTimeouts:405 : Check timeout 1244145123938 against current 1244145123931 FAIL Timer 1 should have fired, but didn't $ strace -ttt -f ./eventtest 1244145232.492059 execve("./eventtest", ["./eventtest"], [/* 59 vars */]) = 0 1244145232.492665 brk(0) = 0x8068000 1244145232.492762 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ef3000 1244145232.492854 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) 1244145232.492987 open("/etc/ld.so.cache", O_RDONLY) = 3 1244145232.493064 fstat64(3, {st_mode=S_IFREG|0644, st_size=271106, ...}) = 0 1244145232.493180 mmap2(NULL, 271106, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7eb0000 1244145232.493231 close(3) = 0 1244145232.493304 open("/lib/i686/librt.so.1", O_RDONLY) = 3 1244145232.493399 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 \31\0\0004\0\0\0\244"..., 512) = 512 1244145232.493522 fstat64(3, {st_mode=S_IFREG|0755, st_size=30628, ...}) = 0 1244145232.493621 mmap2(NULL, 33392, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7ea7000 1244145232.493677 mmap2(0xb7eae000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6) = 0xb7eae000 1244145232.493768 close(3) = 0 1244145232.493872 open("/lib/i686/libpthread.so.0", O_RDONLY) = 3 1244145232.493949 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360G\0\0004\0\0\0\260"..., 512) = 512 1244145232.494028 fstat64(3, {st_mode=S_IFREG|0755, st_size=111873, ...}) = 0 1244145232.494127 mmap2(NULL, 94688, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e8f000 1244145232.494194 mmap2(0xb7ea3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13) = 0xb7ea3000 1244145232.494275 mmap2(0xb7ea5000, 4576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7ea5000 1244145232.494335 close(3) = 0 1244145232.494411 open("/lib/libintl.so.8", O_RDONLY) = 3 1244145232.494823 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\24\0\0004\0\0\0 "..., 512) = 512 1244145232.494939 fstat64(3, {st_mode=S_IFREG|0644, st_size=38368, ...}) = 0 1244145232.495038 mmap2(NULL, 41680, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e84000 1244145232.495091 mmap2(0xb7e8d000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x8) = 0xb7e8d000 1244145232.495169 close(3) = 0 1244145232.495244 open("/lib/i686/libc.so.6", O_RDONLY) = 3 1244145232.495312 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0h\1\0004\0\0\0\320"..., 512) = 512 1244145232.495403 fstat64(3, {st_mode=S_IFREG|0755, st_size=1376624, ...}) = 0 1244145232.495504 mmap2(NULL, 1381968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7d32000 1244145232.495558 mmap2(0xb7e7e000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14c) = 0xb7e7e000 1244145232.495631 mmap2(0xb7e81000, 9808, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7e81000 1244145232.495693 close(3) = 0 1244145232.495775 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7d31000 1244145232.495864 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7d30000 1244145232.495931 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7d306c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 1244145232.496136 mprotect(0xb7e7e000, 8192, PROT_READ) = 0 1244145232.496220 mprotect(0xb7e8d000, 4096, PROT_READ) = 0 1244145232.496283 mprotect(0xb7ea3000, 4096, PROT_READ) = 0 1244145232.496339 mprotect(0xb7eae000, 4096, PROT_READ) = 0 1244145232.496391 mprotect(0x8057000, 4096, PROT_READ) = 0 1244145232.496444 mprotect(0xb7f0f000, 4096, PROT_READ) = 0 1244145232.496490 munmap(0xb7eb0000, 271106) = 0 1244145232.496568 set_tid_address(0xb7d30708) = 32197 1244145232.496614 set_robust_list(0xb7d30710, 0xc) = 0 1244145232.496657 futex(0xbfd4e6f0, FUTEX_WAKE_PRIVATE, 1) = 0 1244145232.496721 rt_sigaction(SIGRTMIN, {0xb7e932a0, [], SA_SIGINFO}, NULL, 8) = 0 1244145232.496802 rt_sigaction(SIGRT_1, {0xb7e936e0, [], SA_RESTART|SA_SIGINFO}, NULL, 8) = 0 1244145232.496860 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0 1244145232.496920 getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0 1244145232.497013 uname({sys="Linux", node="n4.mandriva.com", ...}) = 0 1244145232.497322 pipe([3, 4]) = 0 1244145232.497394 pipe([5, 6]) = 0 1244145232.497441 pipe([7, 8]) = 0 1244145232.497492 pipe([9, 10]) = 0 1244145232.497538 pipe([11, 12]) = 0 1244145232.497595 pipe([13, 14]) = 0 1244145232.497661 fcntl64(13, F_GETFL) = 0 (flags O_RDONLY) 1244145232.498007 fcntl64(13, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 1244145232.498055 fcntl64(14, F_GETFL) = 0x1 (flags O_WRONLY) 1244145232.498098 fcntl64(14, F_SETFL, O_WRONLY|O_NONBLOCK) = 0 1244145232.498142 fcntl64(13, F_GETFD) = 0 1244145232.498186 fcntl64(13, F_SETFD, FD_CLOEXEC) = 0 1244145232.498234 fcntl64(14, F_GETFD) = 0 1244145232.498273 fcntl64(14, F_SETFD, FD_CLOEXEC) = 0 1244145232.498383 brk(0) = 0x8068000 1244145232.498439 brk(0x8089000) = 0x8089000 1244145232.498508 gettimeofday({1244145232, 498524}, NULL) = 0 1244145232.498566 gettimeofday({1244145232, 498576}, NULL) = 0 1244145232.498615 gettimeofday({1244145232, 498625}, NULL) = 0 1244145232.498661 gettimeofday({1244145232, 498677}, NULL) = 0 1244145232.498715 gettimeofday({1244145232, 498727}, NULL) = 0 1244145232.498776 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb752f000 1244145232.498845 mprotect(0xb752f000, 4096, PROT_NONE) = 0 1244145232.498901 clone(Process 32198 attached child_stack=0xb7d2f4b4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb7d2fbd8, {entry_number:6, base_addr:0xb7d2fb90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb7d2fbd8) = 32198 [pid 32198] 1244145232.499059 set_robust_list(0xb7d2fbe0, 0xc <unfinished ...> [pid 32197] 1244145232.499084 write(2, " 1: Simple write "..., 17 1: Simple write <unfinished ...> [pid 32198] 1244145232.499125 <... set_robust_list resumed> ) = 0 [pid 32197] 1244145232.499142 <... write resumed> ) = 17 [pid 32198] 1244145232.499184 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.499208 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.499230 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32197] 1244145232.499258 <... futex resumed> ) = 0 [pid 32198] 1244145232.499284 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.499304 sched_yield( <unfinished ...> [pid 32198] 1244145232.499324 <... futex resumed> ) = 0 [pid 32197] 1244145232.499341 <... sched_yield resumed> ) = 0 [pid 32197] 1244145232.499374 write(6, "1"..., 1 <unfinished ...> [pid 32198] 1244145232.499414 poll([{fd=13, events=POLLIN}, {fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=11, events=POLLIN}], 6, -1 <unfinished ...> [pid 32197] 1244145232.499477 <... write resumed> ) = 1 [pid 32198] 1244145232.499499 <... poll resumed> ) = 1 ([{fd=5, revents=POLLIN}]) [pid 32197] 1244145232.499552 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.499576 gettimeofday( <unfinished ...> [pid 32197] 1244145232.499592 <... clock_gettime resumed> {1244145232, 499565614}) = 0 [pid 32198] 1244145232.499618 <... gettimeofday resumed> {1244145232, 499589}, NULL) = 0 [pid 32197] 1244145232.499642 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.499671 read(5, <unfinished ...> [pid 32197] 1244145232.499687 <... clock_gettime resumed> {1244145232, 499656209}) = 0 [pid 32198] 1244145232.499712 <... read resumed> "1"..., 1) = 1 [pid 32197] 1244145232.499737 futex(0x8058264, FUTEX_WAIT_PRIVATE, 1, {4, 999909405} <unfinished ...> [pid 32198] 1244145232.499773 futex(0x8058264, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058260, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> [pid 32197] 1244145232.499805 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.499827 <... futex resumed> ) = 0 [pid 32197] 1244145232.499846 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32198] 1244145232.499873 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.499890 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.499909 <... futex resumed> ) = 0 [pid 32197] 1244145232.499927 write(2, "OK\n"..., 3OK <unfinished ...> [pid 32198] 1244145232.499965 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.499982 <... write resumed> ) = 3 [pid 32197] 1244145232.500014 write(2, " 2: Deleted before poll "..., 24 2: Deleted before poll ) = 24 [pid 32197] 1244145232.500087 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.500122 <... futex resumed> ) = 0 [pid 32197] 1244145232.500140 <... futex resumed> ) = 1 [pid 32198] 1244145232.500162 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.500180 sched_yield( <unfinished ...> [pid 32198] 1244145232.500201 <... futex resumed> ) = 0 [pid 32197] 1244145232.500213 <... sched_yield resumed> ) = 0 [pid 32197] 1244145232.500238 write(6, "1"..., 1 <unfinished ...> [pid 32198] 1244145232.500269 poll([{fd=13, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=11, events=POLLIN}], 5, -1 <unfinished ...> [pid 32197] 1244145232.500319 <... write resumed> ) = 1 [pid 32198] 1244145232.500342 <... poll resumed> ) = 1 ([{fd=5, revents=POLLIN}]) [pid 32197] 1244145232.500384 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.500412 gettimeofday( <unfinished ...> [pid 32197] 1244145232.500427 <... clock_gettime resumed> {1244145232, 500397532}) = 0 [pid 32198] 1244145232.500451 <... gettimeofday resumed> {1244145232, 500422}, NULL) = 0 [pid 32197] 1244145232.500473 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.500508 read(5, <unfinished ...> [pid 32197] 1244145232.500526 <... clock_gettime resumed> {1244145232, 500484718}) = 0 [pid 32197] 1244145232.500561 futex(0x8058264, FUTEX_WAIT_PRIVATE, 3, {4, 999912814} <unfinished ...> [pid 32198] 1244145232.500589 <... read resumed> "1"..., 1) = 1 [pid 32198] 1244145232.500666 futex(0x8058264, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058260, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> [pid 32197] 1244145232.500722 <... futex resumed> ) = 0 [pid 32198] 1244145232.500738 <... futex resumed> ) = 1 [pid 32197] 1244145232.500761 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32198] 1244145232.500791 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.500808 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.500828 <... futex resumed> ) = 0 [pid 32197] 1244145232.500848 write(2, "OK\n"..., 3OK <unfinished ...> [pid 32198] 1244145232.500883 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.500904 <... write resumed> ) = 3 [pid 32197] 1244145232.500930 write(2, " 3: Interrupted during poll "..., 28 3: Interrupted during poll ) = 28 [pid 32197] 1244145232.500999 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1) = 1 [pid 32197] 1244145232.501043 sched_yield( <unfinished ...> [pid 32198] 1244145232.501064 <... futex resumed> ) = 0 [pid 32197] 1244145232.501076 <... sched_yield resumed> ) = 0 [pid 32198] 1244145232.501099 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.501116 sched_yield() = 0 [pid 32198] 1244145232.501150 <... futex resumed> ) = 0 [pid 32197] 1244145232.501167 nanosleep({0, 100000000}, <unfinished ...> [pid 32198] 1244145232.501210 poll([{fd=13, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=11, events=POLLIN}], 5, -1 <unfinished ...> [pid 32197] 1244145232.601239 <... nanosleep resumed> NULL) = 0 [pid 32197] 1244145232.601277 write(14, "\0"..., 1) = 1 [pid 32198] 1244145232.601346 <... poll resumed> ) = 1 ([{fd=13, revents=POLLIN}]) [pid 32197] 1244145232.601404 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.601438 gettimeofday( <unfinished ...> [pid 32197] 1244145232.601459 <... clock_gettime resumed> {1244145232, 601414845}) = 0 [pid 32198] 1244145232.601482 <... gettimeofday resumed> {1244145232, 601449}, NULL) = 0 [pid 32197] 1244145232.601511 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.601532 read(13, <unfinished ...> [pid 32197] 1244145232.601551 <... clock_gettime resumed> {1244145232, 601521591}) = 0 [pid 32198] 1244145232.601576 <... read resumed> "\0"..., 1) = 1 [pid 32197] 1244145232.601609 futex(0x8058264, FUTEX_WAIT_PRIVATE, 5, {4, 999893254} <unfinished ...> [pid 32198] 1244145232.601640 futex(0x8058264, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058260, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> [pid 32197] 1244145232.601663 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.601686 <... futex resumed> ) = 0 [pid 32197] 1244145232.601708 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32198] 1244145232.601738 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.601757 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.601776 <... futex resumed> ) = 0 [pid 32197] 1244145232.601795 write(2, "OK\n"..., 3OK <unfinished ...> [pid 32198] 1244145232.601830 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.601853 <... write resumed> ) = 3 [pid 32197] 1244145232.601882 write(2, " 4: Deleted during dispatch "..., 28 4: Deleted during dispatch ) = 28 [pid 32197] 1244145232.601957 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.601988 <... futex resumed> ) = 0 [pid 32197] 1244145232.602006 <... futex resumed> ) = 1 [pid 32198] 1244145232.602027 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.602048 sched_yield( <unfinished ...> [pid 32198] 1244145232.602071 <... futex resumed> ) = 0 [pid 32197] 1244145232.602088 <... sched_yield resumed> ) = 0 [pid 32198] 1244145232.602113 poll([{fd=13, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=11, events=POLLIN}], 4, -1 <unfinished ...> [pid 32197] 1244145232.602160 write(8, "1"..., 1 <unfinished ...> [pid 32198] 1244145232.602206 <... poll resumed> ) = 1 ([{fd=7, revents=POLLIN}]) [pid 32197] 1244145232.602248 <... write resumed> ) = 1 [pid 32198] 1244145232.602272 gettimeofday( <unfinished ...> [pid 32197] 1244145232.602297 write(10, "1"..., 1 <unfinished ...> [pid 32198] 1244145232.602321 <... gettimeofday resumed> {1244145232, 602283}, NULL) = 0 [pid 32197] 1244145232.602345 <... write resumed> ) = 1 [pid 32198] 1244145232.602374 read(7, <unfinished ...> [pid 32197] 1244145232.602395 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.602415 <... read resumed> "1"..., 1) = 1 [pid 32197] 1244145232.602439 <... clock_gettime resumed> {1244145232, 602406722}) = 0 [pid 32198] 1244145232.602472 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.602502 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.602524 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32197] 1244145232.602543 <... futex resumed> ) = 0 [pid 32198] 1244145232.602567 futex(0x8058260, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.602591 clock_gettime(CLOCK_REALTIME, {1244145232, 602606075}) = 0 [pid 32197] 1244145232.602652 futex(0x8058260, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.602761 <... futex resumed> ) = 0 [pid 32197] 1244145232.602815 <... futex resumed> ) = 1 [pid 32198] 1244145232.602863 futex(0x8058264, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058260, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> [pid 32197] 1244145232.602923 futex(0x8058264, FUTEX_WAIT_PRIVATE, 7, {4, 999800647} <unfinished ...> [pid 32198] 1244145232.602983 <... futex resumed> ) = 0 [pid 32197] 1244145232.603012 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.603050 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.603119 write(2, "OK\n"..., 3OK <unfinished ...> [pid 32198] 1244145232.603196 <... futex resumed> ) = 0 [pid 32197] 1244145232.603233 <... write resumed> ) = 3 [pid 32198] 1244145232.603269 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.603306 write(2, " 5: Deleted during dispatch "..., 28 5: Deleted during dispatch ) = 28 [pid 32197] 1244145232.603414 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.603493 <... futex resumed> ) = 0 [pid 32197] 1244145232.603516 <... futex resumed> ) = 1 [pid 32198] 1244145232.603551 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.603615 sched_yield( <unfinished ...> [pid 32198] 1244145232.603661 <... futex resumed> ) = 0 [pid 32197] 1244145232.603694 <... sched_yield resumed> ) = 0 [pid 32198] 1244145232.603745 poll([{fd=13, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN}], 3, -1 <unfinished ...> [pid 32197] 1244145232.603846 write(8, "1"..., 1 <unfinished ...> [pid 32198] 1244145232.603913 <... poll resumed> ) = 1 ([{fd=7, revents=POLLIN}]) [pid 32197] 1244145232.604013 <... write resumed> ) = 1 [pid 32198] 1244145232.604069 gettimeofday( <unfinished ...> [pid 32197] 1244145232.604105 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.604159 <... gettimeofday resumed> {1244145232, 604082}, NULL) = 0 [pid 32197] 1244145232.604222 <... clock_gettime resumed> {1244145232, 604120490}) = 0 [pid 32198] 1244145232.604262 read(7, <unfinished ...> [pid 32197] 1244145232.604296 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.604338 <... read resumed> "1"..., 1) = 1 [pid 32197] 1244145232.604367 <... clock_gettime resumed> {1244145232, 604311143}) = 0 [pid 32198] 1244145232.604416 futex(0x8058260, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.604494 futex(0x8058260, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.604533 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32197] 1244145232.604567 <... futex resumed> ) = 0 [pid 32198] 1244145232.604609 futex(0x8058264, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058260, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> [pid 32197] 1244145232.604698 futex(0x8058264, FUTEX_WAIT_PRIVATE, 9, {4, 999809347} <unfinished ...> [pid 32198] 1244145232.604750 <... futex resumed> ) = 0 [pid 32197] 1244145232.604770 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32198] 1244145232.604817 futex(0x8058224, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...> [pid 32197] 1244145232.604863 write(2, "OK\n"..., 3OK ) = 3 [pid 32197] 1244145232.604948 gettimeofday({1244145232, 604960}, NULL) = 0 [pid 32197] 1244145232.605008 write(2, " 6: Firing a timer "..., 19 6: Firing a timer ) = 19 [pid 32197] 1244145232.605084 futex(0x8058224, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058220, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> [pid 32198] 1244145232.605157 <... futex resumed> ) = 0 [pid 32197] 1244145232.605179 <... futex resumed> ) = 1 [pid 32198] 1244145232.605210 futex(0x8058200, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 32197] 1244145232.605278 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32198] 1244145232.605307 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 32197] 1244145232.605355 <... futex resumed> ) = 0 [pid 32198] 1244145232.605399 futex(0x8058200, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 32197] 1244145232.605432 sched_yield( <unfinished ...> [pid 32198] 1244145232.605462 <... futex resumed> ) = 0 [pid 32197] 1244145232.605497 <... sched_yield resumed> ) = 0 [pid 32198] 1244145232.605533 gettimeofday( <unfinished ...> [pid 32197] 1244145232.605563 clock_gettime(CLOCK_REALTIME, <unfinished ...> [pid 32198] 1244145232.605620 <... gettimeofday resumed> {1244145232, 605546}, NULL) = 0 [pid 32197] 1244145232.605696 <... clock_gettime resumed> {1244145232, 605606509}) = 0 [pid 32198] 1244145232.605779 poll([{fd=13, events=POLLIN}, {fd=11, events=POLLIN}], 2, 99 <unfinished ...> [pid 32197] 1244145232.605840 clock_gettime(CLOCK_REALTIME, {1244145232, 605855562}) = 0 [pid 32197] 1244145232.605964 futex(0x8058264, FUTEX_WAIT_PRIVATE, 11, {4, 999750947} <unfinished ...> [pid 32198] 1244145232.701469 <... poll resumed> ) = 0 (Timeout) [pid 32198] 1244145232.701519 gettimeofday({1244145232, 701536}, NULL) = 0 [pid 32198] 1244145232.701596 futex(0x8058264, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x8058260, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 [pid 32197] 1244145232.701656 <... futex resumed> ) = 0 [pid 32198] 1244145232.701679 futex(0x8058224, FUTEX_WAIT_PRIVATE, 3, NULL <unfinished ...> [pid 32197] 1244145232.701709 write(2, "FAIL Timer 1 should have fired, b"..., 43FAIL Timer 1 should have fired, but didn't ) = 43 [pid 32197] 1244145232.701846 exit_group(1) = ? [pid 32198] 1244145232.701897 <... futex resumed> ) = ? ERESTARTSYS (To be restarted) -- Frederik Himpe
On Thu, Jun 04, 2009 at 07:55:43PM +0000, Frederik Himpe wrote:
> - test case for exercising the event loop (Daniel Berrange)
I think this test is failing for me on Mandriva Cooker (both i586 and x86_64):
What I think is happening is that poll() is returning much sooner than we anticipate. When you give it a timeout, it'll return upto 1 timeslice before the timeout is due. I suspect that this is what is tripping up the test case on Mandriva. Could you apply the following patch, and re-build & run LIBVIRT_DEBUG=1 ./eventtest again, and also re-run with the 'strace -ttt -f ./eventtest' (i forgot to ask for -f last time).
$ LIBVIRT_DEBUG=1 ./eventtest
OK 21:52:03.838: debug : virEventUpdateTimeoutImpl:247 : Updating timer 2 timeout with 100 ms freq 21:52:03.838: debug : virEventInterruptLocked:637 : Skip interrupt, 0 -1210193008 6: Firing a timer 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=0 w=1, f=13 e=1 21:52:03.838: debug : virEventMakePollFDs:365 : Prepare n=1 w=6, f=11 e=1 21:52:03.838: debug : virEventCalculateTimeout:313 : Calculate expiry of 5 timers 21:52:03.838: debug : virEventCalculateTimeout:319 : Got a timeout scheduled for 1244145123938 21:52:03.838: debug : virEventCalculateTimeout:343 : Timeout at 1244145123938 due in 100 ms 21:52:03.838: debug : virEventRunOnce:566 : Poll on 2 handles 0x8068098 timeout 100 21:52:03.931: debug : virEventRunOnce:568 : Poll got 0 event 21:52:03.931: info : virEventDispatchTimeouts:405 : Check timeout 1244145123938 against current 1244145123931 FAIL Timer 1 should have fired, but didn't
$ strace -ttt -f ./eventtest
[pid 32197] 1244145232.605696 <... clock_gettime resumed> {1244145232, 605606509}) = 0 [pid 32198] 1244145232.605779 poll([{fd=13, events=POLLIN}, {fd=11, events=POLLIN}], 2, 99 <unfinished ...> [pid 32197] 1244145232.605840 clock_gettime(CLOCK_REALTIME, {1244145232, 605855562}) = 0
Great, this confirms my thought. We asked for a 99 ms timeout, but poll returned significantly sooner than we asked for - approx 60-80 ms. So when we then ncompare the elapsed time, with scheduled timer, we don't see the expiry. I suspect that Mandriva is either using a lower HZ for the kernel, or do not have the hi-res timers or tickless feature. Not Mandriva's fault if this is correct - we'll just have to take account of this potential for early return of poll in our tests, since it is clearly allowed by the API spec. "The timeout argument specifies an upper limit on the time for which poll() will block, in milliseconds.: so by definition, it must return at least 1 timeslice before the expiry. Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
On Thu, 04 Jun 2009 22:32:00 +0100, Daniel P. Berrange wrote:
Great, this confirms my thought. We asked for a 99 ms timeout, but poll returned significantly sooner than we asked for - approx 60-80 ms. So when we then ncompare the elapsed time, with scheduled timer, we don't see the expiry.
I suspect that Mandriva is either using a lower HZ for the kernel, or do not have the hi-res timers or tickless feature.
That's correct, Mandriva's server kernel is using 100 hz: $ uname -a Linux n4.mandriva.com 2.6.22.12-server-1mdv #1 SMP Tue Nov 20 09:35:09 EST 2007 i686 Intel(R) Xeon(TM) CPU 2.80GHz GNU/Linux $ zgrep HZ /proc/config.gz CONFIG_NO_HZ=y CONFIG_HZ_100=y # CONFIG_HZ_250 is not set # CONFIG_HZ_300 is not set # CONFIG_HZ_1000 is not set CONFIG_HZ=100 CONFIG_MACHZ_WDT=m -- Frederik Himpe
participants (3)
-
Daniel P. Berrange -
Daniel Veillard -
Frederik Himpe