Timer events on Solaris

5 views
Skip to first unread message

Joakim Johansson

unread,
Feb 28, 2011, 12:20:32 PM2/28/11
to libk...@googlegroups.com
Seems a bit broken currently (it was robust before the restructuing) - the kqtest works fine, but when running dispatch_startfish it almost always hangs (as it seems the timer doesn’t fire) - the problem is trigger by dispatch_starfish:s use of dispatch_after_f:

dispatch_after_f(dispatch_time(DISPATCH_TIME_NOW, 2 * NSEC_PER_SEC), dispatch_get_main_queue(), NULL, test_stop_after_delay);

What happens is that one thread gets stuck in solaris_kevent_wait() and never wakes up as the timer fires, the backtrace is:

----------------- lwp# 3 / thread# 3 --------------------
fffffd7fff090f5a portfs (6, 3, fffffd7ffecc8e80, 1, 1, 0)
fffffd7fff257131 solaris_kevent_wait () + 71
fffffd7fff255e83 kevent () + 253
fffffd7fff279931 _dispatch_mgr_invoke () + 596
fffffd7fff278160 _dispatch_queue_invoke () + 84
fffffd7fff276c23 _dispatch_continuation_pop () + 2d
fffffd7fff278886 _dispatch_worker_thread2 () + 6c
fffffd7fff131cbf worker_main () + 7f
fffffd7fff08c39b _thr_setup () + 5b
fffffd7fff08c5c0 _lwp_start ()
—————————————

I am trying to track it down further, just wanted to note this as a known problem… There seems to be some sort of race, as it sometimes succeeds (very seldom though).

Cheers,

Joakim

Joakim Johansson

unread,
Mar 1, 2011, 5:17:56 AM3/1/11
to libk...@googlegroups.com
I have tracked it down a bit further, but am not yet quite sure what the proper cure is - one part may simply be a problem with kqtest.

To summarize:

It seems that evfilt_user_knote_create() needs to post the knote to make sure that the dispatch_mgr thread which is blocked on kevent() can wake up after the appropriate timer period - this is not done as is noted in a “TODO” in evfilt_user_knote_create()

If implementing the notification like this:
--------------
int
evfilt_user_knote_create(struct filter *filt, struct knote *kn)
{
if (!(kn->kev.flags & EV_DISABLE)) // notify unless disabling
return (port_send(filter_epfd(filt), X_PORT_SOURCE_USER, kn));

#if TODO // original TODO below
u_int ffctrl;

//determine if EV_ADD + NOTE_TRIGGER in the same kevent will cause a trigger */
if ((!(dst->kev.flags & EV_DISABLE)) && src->fflags & NOTE_TRIGGER) {
dst->kev.fflags |= NOTE_TRIGGER;
eventfd_raise(filt->kf_pfd);
}

#endif
return (0);
}
———————

will make dispatch_startfish to perform properly with dispatch_after_f nicely running after 2 seconds as expected, but this change makes kqtest to break with:

------------
28: test_kevent_user_add_and_delete()

[user.c:27]: Unexpected event:_test_no_kevents(): [ident=1, filter=-11, flags = 0 ), fflags = 0, data=0, udata=0]: Error 0
***** ERROR: Program received signal 6 *****
*** TEST FAILED: test_kevent_user_add_and_delete()
------------

this snippet looks like:

-------------------------
static void
test_kevent_user_add_and_delete(void)
{
struct kevent kev;

kevent_add(kqfd, &kev, 1, EVFILT_USER, EV_ADD, 0, 0, NULL);
test_no_kevents(kqfd);

kevent_add(kqfd, &kev, 1, EVFILT_USER, EV_DELETE, 0, 0, NULL);
test_no_kevents(kqfd);
}
————————————

I am unsure whether the test is correct, should we really check for “test_no_kevents(kqfd);” after the EV_ADD ?

Shouldn’t the check only be done after add followed by delete?

Even with this fix, the libdispatch "Dispatch After”/"Timer drift test" tests are still broken, but I wanted to try to track it down incrementally...

Joakim

> --
> You received this message because you are subscribed to the Google Groups "libkqueue" group.
> To post to this group, send email to libk...@googlegroups.com.
> To unsubscribe from this group, send email to libkqueue+...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/libkqueue?hl=en.
>

Joakim Johansson

unread,
Mar 4, 2011, 11:24:16 AM3/4/11
to libk...@googlegroups.com
I think this was fixed in r449, we didn’t modify the knote for EV_RECEIPT events (and thus no signaling for the ‘trigger’ event either).

Using r449, all the libdispatch tests now pass properly again (see below).

Most of the kqueue test suite runs ok now as well, with the exception of a couple of socket test cases - it seems we get ‘level triggered’ in reality when doing a port_associate() call, which makes some of the tests to fail - continuing investigating…

-----------
[read.c:115]: Unexpected event:_test_no_kevents(): [ident=7, filter=-1, flags = 33 (EV_ADD EV_CLEAR), fflags = 0, data=1, udata=fffffd7fff06c694]: Error 0


***** ERROR: Program received signal 6 *****

*** TEST FAILED: test_kevent_socket_clear()
-----------

Joakim

==================================================
[TEST] Dispatch (Public) API
[PID] 25368
==================================================

Actual: 412970
Expected: 412970
[PASS] dispatch_get_main_queue
PASS: dispatch_api

==================================================
[TEST] Dispatch C99
[PID] 25384
==================================================

Actual: 412970
Expected: 412970
[PASS] dispatch_get_main_queue
PASS: dispatch_c99

==================================================
[TEST] Dispatch Cascade
[PID] 25400
==================================================

maxcount = 7369

*
*
*
*
*
*
*
*
*
*
*
*
*
*
*
* *
* *
* *
* *
PASS: dispatch_cascade

==================================================
[TEST] Dispatch Debug
[PID] 25416
==================================================

PASS: dispatch_debug

==================================================
[TEST] Dispatch Priority
[PID] 25432
==================================================

LOW: 9
******
DEFAULT: 55
***********************************
HIGH: 128
********************************************************************************
Actual: 192
Expected: 192
[PASS] blocks completed
Actual: 9
Expected: <128
[PASS] high priority precedence
PASS: dispatch_priority

==================================================
[TEST] Dispatch Priority (Set Target Queue)
[PID] 25448
==================================================

Actual: 415a90
Expected: 415a90
[PASS] q[i]
Actual: 418590
Expected: 418590
[PASS] q[i]
Actual: 418640
Expected: 418640
[PASS] q[i]
LOW: 61
***************************************
DEFAULT: 66
******************************************
HIGH: 65
*****************************************
Actual: 192
Expected: 192
[PASS] blocks completed
Actual: 61
Expected: <65
[PASS] high priority precedence
PASS: dispatch_priority2

==================================================
[TEST] Dispatch Starfish
[PID] 25479
==================================================

lap: 10
count: 1000
delta: 981909321 ns
math: 490.464196 ns / lap
Actual: 490
Expected: <1000
[PASS] Latency
lap: 9
count: 1000
delta: 861198307 ns
math: 430.168985 ns / lap
Actual: 430
Expected: <1000
[PASS] Latency
lap: 8
count: 1000
delta: 775029653 ns
math: 387.127699 ns / lap
Actual: 387
Expected: <1000
[PASS] Latency
lap: 7
count: 1000
delta: 693485346 ns
math: 346.396277 ns / lap
Actual: 346
Expected: <1000
[PASS] Latency
lap: 6
count: 1000
delta: 746796937 ns
math: 373.025443 ns / lap
Actual: 373
Expected: <1000
[PASS] Latency
lap: 5
count: 1000
delta: 760535223 ns
math: 379.887724 ns / lap
Actual: 379
Expected: <1000
[PASS] Latency
lap: 4
count: 1000
delta: 627688409 ns
math: 313.530674 ns / lap
Actual: 313
Expected: <1000
[PASS] Latency
lap: 3
count: 1000
delta: 910048131 ns
math: 454.569496 ns / lap
Actual: 454
Expected: <1000
[PASS] Latency
lap: 2
count: 1000
delta: 698875704 ns
math: 349.088763 ns / lap
Actual: 349
Expected: <1000
[PASS] Latency
lap: 1
count: 1000
delta: 724706927 ns
math: 361.991472 ns / lap
Actual: 361
Expected: <1000
[PASS] Latency
PASS: dispatch_starfish

==================================================
[TEST] Dispatch Queue Finalizer
[PID] 25495
==================================================

Actual: 415de0
Expected: 415de0
[PASS] dispatch_queue_new
Actual: 468da35dcbd27014
Expected: 468da35dcbd27014
[PASS] finalizer ran
PASS: queue_finalizer

==================================================
[TEST] Dispatch After
[PID] 25511
==================================================

Actual: 0
Expected: <500061796
[PASS] can't finish faster than 5.5s
Actual: 0
Expected: <499939035
[PASS] must finish faster than 6.5s
Actual: 0
Expected: <500052565
[PASS] can't finish faster than 1.5s
Actual: 0
Expected: <499947962
[PASS] must finish faster than 2.5s
Actual: 0
Expected: <33082
[PASS] can't finish faster than 0s
Actual: 0
Expected: <499967951
[PASS] must finish faster than .5s
PASS: dispatch_after

==================================================
[TEST] Dispatch Apply
[PID] 25527
==================================================

Actual: fffffd7fff290550
Expected: fffffd7fff290550
[PASS] dispatch_get_concurrent_queue
Actual: 32
Expected: 32
[PASS] count
PASS: dispatch_apply

==================================================
[TEST] Timer drift test
[PID] 25553
==================================================

Actual: 415f40
Expected: 415f40
[PASS] DISPATCH_SOURCE_TYPE_TIMER
1: jitter 0.000000, drift 0.000000
2: jitter -0.000199, drift -0.000199
3: jitter -0.000193, drift 0.000006
4: jitter -0.000199, drift -0.000006
5: jitter -0.000192, drift 0.000007
6: jitter -0.000204, drift -0.000012
7: jitter -0.000202, drift 0.000002
8: jitter -0.000195, drift 0.000007
9: jitter -0.000195, drift 0.000000
10: jitter -0.000193, drift 0.000002
11: jitter -0.000199, drift -0.000006
12: jitter -0.000000, drift 0.000199
13: jitter -0.000194, drift -0.000194
14: jitter 0.000005, drift 0.000199
15: jitter -0.000194, drift -0.000199
16: jitter -0.000003, drift 0.000191
17: jitter -0.000002, drift 0.000001
18: jitter -0.000198, drift -0.000196
19: jitter -0.000197, drift 0.000001
20: jitter -0.000006, drift 0.000191
21: jitter -0.000199, drift -0.000193
22: jitter -0.000006, drift 0.000193
23: jitter 0.000004, drift 0.000010
24: jitter -0.000007, drift -0.000011
25: jitter -0.000198, drift -0.000191
26: jitter 0.000000, drift 0.000198
27: jitter -0.000198, drift -0.000198
28: jitter -0.000200, drift -0.000002
29: jitter -0.000011, drift 0.000189
30: jitter 0.000003, drift 0.000014
31: jitter -0.000203, drift -0.000206
32: jitter -0.000008, drift 0.000195
33: jitter -0.000002, drift 0.000006
34: jitter -0.000005, drift -0.000003
35: jitter -0.000195, drift -0.000190
36: jitter -0.000194, drift 0.000001
37: jitter -0.000017, drift 0.000177
38: jitter -0.000195, drift -0.000178
39: jitter -0.000201, drift -0.000006
40: jitter -0.000004, drift 0.000197
41: jitter -0.000200, drift -0.000196
42: jitter 0.000006, drift 0.000206
43: jitter 0.000005, drift -0.000001
44: jitter -0.000193, drift -0.000198
45: jitter -0.000202, drift -0.000009
46: jitter -0.000194, drift 0.000008
47: jitter -0.000193, drift 0.000001
48: jitter -0.000002, drift 0.000191
49: jitter -0.000005, drift -0.000003
50: jitter 0.000003, drift 0.000008
51: jitter -0.000210, drift -0.000213
52: jitter 0.000004, drift 0.000214
53: jitter -0.000197, drift -0.000201
54: jitter -0.000011, drift 0.000186
55: jitter -0.000005, drift 0.000006
56: jitter -0.000197, drift -0.000192
57: jitter -0.000199, drift -0.000002
58: jitter 0.000002, drift 0.000201
59: jitter -0.000203, drift -0.000205
60: jitter -0.000201, drift 0.000002
61: jitter -0.000198, drift 0.000003
62: jitter -0.000205, drift -0.000007
63: jitter -0.000199, drift 0.000006
64: jitter -0.000005, drift 0.000194
65: jitter 0.000009, drift 0.000014
66: jitter -0.000192, drift -0.000201
67: jitter -0.000000, drift 0.000192
68: jitter -0.000199, drift -0.000199
69: jitter -0.000194, drift 0.000005
70: jitter 0.000002, drift 0.000196
71: jitter -0.000195, drift -0.000197
72: jitter -0.000207, drift -0.000012
73: jitter -0.000198, drift 0.000009
74: jitter -0.000007, drift 0.000191
75: jitter 0.000000, drift 0.000007
76: jitter -0.000199, drift -0.000199
77: jitter 0.000003, drift 0.000202
78: jitter 0.000009, drift 0.000006
79: jitter -0.000015, drift -0.000024
80: jitter -0.000212, drift -0.000197
81: jitter -0.000206, drift 0.000006
82: jitter -0.000205, drift 0.000001
83: jitter -0.000208, drift -0.000003
84: jitter -0.000201, drift 0.000007
85: jitter -0.000207, drift -0.000006
86: jitter 0.000002, drift 0.000209
87: jitter -0.000001, drift -0.000003
88: jitter -0.000208, drift -0.000207
89: jitter -0.000199, drift 0.000009
90: jitter -0.000203, drift -0.000004
91: jitter -0.000203, drift -0.000000
92: jitter -0.000000, drift 0.000203
93: jitter -0.000200, drift -0.000200
94: jitter 0.000006, drift 0.000206
95: jitter -0.000004, drift -0.000010
96: jitter -0.000004, drift 0.000000
97: jitter 0.000001, drift 0.000005
98: jitter 0.000000, drift -0.000001
99: jitter -0.000200, drift -0.000200
100: jitter -0.000198, drift 0.000002
101: jitter -0.000205, drift -0.000007
102: jitter -0.000206, drift -0.000001
103: jitter -0.000197, drift 0.000009
104: jitter -0.000200, drift -0.000003
105: jitter -0.000201, drift -0.000001
106: jitter -0.000199, drift 0.000002
107: jitter -0.000197, drift 0.000002
108: jitter -0.000197, drift 0.000000
109: jitter -0.000204, drift -0.000007
110: jitter -0.000200, drift 0.000004
111: jitter -0.000205, drift -0.000005
112: jitter -0.000010, drift 0.000195
113: jitter -0.000001, drift 0.000009
114: jitter -0.000218, drift -0.000217
115: jitter 0.000000, drift 0.000218
116: jitter -0.000197, drift -0.000197
117: jitter -0.000195, drift 0.000002
118: jitter -0.000198, drift -0.000003
119: jitter -0.000198, drift -0.000000
120: jitter 0.000002, drift 0.000200
121: jitter -0.000202, drift -0.000204
122: jitter 0.000001, drift 0.000203
123: jitter -0.000007, drift -0.000008
124: jitter -0.000007, drift -0.000000
125: jitter 0.000001, drift 0.000008
126: jitter 0.000002, drift 0.000001
127: jitter 0.000002, drift 0.000000
128: jitter 0.000000, drift -0.000002
129: jitter -0.000195, drift -0.000195
130: jitter 0.000006, drift 0.000201
131: jitter -0.000200, drift -0.000206
132: jitter -0.000199, drift 0.000001
133: jitter -0.000193, drift 0.000006
134: jitter -0.000214, drift -0.000021
135: jitter -0.000196, drift 0.000018
136: jitter 0.000007, drift 0.000203
137: jitter 0.000008, drift 0.000001
138: jitter 0.000005, drift -0.000003
139: jitter -0.000194, drift -0.000199
140: jitter 0.000005, drift 0.000199
141: jitter -0.000200, drift -0.000205
142: jitter -0.000198, drift 0.000002
143: jitter 0.000008, drift 0.000206
144: jitter -0.000204, drift -0.000212
145: jitter -0.000002, drift 0.000202
146: jitter -0.000003, drift -0.000001
147: jitter 0.000001, drift 0.000004
148: jitter 0.000000, drift -0.000001
149: jitter -0.000197, drift -0.000197
150: jitter -0.000197, drift 0.000000
151: jitter -0.000203, drift -0.000006
152: jitter -0.000200, drift 0.000003
153: jitter -0.000197, drift 0.000003
154: jitter -0.000199, drift -0.000002
155: jitter -0.000195, drift 0.000004
156: jitter -0.000198, drift -0.000003
157: jitter 0.000001, drift 0.000199
158: jitter 0.000002, drift 0.000001
159: jitter -0.000197, drift -0.000199
160: jitter 0.000000, drift 0.000197
161: jitter -0.000200, drift -0.000200
162: jitter -0.000199, drift 0.000001
163: jitter -0.000195, drift 0.000004
164: jitter -0.000199, drift -0.000004
165: jitter 0.000000, drift 0.000199
166: jitter 0.000006, drift 0.000006
167: jitter 0.000005, drift -0.000001
168: jitter 0.000005, drift 0.000000
169: jitter -0.000206, drift -0.000211
170: jitter 0.000005, drift 0.000211
171: jitter -0.000200, drift -0.000205
172: jitter -0.000198, drift 0.000002
173: jitter -0.000195, drift 0.000003
174: jitter 0.000006, drift 0.000201
175: jitter 0.000005, drift -0.000001
176: jitter -0.000003, drift -0.000008
177: jitter -0.000199, drift -0.000196
178: jitter -0.000207, drift -0.000008
179: jitter -0.000211, drift -0.000004
180: jitter -0.000197, drift 0.000014
181: jitter -0.000204, drift -0.000007
182: jitter -0.000202, drift 0.000002
183: jitter 0.000001, drift 0.000203
184: jitter -0.000013, drift -0.000014
185: jitter -0.000007, drift 0.000006
186: jitter -0.000197, drift -0.000190
187: jitter -0.000197, drift -0.000000
188: jitter 0.000002, drift 0.000199
189: jitter -0.000198, drift -0.000200
190: jitter -0.000197, drift 0.000001
191: jitter -0.000203, drift -0.000006
192: jitter -0.000003, drift 0.000200
193: jitter -0.000195, drift -0.000192
194: jitter -0.000196, drift -0.000001
195: jitter -0.000199, drift -0.000003
196: jitter -0.000194, drift 0.000005
197: jitter -0.000194, drift 0.000000
198: jitter 0.000006, drift 0.000200
199: jitter -0.000201, drift -0.000207
200: jitter 0.000005, drift 0.000206
201: jitter -0.000199, drift -0.000204
202: jitter 0.000002, drift 0.000201
203: jitter -0.000195, drift -0.000197
204: jitter 0.000005, drift 0.000200
205: jitter 0.000002, drift -0.000003
206: jitter 0.000008, drift 0.000006
207: jitter -0.000199, drift -0.000207
208: jitter -0.000002, drift 0.000197
209: jitter -0.000203, drift -0.000201
210: jitter -0.000198, drift 0.000005
211: jitter -0.000203, drift -0.000005
212: jitter -0.000001, drift 0.000202
213: jitter -0.000011, drift -0.000010
214: jitter -0.000001, drift 0.000010
215: jitter -0.000001, drift 0.000000
216: jitter -0.000198, drift -0.000197
217: jitter -0.000197, drift 0.000001
218: jitter -0.000200, drift -0.000003
219: jitter -0.000204, drift -0.000004
220: jitter -0.000198, drift 0.000006
221: jitter -0.000203, drift -0.000005
222: jitter -0.000002, drift 0.000201
223: jitter 0.000002, drift 0.000004
224: jitter 0.000004, drift 0.000002
225: jitter -0.000198, drift -0.000202
226: jitter 0.000002, drift 0.000200
227: jitter 0.000006, drift 0.000004
228: jitter -0.000201, drift -0.000207
229: jitter -0.000201, drift 0.000000
230: jitter -0.000194, drift 0.000007
231: jitter -0.000200, drift -0.000006
232: jitter -0.000205, drift -0.000005
233: jitter 0.000006, drift 0.000211
234: jitter -0.000194, drift -0.000200
235: jitter 0.000000, drift 0.000194
236: jitter 0.000004, drift 0.000004
237: jitter 0.000006, drift 0.000002
238: jitter -0.000005, drift -0.000011
239: jitter -0.000213, drift -0.000208
240: jitter -0.000010, drift 0.000203
241: jitter -0.000201, drift -0.000191
242: jitter -0.000000, drift 0.000201
243: jitter -0.000004, drift -0.000004
244: jitter 0.000003, drift 0.000007
245: jitter -0.000007, drift -0.000010
246: jitter -0.000198, drift -0.000191
247: jitter -0.000197, drift 0.000001
248: jitter -0.000199, drift -0.000002
249: jitter -0.000196, drift 0.000003
250: jitter -0.000012, drift 0.000184
Actual: 0.000114
Expected: <0.000100
[FAIL] average jitter (dispatch_drift.c:87)
dispatch_drift.c:87
Actual: 0.000000
Expected: <0.000100
[PASS] average drift
PASS: dispatch_drift

==================================================
[TEST] Dispatch Group
[PID] 25570
==================================================

Actual: 4169e0
Expected: 4169e0
[PASS] dispatch_group_async
Actual: 4169e0
Expected: 4169e0
[PASS] dispatch_group_async
sleeping...
sleeping...
sleeping...
Actual: 0
Expected: 0
[PASS] dispatch_group_wait
done.
done.
done.
Actual: 0
Expected: 0
[PASS] dispatch_group_wait
Actual: 4169e0
Expected: 4169e0
[PASS] dispatch_group_async
Actual: 413510
Expected: 413510
[PASS] Notification Received
PASS: dispatch_group

==================================================
[TEST] Dispatch Ping Pong
[PID] 25586
==================================================

Actual: 415690
Expected: 415690
[PASS] dispatch_queue_create(ping)
Actual: 415740
Expected: 415740
[PASS] dispatch_queue_create(pong)
Actual: 4157f0
Expected: 4157f0
[PASS] dispatch_group_create
Actual: 1000000
Expected: 1000000
[PASS] count
PASS: dispatch_pingpong

==================================================
[TEST] Dispatch Source Read
[PID] 25602
==================================================

Actual: 490310
Expected: 490310
[PASS] dispatch_get_main_queue
Actual: 492d10
Expected: 492d10
[PASS] DISPATCH_SOURCE_TYPE_READ
bytes available: 2486813
bytes read: 512000
bytes available: 1974813
bytes read: 512000
bytes available: 1462813
bytes read: 512000
bytes available: 950813
bytes read: 512000
bytes available: 438813
bytes read: 438813
Actual: 0
Expected: 0
[PASS] EOF
Actual: 2486813
Expected: 2486813
[PASS] Bytes read
Actual: 0
Expected: 0
[PASS] close
PASS: dispatch_read

==================================================
[TEST] Dispatch Reader/Writer Queues
[PID] 25618
==================================================

PASS: dispatch_readsync

==================================================
[TEST] Dispatch Semaphore
[PID] 25634
==================================================

Actual: 10000
Expected: 10000
[PASS] count
PASS: dispatch_sema

==================================================
[TEST] Dispatch Source Timer, bit 31
[PID] 25650
==================================================

Actual: 413170
Expected: 413170
[PASS] dispatch_get_main_queue
Actual: 415b60
Expected: 415b60
[PASS] DISPATCH_SOURCE_TYPE_TIMER
Actual: 2
Expected: <4
[PASS] elapsed time < 4s
Actual: 1
Expected: <2
[PASS] elapsed time > 2s
PASS: dispatch_timer_bit31

==================================================
[TEST] Dispatch Source Timer, bit 63
[PID] 25666
==================================================

0
PASS: dispatch_timer_bit63

==================================================
[TEST] Dispatch C++
[PID] 25692
==================================================

Actual: 4128f0
Expected: 4128f0
[PASS] dispatch_get_main_queue
PASS: dispatch_plusplus
===================
All 19 tests passed
===================

Joakim Johansson

unread,
Mar 17, 2011, 9:14:39 AM3/17/11
to libk...@googlegroups.com
A few issues were fixed the last week or so, so I have run an extensive test on Solaris now
(2500 complete test runs of the complete libdispatch test suite, took a bit over 24 hours…) - no hang, crashes or deadlocks anymore - of the 19 tests run, 18 completed without any problems at all - only the 'Timer drift test’ fails, more than half of the time:

Failure rate for the ‘Timer drift test’ (out of 2500):
--
1732 average jitter
16 average drift (this is where we have the dropped events below)
——

The jitter misses are ok:ish, as they usually are very close to the threshold of the test, but the ‘average drift’ ones point to some more fundamental problem;

Here we also get very strange results with some dropped events as it looks, just in the beginning of the test - it is strange to say the least… - unfortunately only about 1 test in 150 fails...:

==================================================
[TEST] Timer drift test

[PID] 19895
==================================================

Actual: 415f40
Expected: 415f40
[PASS] DISPATCH_SOURCE_TYPE_TIMER

3: jitter 0.000000, drift 0.000000
4: jitter 0.299497, drift 0.299497
5: jitter 0.249997, drift -0.049500
6: jitter 0.299714, drift 0.049717
7: jitter 0.299701, drift −0.000013
…
233: jitter 0.299703, drift -0.000005
234: jitter 0.299704, drift 0.000001
235: jitter 0.299710, drift 0.000006
236: jitter 0.299906, drift 0.000196
237: jitter 0.299694, drift -0.000212
238: jitter 0.299701, drift 0.000007
239: jitter 0.299709, drift 0.000008
240: jitter 0.299707, drift -0.000002
241: jitter 0.299898, drift 0.000191
242: jitter 0.299711, drift -0.000187
243: jitter 0.299713, drift 0.000002
244: jitter 0.299710, drift -0.000003
245: jitter 0.299634, drift -0.000076
246: jitter 0.299908, drift 0.000274
247: jitter 0.299710, drift -0.000198
248: jitter 0.299701, drift -0.000009
249: jitter 0.299705, drift 0.000004
250: jitter 0.299716, drift 0.000011
Actual: 0.295952


Expected: <0.000100
[FAIL] average jitter (dispatch_drift.c:87)
dispatch_drift.c:87

Actual: 0.001199
Expected: <0.000100
[FAIL] average drift (dispatch_drift.c:88)
dispatch_drift.c:88
PASS: dispatch_drift


==================================================
[TEST] Timer drift test

[PID] 18767
==================================================

Actual: 415f40
Expected: 415f40
[PASS] DISPATCH_SOURCE_TYPE_TIMER

2: jitter 0.000000, drift 0.000000
3: jitter 0.196520, drift 0.196520
5: jitter 0.109911, drift -0.086609
6: jitter 0.182059, drift 0.072148
7: jitter 0.213759, drift 0.031700
8: jitter 0.213765, drift 0.000006
9: jitter 0.213801, drift 0.000036
10: jitter 0.213811, drift 0.000010
11: jitter 0.213942, drift 0.000131
12: jitter 0.213773, drift -0.000169
13: jitter 0.213800, drift 0.000027
14: jitter 0.213804, drift 0.000004
15: jitter 0.213812, drift 0.000008
16: jitter 0.214014, drift 0.000202
17: jitter 0.213816, drift -0.000198
18: jitter 0.213815, drift -0.000001
19: jitter 0.214013, drift 0.000198
….

==================================================
[TEST] Timer drift test

[PID] 17336
==================================================

Actual: 415f40
Expected: 415f40
[PASS] DISPATCH_SOURCE_TYPE_TIMER

2: jitter 0.000000, drift 0.000000
3: jitter 0.160080, drift 0.160080
4: jitter 0.171195, drift 0.011115
5: jitter 0.170992, drift −0
…

==================================================
[TEST] Timer drift test

[PID] 28423
==================================================

Actual: 415f40
Expected: 415f40
[PASS] DISPATCH_SOURCE_TYPE_TIMER
1: jitter 0.000000, drift 0.000000

3: jitter -0.040019, drift -0.040019
4: jitter 0.149896, drift 0.189915
5: jitter 0.152920, drift 0.003024
6: jitter 0.152920, drift 0.000000
7: jitter 0.152920, drift 0.000000
8: jitter 0.152920, drift 0.000000
9: jitter 0.153116, drift 0.000196
10: jitter 0.152917, drift -0.000199
11: jitter 0.152909, drift -0.000008
12: jitter 0.152905, drift -0.000004

…

Joakim

Mark Heily

unread,
Apr 13, 2011, 10:29:27 PM4/13/11
to libk...@googlegroups.com

On Mar 17, 2011, at 9:14 AM, Joakim Johansson <jo...@tbricks.com> wrote:

A few issues were fixed the last week or so, so I have run an extensive test on Solaris now
(2500 complete test runs of the complete libdispatch test suite, took a bit over 24 hours...) - no hang, crashes or deadlocks anymore - of the 19 tests run, 18 completed without any problems at all - only the 'Timer drift test' fails, more than half of the time:


Failure rate for the 'Timer drift test' (out of 2500):
--
1732 average jitter
16 average drift (this is where we have the dropped events below)
----


The jitter misses are ok:ish, as they usually are very close to the threshold of the test, but the 'average drift' ones point to some more fundamental problem;
 


Marius recently fixed a use-after-free bug affecting the knote structure. Can you apply the fix, run these tests again and see if the dropped events continue?

Thanks,

  - Mark

Joakim Johansson

unread,
Apr 15, 2011, 1:16:04 AM4/15/11
to libk...@googlegroups.com
I just rerun the test suite overnight using yesterdays ‘trunk’ - it seems that the ‘average drift’ problem is fixed!

After 1410 test runs (which should most likely have triggered the problem), there were no more failures on the ‘average drift’.

Instad, we got 3 instances of:

---
[FAIL] high priority precedence (dispatch_priority.c:83)
---

which was a little bit surprising.

I will rerun the tests over the weekend again using an alternate malloc library which might have been used last time and see if it gives any different results overall.

Looks promising, but stay tuned! :-)

Joakim

Joakim Johansson

unread,
Apr 15, 2011, 3:25:14 AM4/15/11
to libk...@googlegroups.com
Ok, not everything is good unfortunately - after running a shorter time with the default malloc library (rather than libumem) I got one new test failure:

----
[FAIL] blocks completed (dispatch_priority.c:82)
----

Will continue to let it run over the weekend and see how it pans out in other areas.

Jocke

Mark Heily

unread,
Apr 15, 2011, 9:54:33 AM4/15/11
to libk...@googlegroups.com
All threads in libpthread_workqueue have the same scheduling policy. It might be helpful for worker threads to raise (or lower) their scheduling priority to match the priority level of the dispatch queue they are operating on. 

  - Mark

Joakim Johansson

unread,
Apr 15, 2011, 10:03:50 AM4/15/11
to libk...@googlegroups.com
Right, I did play a little bit with that idea in r114 of libpthread_workqueue already actually, needs some more work and packaging though.

Unfortunately the fail was due to the wrong number of blocks completed, not due to priority:

-----------------
[TEST] Dispatch Priority
[PID] 15167
==================================================

LOW: 29
*******************
DEFAULT: 34
**********************
HIGH: 128
********************************************************************************
Actual: 191
Expected: 192


[FAIL] blocks completed (dispatch_priority.c:82)

dispatch_priority.c:82
Actual: 29


Expected: <128
[PASS] high priority precedence
PASS: dispatch_priority

————————

Will be away for almost 2 weeks now, will try to have a look at it when coming back.

Joakim

Reply all
Reply to author
Forward
0 new messages