Project

General

Profile

Bug #1605 ยป devpoll_test.c

Matt Amdur, 2011-10-05 07:21 PM

 
1
/*
2
 * Copyright (c) 2011 by Delphix.
3
 * All rights reserved.
4
 */
5

    
6
#include <stdlib.h>
7
#include <stdio.h>
8
#include <stdarg.h>
9
#include <fcntl.h>
10
#include <pthread.h>
11
#include <assert.h>
12
#include <errno.h>
13
#include <ctype.h>
14
#include <unistd.h>
15
#include <poll.h>
16
#include <sys/types.h>
17
#include <sys/stat.h>
18
#include <sys/socket.h>
19
#include <sys/devpoll.h>
20

    
21
/*
22
 * devpoll_test.c --
23
 *
24
 *	This file implements some simple tests to verify the behavior of the
25
 *	DP_POLL ioctl on /dev/poll.
26
 *
27
 * Background:
28
 *
29
 *	Several customers recently ran into an issue where threads in grizzly
30
 *	(java http server implementation) would randomly wake up from a java
31
 *	call to select against a java.nio.channels.Selector with no events ready
32
 *	but well before the specified timeout expired. The
33
 *	java.nio.channels.Selector select logic is implemented via /dev/poll.
34
 *	The selector opens /dev/poll, writes the file descriptors it wants to
35
 *	select on to the file descritpor, and then issues a DP_POLL ioctl to
36
 *	wait for events to be ready.
37
 *
38
 *	The DP_POLL ioctl arguments include a relative timeout in milliseconds,
39
 *	according to man poll.7d the ioctl should block until events are ready,
40
 *	the timeout expires, or a signal was received. In this case we noticed
41
 *	that DP_POLL was returning before the timeout expired despite no events
42
 *	being ready and no signal being delivered.
43
 *
44
 *	Using dtrace we discovered that DP_POLL was returning in cases where the
45
 *	system time was changed and the thread calling DP_POLL was woken up as
46
 *	a result of the process forking. The DP_POLL logic was in a loop
47
 *	checking if events were ready and then calling cv_waituntil_sig to
48
 *	block. cv_waituntil_sig will return -1 if the system time has changed,
49
 *	causing the DP_POLL to complete prematurely.
50
 *
51
 * Fix:
52
 *
53
 *	The fix changes dpioctl to use cv_relwait_sig rather then
54
 *	cv_waituntil_sig. cv_relwait_sig expects a relative timeout rather then
55
 *	an absolute timeout, so we avoid the problem.
56
 *
57
 * Test:
58
 *
59
 *	The test verifies that changing the date does not wake up threads
60
 *	blocked processing a DP_POLL ioctl. The test spawns one thread that
61
 *	changes the date and forks (to force the threads to wakeup from
62
 *	cv_relwait_sig) every two seconds. The test spawns a second thread that
63
 *	issues a DP_IOCTL on an fd set that will never have events ready and
64
 *	verifies that it does not return until the specified timeout expires.
65
 */
66

    
67
/*
68
 * The maximum amount of skew in seconds allowed between the
69
 * expected an actual time that a test takes.
70
 */
71
#define	TIME_DRIFT	1
72

    
73
static pthread_mutex_t	exitLock = PTHREAD_MUTEX_INITIALIZER;
74
static pthread_cond_t	exitCond = PTHREAD_COND_INITIALIZER;
75
static int		terminated = 0;
76

    
77
/*
78
 * Set via -d to enable debug logging
79
 */
80
static int debug = 0;
81

    
82
static void
83
debug_log(const char *format, ...)
84
{
85
	va_list	args;
86

    
87
	if (!debug) {
88
		return;
89
	}
90

    
91
	(void) printf("DEBUG: ");
92

    
93
	va_start(args, format);
94
	(void) vprintf(format, args);
95
	va_end(args);
96
}
97

    
98
static void
99
test_start(const char *testName, const char *format, ...)
100
{
101
	va_list	args;
102

    
103
	(void) printf("TEST STARTING %s: ", testName);
104

    
105
	va_start(args, format);
106
	(void) vprintf(format, args);
107
	va_end(args);
108
}
109

    
110
static void
111
test_failed(const char *testName, const char *format, ...)
112
{
113
	va_list	args;
114

    
115
	(void) printf("TEST FAILED %s: ", testName);
116

    
117
	va_start(args, format);
118
	(void) vprintf(format, args);
119
	va_end(args);
120

    
121
	(void) exit(-1);
122
}
123

    
124
static void
125
test_passed(const char *testName)
126
{
127
	(void) printf("TEST PASS: %s\n", testName);
128
}
129

    
130
static int
131
check_time(time_t elapsed, time_t expected)
132
{
133
	time_t	diff = expected - elapsed;
134

    
135
	/*
136
	 * We may take slightly more or less time then expected,
137
	 * we allow for a small fudge factor if things completed
138
	 * before we expect them to.
139
	 */
140
	return (elapsed >= expected || diff <= TIME_DRIFT);
141
}
142

    
143
static int
144
dppoll(int pollFD, pollfd_t *fds, nfds_t nfds, int timeout, time_t *elapsed)
145
{
146
	struct dvpoll	arg;
147
	int		ret;
148
	time_t		start = time(NULL);
149

    
150
	arg.dp_fds = fds;
151
	arg.dp_nfds = nfds;
152
	arg.dp_timeout = timeout;
153

    
154
	debug_log("DP_POLL start: (0x%p, %d, %d)\n", fds, nfds, timeout);
155

    
156
	ret = ioctl(pollFD, DP_POLL, &arg);
157

    
158
	*elapsed = time(NULL) - start;
159

    
160
	debug_log("DP_POLL end: (0x%p, %d, %d) returns %d (elapse=%d)\n",
161
	    fds, arg.dp_nfds, arg.dp_timeout, ret, (*elapsed));
162

    
163
	return (ret);
164
}
165

    
166
static void
167
clear_fd(const char *testName, int pollFD, int testFD)
168
{
169
	int		ret;
170
	pollfd_t	fd;
171

    
172
	fd.fd = testFD;
173
	fd.events = POLLREMOVE;
174
	fd.revents = 0;
175

    
176
	ret = write(pollFD, &fd, sizeof (pollfd_t));
177

    
178
	if (ret != sizeof (pollfd_t)) {
179
		if (ret < 0) {
180
			test_failed(testName, "Failed to clear fd %d: %s",
181
			    testFD, strerror(ret));
182
		}
183

    
184

    
185
		test_failed(testName, "Failed to clear fd %d: %d", testFD, ret);
186
	}
187
}
188

    
189
/*
190
 * TEST poll-no-fd: DP_POLL with no FDs set, verify we wait the appropriate
191
 * amount of time.
192
 */
193
static void
194
poll_no_fd_test(int pollFD, int testFD)
195
{
196
	const char	*testName = "poll-no-fd";
197
	time_t		elapsed;
198
	int		timeout = 10;
199
	int		ret;
200

    
201
	test_start(testName, "poll for %d sec with no fds\n", timeout);
202

    
203
	ret = dppoll(pollFD, NULL, 0, timeout * 1000, &elapsed);
204

    
205
	if (ret != 0) {
206
		test_failed(testName, "DP_POLL returns %d (expected 0)\n", ret);
207
	}
208

    
209
	if (!check_time(elapsed, timeout)) {
210
		test_failed(testName, "took %d (expected %d)\n",
211
		    elapsed, timeout);
212
	}
213

    
214
	test_passed(testName);
215
}
216

    
217
/*
218
 * TEST poll-with-fds: DP_POLL with a valid FD set, verify that we wait
219
 * the appropriate amount of time.
220
 */
221
static void
222
poll_with_fds_test(int pollFD, int testFD)
223
{
224
	const char	*testName = "poll-with-fds";
225
	time_t		elapsed;
226
	int		timeout = 10;
227
	int		ret;
228
	pollfd_t	fds[5];
229

    
230
	test_start(testName, "poll for %d sec with fds\n", timeout);
231

    
232
	/*
233
	 * Clear the FD in case it's already in the cached set
234
	 */
235
	clear_fd(testName, pollFD, testFD);
236

    
237
	/*
238
	 * Add the FD with POLLIN
239
	 */
240
	fds[0].fd = testFD;
241
	fds[0].events = POLLIN;
242
	fds[0].revents = 0;
243

    
244
	ret = write(pollFD, fds, sizeof (pollfd_t));
245

    
246
	if (ret != sizeof (pollfd_t)) {
247
		if (ret < 0) {
248
			test_failed(testName, "Failed to set fds: %s",
249
			    strerror(ret));
250
		}
251

    
252
		test_failed(testName, "Failed to set fds: %d", ret);
253
	}
254

    
255
	ret = dppoll(pollFD, fds, 5, timeout * 1000, &elapsed);
256

    
257
	if (ret != 0) {
258
		test_failed(testName, "DP_POLL returns %d (expected 0)\n", ret);
259
	}
260

    
261
	if (!check_time(elapsed, timeout)) {
262
		test_failed(testName, "took %d (expected %d)\n",
263
		    elapsed, timeout);
264
	}
265

    
266
	clear_fd(testName, pollFD, testFD);
267

    
268
	test_passed(testName);
269
}
270

    
271
static void *
272
poll_thread(void *data)
273
{
274
	int	err;
275
	int	pollFD;
276
	int	testFD;
277
	char	*file = tmpnam(NULL);
278
	int	ret;
279

    
280
	pollFD = open("/dev/poll", O_RDWR);
281

    
282
	if (pollFD <  0) {
283
		perror("Failed to open /dev/poll: ");
284
		exit(-1);
285
	}
286

    
287
	/*
288
	 * Create a dummy FD that will never have POLLIN set
289
	 */
290
	testFD = socket(PF_INET, SOCK_STREAM, 0);
291

    
292
	poll_no_fd_test(pollFD, testFD);
293
	poll_with_fds_test(pollFD, testFD);
294

    
295
	close(testFD);
296
	close(pollFD);
297

    
298
	pthread_exit(0);
299
}
300

    
301
/*
302
 * This function causes any threads blocked in cv_timedwait_sig_hires
303
 * to wakeup, which allows us to test how dpioctl handles spurious
304
 * wakeups.
305
 */
306
trigger_wakeup(void)
307
{
308
	pid_t   child;
309

    
310
	/*
311
	 * Forking will force all of the threads to be woken up so
312
	 * they can be moved to a well known state.
313
	 */
314
	child = vfork();
315

    
316
	if (child == -1) {
317
		perror("Fork failed: ");
318
		exit(-1);
319
	} else if (child == 0) {
320
		exit(0);
321
	} else {
322
		pid_t   result = -1;
323
		int	status;
324

    
325
		do {
326
			result = waitpid(child, &status, 0);
327

    
328
			if (result == -1 && errno != EINTR) {
329
				(void) printf("Waitpid for %d failed: %s\n",
330
				    child, strerror(errno));
331
				exit(-1);
332
			}
333
		} while (result != child);
334

    
335
		if (status != 0) {
336
			(void) printf("Child pid %d failed: %d\n",
337
			    child, status);
338
			exit(-1);
339
		}
340
	}
341
}
342

    
343
/*
344
 * This function changes the system time, which has the side
345
 * effect of updating timechanged in the kernel.
346
 */
347
static void
348
change_date(void)
349
{
350
	int	ret;
351
	struct timeval  tp;
352

    
353
	ret = gettimeofday(&tp, NULL);
354
	assert(ret == 0);
355

    
356
	tp.tv_usec++;
357
	ret = settimeofday(&tp, NULL);
358
	assert(ret == 0);
359
}
360

    
361
/*
362
 * The helper thread runs in a loop changing the time and
363
 * forcing wakeups every 2 seconds.
364
 */
365
static void *
366
helper_thread(void *data)
367
{
368
	int	exit;
369
	struct	timespec ts = {2, 0};
370

    
371
	debug_log("Helper thread started ...\n");
372

    
373
	while (1) {
374
		pthread_mutex_lock(&exitLock);
375
		pthread_cond_reltimedwait_np(&exitCond, &exitLock, &ts);
376
		exit = terminated;
377
		pthread_mutex_unlock(&exitLock);
378

    
379
		if (exit) {
380
			break;
381
		}
382

    
383
		change_date();
384
		trigger_wakeup();
385
		debug_log("Time changed and force wakeup issued\n");
386
	}
387

    
388
	debug_log("Helper thread exiting ...\n");
389

    
390
	pthread_exit(0);
391
}
392

    
393
static void
394
stop_threads(void)
395
{
396
	pthread_mutex_lock(&exitLock);
397
	terminated = 1;
398
	pthread_cond_broadcast(&exitCond);
399
	pthread_mutex_unlock(&exitLock);
400
}
401

    
402
static void
403
run_tests(void)
404
{
405
	pthread_t	pollThread = -1;
406
	pthread_t	helperThread = -1;
407
	int		ret;
408

    
409
	ret = pthread_create(&helperThread, NULL, helper_thread, NULL);
410

    
411
	if (ret != 0) {
412
		(void) printf("Failed to create date thread: %s",
413
		    strerror(ret));
414
		exit(-1);
415
	}
416

    
417
	ret = pthread_create(&pollThread, NULL, poll_thread, NULL);
418

    
419
	if (ret != 0) {
420
		(void) printf("Failed to create poll thread: %s",
421
		    strerror(ret));
422
		exit(-1);
423
	}
424

    
425
	pthread_join(pollThread, NULL);
426
	stop_threads();
427
	pthread_join(helperThread, NULL);
428
}
429

    
430
int
431
main(int argc, char * const argv[])
432
{
433
	int	c;
434

    
435
	while ((c = getopt(argc, argv, "d")) != -1) {
436
		switch (c) {
437
		case 'd':
438
			debug = 1;
439
			break;
440
		default:
441
			break;
442
		}
443
	}
444

    
445
	/*
446
	 * We need to be root to change the system time
447
	 */
448
	if (getuid() != 0 && geteuid() != 0) {
449
		(void) printf("%s must be run as root\n", argv[0]);
450
		exit(-1);
451
	}
452

    
453
	run_tests();
454

    
455
	exit(0);
456
}
    (1-1/1)