xref: /titanic_41/usr/src/test/os-tests/tests/poll/poll_test.c (revision d583b39bfb4e2571d3e41097c5c357ffe353ad45)
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