[igt-dev] [PATCH i-g-t 1/2] tools/intel_guc_logger: Re-enable basic functionality
Teres Alexis, Alan Previn
alan.previn.teres.alexis at intel.com
Tue Jul 19 21:35:03 UTC 2022
On Mon, 2022-05-09 at 14:21 -0700, Alan Previn wrote:
> Fix these multiple issues to get basic functionality up
> and running on GuC using:
> 1. Start using the updated debugfs path for all GuC relay-logging
> file names.
> 2. Use the updated debugfs names for the relay-logging control
> and channel files to match kernel changes.
> 3. Start querrying the relay sub-buffer info (buffer size and
> number of sub-buffers) from kernel's new debugfs files.
> 4. Separate the control enabling from the log-level-setting and
> keep the control handle open while collecting the logs.
>
> Signed-off-by: Alan Previn <alan.previn.teres.alexis at intel.com>
> ---
> tools/intel_guc_logger.c | 179 ++++++++++++++++++++++++++++-----------
> 1 file changed, 129 insertions(+), 50 deletions(-)
>
> diff --git a/tools/intel_guc_logger.c b/tools/intel_guc_logger.c
> index 5f1de8db..4a991127 100644
> --- a/tools/intel_guc_logger.c
> +++ b/tools/intel_guc_logger.c
> @@ -42,24 +42,30 @@
>
> #include "igt.h"
>
> +#define KB(x) ((uint64_t)(x) * 1024)
> #define MB(x) ((uint64_t)(x) * 1024 * 1024)
> #ifndef PAGE_SIZE
> #define PAGE_SIZE 4096
> #endif
> -/* Currently the size of GuC log buffer is 19 pages & so is the size of relay
> - * subbuffer. If the size changes in future, then this define also needs to be
> - * updated accordingly.
> - */
> -#define SUBBUF_SIZE (19*PAGE_SIZE)
> -/* Need large buffering from logger side to hide the DISK IO latency, Driver
> - * can only store 8 snapshots of GuC log buffer in relay.
> - */
> -#define NUM_SUBBUFS 100
>
> -#define RELAY_FILE_NAME "guc_log"
> #define DEFAULT_OUTPUT_FILE_NAME "guc_log_dump.dat"
> -#define CONTROL_FILE_NAME "i915_guc_log_control"
>
> +#define GLR_LOGLEVEL_NAME "guc_log_level"
> +#define GLR_CTL_NAME "guc_log_relay_ctl"
> +#define GLR_CHANNEL_NAME "guc_log_relay_chan0"
> +
> +#define DEFAULT_SUBBUF_COUNT (4 * 8)
> + /* default to kernel built-in: *
> + * 4 x 8 subbuf regions *
> + */
> +#define DEFAULT_SUBBUF_SIZE (KB(4 + 8 + 64))
> + /* default to kernel built-ins : *
> + * 4K -> buffer states array *
> + * 8K -> GuC crash dump *
> + * 64K -> log events buffer *
> + */
> +
> +int drm_fd;
> char *read_buffer;
> char *out_filename;
> int poll_timeout = 2; /* by default 2ms timeout */
> @@ -68,23 +74,53 @@ pthread_t flush_thread;
> int verbosity_level = 3; /* by default capture logs at max verbosity */
> uint32_t produced, consumed;
> uint64_t total_bytes_written;
> -int num_buffers = NUM_SUBBUFS;
> -int relay_fd, outfile_fd = -1;
> +int subbuf_count;
> +int subbuf_size;
> +int ctl_fd, relay_fd, outfile_fd = -1;
> uint32_t test_duration, max_filesize;
> pthread_cond_t underflow_cond, overflow_cond;
> bool stop_logging, discard_oldlogs, capturing_stopped;
> +char *gucfspath;
>
> -static void guc_log_control(bool enable, uint32_t log_level)
> +static void get_guc_subbuf_info(void)
> +{
> + int fd, ret, j;
> + char *path;
> + const char *dbg_fs_names[2] = {"guc_log_relay_buf_size\0",
> + "guc_log_relay_subbuf_count\0"};
> + char outstr[128];
> + uint64_t tmp[2] = {DEFAULT_SUBBUF_SIZE, DEFAULT_SUBBUF_COUNT};
> +
> + for (j = 0; j < 2; j++) {
> + igt_assert_neq(asprintf(&path, "%s/%s", gucfspath, dbg_fs_names[j]), -1);
> + igt_info("Opening subbuf path %s\n", path);
> + fd = igt_debugfs_open(drm_fd, path, O_RDONLY);
> + free(path);
> + igt_assert_f(fd >= 0, "couldn't open the GuC log relay-subbuf file\n");
> + ret = read(fd, outstr, sizeof(outstr) - 1);
> + igt_assert(ret > 0);
> + outstr[ret] = '\0';
> + tmp[j] = atoll(outstr);
> + close(fd);
> + }
> + subbuf_size = tmp[0];
> + subbuf_count = tmp[1];
> + igt_info("Debugfs retrieved subbuf info: size=%d, count=%d\n",
> + subbuf_size, subbuf_count);
> +}
> +
> +static void guc_log_verbosity(bool enable, int log_level)
> {
> - int control_fd;
> - char data[19];
> + char *str;
> + int loglevelfd;
> uint64_t val;
> int ret;
>
> - igt_assert_lte(log_level, 3);
> -
> - control_fd = igt_debugfs_open(-1, CONTROL_FILE_NAME, O_WRONLY);
> - igt_assert_f(control_fd >= 0, "couldn't open the guc log control file\n");
> + igt_assert_neq(asprintf(&str, "%s/%s", gucfspath, GLR_LOGLEVEL_NAME), -1);
> + igt_info("Opening log level -> %s\n", str);
> + loglevelfd = igt_debugfs_open(drm_fd, str, O_WRONLY);
> + free(str);
> + igt_assert_f(loglevelfd >= 0, "couldn't open the GuC log level file\n");
>
> /*
> * i915 expects GuC log level to be specified as:
> @@ -96,13 +132,51 @@ static void guc_log_control(bool enable, uint32_t log_level)
> */
> val = enable ? log_level + 1 : 0;
>
> - ret = snprintf(data, sizeof(data), "0x%" PRIx64, val);
> - igt_assert(ret > 2 && ret < sizeof(data));
> + ret = asprintf(&str, "0x%" PRIx64, val);
> + igt_assert_neq(ret, -1);
> + ret = write(loglevelfd, str, ret);
> + free(str);
> + igt_assert_f(ret > 0, "couldn't write verbosity to log level file\n");
> + igt_info("Set GuC log level = %d\n", (int)val);
> +
> + close(loglevelfd);
> +}
>
> - ret = write(control_fd, data, ret);
> - igt_assert_f(ret > 0, "couldn't write to the log control file\n");
> +static void guc_log_control(bool enable, uint32_t log_level)
> +{
> + char *str;
> + uint64_t val = 0;
> + int ret;
>
> - close(control_fd);
> + if (enable) {
> + igt_assert_neq(asprintf(&str, "%s/%s", gucfspath, GLR_CTL_NAME), -1);
> + igt_info("Opening control file -> %s\n", str);
> + ctl_fd = igt_debugfs_open(drm_fd, str, O_WRONLY);
> + free(str);
> + igt_assert_f(ctl_fd >= 0, "couldn't open the GuC log relay-ctl file\n");
> + val = 1;
> + }
> +
> + /*
> + * i915 expects relay logging controls:
> + * 1 : open + enable relay logging
> + * 2 : flush
> + * 0 : disable relay logging + close
> + */
> + if (ctl_fd) {
> + ret = asprintf(&str, "0x%" PRIx64, val);
> + igt_assert_neq(ret, -1);
> + ret = write(ctl_fd, str, ret);
> + free(str);
> + igt_assert_f(ret > 0, "couldn't write to the log control file\n");
> + }
> +
> + guc_log_verbosity(enable, log_level);
> +
> + if (!enable) {
> + igt_info("Closing control file\n");
> + close(ctl_fd);
> + }
> }
>
> static void int_sig_handler(int sig)
> @@ -119,18 +193,18 @@ static void pull_leftover_data(void)
>
> do {
> /* Read the logs from relay buffer */
> - ret = read(relay_fd, read_buffer, SUBBUF_SIZE);
> + ret = read(relay_fd, read_buffer, subbuf_size);
> if (!ret)
> break;
>
> - igt_assert_f(ret > 0, "failed to read from the guc log file\n");
> - igt_assert_f(ret == SUBBUF_SIZE, "invalid read from relay file\n");
> + igt_assert_f(ret > 0, "failed to read from the GuC log file\n");
> + igt_assert_f(ret == subbuf_size, "invalid read from relay file\n");
>
> bytes_read += ret;
>
> if (outfile_fd >= 0) {
> - ret = write(outfile_fd, read_buffer, SUBBUF_SIZE);
> - igt_assert_f(ret == SUBBUF_SIZE, "couldn't dump the logs in a file\n");
> + ret = write(outfile_fd, read_buffer, subbuf_size);
> + igt_assert_f(ret == subbuf_size, "couldn't dump the logs in a file\n");
> total_bytes_written += ret;
> }
> } while(1);
> @@ -149,7 +223,7 @@ static void pull_data(void)
> int ret;
>
> pthread_mutex_lock(&mutex);
> - while (num_filled_bufs() >= num_buffers) {
> + while (num_filled_bufs() >= subbuf_count) {
> igt_debug("overflow, will wait, produced %u, consumed %u\n", produced, consumed);
> /* Stall the main thread in case of overflow, as there are no
> * buffers available to store the new logs, otherwise there
> @@ -159,12 +233,12 @@ static void pull_data(void)
> };
> pthread_mutex_unlock(&mutex);
>
> - ptr = read_buffer + (produced % num_buffers) * SUBBUF_SIZE;
> + ptr = read_buffer + (produced % subbuf_count) * subbuf_size;
>
> /* Read the logs from relay buffer */
> - ret = read(relay_fd, ptr, SUBBUF_SIZE);
> - igt_assert_f(ret >= 0, "failed to read from the guc log file\n");
> - igt_assert_f(!ret || ret == SUBBUF_SIZE, "invalid read from relay file\n");
> + ret = read(relay_fd, ptr, subbuf_size);
> + igt_assert_f(ret >= 0, "failed to read from the GuC log file\n");
> + igt_assert_f(!ret || ret == subbuf_size, "invalid read from relay file\n");
>
> if (ret) {
> pthread_mutex_lock(&mutex);
> @@ -204,10 +278,10 @@ static void *flusher(void *arg)
> };
> pthread_mutex_unlock(&mutex);
>
> - ptr = read_buffer + (consumed % num_buffers) * SUBBUF_SIZE;
> + ptr = read_buffer + (consumed % subbuf_count) * subbuf_size;
>
> - ret = write(outfile_fd, ptr, SUBBUF_SIZE);
> - igt_assert_f(ret == SUBBUF_SIZE, "couldn't dump the logs in a file\n");
> + ret = write(outfile_fd, ptr, subbuf_size);
> + igt_assert_f(ret == subbuf_size, "couldn't dump the logs in a file\n");
>
To fix: A recent discussion with team mates revealed that the original design goal was to not just
take the incoming sequences of GuC-log-buffer snapshots from the kernel and dump to file.
The kernel is sending the entire GuC log buffers - both the guc-log-region-headers and
GuC-log-region-data. Side note: the kernel did limit the amount of data it copied over the channel
to only the new data (region usage is implemented as a ring buffer by the GuC firmware).
That said, new code needs to be added into this flusher thread to peek into the header,
and only copy the new data (reordering to flatten out wraparounds) and skip copying the
header itself.(of course keep just one header at the beginning with an ever-increasing
tail-ptr).
...alan
>
> total_bytes_written += ret;
> if (max_filesize && (total_bytes_written > MB(max_filesize))) {
> @@ -260,8 +334,13 @@ static void init_flusher_thread(void)
>
> static void open_relay_file(void)
> {
> - relay_fd = igt_debugfs_open(-1, RELAY_FILE_NAME, O_RDONLY);
> - igt_assert_f(relay_fd >= 0, "couldn't open the guc log file\n");
> + char *path;
> +
> + igt_assert_neq(asprintf(&path, "%s/%s", gucfspath, GLR_CHANNEL_NAME), -1);
> + igt_info("Opening this path -> %s\n", path);
> + relay_fd = igt_debugfs_open(drm_fd, path, O_RDONLY);
> + free(path);
> + igt_assert_f(relay_fd >= 0, "couldn't open the GuC log relay-channel file\n");
>
> /* Purge the old/boot-time logs from the relay buffer.
> * This is more for Val team's requirement, where they have to first
> @@ -292,7 +371,7 @@ static void open_output_file(void)
>
> static void init_main_thread(void)
> {
> - struct sched_param thread_sched;
> + struct sched_param thread_sched;
> int ret;
>
> /* Run the main thread at highest priority to ensure that it always
> @@ -311,11 +390,11 @@ static void init_main_thread(void)
> igt_assert_f(0, "SIGALRM handler registration failed\n");
>
> /* Need an aligned pointer for direct IO */
> - ret = posix_memalign((void **)&read_buffer, PAGE_SIZE, num_buffers * SUBBUF_SIZE);
> + ret = posix_memalign((void **)&read_buffer, PAGE_SIZE, subbuf_count * subbuf_size);
> igt_assert_f(ret == 0, "couldn't allocate the read buffer\n");
>
> /* Keep the pages locked in RAM, avoid page fault overhead */
> - ret = mlock(read_buffer, num_buffers * SUBBUF_SIZE);
> + ret = mlock(read_buffer, subbuf_count * subbuf_size);
> igt_assert_f(ret == 0, "failed to lock memory\n");
>
> /* Enable the logging, it may not have been enabled from boot and so
> @@ -342,11 +421,6 @@ static int parse_options(int opt, int opt_index, void *data)
> igt_assert_f(out_filename, "Couldn't allocate the o/p filename\n");
> igt_debug("logs to be stored in file %s\n", out_filename);
> break;
> - case 'b':
> - num_buffers = atoi(optarg);
> - igt_assert_f(num_buffers > 0, "invalid input for -b option\n");
> - igt_debug("number of buffers to be used is %d\n", num_buffers);
> - break;
> case 't':
> test_duration = atoi(optarg);
> igt_assert_f(test_duration > 0, "invalid input for -t option\n");
> @@ -377,7 +451,6 @@ static void process_command_line(int argc, char **argv)
> static struct option long_options[] = {
> {"verbosity", required_argument, 0, 'v'},
> {"outputfile", required_argument, 0, 'o'},
> - {"buffers", required_argument, 0, 'b'},
> {"testduration", required_argument, 0, 't'},
> {"polltimeout", required_argument, 0, 'p'},
> {"size", required_argument, 0, 's'},
> @@ -388,7 +461,6 @@ static void process_command_line(int argc, char **argv)
> const char *help =
> " -v --verbosity=level verbosity level of GuC logging (0-3)\n"
> " -o --outputfile=name name of the output file, including the location, where logs will be stored\n"
> - " -b --buffers=num number of buffers to be maintained on logger side for storing logs\n"
> " -t --testduration=sec max duration in seconds for which the logger should run\n"
> " -p --polltimeout=ms polling timeout in ms, -1 == indefinite wait for the new data\n"
> " -s --size=MB max size of output file in MBs after which logging will be stopped\n"
> @@ -404,6 +476,11 @@ int main(int argc, char **argv)
> int nfds;
> int ret;
>
> + drm_fd = drm_open_driver(DRIVER_INTEL);
> + igt_assert(drm_fd != -1);
> + igt_assert_neq(asprintf(&gucfspath, "gt0/uc"), -1);
> +
> + get_guc_subbuf_info();
> process_command_line(argc, argv);
>
> init_main_thread();
> @@ -466,5 +543,7 @@ int main(int argc, char **argv)
> free(read_buffer);
> close(relay_fd);
> close(outfile_fd);
> + free(gucfspath);
> + close(drm_fd);
> igt_exit();
> }
> --
> 2.25.1
>
More information about the igt-dev
mailing list