2:55 p.m.
> > >> > - 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