1 /*
2 * This file and its contents are supplied under the terms of the
3 * Common Development and Distribution License ("CDDL"), version 1.0.
4 * You may only use this file in accordance with the terms of version
5 * 1.0 of the CDDL.
6 *
7 * A full copy of the text of the CDDL should have accompanied this
8 * source. A copy of the CDDL is also available via the Internet at
9 * http://www.illumos.org/license/CDDL.
10 */
11
12 /*
13 * Copyright (c) 2012 by Delphix. All rights reserved.
14 */
15
16 #include <stdlib.h>
17 #include <stdio.h>
18 #include <stdarg.h>
19 #include <string.h>
20 #include <fcntl.h>
21 #include <pthread.h>
22 #include <assert.h>
23 #include <errno.h>
24 #include <ctype.h>
25 #include <unistd.h>
26 #include <poll.h>
27 #include <sys/types.h>
28 #include <sys/wait.h>
29 #include <sys/stat.h>
30 #include <sys/socket.h>
31 #include <sys/devpoll.h>
32
33 /*
34 * poll_test.c --
35 *
36 * This file implements some simple tests to verify the behavior of the
37 * poll system call and the DP_POLL ioctl on /dev/poll.
38 *
39 * Background:
40 *
41 * Several customers recently ran into an issue where threads in grizzly
42 * (java http server implementation) would randomly wake up from a java
43 * call to select against a java.nio.channels.Selector with no events ready
44 * but well before the specified timeout expired. The
45 * java.nio.channels.Selector select logic is implemented via /dev/poll.
46 * The selector opens /dev/poll, writes the file descriptors it wants to
47 * select on to the file descritpor, and then issues a DP_POLL ioctl to
48 * wait for events to be ready.
49 *
50 * The DP_POLL ioctl arguments include a relative timeout in milliseconds,
51 * according to man poll.7d the ioctl should block until events are ready,
52 * the timeout expires, or a signal was received. In this case we noticed
53 * that DP_POLL was returning before the timeout expired despite no events
54 * being ready and no signal being delivered.
55 *
56 * Using dtrace we discovered that DP_POLL was returning in cases where the
57 * system time was changed and the thread calling DP_POLL was woken up as
58 * a result of the process forking. The DP_POLL logic was in a loop
59 * checking if events were ready and then calling cv_waituntil_sig to
60 * block. cv_waituntil_sig will return -1 if the system time has changed,
61 * causing the DP_POLL to complete prematurely.
62 *
63 * Looking at the code it turns out the same problem exists in
64 * the implementation for poll.2 as well.
65 *
66 * Fix:
67 *
68 * The fix changes dpioctl and poll_common to use cv_relwaituntil_sig
69 * rather then cv_waituntil_sig. cv_reltimedwait_sig expects a
70 * relative timeout rather then an absolute timeout, so we avoid the
71 * problem.
72 *
73 * Test:
74 *
75 * The test verifies that changing the date does not wake up threads
76 * blocked processing a poll request or a DP_POLL ioctl. The test spawns
77 * one thread that changes the date and forks (to force the threads to
78 * wakeup from cv_reltimedwait_sig) every two seconds. The test spawns
79 * a second thread that issues poll / DP_POLL on an fd set that will
80 * never have events ready and verifies that it does not return until
81 * the specified timeout expires.
82 */
83
84 /*
85 * The maximum amount of skew in seconds allowed between the
86 * expected an actual time that a test takes.
87 */
88 #define TIME_DRIFT 1
89
90 static pthread_mutex_t exitLock = PTHREAD_MUTEX_INITIALIZER;
91 static pthread_cond_t exitCond = PTHREAD_COND_INITIALIZER;
92 static int terminated = 0;
93
94 /*
95 * Set via -d to enable debug logging
96 */
97 static int debug = 0;
98
99 static void
debug_log(const char * format,...)100 debug_log(const char *format, ...)
101 {
102 va_list args;
103
104 if (!debug) {
105 return;
106 }
107
108 (void) printf("DEBUG: ");
109
110 va_start(args, format);
111 (void) vprintf(format, args);
112 va_end(args);
113 }
114
115 static void
test_start(const char * testName,const char * format,...)116 test_start(const char *testName, const char *format, ...)
117 {
118 va_list args;
119
120 (void) printf("TEST STARTING %s: ", testName);
121
122 va_start(args, format);
123 (void) vprintf(format, args);
124 va_end(args);
125 (void) fflush(stdout);
126 }
127
128 static void
test_failed(const char * testName,const char * format,...)129 test_failed(const char *testName, const char *format, ...)
130 {
131 va_list args;
132
133 (void) printf("TEST FAILED %s: ", testName);
134
135 va_start(args, format);
136 (void) vprintf(format, args);
137 va_end(args);
138
139 (void) exit(-1);
140 }
141
142 static void
test_passed(const char * testName)143 test_passed(const char *testName)
144 {
145 (void) printf("TEST PASS: %s\n", testName);
146 (void) fflush(stdout);
147 }
148
149 static int
check_time(time_t elapsed,time_t expected)150 check_time(time_t elapsed, time_t expected)
151 {
152 time_t diff = expected - elapsed;
153
154 /*
155 * We may take slightly more or less time then expected,
156 * we allow for a small fudge factor if things completed
157 * before we expect them to.
158 */
159 return (elapsed >= expected || diff <= TIME_DRIFT);
160 }
161
162 static int
poll_wrapper(pollfd_t * fds,nfds_t nfds,int timeout,time_t * elapsed)163 poll_wrapper(pollfd_t *fds, nfds_t nfds, int timeout, time_t *elapsed)
164 {
165 int ret;
166 time_t start = time(NULL);
167
168 debug_log("POLL start: (0x%p, %d, %d)\n", fds, nfds, timeout);
169
170 ret = poll(fds, nfds, timeout);
171
172 *elapsed = time(NULL) - start;
173
174 debug_log("POLL end: (0x%p, %d, %d) returns %d (elapse=%d)\n",
175 fds, nfds, timeout, ret, (*elapsed));
176
177 return (ret);
178 }
179
180 static int
dppoll(int pollfd,pollfd_t * fds,nfds_t nfds,int timeout,time_t * elapsed)181 dppoll(int pollfd, pollfd_t *fds, nfds_t nfds, int timeout, time_t *elapsed)
182 {
183 struct dvpoll arg;
184 int ret;
185 time_t start = time(NULL);
186
187 arg.dp_fds = fds;
188 arg.dp_nfds = nfds;
189 arg.dp_timeout = timeout;
190
191 debug_log("DP_POLL start: (0x%p, %d, %d)\n", fds, nfds, timeout);
192
193 ret = ioctl(pollfd, DP_POLL, &arg);
194
195 *elapsed = time(NULL) - start;
196
197 debug_log("DP_POLL end: (0x%p, %d, %d) returns %d (elapse=%d)\n",
198 fds, arg.dp_nfds, arg.dp_timeout, ret, (*elapsed));
199
200 return (ret);
201 }
202
203 static void
clear_fd(const char * testName,int pollfd,int testfd)204 clear_fd(const char *testName, int pollfd, int testfd)
205 {
206 int ret;
207 pollfd_t fd;
208
209 fd.fd = testfd;
210 fd.events = POLLREMOVE;
211 fd.revents = 0;
212
213 ret = write(pollfd, &fd, sizeof (pollfd_t));
214
215 if (ret != sizeof (pollfd_t)) {
216 if (ret < 0) {
217 test_failed(testName, "Failed to clear fd %d: %s",
218 testfd, strerror(ret));
219 }
220
221
222 test_failed(testName, "Failed to clear fd %d: %d", testfd, ret);
223 }
224 }
225
226 /*
227 * TEST: poll with no FDs set, verify we wait the appropriate amount of time.
228 */
229 static void
poll_no_fd_test(void)230 poll_no_fd_test(void)
231 {
232 const char *testName = __func__;
233 time_t elapsed;
234 int timeout = 10;
235 int ret;
236
237 test_start(testName, "poll for %d sec with no fds\n", timeout);
238
239 ret = poll_wrapper(NULL, 0, timeout * 1000, &elapsed);
240
241 if (ret != 0) {
242 test_failed(testName, "POLL returns %d (expected 0)\n", ret);
243 }
244
245 if (!check_time(elapsed, timeout)) {
246 test_failed(testName, "took %d (expected %d)\n",
247 elapsed, timeout);
248 }
249
250 test_passed(testName);
251 }
252
253 /*
254 * TEST: POLL with a valid FD set, verify that we wait the appropriate amount
255 * of time.
256 */
257 static void
poll_with_fds_test(int testfd)258 poll_with_fds_test(int testfd)
259 {
260 const char *testName = __func__;
261 time_t elapsed;
262 int timeout = 10;
263 int ret;
264 pollfd_t fd;
265
266 fd.fd = testfd;
267 fd.events = 0;
268 fd.revents = 0;
269
270 test_start(testName, "poll for %d sec with fds\n", timeout);
271
272 ret = poll_wrapper(&fd, 1, timeout * 1000, &elapsed);
273
274 if (ret != 0) {
275 test_failed(testName, "POLL returns %d (expected 0)\n", ret);
276 }
277
278 if (!check_time(elapsed, timeout)) {
279 test_failed(testName, "took %d (expected %d)\n",
280 elapsed, timeout);
281 }
282
283 test_passed(testName);
284 }
285
286 /*
287 * TEST: DP_POLL with no FDs set, verify we wait the appropriate
288 * amount of time.
289 */
290 static void
dev_poll_no_fd_test(int pollfd)291 dev_poll_no_fd_test(int pollfd)
292 {
293 const char *testName = __func__;
294 time_t elapsed;
295 int timeout = 10;
296 int ret;
297
298 test_start(testName, "poll for %d sec with no fds\n", timeout);
299
300 ret = dppoll(pollfd, NULL, 0, timeout * 1000, &elapsed);
301
302 if (ret != 0) {
303 test_failed(testName, "DP_POLL returns %d (expected 0)\n", ret);
304 }
305
306 if (!check_time(elapsed, timeout)) {
307 test_failed(testName, "took %d (expected %d)\n",
308 elapsed, timeout);
309 }
310
311 test_passed(testName);
312 }
313
314 /*
315 * TEST: DP_POLL with a valid FD set, verify that we wait
316 * the appropriate amount of time.
317 */
318 static void
dev_poll_with_fds_test(int pollfd,int testfd)319 dev_poll_with_fds_test(int pollfd, int testfd)
320 {
321 const char *testName = __func__;
322 time_t elapsed;
323 int timeout = 10;
324 int ret;
325 pollfd_t fds[5];
326
327 test_start(testName, "poll for %d sec with fds\n", timeout);
328
329 /*
330 * Clear the FD in case it's already in the cached set
331 */
332 clear_fd(testName, pollfd, testfd);
333
334 /*
335 * Add the FD with POLLIN
336 */
337 fds[0].fd = testfd;
338 fds[0].events = POLLIN;
339 fds[0].revents = 0;
340
341 ret = write(pollfd, fds, sizeof (pollfd_t));
342
343 if (ret != sizeof (pollfd_t)) {
344 if (ret < 0) {
345 test_failed(testName, "Failed to set fds: %s",
346 strerror(ret));
347 }
348
349 test_failed(testName, "Failed to set fds: %d", ret);
350 }
351
352 ret = dppoll(pollfd, fds, 5, timeout * 1000, &elapsed);
353
354 if (ret != 0) {
355 test_failed(testName, "DP_POLL returns %d (expected 0)\n", ret);
356 }
357
358 if (!check_time(elapsed, timeout)) {
359 test_failed(testName, "took %d (expected %d)\n",
360 elapsed, timeout);
361 }
362
363 clear_fd(testName, pollfd, testfd);
364
365 test_passed(testName);
366 }
367
368 /* ARGSUSED */
369 static void *
poll_thread(void * data)370 poll_thread(void *data)
371 {
372 int pollfd;
373 int testfd;
374
375 pollfd = open("/dev/poll", O_RDWR);
376
377 if (pollfd < 0) {
378 perror("Failed to open /dev/poll: ");
379 exit(-1);
380 }
381
382 /*
383 * Create a dummy FD that will never have POLLIN set
384 */
385 testfd = socket(PF_INET, SOCK_STREAM, 0);
386
387 poll_no_fd_test();
388 poll_with_fds_test(testfd);
389
390 dev_poll_no_fd_test(pollfd);
391 dev_poll_with_fds_test(pollfd, testfd);
392
393 (void) close(testfd);
394 (void) close(pollfd);
395
396 pthread_exit(0);
397 return (NULL);
398 }
399
400 /*
401 * This function causes any threads blocked in cv_timedwait_sig_hires
402 * to wakeup, which allows us to test how dpioctl handles spurious
403 * wakeups.
404 */
405 static void
trigger_wakeup(void)406 trigger_wakeup(void)
407 {
408 pid_t child;
409
410 /*
411 * Forking will force all of the threads to be woken up so
412 * they can be moved to a well known state.
413 */
414 child = vfork();
415
416 if (child == -1) {
417 perror("Fork failed: ");
418 exit(-1);
419 } else if (child == 0) {
420 _exit(0);
421 } else {
422 pid_t result = -1;
423 int status;
424
425 do {
426 result = waitpid(child, &status, 0);
427
428 if (result == -1 && errno != EINTR) {
429 (void) printf("Waitpid for %ld failed: %s\n",
430 child, strerror(errno));
431 exit(-1);
432 }
433 } while (result != child);
434
435 if (status != 0) {
436 (void) printf("Child pid %ld failed: %d\n",
437 child, status);
438 exit(-1);
439 }
440 }
441 }
442
443 /*
444 * This function changes the system time, which has the side
445 * effect of updating timechanged in the kernel.
446 */
447 static void
change_date(void)448 change_date(void)
449 {
450 int ret;
451 struct timeval tp;
452
453 ret = gettimeofday(&tp, NULL);
454 assert(ret == 0);
455
456 tp.tv_usec++;
457 ret = settimeofday(&tp, NULL);
458 assert(ret == 0);
459 }
460
461 /*
462 * The helper thread runs in a loop changing the time and
463 * forcing wakeups every 2 seconds.
464 */
465 /* ARGSUSED */
466 static void *
helper_thread(void * data)467 helper_thread(void *data)
468 {
469 int exit;
470 struct timespec ts = {2, 0};
471
472 debug_log("Helper thread started ...\n");
473
474 /* CONSTCOND */
475 while (1) {
476 (void) pthread_mutex_lock(&exitLock);
477 (void) pthread_cond_reltimedwait_np(&exitCond, &exitLock, &ts);
478 exit = terminated;
479 (void) pthread_mutex_unlock(&exitLock);
480
481 if (exit) {
482 break;
483 }
484
485 change_date();
486 trigger_wakeup();
487 debug_log("Time changed and force wakeup issued\n");
488 }
489
490 debug_log("Helper thread exiting ...\n");
491
492 pthread_exit(0);
493 return (NULL);
494 }
495
496 static void
stop_threads(void)497 stop_threads(void)
498 {
499 (void) pthread_mutex_lock(&exitLock);
500 terminated = 1;
501 (void) pthread_cond_broadcast(&exitCond);
502 (void) pthread_mutex_unlock(&exitLock);
503 }
504
505 static void
run_tests(void)506 run_tests(void)
507 {
508 pthread_t pollThread;
509 pthread_t helperThread;
510 int ret;
511
512 ret = pthread_create(&helperThread, NULL, helper_thread, NULL);
513
514 if (ret != 0) {
515 (void) printf("Failed to create date thread: %s",
516 strerror(ret));
517 exit(-1);
518 }
519
520 ret = pthread_create(&pollThread, NULL, poll_thread, NULL);
521
522 if (ret != 0) {
523 (void) printf("Failed to create poll thread: %s",
524 strerror(ret));
525 exit(-1);
526 }
527
528 (void) pthread_join(pollThread, NULL);
529 stop_threads();
530 (void) pthread_join(helperThread, NULL);
531 }
532
533 int
main(int argc,char * const argv[])534 main(int argc, char * const argv[])
535 {
536 int c;
537
538 while ((c = getopt(argc, argv, "d")) != -1) {
539 switch (c) {
540 case 'd':
541 debug = 1;
542 break;
543 default:
544 break;
545 }
546 }
547
548 /*
549 * We need to be root to change the system time
550 */
551 if (getuid() != 0 && geteuid() != 0) {
552 (void) printf("%s must be run as root\n", argv[0]);
553 exit(-1);
554 }
555
556 run_tests();
557
558 exit(0);
559 }
560