1 /*
2 * Copyright © 2014-2018 Intel Corporation
3 *
4 * Permission is hereby granted, free of charge, to any person obtaining a
5 * copy of this software and associated documentation files (the "Software"),
6 * to deal in the Software without restriction, including without limitation
7 * the rights to use, copy, modify, merge, publish, distribute, sublicense,
8 * and/or sell copies of the Software, and to permit persons to whom the
9 * Software is furnished to do so, subject to the following conditions:
10 *
11 * The above copyright notice and this permission notice (including the next
12 * paragraph) shall be included in all copies or substantial portions of the
13 * Software.
14 *
15 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
16 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
17 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL
18 * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
19 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
20 * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
21 * IN THE SOFTWARE.
22 *
23 */
24
25 #include <inttypes.h>
26 #include <stdio.h>
27 #include <fcntl.h>
28 #include <sched.h>
29 #include <sys/ioctl.h>
30 #include <string.h>
31 #include <errno.h>
32 #include <signal.h>
33 #include <stdlib.h>
34 #include <unistd.h>
35 #include <sys/poll.h>
36 #include <sys/wait.h>
37 #include <sys/types.h>
38 #include <sys/syscall.h>
39 #include <sys/mman.h>
40 #include <assert.h>
41 #include <pthread.h>
42
43 #include "igt.h"
44
45 #define MB(x) ((uint64_t)(x) * 1024 * 1024)
46 #ifndef PAGE_SIZE
47 #define PAGE_SIZE 4096
48 #endif
49 /* Currently the size of GuC log buffer is 19 pages & so is the size of relay
50 * subbuffer. If the size changes in future, then this define also needs to be
51 * updated accordingly.
52 */
53 #define SUBBUF_SIZE (19*PAGE_SIZE)
54 /* Need large buffering from logger side to hide the DISK IO latency, Driver
55 * can only store 8 snapshots of GuC log buffer in relay.
56 */
57 #define NUM_SUBBUFS 100
58
59 #define RELAY_FILE_NAME "guc_log"
60 #define DEFAULT_OUTPUT_FILE_NAME "guc_log_dump.dat"
61 #define CONTROL_FILE_NAME "i915_guc_log_control"
62
63 char *read_buffer;
64 char *out_filename;
65 int poll_timeout = 2; /* by default 2ms timeout */
66 pthread_mutex_t mutex;
67 pthread_t flush_thread;
68 int verbosity_level = 3; /* by default capture logs at max verbosity */
69 uint32_t produced, consumed;
70 uint64_t total_bytes_written;
71 int num_buffers = NUM_SUBBUFS;
72 int relay_fd, outfile_fd = -1;
73 uint32_t test_duration, max_filesize;
74 pthread_cond_t underflow_cond, overflow_cond;
75 bool stop_logging, discard_oldlogs, capturing_stopped;
76
guc_log_control(bool enable,uint32_t log_level)77 static void guc_log_control(bool enable, uint32_t log_level)
78 {
79 int control_fd;
80 char data[19];
81 uint64_t val;
82 int ret;
83
84 igt_assert_lte(log_level, 3);
85
86 control_fd = igt_debugfs_open(-1, CONTROL_FILE_NAME, O_WRONLY);
87 igt_assert_f(control_fd >= 0, "couldn't open the guc log control file\n");
88
89 /*
90 * i915 expects GuC log level to be specified as:
91 * 0: disabled
92 * 1: enabled (verbosity level 0 = min)
93 * 2: enabled (verbosity level 1)
94 * 3: enabled (verbosity level 2)
95 * 4: enabled (verbosity level 3 = max)
96 */
97 val = enable ? log_level + 1 : 0;
98
99 ret = snprintf(data, sizeof(data), "0x%" PRIx64, val);
100 igt_assert(ret > 2 && ret < sizeof(data));
101
102 ret = write(control_fd, data, ret);
103 igt_assert_f(ret > 0, "couldn't write to the log control file\n");
104
105 close(control_fd);
106 }
107
int_sig_handler(int sig)108 static void int_sig_handler(int sig)
109 {
110 igt_info("received signal %d\n", sig);
111
112 stop_logging = true;
113 }
114
pull_leftover_data(void)115 static void pull_leftover_data(void)
116 {
117 unsigned int bytes_read = 0;
118 int ret;
119
120 do {
121 /* Read the logs from relay buffer */
122 ret = read(relay_fd, read_buffer, SUBBUF_SIZE);
123 if (!ret)
124 break;
125
126 igt_assert_f(ret > 0, "failed to read from the guc log file\n");
127 igt_assert_f(ret == SUBBUF_SIZE, "invalid read from relay file\n");
128
129 bytes_read += ret;
130
131 if (outfile_fd >= 0) {
132 ret = write(outfile_fd, read_buffer, SUBBUF_SIZE);
133 igt_assert_f(ret == SUBBUF_SIZE, "couldn't dump the logs in a file\n");
134 total_bytes_written += ret;
135 }
136 } while(1);
137
138 igt_debug("%u bytes flushed\n", bytes_read);
139 }
140
num_filled_bufs(void)141 static int num_filled_bufs(void)
142 {
143 return (produced - consumed);
144 }
145
pull_data(void)146 static void pull_data(void)
147 {
148 char *ptr;
149 int ret;
150
151 pthread_mutex_lock(&mutex);
152 while (num_filled_bufs() >= num_buffers) {
153 igt_debug("overflow, will wait, produced %u, consumed %u\n", produced, consumed);
154 /* Stall the main thread in case of overflow, as there are no
155 * buffers available to store the new logs, otherwise there
156 * could be corruption if both threads work on the same buffer.
157 */
158 pthread_cond_wait(&overflow_cond, &mutex);
159 };
160 pthread_mutex_unlock(&mutex);
161
162 ptr = read_buffer + (produced % num_buffers) * SUBBUF_SIZE;
163
164 /* Read the logs from relay buffer */
165 ret = read(relay_fd, ptr, SUBBUF_SIZE);
166 igt_assert_f(ret >= 0, "failed to read from the guc log file\n");
167 igt_assert_f(!ret || ret == SUBBUF_SIZE, "invalid read from relay file\n");
168
169 if (ret) {
170 pthread_mutex_lock(&mutex);
171 produced++;
172 pthread_cond_signal(&underflow_cond);
173 pthread_mutex_unlock(&mutex);
174 } else {
175 /* Occasionally (very rare) read from the relay file returns no
176 * data, albeit the polling done prior to read call indicated
177 * availability of data.
178 */
179 igt_debug("no data read from the relay file\n");
180 }
181 }
182
flusher(void * arg)183 static void *flusher(void *arg)
184 {
185 char *ptr;
186 int ret;
187
188 igt_debug("execution started of flusher thread\n");
189
190 do {
191 pthread_mutex_lock(&mutex);
192 while (!num_filled_bufs()) {
193 /* Exit only after completing the flush of all the filled
194 * buffers as User would expect that all logs captured up
195 * till the point of interruption/exit are written out to
196 * the disk file.
197 */
198 if (capturing_stopped) {
199 igt_debug("flusher to exit now\n");
200 pthread_mutex_unlock(&mutex);
201 return NULL;
202 }
203 pthread_cond_wait(&underflow_cond, &mutex);
204 };
205 pthread_mutex_unlock(&mutex);
206
207 ptr = read_buffer + (consumed % num_buffers) * SUBBUF_SIZE;
208
209 ret = write(outfile_fd, ptr, SUBBUF_SIZE);
210 igt_assert_f(ret == SUBBUF_SIZE, "couldn't dump the logs in a file\n");
211
212 total_bytes_written += ret;
213 if (max_filesize && (total_bytes_written > MB(max_filesize))) {
214 igt_debug("reached the target of %" PRIu64 " bytes\n", MB(max_filesize));
215 stop_logging = true;
216 }
217
218 pthread_mutex_lock(&mutex);
219 consumed++;
220 pthread_cond_signal(&overflow_cond);
221 pthread_mutex_unlock(&mutex);
222 } while(1);
223
224 return NULL;
225 }
226
init_flusher_thread(void)227 static void init_flusher_thread(void)
228 {
229 struct sched_param thread_sched;
230 pthread_attr_t p_attr;
231 int ret;
232
233 pthread_cond_init(&underflow_cond, NULL);
234 pthread_cond_init(&overflow_cond, NULL);
235 pthread_mutex_init(&mutex, NULL);
236
237 ret = pthread_attr_init(&p_attr);
238 igt_assert_f(ret == 0, "error obtaining default thread attributes\n");
239
240 ret = pthread_attr_setinheritsched(&p_attr, PTHREAD_EXPLICIT_SCHED);
241 igt_assert_f(ret == 0, "couldn't set inheritsched\n");
242
243 ret = pthread_attr_setschedpolicy(&p_attr, SCHED_RR);
244 igt_assert_f(ret == 0, "couldn't set thread scheduling policy\n");
245
246 /* Keep the flusher task also at rt priority, so that it doesn't get
247 * too late in flushing the collected logs in local buffers to the disk,
248 * and so main thread always have spare buffers to collect the logs.
249 */
250 thread_sched.sched_priority = 5;
251 ret = pthread_attr_setschedparam(&p_attr, &thread_sched);
252 igt_assert_f(ret == 0, "couldn't set thread priority\n");
253
254 ret = pthread_create(&flush_thread, &p_attr, flusher, NULL);
255 igt_assert_f(ret == 0, "thread creation failed\n");
256
257 ret = pthread_attr_destroy(&p_attr);
258 igt_assert_f(ret == 0, "error destroying thread attributes\n");
259 }
260
open_relay_file(void)261 static void open_relay_file(void)
262 {
263 relay_fd = igt_debugfs_open(-1, RELAY_FILE_NAME, O_RDONLY);
264 igt_assert_f(relay_fd >= 0, "couldn't open the guc log file\n");
265
266 /* Purge the old/boot-time logs from the relay buffer.
267 * This is more for Val team's requirement, where they have to first
268 * purge the existing logs before starting the tests for which the logs
269 * are actually needed. After this logger will enter into a loop and
270 * wait for the new data, at that point benchmark can be launched from
271 * a different shell.
272 */
273 if (discard_oldlogs)
274 pull_leftover_data();
275 }
276
open_output_file(void)277 static void open_output_file(void)
278 {
279 /* Use Direct IO mode for the output file, as the data written is not
280 * supposed to be accessed again, this saves a copy of data from App's
281 * buffer to kernel buffer (Page cache). Due to no buffering on kernel
282 * side, data is flushed out to disk faster and more buffering can be
283 * done on the logger side to hide the disk IO latency.
284 */
285 outfile_fd = open(out_filename ? : DEFAULT_OUTPUT_FILE_NAME,
286 O_CREAT | O_WRONLY | O_TRUNC | O_DIRECT,
287 0440);
288 igt_assert_f(outfile_fd >= 0, "couldn't open the output file\n");
289
290 free(out_filename);
291 }
292
init_main_thread(void)293 static void init_main_thread(void)
294 {
295 struct sched_param thread_sched;
296 int ret;
297
298 /* Run the main thread at highest priority to ensure that it always
299 * gets woken-up at earliest on arrival of new data and so is always
300 * ready to pull the logs, otherwise there could be loss logs if
301 * GuC firmware is generating logs at a very high rate.
302 */
303 thread_sched.sched_priority = 1;
304 ret = sched_setscheduler(getpid(), SCHED_FIFO, &thread_sched);
305 igt_assert_f(ret == 0, "couldn't set the priority\n");
306
307 if (signal(SIGINT, int_sig_handler) == SIG_ERR)
308 igt_assert_f(0, "SIGINT handler registration failed\n");
309
310 if (signal(SIGALRM, int_sig_handler) == SIG_ERR)
311 igt_assert_f(0, "SIGALRM handler registration failed\n");
312
313 /* Need an aligned pointer for direct IO */
314 ret = posix_memalign((void **)&read_buffer, PAGE_SIZE, num_buffers * SUBBUF_SIZE);
315 igt_assert_f(ret == 0, "couldn't allocate the read buffer\n");
316
317 /* Keep the pages locked in RAM, avoid page fault overhead */
318 ret = mlock(read_buffer, num_buffers * SUBBUF_SIZE);
319 igt_assert_f(ret == 0, "failed to lock memory\n");
320
321 /* Enable the logging, it may not have been enabled from boot and so
322 * the relay file also wouldn't have been created.
323 */
324 guc_log_control(true, verbosity_level);
325
326 open_relay_file();
327 open_output_file();
328 }
329
parse_options(int opt,int opt_index,void * data)330 static int parse_options(int opt, int opt_index, void *data)
331 {
332 igt_debug("opt %c optarg %s\n", opt, optarg);
333
334 switch(opt) {
335 case 'v':
336 verbosity_level = atoi(optarg);
337 igt_assert_f(verbosity_level >= 0 && verbosity_level <= 3, "invalid input for -v option\n");
338 igt_debug("verbosity level to be used is %d\n", verbosity_level);
339 break;
340 case 'o':
341 out_filename = strdup(optarg);
342 igt_assert_f(out_filename, "Couldn't allocate the o/p filename\n");
343 igt_debug("logs to be stored in file %s\n", out_filename);
344 break;
345 case 'b':
346 num_buffers = atoi(optarg);
347 igt_assert_f(num_buffers > 0, "invalid input for -b option\n");
348 igt_debug("number of buffers to be used is %d\n", num_buffers);
349 break;
350 case 't':
351 test_duration = atoi(optarg);
352 igt_assert_f(test_duration > 0, "invalid input for -t option\n");
353 igt_debug("logger to run for %d second\n", test_duration);
354 break;
355 case 'p':
356 poll_timeout = atoi(optarg);
357 igt_assert_f(poll_timeout != 0, "invalid input for -p option\n");
358 if (poll_timeout > 0)
359 igt_debug("polling to be done with %d millisecond timeout\n", poll_timeout);
360 break;
361 case 's':
362 max_filesize = atoi(optarg);
363 igt_assert_f(max_filesize > 0, "invalid input for -s option\n");
364 igt_debug("max allowed size of the output file is %d MB\n", max_filesize);
365 break;
366 case 'd':
367 discard_oldlogs = true;
368 igt_debug("old/boot-time logs will be discarded\n");
369 break;
370 }
371
372 return 0;
373 }
374
process_command_line(int argc,char ** argv)375 static void process_command_line(int argc, char **argv)
376 {
377 static struct option long_options[] = {
378 {"verbosity", required_argument, 0, 'v'},
379 {"outputfile", required_argument, 0, 'o'},
380 {"buffers", required_argument, 0, 'b'},
381 {"testduration", required_argument, 0, 't'},
382 {"polltimeout", required_argument, 0, 'p'},
383 {"size", required_argument, 0, 's'},
384 {"discard", no_argument, 0, 'd'},
385 { 0, 0, 0, 0 }
386 };
387
388 const char *help =
389 " -v --verbosity=level verbosity level of GuC logging (0-3)\n"
390 " -o --outputfile=name name of the output file, including the location, where logs will be stored\n"
391 " -b --buffers=num number of buffers to be maintained on logger side for storing logs\n"
392 " -t --testduration=sec max duration in seconds for which the logger should run\n"
393 " -p --polltimeout=ms polling timeout in ms, -1 == indefinite wait for the new data\n"
394 " -s --size=MB max size of output file in MBs after which logging will be stopped\n"
395 " -d --discard discard the old/boot-time logs before entering into the capture loop\n";
396
397 igt_simple_init_parse_opts(&argc, argv, "v:o:b:t:p:s:d", long_options,
398 help, parse_options, NULL);
399 }
400
main(int argc,char ** argv)401 int main(int argc, char **argv)
402 {
403 struct pollfd relay_poll_fd;
404 int nfds;
405 int ret;
406
407 process_command_line(argc, argv);
408
409 init_main_thread();
410
411 /* Use a separate thread for flushing the logs to a file on disk.
412 * Main thread will buffer the data from relay file in its pool of
413 * buffers and other thread will flush the data to disk in background.
414 * This is needed, albeit by default data is written out to disk in
415 * async mode, as when there are too many dirty pages in the RAM,
416 * (/proc/sys/vm/dirty_ratio), kernel starts blocking the processes
417 * doing the file writes.
418 */
419 init_flusher_thread();
420
421 relay_poll_fd.fd = relay_fd;
422 relay_poll_fd.events = POLLIN;
423 relay_poll_fd.revents = 0;
424
425 nfds = 1; /* only one fd to poll */
426
427 alarm(test_duration); /* Start the alarm */
428
429 do {
430 /* Wait/poll for the new data to be available, relay doesn't
431 * provide a blocking read.
432 * On older kernels need to do polling with a timeout instead of
433 * indefinite wait to avoid relying on relay for the wakeup, as
434 * relay used to do the wakeup in a deferred manner on jiffies
435 * granularity by scheduling a timer and moreover that timer was
436 * re-scheduled on every newly produced buffer and so was pushed
437 * out if there were multiple flush interrupts in a very quick
438 * succession (less than a jiffy gap between 2 flush interrupts)
439 * causing relay to run out of sub buffers to store new logs.
440 */
441 ret = poll(&relay_poll_fd, nfds, poll_timeout);
442 if (ret < 0) {
443 if (errno == EINTR)
444 break;
445 igt_assert_f(0, "poll call failed\n");
446 }
447
448 /* No data available yet, poll again, hopefully new data is round the corner */
449 if (!relay_poll_fd.revents)
450 continue;
451
452 pull_data();
453 } while (!stop_logging);
454
455 /* Pause logging on the GuC side */
456 guc_log_control(false, 0);
457
458 /* Signal flusher thread to make an exit */
459 capturing_stopped = 1;
460 pthread_cond_signal(&underflow_cond);
461 pthread_join(flush_thread, NULL);
462
463 pull_leftover_data();
464 igt_info("total bytes written %" PRIu64 "\n", total_bytes_written);
465
466 free(read_buffer);
467 close(relay_fd);
468 close(outfile_fd);
469 igt_exit();
470 }
471