From patchwork Thu Mar 24 02:57:15 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 553986 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 28C56C4321E for ; Thu, 24 Mar 2022 02:57:38 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347923AbiCXC7H (ORCPT ); Wed, 23 Mar 2022 22:59:07 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43520 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347896AbiCXC7A (ORCPT ); Wed, 23 Mar 2022 22:59:00 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 475DD939ED; Wed, 23 Mar 2022 19:57:29 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 95B40619AB; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id E678DC340E9; Thu, 24 Mar 2022 02:57:27 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfC-007FKw-Vo; Wed, 23 Mar 2022 22:57:26 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 01/12] trace-cmd: Add trace-cmd analyze Date: Wed, 23 Mar 2022 22:57:15 -0400 Message-Id: <20220324025726.1727204-2-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" Add a new trace-cmd command "analyze" that will look at a trace.dat file and report various statistics about the code. Start off by showing the amount each CPU is idle. Signed-off-by: Steven Rostedt (Google) --- tracecmd/Makefile | 1 + tracecmd/include/trace-local.h | 2 + tracecmd/trace-analyze.c | 508 +++++++++++++++++++++++++++++++++ tracecmd/trace-cmd.c | 1 + 4 files changed, 512 insertions(+) create mode 100644 tracecmd/trace-analyze.c diff --git a/tracecmd/Makefile b/tracecmd/Makefile index 355f04723ad7..895294d09092 100644 --- a/tracecmd/Makefile +++ b/tracecmd/Makefile @@ -37,6 +37,7 @@ TRACE_CMD_OBJS += trace-dump.o TRACE_CMD_OBJS += trace-clear.o TRACE_CMD_OBJS += trace-vm.o TRACE_CMD_OBJS += trace-convert.o +TRACE_CMD_OBJS += trace-analyze.o ifeq ($(VSOCK_DEFINED), 1) TRACE_CMD_OBJS += trace-agent.o diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h index bb33de06bb58..f9d0745914fe 100644 --- a/tracecmd/include/trace-local.h +++ b/tracecmd/include/trace-local.h @@ -112,6 +112,8 @@ void trace_dump(int argc, char **argv); void trace_convert(int argc, char **argv); +void trace_analyze(int argc, char **argv); + int trace_record_agent(struct tracecmd_msg_handle *msg_handle, int cpus, int *fds, int argc, char **argv, bool use_fifos, diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c new file mode 100644 index 000000000000..4a17cf12eb07 --- /dev/null +++ b/tracecmd/trace-analyze.c @@ -0,0 +1,508 @@ +// SPDX-License-Identifier: LGPL-2.1 +/* + * Copyright (C) 2022 Google Inc, Steven Rostedt + */ +#define _LARGEFILE64_SOURCE +#include +#include + +#include "trace-cmd-local.h" +#include "trace-local.h" +#include "trace-hash.h" +#include "list.h" + +static bool time_in_nsecs; + +struct analysis_data; + +struct cpu_data { + unsigned long long start_ts; + unsigned long long last_ts; + struct analysis_data *data; + struct trace_hash tasks; + int nr_tasks; + int cpu; + int current_pid; + int first_pid; +}; + +struct analysis_data { + unsigned long long start_ts; + unsigned long long last_ts; + struct cpu_data *cpu_data; + struct trace_hash tasks; + int nr_tasks; + int allocated_cpus; + int cpus; +}; + +struct task_item { + unsigned long long runtime; + unsigned long long start_ts; + struct trace_hash_item hash; + int pid; +}; + +struct task_cpu_item { + struct trace_hash_item hash; + struct task_item *task; +}; + +#define CPU_BLOCKS 32 + +#define task_from_hash(item) container_of(item, struct task_item, hash) +#define task_cpu_from_hash(item) container_of(item, struct task_cpu_item, hash) + +static struct cpu_data *get_cpu_data(struct analysis_data *data, + struct tep_record *record) +{ + struct cpu_data *cpu_data; + int cpu = record->cpu; + int cnt; + + if (cpu < data->allocated_cpus) { + cpu_data = &data->cpu_data[cpu]; + if (!cpu_data->data) + goto init_cpu_data; + return cpu_data; + } + + /* Round up to CPU_BLOCKS multiplier */ + cnt = ((cpu + CPU_BLOCKS) / CPU_BLOCKS) * CPU_BLOCKS; + + cpu_data = realloc(data->cpu_data, sizeof(*cpu_data) * cnt); + + if (!cpu_data) + die("Allocating cpu size %d for cpu %d", cnt, cpu); + + memset(cpu_data + data->allocated_cpus, 0, + sizeof(*cpu_data) * (cnt - data->allocated_cpus)); + + data->allocated_cpus = cnt; + + data->cpu_data = cpu_data; + cpu_data += cpu; + + init_cpu_data: + cpu_data->current_pid = -1; + cpu_data->cpu = cpu; + cpu_data->data = data; + + trace_hash_init(&cpu_data->tasks, 32); + + return cpu_data; +} + +static int check_idle(struct cpu_data *cpu_data, int pid) +{ + if (pid) + return pid; + + /* + * Since pid 0 is the per cpu swapper task that + * means several of these tasks have the same pid + * and only differentiate between CPUs. Set the pid + * that is stored in the hash as -2 - CPU id. + */ + + return -2 - cpu_data->cpu; +} + +static struct task_item *get_task(struct cpu_data *cpu_data, int pid) +{ + struct trace_hash_item *hash; + struct task_item *task; + int find_pid; + + find_pid = check_idle(cpu_data, pid); + + hash = trace_hash_find(&cpu_data->data->tasks, find_pid, NULL, NULL); + if (!hash) { + task = calloc(sizeof(*task), 1); + if (!task) + die("allocating task"); + task->pid = find_pid; + hash = &task->hash; + hash->key = find_pid; + cpu_data->data->nr_tasks++; + trace_hash_add(&cpu_data->data->tasks, hash); + } + + return task_from_hash(hash); +} + +static struct task_cpu_item *get_cpu_task(struct cpu_data *cpu_data, int pid) +{ + struct trace_hash_item *hash; + struct task_cpu_item *task; + + hash = trace_hash_find(&cpu_data->tasks, pid, NULL, NULL); + if (!hash) { + task = calloc(sizeof(*task), 1); + if (!task) + die("allocating cpu task"); + task->task = get_task(cpu_data, pid); + hash = &task->hash; + hash->key = pid; + cpu_data->nr_tasks++; + trace_hash_add(&cpu_data->tasks, hash); + } + + return task_cpu_from_hash(hash); +}; + +/* Update times for a task scheduling off the CPU */ +static void update_cpu_task_times(struct cpu_data *cpu_data, + struct task_cpu_item *cpu_task, + unsigned long long ts) +{ + unsigned long long delta; + struct task_item *task = cpu_task->task; + + /* + * If the last event was a sched switch where the previous task + * ran on another CPU, and migrated back to this CPU, and sched + * switch was not recorded (saying that this task scheduled off) + * It could be miscronstrued to still be on this CPU, and that + * its start_ts is later than the last_ts of this CPU. + */ + if (ts < task->start_ts) + return; + + delta = ts - task->start_ts; + task->runtime += delta; +} + +static void update_pid(struct cpu_data *cpu_data, + struct tep_record *record, int pid) +{ + struct task_cpu_item *cpu_task; + struct task_item *task; + int curr_pid = cpu_data->current_pid; + unsigned long long delta; + + cpu_task = get_cpu_task(cpu_data, curr_pid); + task = cpu_task->task; + + update_cpu_task_times(cpu_data, cpu_task, cpu_data->last_ts); + + if (!record) + return; + + cpu_task = get_cpu_task(cpu_data, pid); + task = cpu_task->task; + + if (record->ts < cpu_data->last_ts) { + tracecmd_warning("task %d start time %llu greater than CPU time %llu", + pid, record->ts, cpu_data->last_ts); + } else { + delta = record->ts - cpu_data->last_ts; + task->runtime += delta; + } + + cpu_data->last_ts = record->ts; + + task->start_ts = cpu_data->last_ts; + cpu_data->current_pid = pid; +} + +static void update_cpu_times(struct cpu_data *cpu_data, + struct tep_handle *tep, int pid, + struct tep_record *record) +{ + struct task_cpu_item *cpu_task; + struct task_item *task; + + if (cpu_data->current_pid < 0) { + /* First time called */ + cpu_data->start_ts = record->ts; + cpu_data->last_ts = record->ts; + cpu_data->current_pid = pid; + cpu_data->first_pid = pid; + cpu_task = get_cpu_task(cpu_data, pid); + task = cpu_task->task; + task->start_ts = record->ts; + if (record->ts < cpu_data->data->start_ts) + cpu_data->data->start_ts = record->ts; + return; + } + + if (pid != cpu_data->current_pid) { + update_pid(cpu_data, record, pid); + return; + } + + cpu_data->last_ts = record->ts; +} + +static void update_first_pid(struct cpu_data *cpu_data) +{ + struct task_cpu_item *cpu_task; + struct task_item *task; + unsigned long long start_ts = cpu_data->data->start_ts; + unsigned long long delta; + + cpu_task = get_cpu_task(cpu_data, cpu_data->first_pid); + task = cpu_task->task; + delta = cpu_data->start_ts - start_ts; + task->runtime += delta; + cpu_data->start_ts = start_ts; +} + +static void process_cpu(struct analysis_data *data, + struct tep_handle *tep, + struct tep_record *record) +{ + struct cpu_data *cpu_data; + int pid; + + pid = tep_data_pid(tep, record); + if (pid < 0) /* Warn? */ + return; + + cpu_data = get_cpu_data(data, record); + update_cpu_times(cpu_data, tep, pid, record); +} + +static void print_time(unsigned long long ts, char delim) +{ + unsigned long long secs; + unsigned long long msecs; + unsigned long long usecs; + unsigned long long nsecs; + + secs = ts / 1000000000; + ts -= secs * 1000000000; + + msecs = ts / 1000000; + ts -= msecs * 1000000; + + usecs = ts / 1000; + ts -= usecs * 1000; + + nsecs = ts; + + if (delim) { + printf("%6llu.%03llu%c%03llu", + secs, msecs, delim, usecs); + if (time_in_nsecs) + printf("%c%03llu", delim, nsecs); + } else { + printf("%6llu.%03llu%03llu", + secs, msecs, usecs); + if (time_in_nsecs) + printf("%03llu", nsecs); + } +} + +static void print_total(struct tep_handle *tep, struct analysis_data *data) +{ + unsigned long long total_time; + struct trace_hash_item **bucket; + struct trace_hash_item *item; + struct task_item **idle_tasks; + struct task_item *task; + bool first = true; + int cpu; + int i = 0; + + total_time = data->last_ts - data->start_ts; + printf("\nTotal time: "); + print_time(total_time, '_'); + printf("\n"); + + idle_tasks = calloc(sizeof(*idle_tasks), data->allocated_cpus); + if (!idle_tasks) + die("Could not allocate idle task array"); + + trace_hash_for_each_bucket(bucket, &data->tasks) { + trace_hash_for_each_item(item, bucket) { + task = task_from_hash(item); + if (task->pid < 0) { + cpu = -2 - task->pid; + idle_tasks[cpu] = task; + } + } + } + + for (i = 0; i < data->allocated_cpus; i++) { + if (!idle_tasks[i]) + continue; + + if (first) { + printf("\n Idle CPU\t Run time\n"); + printf(" --------\t --------\n"); + first = false; + } + printf("CPU %d idle:\t", i); + print_time(idle_tasks[i]->runtime, '_'); + printf(" (%%%lld)\n", (idle_tasks[i]->runtime * 100) / total_time); + } + free(idle_tasks); +} + +static void free_tasks(struct trace_hash *hash) +{ + struct trace_hash_item **bucket; + struct trace_hash_item *item; + struct task_item *task; + + trace_hash_for_each_bucket(bucket, hash) { + trace_hash_while_item(item, bucket) { + task = task_from_hash(item); + trace_hash_del(item); + free(task); + } + } + trace_hash_free(hash); +} + +static void free_cpu_tasks(struct trace_hash *hash) +{ + struct trace_hash_item **bucket; + struct trace_hash_item *item; + struct task_cpu_item *cpu_task; + + trace_hash_for_each_bucket(bucket, hash) { + trace_hash_while_item(item, bucket) { + cpu_task = task_cpu_from_hash(item); + trace_hash_del(item); + free(cpu_task); + } + } + trace_hash_free(hash); +} + +static void free_cpus(struct analysis_data *data) +{ + struct cpu_data *cpu_data; + int i; + + for (i = 0; i < data->allocated_cpus; i++) { + cpu_data = &data->cpu_data[i]; + if (!cpu_data->data) + continue; + free_cpu_tasks(&cpu_data->tasks); + } + free(data->cpu_data); +} + +static void do_trace_analyze(struct tracecmd_input *handle) +{ + struct tep_handle *tep = tracecmd_get_tep(handle); + struct tep_record *record; + struct analysis_data data; + struct cpu_data *cpu_data; + int i; + + memset(&data, 0, sizeof(data)); + + trace_hash_init(&data.tasks, 128); + + /* Set to a very large number */ + data.start_ts = -1ULL; + + do { + record = tracecmd_read_next_data(handle, NULL); + if (record) + process_cpu(&data, tep, record); + tracecmd_free_record(record); + } while (record); + + for (i = 0; i < data.allocated_cpus; i++) { + cpu_data = &data.cpu_data[i]; + if (!cpu_data->data || !cpu_data->nr_tasks) + continue; + if (cpu_data->last_ts > data.last_ts) + data.last_ts = cpu_data->last_ts; + } + + for (i = 0; i < data.allocated_cpus; i++) { + cpu_data = &data.cpu_data[i]; + if (!cpu_data->data || !cpu_data->nr_tasks) + continue; + cpu_data->last_ts = data.last_ts; + update_pid(cpu_data, NULL, -1); + update_first_pid(cpu_data); + } + + print_total(tep, &data); + + free_cpus(&data); + free_tasks(&data.tasks); +} + +void trace_analyze(int argc, char **argv) +{ + struct tracecmd_input *handle; + const char *input_file = NULL; + int instances; + int ret; + + for (;;) { + int c; + + c = getopt(argc-1, argv+1, "+hti:"); + if (c == -1) + break; + switch (c) { + case 'h': + usage(argv); + break; + case 'i': + if (input_file) + die("Only one input for historgram"); + input_file = optarg; + break; + case 't': + time_in_nsecs = true; + break; + default: + usage(argv); + } + } + + if ((argc - optind) >= 2) { + if (input_file) + usage(argv); + input_file = argv[optind + 1]; + } + + if (!input_file) + input_file = DEFAULT_INPUT_FILE; + + handle = tracecmd_alloc(input_file, 0); + if (!handle) + die("can't open %s\n", input_file); + + ret = tracecmd_read_headers(handle, 0); + if (ret) + return; + + ret = tracecmd_init_data(handle); + if (ret < 0) + die("failed to init data"); + + if (ret > 0) + die("trace-cmd hist does not work with latency traces\n"); + + do_trace_analyze(handle); + + instances = tracecmd_buffer_instances(handle); + if (instances) { + struct tracecmd_input *new_handle; + int i; + + for (i = 0; i < instances; i++) { + new_handle = tracecmd_buffer_instance_handle(handle, i); + if (!new_handle) { + warning("could not retrieve handle %d", i); + continue; + } + do_trace_analyze(new_handle); + tracecmd_close(new_handle); + } + } + + tracecmd_close(handle); +} diff --git a/tracecmd/trace-cmd.c b/tracecmd/trace-cmd.c index a83a8d0bb9e4..d6e1f9dacc3c 100644 --- a/tracecmd/trace-cmd.c +++ b/tracecmd/trace-cmd.c @@ -134,6 +134,7 @@ struct command commands[] = { {"help", trace_usage}, {"dump", trace_dump}, {"convert", trace_convert}, + {"analyze", trace_analyze}, {"-h", trace_usage}, }; From patchwork Thu Mar 24 02:57:16 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 554932 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id E2C7EC433F5 for ; Thu, 24 Mar 2022 02:57:32 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347902AbiCXC7B (ORCPT ); Wed, 23 Mar 2022 22:59:01 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43510 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347893AbiCXC7A (ORCPT ); Wed, 23 Mar 2022 22:59:00 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id F1399939E9; Wed, 23 Mar 2022 19:57:28 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 94852619A9; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id EBD02C340EE; Thu, 24 Mar 2022 02:57:27 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FKz-0N; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 02/12] trace-cmd analyze: Show what tasks are running the most Date: Wed, 23 Mar 2022 22:57:16 -0400 Message-Id: <20220324025726.1727204-3-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" Print out the tasks that are running the most on the system. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 39 ++++++++++++++++++++++++++++++++++++++- 1 file changed, 38 insertions(+), 1 deletion(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 4a17cf12eb07..2211079668e4 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -264,6 +264,17 @@ static void process_cpu(struct analysis_data *data, update_cpu_times(cpu_data, tep, pid, record); } +static int cmp_tasks(const void *A, const void *B) +{ + struct task_item * const *a = A; + struct task_item * const *b = B; + + if ((*a)->runtime > (*b)->runtime) + return -1; + + return (*a)->runtime < (*b)->runtime; +} + static void print_time(unsigned long long ts, char delim) { unsigned long long secs; @@ -301,8 +312,10 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) struct trace_hash_item **bucket; struct trace_hash_item *item; struct task_item **idle_tasks; + struct task_item **tasks; struct task_item *task; bool first = true; + int nr_tasks; int cpu; int i = 0; @@ -311,6 +324,10 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) print_time(total_time, '_'); printf("\n"); + tasks = malloc(sizeof(*tasks) * data->nr_tasks); + if (!tasks) + die("Could not allocate task array"); + idle_tasks = calloc(sizeof(*idle_tasks), data->allocated_cpus); if (!idle_tasks) die("Could not allocate idle task array"); @@ -321,9 +338,13 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) if (task->pid < 0) { cpu = -2 - task->pid; idle_tasks[cpu] = task; - } + } else + tasks[i++] = task; } } + nr_tasks = i; + + qsort(tasks, nr_tasks, sizeof(*tasks), cmp_tasks); for (i = 0; i < data->allocated_cpus; i++) { if (!idle_tasks[i]) @@ -339,6 +360,22 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) printf(" (%%%lld)\n", (idle_tasks[i]->runtime * 100) / total_time); } free(idle_tasks); + + printf("\n"); + for (i = 0; i < nr_tasks; i++) { + if (!i) { + printf(" Task name PID \t Run time\n"); + printf(" --------- --- \t --------\n"); + } + printf("%16s %8d\t", + tep_data_comm_from_pid(tep, tasks[i]->pid), + tasks[i]->pid); + print_time(tasks[i]->runtime, '_'); + printf(" (%%%lld)\n", (tasks[i]->runtime * 100) / total_time); + } + free(tasks); + + printf("\n"); } static void free_tasks(struct trace_hash *hash) From patchwork Thu Mar 24 02:57:17 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 553989 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 13A85C4321E for ; Thu, 24 Mar 2022 02:57:32 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347897AbiCXC7A (ORCPT ); Wed, 23 Mar 2022 22:59:00 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43494 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347887AbiCXC67 (ORCPT ); Wed, 23 Mar 2022 22:58:59 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id EF6B364EA; Wed, 23 Mar 2022 19:57:28 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 8F7C8619A6; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id E8B7AC340F3; Thu, 24 Mar 2022 02:57:27 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FL4-18; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 03/12] trace-cmd analyze: Show how much tasks run on each CPU Date: Wed, 23 Mar 2022 22:57:17 -0400 Message-Id: <20220324025726.1727204-4-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" Display for each CPU that was traced, the amount of time tasks ran on them. Listing the tasks from the longest runner to the least. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 82 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 82 insertions(+) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 2211079668e4..43e9ffa95687 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -44,6 +44,7 @@ struct task_item { }; struct task_cpu_item { + unsigned long long runtime; struct trace_hash_item hash; struct task_item *task; }; @@ -171,6 +172,7 @@ static void update_cpu_task_times(struct cpu_data *cpu_data, delta = ts - task->start_ts; task->runtime += delta; + cpu_task->runtime += delta; } static void update_pid(struct cpu_data *cpu_data, @@ -198,6 +200,7 @@ static void update_pid(struct cpu_data *cpu_data, } else { delta = record->ts - cpu_data->last_ts; task->runtime += delta; + cpu_task->runtime += delta; } cpu_data->last_ts = record->ts; @@ -246,6 +249,7 @@ static void update_first_pid(struct cpu_data *cpu_data) task = cpu_task->task; delta = cpu_data->start_ts - start_ts; task->runtime += delta; + cpu_task->runtime += delta; cpu_data->start_ts = start_ts; } @@ -275,6 +279,17 @@ static int cmp_tasks(const void *A, const void *B) return (*a)->runtime < (*b)->runtime; } +static int cmp_cpu_tasks(const void *A, const void *B) +{ + struct task_cpu_item * const *a = A; + struct task_cpu_item * const *b = B; + + if ((*a)->runtime > (*b)->runtime) + return -1; + + return (*a)->runtime < (*b)->runtime; +} + static void print_time(unsigned long long ts, char delim) { unsigned long long secs; @@ -306,6 +321,67 @@ static void print_time(unsigned long long ts, char delim) } } +static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) +{ + unsigned long long total_time; + struct trace_hash_item **bucket; + struct trace_hash_item *item; + struct task_cpu_item **cpu_tasks; + struct task_cpu_item *cpu_task; + struct task_item *idle_task = NULL; + struct task_item *task; + struct analysis_data *data; + int nr_tasks; + int i = 0; + + data = cpu_data->data; + total_time = data->last_ts - data->start_ts; + + printf("\nCPU %d\n", cpu_data->cpu); + printf("-------\n"); + + cpu_tasks = malloc(sizeof(*cpu_tasks) * cpu_data->nr_tasks); + + if (!cpu_tasks) + die("Could not allocate task array"); + + trace_hash_for_each_bucket(bucket, &cpu_data->tasks) { + trace_hash_for_each_item(item, bucket) { + cpu_task = task_cpu_from_hash(item); + if (cpu_task->task->pid <= 0) + idle_task = cpu_task->task; + else + cpu_tasks[i++] = cpu_task; + } + } + nr_tasks = i; + + if (idle_task) { + printf("idle:\t"); + print_time(idle_task->runtime, '_'); + printf(" (%%%lld)\n", (idle_task->runtime * 100) / total_time); + } else { + printf("Never idle!\n"); + } + + qsort(cpu_tasks, nr_tasks, sizeof(*cpu_tasks), cmp_cpu_tasks); + + for (i = 0; i < nr_tasks; i++) { + task = cpu_tasks[i]->task; + + if (!i) { + printf(" Task name PID \t Run time\n"); + printf(" --------- --- \t --------\n"); + } + printf("%16s %8d\t", + tep_data_comm_from_pid(tep, task->pid), + task->pid); + print_time(cpu_tasks[i]->runtime, '_'); + printf(" (%%%lld)\n", (task->runtime * 100) / total_time); + } + free(cpu_tasks); +} + static void print_total(struct tep_handle *tep, struct analysis_data *data) { unsigned long long total_time; @@ -376,6 +452,12 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) free(tasks); printf("\n"); + + for (i = 0; i < data->allocated_cpus; i++) { + if (!data->cpu_data[i].data) + continue; + print_cpu_data(tep, &data->cpu_data[i]); + } } static void free_tasks(struct trace_hash *hash) From patchwork Thu Mar 24 02:57:18 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 554928 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 9E878C433F5 for ; Thu, 24 Mar 2022 02:57:40 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347929AbiCXC7K (ORCPT ); Wed, 23 Mar 2022 22:59:10 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43560 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347907AbiCXC7C (ORCPT ); Wed, 23 Mar 2022 22:59:02 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 58801939ED; Wed, 23 Mar 2022 19:57:31 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id E50EAB8222D; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 04B47C340F6; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FL8-1x; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 04/12] trace-cmd analyze: Use sched_switch to find comm mappings Date: Wed, 23 Mar 2022 22:57:18 -0400 Message-Id: <20220324025726.1727204-5-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" As the saved_cmdlines may miss a lot of comms, especially if the tracing went for a while, to know what the comms mapping of PIDs are, use the sched_switch event if it is present. If so, then update the task with the comm and print that. This way we get more real names instead of just "<...>". Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 62 ++++++++++++++++++++++++++++++++++++++-- 1 file changed, 60 insertions(+), 2 deletions(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 43e9ffa95687..dec705ce8e15 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -29,6 +29,10 @@ struct cpu_data { struct analysis_data { unsigned long long start_ts; unsigned long long last_ts; + struct tep_event *switch_event; + struct tep_format_field *prev_comm; + struct tep_format_field *next_comm; + struct tep_format_field *next_pid; struct cpu_data *cpu_data; struct trace_hash tasks; int nr_tasks; @@ -39,6 +43,7 @@ struct analysis_data { struct task_item { unsigned long long runtime; unsigned long long start_ts; + char *comm; struct trace_hash_item hash; int pid; }; @@ -253,11 +258,51 @@ static void update_first_pid(struct cpu_data *cpu_data) cpu_data->start_ts = start_ts; } +static void process_switch(struct analysis_data *data, + struct tep_handle *tep, int pid, + struct tep_record *record) +{ + struct cpu_data *cpu_data = &data->cpu_data[record->cpu]; + struct task_cpu_item *cpu_task; + struct task_item *task; + const char *comm; + + cpu_task = get_cpu_task(cpu_data, pid); + task = cpu_task->task; + + /* Fill in missing comms */ + if (pid && data->prev_comm && !task->comm) { + comm = (char *)(record->data + data->prev_comm->offset); + task->comm = strdup(comm); + } + + if (data->next_pid) { + unsigned long long val; + + tep_read_number_field(data->next_pid, record->data, &val); + pid = val; + cpu_task = get_cpu_task(cpu_data, pid); + task = cpu_task->task; + + /* Fill in missing comms */ + if (pid && data->next_comm && !task->comm) { + comm = (char *)(record->data + data->next_comm->offset); + task->comm = strdup(comm); + } + } +} + +static bool match_type(int type, struct tep_event *event) +{ + return event && type == event->id; +} + static void process_cpu(struct analysis_data *data, struct tep_handle *tep, struct tep_record *record) { struct cpu_data *cpu_data; + int type; int pid; pid = tep_data_pid(tep, record); @@ -266,6 +311,10 @@ static void process_cpu(struct analysis_data *data, cpu_data = get_cpu_data(data, record); update_cpu_times(cpu_data, tep, pid, record); + + type = tep_data_type(tep, record); + if (match_type(type, data->switch_event)) + process_switch(data, tep, pid, record); } static int cmp_tasks(const void *A, const void *B) @@ -374,7 +423,7 @@ static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) printf(" --------- --- \t --------\n"); } printf("%16s %8d\t", - tep_data_comm_from_pid(tep, task->pid), + task->comm ? : tep_data_comm_from_pid(tep, task->pid), task->pid); print_time(cpu_tasks[i]->runtime, '_'); printf(" (%%%lld)\n", (task->runtime * 100) / total_time); @@ -444,7 +493,7 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) printf(" --------- --- \t --------\n"); } printf("%16s %8d\t", - tep_data_comm_from_pid(tep, tasks[i]->pid), + tasks[i]->comm ? : tep_data_comm_from_pid(tep, tasks[i]->pid), tasks[i]->pid); print_time(tasks[i]->runtime, '_'); printf(" (%%%lld)\n", (tasks[i]->runtime * 100) / total_time); @@ -470,6 +519,7 @@ static void free_tasks(struct trace_hash *hash) trace_hash_while_item(item, bucket) { task = task_from_hash(item); trace_hash_del(item); + free(task->comm); free(task); } } @@ -518,9 +568,17 @@ static void do_trace_analyze(struct tracecmd_input *handle) trace_hash_init(&data.tasks, 128); + data.switch_event = tep_find_event_by_name(tep, "sched", "sched_switch"); + /* Set to a very large number */ data.start_ts = -1ULL; + if (data.switch_event) { + data.next_pid = tep_find_field(data.switch_event, "next_pid"); + data.next_comm = tep_find_field(data.switch_event, "next_comm"); + data.prev_comm = tep_find_field(data.switch_event, "prev_comm"); + } + do { record = tracecmd_read_next_data(handle, NULL); if (record) From patchwork Thu Mar 24 02:57:19 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 553988 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 7ED16C4332F for ; Thu, 24 Mar 2022 02:57:34 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347912AbiCXC7D (ORCPT ); Wed, 23 Mar 2022 22:59:03 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43538 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347900AbiCXC7B (ORCPT ); Wed, 23 Mar 2022 22:59:01 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id A1081939F3; Wed, 23 Mar 2022 19:57:30 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id 3C0B7B82227; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 04C5EC36AE2; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLC-2n; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 05/12] trace-cmd analyze: Use sched_switch event to update times Date: Wed, 23 Mar 2022 22:57:19 -0400 Message-Id: <20220324025726.1727204-6-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" If the sched_switch event is available, use that to figure out how long a task is running on the CPU. It gives better accuracy than just basing it off of events. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index dec705ce8e15..56123f9b4f86 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -270,6 +270,8 @@ static void process_switch(struct analysis_data *data, cpu_task = get_cpu_task(cpu_data, pid); task = cpu_task->task; + update_cpu_task_times(cpu_data, cpu_task, record->ts); + /* Fill in missing comms */ if (pid && data->prev_comm && !task->comm) { comm = (char *)(record->data + data->prev_comm->offset); @@ -283,6 +285,8 @@ static void process_switch(struct analysis_data *data, pid = val; cpu_task = get_cpu_task(cpu_data, pid); task = cpu_task->task; + task->start_ts = record->ts; + cpu_data->current_pid = pid; /* Fill in missing comms */ if (pid && data->next_comm && !task->comm) { From patchwork Thu Mar 24 02:57:20 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 553985 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 0F53BC4332F for ; Thu, 24 Mar 2022 02:57:40 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347931AbiCXC7J (ORCPT ); Wed, 23 Mar 2022 22:59:09 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43554 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347905AbiCXC7C (ORCPT ); Wed, 23 Mar 2022 22:59:02 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 57ABD939E7; Wed, 23 Mar 2022 19:57:31 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id EBDCBB8222E; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 043D1C340F4; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLG-3b; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 06/12] trace-cmd analyze: Add tracing of tasks and their states Date: Wed, 23 Mar 2022 22:57:20 -0400 Message-Id: <20220324025726.1727204-7-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" If sched_switch is found and has the prev_state field, then record them and keep track of the time the task was in the state, the number of times it was scheduled out of the state, and print the total time, average time, and number of times the task was scheduled out of that state. Also show the time stamp of where the longest time it went into that state. Currently the only states that are supported are "preempted" (which was in state running), "blocked" (state uninterruptible), "sleeping" (state interruptible), and "other" (all other states). Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 143 +++++++++++++++++++++++++++++++++++++-- 1 file changed, 139 insertions(+), 4 deletions(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 56123f9b4f86..ee4f71a7da26 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -31,6 +31,7 @@ struct analysis_data { unsigned long long last_ts; struct tep_event *switch_event; struct tep_format_field *prev_comm; + struct tep_format_field *prev_state; struct tep_format_field *next_comm; struct tep_format_field *next_pid; struct cpu_data *cpu_data; @@ -40,12 +41,25 @@ struct analysis_data { int cpus; }; +struct sched_timings { + unsigned long long last; + unsigned long long total; + unsigned long long nr; + unsigned long long longest; + unsigned long long longest_ts; +}; + struct task_item { unsigned long long runtime; unsigned long long start_ts; + struct sched_timings preempt; + struct sched_timings sleep; + struct sched_timings blocked; + struct sched_timings other; char *comm; struct trace_hash_item hash; int pid; + int last_state; }; struct task_cpu_item { @@ -132,6 +146,7 @@ static struct task_item *get_task(struct cpu_data *cpu_data, int pid) hash->key = find_pid; cpu_data->data->nr_tasks++; trace_hash_add(&cpu_data->data->tasks, hash); + task->last_state = -1; } return task_from_hash(hash); @@ -157,6 +172,19 @@ static struct task_cpu_item *get_cpu_task(struct cpu_data *cpu_data, int pid) return task_cpu_from_hash(hash); }; +static void update_sched_timings (struct sched_timings *time, unsigned long long ts) +{ + unsigned long long delta; + + delta = ts - time->last; + time->total += delta; + if (delta > time->longest) { + time->longest = delta; + time->longest_ts = time->last; + } + time->nr++; +} + /* Update times for a task scheduling off the CPU */ static void update_cpu_task_times(struct cpu_data *cpu_data, struct task_cpu_item *cpu_task, @@ -265,6 +293,7 @@ static void process_switch(struct analysis_data *data, struct cpu_data *cpu_data = &data->cpu_data[record->cpu]; struct task_cpu_item *cpu_task; struct task_item *task; + unsigned long long val; const char *comm; cpu_task = get_cpu_task(cpu_data, pid); @@ -273,9 +302,29 @@ static void process_switch(struct analysis_data *data, update_cpu_task_times(cpu_data, cpu_task, record->ts); /* Fill in missing comms */ - if (pid && data->prev_comm && !task->comm) { - comm = (char *)(record->data + data->prev_comm->offset); - task->comm = strdup(comm); + if (pid) { + if (data->prev_state) { + tep_read_number_field(data->prev_state, record->data, &val); + switch (val & 0x1f) { + case 0: + task->preempt.last = record->ts; + break; + case 0x1: + task->sleep.last = record->ts; + break; + case 0x2: + task->blocked.last = record->ts; + break; + default: + task->other.last = record->ts; + } + task->last_state = val & 0x1f; + } + + if (data->prev_comm && !task->comm) { + comm = (char *)(record->data + data->prev_comm->offset); + task->comm = strdup(comm); + } } if (data->next_pid) { @@ -288,6 +337,24 @@ static void process_switch(struct analysis_data *data, task->start_ts = record->ts; cpu_data->current_pid = pid; + switch (task->last_state) { + case -1: + /* First time seen */ + break; + case 0: + update_sched_timings(&task->preempt, record->ts); + break; + case 0x1: + update_sched_timings(&task->sleep, record->ts); + break; + case 0x2: + update_sched_timings(&task->blocked, record->ts); + break; + default: + update_sched_timings(&task->other, record->ts); + } + task->last_state = val & 0x1f; + /* Fill in missing comms */ if (pid && data->next_comm && !task->comm) { comm = (char *)(record->data + data->next_comm->offset); @@ -343,6 +410,17 @@ static int cmp_cpu_tasks(const void *A, const void *B) return (*a)->runtime < (*b)->runtime; } +static int cmp_task_pids(const void *A, const void *B) +{ + struct task_item * const *a = A; + struct task_item * const *b = B; + + if ((*a)->pid < (*b)->pid) + return -1; + + return (*a)->pid > (*b)->pid; +} + static void print_time(unsigned long long ts, char delim) { unsigned long long secs; @@ -374,6 +452,34 @@ static void print_time(unsigned long long ts, char delim) } } +static void print_sched_timings(const char *label, struct sched_timings *time) +{ + unsigned long long avg; + int n; + + if (!time->nr) + return; + + printf("%s:\t", label); + print_time(time->total, 0); + n = printf(" (%llu)", time->nr); + if (n < 8) + printf("%*.s", 8 - n, ""); + avg = time->total / time->nr; + print_time(avg, 0); + if (time_in_nsecs) + printf(" "); + else + printf(" "); + print_time(time->longest, 0); + if (time_in_nsecs) + printf(" "); + else + printf(" "); + print_time(time->longest_ts, 0); + printf("\n"); +} + static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) { unsigned long long total_time; @@ -435,6 +541,27 @@ static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) free(cpu_tasks); } +static void print_task(struct tep_handle *tep, struct task_item *task) +{ + const char *a = ""; + + if (time_in_nsecs) + a = " "; + + printf("\nTask: %d : %s:\n", + task->pid , task->comm ? : tep_data_comm_from_pid(tep, task->pid)); + printf("Runtime: "); + print_time(task->runtime, '_'); + printf("\nType Total %s(cnt) Avg Longest Where\n", + a); + printf("---- ----- %s----- --- ------- -----\n", + a); + print_sched_timings("Preempted", &task->preempt); + print_sched_timings("Blocked", &task->blocked); + print_sched_timings("Sleeping", &task->sleep); + print_sched_timings("Other", &task->other); +} + static void print_total(struct tep_handle *tep, struct analysis_data *data) { unsigned long long total_time; @@ -502,7 +629,6 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) print_time(tasks[i]->runtime, '_'); printf(" (%%%lld)\n", (tasks[i]->runtime * 100) / total_time); } - free(tasks); printf("\n"); @@ -511,6 +637,14 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) continue; print_cpu_data(tep, &data->cpu_data[i]); } + + qsort(tasks, nr_tasks, sizeof(*tasks), cmp_task_pids); + + printf("\n"); + for (i = 0; i < nr_tasks; i++) { + print_task(tep, tasks[i]); + } + free(tasks); } static void free_tasks(struct trace_hash *hash) @@ -581,6 +715,7 @@ static void do_trace_analyze(struct tracecmd_input *handle) data.next_pid = tep_find_field(data.switch_event, "next_pid"); data.next_comm = tep_find_field(data.switch_event, "next_comm"); data.prev_comm = tep_find_field(data.switch_event, "prev_comm"); + data.prev_state = tep_find_field(data.switch_event, "prev_state"); } do { From patchwork Thu Mar 24 02:57:21 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 554931 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 03956C4167D for ; Thu, 24 Mar 2022 02:57:34 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347906AbiCXC7C (ORCPT ); Wed, 23 Mar 2022 22:59:02 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43512 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347892AbiCXC7A (ORCPT ); Wed, 23 Mar 2022 22:59:00 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id A933A939F0; Wed, 23 Mar 2022 19:57:29 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 24B8E619B2; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 0F646C340F7; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLK-4T; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 07/12] trace-cmd analyze: Add "idleness" Date: Wed, 23 Mar 2022 22:57:21 -0400 Message-Id: <20220324025726.1727204-8-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" Report the "idleness" of a CPU. How long it was idle, the longest time it was idle, the average time it is idle, the number of times it was idle, and where the longest time it was idle. Note, anytime there is an event, the CPU is considered "not idle", that is, it was woken up. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 87 +++++++++++++++++++++++++++++++++++----- 1 file changed, 77 insertions(+), 10 deletions(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index ee4f71a7da26..de776b76c343 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -14,16 +14,19 @@ static bool time_in_nsecs; struct analysis_data; +struct task_item; struct cpu_data { unsigned long long start_ts; unsigned long long last_ts; + struct task_item *idle_task; struct analysis_data *data; struct trace_hash tasks; int nr_tasks; int cpu; int current_pid; int first_pid; + bool last_idle; }; struct analysis_data { @@ -185,6 +188,31 @@ static void update_sched_timings (struct sched_timings *time, unsigned long long time->nr++; } +static void update_idle_task(struct cpu_data *cpu_data, struct task_item *task, + unsigned long long ts) +{ + if (!cpu_data->idle_task) { + if (task && task->pid <= 0) { + cpu_data->idle_task = task; + task->other.last = ts; + cpu_data->last_idle = true; + } + return; + } + if (!task || task->pid > 0) { + if (cpu_data->last_idle) + update_sched_timings(&cpu_data->idle_task->other, ts); + + cpu_data->last_idle = false; + return; + } + if (cpu_data->last_idle) + update_sched_timings(&task->other, ts); + + cpu_data->last_idle = true; + task->other.last = ts; +} + /* Update times for a task scheduling off the CPU */ static void update_cpu_task_times(struct cpu_data *cpu_data, struct task_cpu_item *cpu_task, @@ -203,6 +231,8 @@ static void update_cpu_task_times(struct cpu_data *cpu_data, if (ts < task->start_ts) return; + update_idle_task(cpu_data, task, ts); + delta = ts - task->start_ts; task->runtime += delta; cpu_task->runtime += delta; @@ -227,6 +257,8 @@ static void update_pid(struct cpu_data *cpu_data, cpu_task = get_cpu_task(cpu_data, pid); task = cpu_task->task; + update_idle_task(cpu_data, task, record->ts); + if (record->ts < cpu_data->last_ts) { tracecmd_warning("task %d start time %llu greater than CPU time %llu", pid, record->ts, cpu_data->last_ts); @@ -258,6 +290,7 @@ static void update_cpu_times(struct cpu_data *cpu_data, cpu_task = get_cpu_task(cpu_data, pid); task = cpu_task->task; task->start_ts = record->ts; + update_idle_task(cpu_data, task, record->ts); if (record->ts < cpu_data->data->start_ts) cpu_data->data->start_ts = record->ts; return; @@ -268,6 +301,8 @@ static void update_cpu_times(struct cpu_data *cpu_data, return; } + update_idle_task(cpu_data, !pid ? cpu_data->idle_task : NULL, record->ts); + cpu_data->last_ts = record->ts; } @@ -283,6 +318,17 @@ static void update_first_pid(struct cpu_data *cpu_data) delta = cpu_data->start_ts - start_ts; task->runtime += delta; cpu_task->runtime += delta; + + /* Handle idle timings if it was the first task */ + if (task->pid <= 0) { + task->other.total += delta; + if (delta > task->other.longest) { + task->other.longest = delta; + task->other.longest_ts = cpu_data->start_ts; + } + task->other.nr++; + } + cpu_data->start_ts = start_ts; } @@ -337,6 +383,8 @@ static void process_switch(struct analysis_data *data, task->start_ts = record->ts; cpu_data->current_pid = pid; + update_idle_task(cpu_data, task, record->ts); + switch (task->last_state) { case -1: /* First time seen */ @@ -452,6 +500,27 @@ static void print_time(unsigned long long ts, char delim) } } +static void print_timings_title(const char *label) +{ + const char *a = ""; + int len; + int i; + + if (time_in_nsecs) + a = " "; + + len = snprintf(NULL, 0, "%s", label); + + printf("%s%*sTotal %s(cnt) Avg Longest Where\n", + label, 21 - len, "", a); + + for (i = 0; i < len; i++) + printf("-"); + + printf("%*s----- %s----- --- ------- -----\n", + 21 - len, "", a); +} + static void print_sched_timings(const char *label, struct sched_timings *time) { unsigned long long avg; @@ -460,7 +529,10 @@ static void print_sched_timings(const char *label, struct sched_timings *time) if (!time->nr) return; - printf("%s:\t", label); + if (label) + printf("%s:%*s", label, 15 - (int)strlen(label), ""); + else + printf("\t\t"); print_time(time->total, 0); n = printf(" (%llu)", time->nr); if (n < 8) @@ -519,6 +591,8 @@ static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) printf("idle:\t"); print_time(idle_task->runtime, '_'); printf(" (%%%lld)\n", (idle_task->runtime * 100) / total_time); + print_timings_title("Idleness"); + print_sched_timings(NULL, &idle_task->other); } else { printf("Never idle!\n"); } @@ -543,19 +617,12 @@ static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) static void print_task(struct tep_handle *tep, struct task_item *task) { - const char *a = ""; - - if (time_in_nsecs) - a = " "; - printf("\nTask: %d : %s:\n", task->pid , task->comm ? : tep_data_comm_from_pid(tep, task->pid)); printf("Runtime: "); print_time(task->runtime, '_'); - printf("\nType Total %s(cnt) Avg Longest Where\n", - a); - printf("---- ----- %s----- --- ------- -----\n", - a); + printf("\n"); + print_timings_title("Type"); print_sched_timings("Preempted", &task->preempt); print_sched_timings("Blocked", &task->blocked); print_sched_timings("Sleeping", &task->sleep); From patchwork Thu Mar 24 02:57:22 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 554929 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 867FBC43217 for ; Thu, 24 Mar 2022 02:57:39 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347932AbiCXC7I (ORCPT ); Wed, 23 Mar 2022 22:59:08 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43552 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347903AbiCXC7B (ORCPT ); Wed, 23 Mar 2022 22:59:01 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 3F57B939E9; Wed, 23 Mar 2022 19:57:31 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id E2563B8222C; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 12C2EC340F5; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLO-5C; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 08/12] trace-cmd analyze: Track migration Date: Wed, 23 Mar 2022 22:57:22 -0400 Message-Id: <20220324025726.1727204-9-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" Keep track of which CPU event task is at for every event, and if the CPU changes, then mark it as a migration. Print out the number of times the task migrated if it had migrated. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index de776b76c343..4db93367727b 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -55,6 +55,7 @@ struct sched_timings { struct task_item { unsigned long long runtime; unsigned long long start_ts; + unsigned long long migrated; struct sched_timings preempt; struct sched_timings sleep; struct sched_timings blocked; @@ -62,6 +63,7 @@ struct task_item { char *comm; struct trace_hash_item hash; int pid; + int last_cpu; int last_state; }; @@ -149,6 +151,7 @@ static struct task_item *get_task(struct cpu_data *cpu_data, int pid) hash->key = find_pid; cpu_data->data->nr_tasks++; trace_hash_add(&cpu_data->data->tasks, hash); + task->last_cpu = cpu_data->cpu; task->last_state = -1; } @@ -256,6 +259,10 @@ static void update_pid(struct cpu_data *cpu_data, cpu_task = get_cpu_task(cpu_data, pid); task = cpu_task->task; + if (task->last_cpu != cpu_data->cpu) { + task->last_cpu = cpu_data->cpu; + task->migrated++; + } update_idle_task(cpu_data, task, record->ts); @@ -383,6 +390,11 @@ static void process_switch(struct analysis_data *data, task->start_ts = record->ts; cpu_data->current_pid = pid; + if (task->last_cpu != cpu_data->cpu) { + task->last_cpu = cpu_data->cpu; + task->migrated++; + } + update_idle_task(cpu_data, task, record->ts); switch (task->last_state) { @@ -619,9 +631,11 @@ static void print_task(struct tep_handle *tep, struct task_item *task) { printf("\nTask: %d : %s:\n", task->pid , task->comm ? : tep_data_comm_from_pid(tep, task->pid)); - printf("Runtime: "); + printf("Runtime: "); print_time(task->runtime, '_'); printf("\n"); + if (task->migrated) + printf("Migrated:\t%llu\n", task->migrated); print_timings_title("Type"); print_sched_timings("Preempted", &task->preempt); print_sched_timings("Blocked", &task->blocked); From patchwork Thu Mar 24 02:57:23 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 553984 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id C43C6C433EF for ; Thu, 24 Mar 2022 02:57:41 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347907AbiCXC7K (ORCPT ); Wed, 23 Mar 2022 22:59:10 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43584 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347914AbiCXC7D (ORCPT ); Wed, 23 Mar 2022 22:59:03 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 6F276939F2; Wed, 23 Mar 2022 19:57:32 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id D8A37B8222A; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 2E60CC340F8; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLS-5v; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 09/12] trace-cmd analyze: Add wake up latency timings Date: Wed, 23 Mar 2022 22:57:23 -0400 Message-Id: <20220324025726.1727204-10-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" If the sched_waking (or sched_wakeup) event is found, then use it to time the wake up latency for each task. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 39 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 39 insertions(+) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 4db93367727b..7cf63923b962 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -33,10 +33,12 @@ struct analysis_data { unsigned long long start_ts; unsigned long long last_ts; struct tep_event *switch_event; + struct tep_event *wakeup_event; struct tep_format_field *prev_comm; struct tep_format_field *prev_state; struct tep_format_field *next_comm; struct tep_format_field *next_pid; + struct tep_format_field *wakeup_pid; struct cpu_data *cpu_data; struct trace_hash tasks; int nr_tasks; @@ -60,11 +62,13 @@ struct task_item { struct sched_timings sleep; struct sched_timings blocked; struct sched_timings other; + struct sched_timings wakeup; char *comm; struct trace_hash_item hash; int pid; int last_cpu; int last_state; + bool woken; }; struct task_cpu_item { @@ -420,9 +424,31 @@ static void process_switch(struct analysis_data *data, comm = (char *)(record->data + data->next_comm->offset); task->comm = strdup(comm); } + + if (task->woken) + update_sched_timings(&task->wakeup, record->ts); + task->woken = false; } } +static void process_wakeup(struct analysis_data *data, + struct tep_handle *tep, + struct tep_record *record) +{ + struct cpu_data *cpu_data = &data->cpu_data[record->cpu]; + struct task_cpu_item *cpu_task; + struct task_item *task; + unsigned long long val; + int pid; + + tep_read_number_field(data->wakeup_pid, record->data, &val); + pid = val; + cpu_task = get_cpu_task(cpu_data, pid); + task = cpu_task->task; + task->wakeup.last = record->ts; + task->woken = true; +} + static bool match_type(int type, struct tep_event *event) { return event && type == event->id; @@ -446,6 +472,9 @@ static void process_cpu(struct analysis_data *data, type = tep_data_type(tep, record); if (match_type(type, data->switch_event)) process_switch(data, tep, pid, record); + + else if (match_type(type, data->wakeup_event)) + process_wakeup(data, tep, record); } static int cmp_tasks(const void *A, const void *B) @@ -637,6 +666,7 @@ static void print_task(struct tep_handle *tep, struct task_item *task) if (task->migrated) printf("Migrated:\t%llu\n", task->migrated); print_timings_title("Type"); + print_sched_timings("Wakeup", &task->wakeup); print_sched_timings("Preempted", &task->preempt); print_sched_timings("Blocked", &task->blocked); print_sched_timings("Sleeping", &task->sleep); @@ -788,6 +818,9 @@ static void do_trace_analyze(struct tracecmd_input *handle) trace_hash_init(&data.tasks, 128); data.switch_event = tep_find_event_by_name(tep, "sched", "sched_switch"); + data.wakeup_event = tep_find_event_by_name(tep, "sched", "sched_waking"); + if (!data.wakeup_event) + data.wakeup_event = tep_find_event_by_name(tep, "sched", "sched_wakeup"); /* Set to a very large number */ data.start_ts = -1ULL; @@ -799,6 +832,12 @@ static void do_trace_analyze(struct tracecmd_input *handle) data.prev_state = tep_find_field(data.switch_event, "prev_state"); } + if (data.wakeup_event) { + data.wakeup_pid = tep_find_field(data.wakeup_event, "pid"); + if (!data.wakeup_pid) + data.wakeup_event = NULL; + } + do { record = tracecmd_read_next_data(handle, NULL); if (record) From patchwork Thu Mar 24 02:57:24 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 554930 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 42D8FC4332F for ; Thu, 24 Mar 2022 02:57:37 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347911AbiCXC7F (ORCPT ); Wed, 23 Mar 2022 22:59:05 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43532 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347898AbiCXC7B (ORCPT ); Wed, 23 Mar 2022 22:59:01 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [IPv6:2604:1380:4641:c500::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5C5EA939F2; Wed, 23 Mar 2022 19:57:30 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 2C2FF619B6; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 2DD6BC340F9; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLW-6m; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 10/12] trace-cmd analyze: Add counting of page faults Date: Wed, 23 Mar 2022 22:57:24 -0400 Message-Id: <20220324025726.1727204-11-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" If the page_fault_user event is found, then add counting of page faults for each task and display them. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 23 ++++++++++++++++++++++- 1 file changed, 22 insertions(+), 1 deletion(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 7cf63923b962..2603c360c404 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -34,6 +34,7 @@ struct analysis_data { unsigned long long last_ts; struct tep_event *switch_event; struct tep_event *wakeup_event; + struct tep_event *page_fault_event; struct tep_format_field *prev_comm; struct tep_format_field *prev_state; struct tep_format_field *next_comm; @@ -58,6 +59,7 @@ struct task_item { unsigned long long runtime; unsigned long long start_ts; unsigned long long migrated; + unsigned long long faulted; struct sched_timings preempt; struct sched_timings sleep; struct sched_timings blocked; @@ -449,6 +451,19 @@ static void process_wakeup(struct analysis_data *data, task->woken = true; } +static void process_page_fault(struct analysis_data *data, + struct tep_handle *tep, int pid, + struct tep_record *record) +{ + struct cpu_data *cpu_data = &data->cpu_data[record->cpu]; + struct task_cpu_item *cpu_task; + struct task_item *task; + + cpu_task = get_cpu_task(cpu_data, pid); + task = cpu_task->task; + task->faulted++; +} + static bool match_type(int type, struct tep_event *event) { return event && type == event->id; @@ -475,6 +490,9 @@ static void process_cpu(struct analysis_data *data, else if (match_type(type, data->wakeup_event)) process_wakeup(data, tep, record); + + else if (match_type(type, data->page_fault_event)) + process_page_fault(data, tep, pid, record); } static int cmp_tasks(const void *A, const void *B) @@ -664,7 +682,9 @@ static void print_task(struct tep_handle *tep, struct task_item *task) print_time(task->runtime, '_'); printf("\n"); if (task->migrated) - printf("Migrated:\t%llu\n", task->migrated); + printf("Migrated: %8llu\n", task->migrated); + if (task->faulted) + printf("Faulted: %8llu\n", task->faulted); print_timings_title("Type"); print_sched_timings("Wakeup", &task->wakeup); print_sched_timings("Preempted", &task->preempt); @@ -821,6 +841,7 @@ static void do_trace_analyze(struct tracecmd_input *handle) data.wakeup_event = tep_find_event_by_name(tep, "sched", "sched_waking"); if (!data.wakeup_event) data.wakeup_event = tep_find_event_by_name(tep, "sched", "sched_wakeup"); + data.page_fault_event = tep_find_event_by_name(tep, "exceptions", "page_fault_user"); /* Set to a very large number */ data.start_ts = -1ULL; From patchwork Thu Mar 24 02:57:25 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 553987 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id C1A39C41535 for ; Thu, 24 Mar 2022 02:57:35 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347918AbiCXC7E (ORCPT ); Wed, 23 Mar 2022 22:59:04 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43530 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347899AbiCXC7B (ORCPT ); Wed, 23 Mar 2022 22:59:01 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [IPv6:2604:1380:4641:c500::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 1375D939E7; Wed, 23 Mar 2022 19:57:30 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 3E12A619BA; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 2FFACC340FB; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLa-7c; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 11/12] trace-cmd analyze: Account for dropped events Date: Wed, 23 Mar 2022 22:57:25 -0400 Message-Id: <20220324025726.1727204-12-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" If the trace.dat file contains dropped events due to the reader not being able to keep up with the writer, account for it. Update the CPUs where there are dropped events and tag the tasks that are on those CPUs. Add to the output the fact that events were dropped. Signed-off-by: Steven Rostedt (Google) --- tracecmd/trace-analyze.c | 87 ++++++++++++++++++++++++++++++++++++++-- 1 file changed, 84 insertions(+), 3 deletions(-) diff --git a/tracecmd/trace-analyze.c b/tracecmd/trace-analyze.c index 2603c360c404..2f1b2720810e 100644 --- a/tracecmd/trace-analyze.c +++ b/tracecmd/trace-analyze.c @@ -19,6 +19,8 @@ struct task_item; struct cpu_data { unsigned long long start_ts; unsigned long long last_ts; + unsigned long long missed_events; + unsigned long long unknown_missed_events; struct task_item *idle_task; struct analysis_data *data; struct trace_hash tasks; @@ -27,6 +29,7 @@ struct cpu_data { int current_pid; int first_pid; bool last_idle; + bool keep_start; }; struct analysis_data { @@ -45,6 +48,7 @@ struct analysis_data { int nr_tasks; int allocated_cpus; int cpus; + bool missed_events; }; struct sched_timings { @@ -71,6 +75,7 @@ struct task_item { int last_cpu; int last_state; bool woken; + bool dropped_events; }; struct task_cpu_item { @@ -306,6 +311,9 @@ static void update_cpu_times(struct cpu_data *cpu_data, update_idle_task(cpu_data, task, record->ts); if (record->ts < cpu_data->data->start_ts) cpu_data->data->start_ts = record->ts; + /* If we lost events before here, keep the current start time */ + if (record->missed_events) + cpu_data->keep_start = true; return; } @@ -326,6 +334,10 @@ static void update_first_pid(struct cpu_data *cpu_data) unsigned long long start_ts = cpu_data->data->start_ts; unsigned long long delta; + /* If the CPU started with dropped events, do not update */ + if (cpu_data->keep_start) + return; + cpu_task = get_cpu_task(cpu_data, cpu_data->first_pid); task = cpu_task->task; delta = cpu_data->start_ts - start_ts; @@ -464,6 +476,50 @@ static void process_page_fault(struct analysis_data *data, task->faulted++; } +static void handle_missed_events(struct analysis_data *data, + struct tep_record *record) +{ + struct trace_hash_item **bucket; + struct trace_hash_item *item; + struct task_cpu_item *cpu_task; + struct cpu_data *cpu_data; + struct task_item *task; + long long missed_events = record->missed_events; + int cpu; + + /* If this is the first event for the CPU do nothing here */ + if (record->cpu >= data->allocated_cpus || + !data->cpu_data[record->cpu].data) + return; + + data->missed_events = true; + + cpu_data = &data->cpu_data[record->cpu]; + cpu = cpu_data->cpu; + + if (missed_events > 0) + cpu_data->missed_events += missed_events; + else + cpu_data->unknown_missed_events++; + + /* Need to reset all timings */ + trace_hash_for_each_bucket(bucket, &cpu_data->tasks) { + trace_hash_for_each_item(item, bucket) { + cpu_task = task_cpu_from_hash(item); + task = cpu_task->task; + if (task->last_cpu != cpu) + continue; + task->preempt.last = record->ts; + task->sleep.last = record->ts; + task->blocked.last = record->ts; + task->other.last = record->ts; + task->woken = false; + task->last_state = -1; + task->dropped_events = true; + } + } +} + static bool match_type(int type, struct tep_event *event) { return event && type == event->id; @@ -477,6 +533,9 @@ static void process_cpu(struct analysis_data *data, int type; int pid; + if (record->missed_events) + handle_missed_events(data, record); + pid = tep_data_pid(tep, record); if (pid < 0) /* Warn? */ return; @@ -624,12 +683,29 @@ static void print_cpu_data(struct tep_handle *tep, struct cpu_data *cpu_data) int nr_tasks; int i = 0; - data = cpu_data->data; - total_time = data->last_ts - data->start_ts; - printf("\nCPU %d\n", cpu_data->cpu); printf("-------\n"); + if (cpu_data->missed_events || cpu_data->unknown_missed_events) { + printf("Missed: %llu events", cpu_data->missed_events); + if (cpu_data->unknown_missed_events) + printf(" + %llu drops of unknown events", + cpu_data->unknown_missed_events); + printf("\n"); + } + + data = cpu_data->data; + + if (cpu_data->keep_start) { + total_time = data->last_ts - cpu_data->start_ts; + printf("[ Events dropped before start of this CPU ]\n"); + printf("Total time: "); + print_time(total_time, '_'); + printf("\n"); + } else { + total_time = data->last_ts - data->start_ts; + } + cpu_tasks = malloc(sizeof(*cpu_tasks) * cpu_data->nr_tasks); if (!cpu_tasks) @@ -678,6 +754,8 @@ static void print_task(struct tep_handle *tep, struct task_item *task) { printf("\nTask: %d : %s:\n", task->pid , task->comm ? : tep_data_comm_from_pid(tep, task->pid)); + if (task->dropped_events) + printf("[ Events dropped for this task's CPU, may be missing data ]\n"); printf("Runtime: "); print_time(task->runtime, '_'); printf("\n"); @@ -706,6 +784,9 @@ static void print_total(struct tep_handle *tep, struct analysis_data *data) int cpu; int i = 0; + if (data->missed_events) + printf("\n[ Missed events, some data may be missing ]\n"); + total_time = data->last_ts - data->start_ts; printf("\nTotal time: "); print_time(total_time, '_'); From patchwork Thu Mar 24 02:57:26 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 554927 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 02360C433F5 for ; Thu, 24 Mar 2022 02:57:42 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1347941AbiCXC7L (ORCPT ); Wed, 23 Mar 2022 22:59:11 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43582 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1347913AbiCXC7D (ORCPT ); Wed, 23 Mar 2022 22:59:03 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [IPv6:2604:1380:4601:e00::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 3A089939E9; Wed, 23 Mar 2022 19:57:31 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id DF083B82229; Thu, 24 Mar 2022 02:57:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 384B6C340FA; Thu, 24 Mar 2022 02:57:28 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.95) (envelope-from ) id 1nXDfD-007FLe-8M; Wed, 23 Mar 2022 22:57:27 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: williskung@google.com, kaleshsingh@google.com, linux-rt-users@vger.kernel.org, "Steven Rostedt (Google)" Subject: [PATCH 12/12] trace-cmd analyze: Add documentation Date: Wed, 23 Mar 2022 22:57:26 -0400 Message-Id: <20220324025726.1727204-13-rostedt@goodmis.org> X-Mailer: git-send-email 2.35.1 In-Reply-To: <20220324025726.1727204-1-rostedt@goodmis.org> References: <20220324025726.1727204-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-rt-users@vger.kernel.org From: "Steven Rostedt (Google)" Add the help messages and the man page for trace-cmd analyze. Signed-off-by: Steven Rostedt (Google) --- .../trace-cmd/trace-cmd-analyze.1.txt | 290 ++++++++++++++++++ tracecmd/trace-usage.c | 7 + 2 files changed, 297 insertions(+) create mode 100644 Documentation/trace-cmd/trace-cmd-analyze.1.txt diff --git a/Documentation/trace-cmd/trace-cmd-analyze.1.txt b/Documentation/trace-cmd/trace-cmd-analyze.1.txt new file mode 100644 index 000000000000..17c0f7029215 --- /dev/null +++ b/Documentation/trace-cmd/trace-cmd-analyze.1.txt @@ -0,0 +1,290 @@ +TRACE-CMD-ANALYZE(1) +==================== + +NAME +---- +trace-cmd-analyze - Report useful information from data in a trace.dat file + +SYNOPSIS +-------- +*trace-cmd analyze ['OPTIONS']* [input-file] + +DESCRIPTION +----------- +The trace-cmd(1) analyze will read a trace.dat file created by *trace-cmd-record*(1) +and report statistical information out of it. Such as, how much the CPUs were +idle, what tasks ran most on each CPU, the timings of tasks such as wake up to +scheduling, how long they were preempted, blocked, sleeping. + +The timings are reported in microseconds (assuming the trace.dat file was recorded +using a nanosecond clock), unless the *-t* option is used. + +OPTIONS +------- +*-i* 'file':: + Input file to read from. Otherwise it uses the first file passed in to it. + +*-t*:: + Show timings in nanoseconds instead of microseconds. + +EXAMPLES +-------- + +..... +# trace-cmd record -e sched_switch -e sched_waking -e page_fault_user -e timer -e irq -e irq_vectors sleep 1 +# trace-cmd analyze +version = 6 + +Total time: 1.015_180 + + Idle CPU Run time + -------- -------- +CPU 0 idle: 1.011_667 (%99) +CPU 1 idle: 1.015_180 (%100) + + Task name PID Run time + --------- --- -------- + trace-cmd 1116 0.002_285 (%0) + trace-cmd 1115 0.000_395 (%0) + trace-cmd 1114 0.000_382 (%0) + NetworkManager 580 0.000_181 (%0) + rtkit-daemon 618 0.000_088 (%0) + rcu_sched 12 0.000_045 (%0) + runaway-killer- 635 0.000_043 (%0) + kworker/u4:1 56 0.000_025 (%0) + rtkit-daemon 619 0.000_020 (%0) + kcompactd0 29 0.000_020 (%0) + kworker/0:4 408 0.000_015 (%0) + migration/0 13 0.000_009 (%0) + trace-cmd 1113 0.000_000 (%0) + + +CPU 0 +------- +idle: 1.011_667 (%99) +Idleness Total (cnt) Avg Longest Where +-------- ----- ----- --- ------- ----- + 1.011667 (6252) 0.000161 0.001021 184.420132 + Task name PID Run time + --------- --- -------- + trace-cmd 1116 0.002_285 (%0) + trace-cmd 1115 0.000_395 (%0) + trace-cmd 1114 0.000_382 (%0) + NetworkManager 580 0.000_181 (%0) + rtkit-daemon 618 0.000_088 (%0) + rcu_sched 12 0.000_045 (%0) + runaway-killer- 635 0.000_043 (%0) + kworker/u4:1 56 0.000_025 (%0) + rtkit-daemon 619 0.000_020 (%0) + kcompactd0 29 0.000_020 (%0) + kworker/0:4 408 0.000_015 (%0) + migration/0 13 0.000_009 (%0) + trace-cmd 1113 0.000_000 (%0) + +CPU 1 +------- +idle: 1.015_180 (%100) +Idleness Total (cnt) Avg Longest Where +-------- ----- ----- --- ------- ----- + 1.015180 (62) 0.016373 0.443041 183.979216 + + +Task: 12 : rcu_sched: +Runtime: 0.000_045 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000043 (5) 0.000008 0.000009 183.976142 +Preempted: 0.016962 (4) 0.004240 0.004973 183.984156 + +Task: 13 : migration/0: +Runtime: 0.000_009 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000028 (1) 0.000028 0.000028 184.047119 + +Task: 29 : kcompactd0: +Runtime: 0.000_020 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000022 (2) 0.000011 0.000012 184.542135 +Sleeping: 0.503988 (1) 0.503988 0.503988 184.038158 + +Task: 56 : kworker/u4:1: +Runtime: 0.000_025 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000018 (2) 0.000009 0.000009 184.398136 +Preempted: 0.191983 (1) 0.191983 0.191983 184.206162 + +Task: 408 : kworker/0:4: +Runtime: 0.000_015 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000010 (1) 0.000010 0.000010 184.654135 + +Task: 580 : NetworkManager: +Runtime: 0.000_181 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000024 (1) 0.000024 0.000024 184.886115 + +Task: 618 : rtkit-daemon: +Runtime: 0.000_088 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000025 (1) 0.000025 0.000025 184.565118 +Preempted: 0.000020 (1) 0.000020 0.000020 184.565222 + +Task: 619 : rtkit-daemon: +Runtime: 0.000_020 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000056 (1) 0.000056 0.000056 184.565166 + +Task: 635 : runaway-killer-: +Runtime: 0.000_043 +Faulted: 2 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000025 (1) 0.000025 0.000025 184.891113 + +Task: 1113 : trace-cmd: +Runtime: 0.000_000 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000008 (1) 0.000008 0.000008 184.989274 + +Task: 1114 : trace-cmd: +Runtime: 0.000_382 +Faulted: 37 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- + +Task: 1115 : trace-cmd: +Runtime: 0.000_395 +Faulted: 37 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- + +Task: 1116 : trace-cmd: +Runtime: 0.002_285 +Faulted: 52 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000090 (3) 0.000030 0.000056 184.989032 +Blocked: 0.012737 (2) 0.006368 0.012149 183.974451 +Sleeping: 1.000157 (1) 1.000157 1.000157 183.988932 +..... + +Breaking down the above: +..... +Total time: 1.015_180 +..... + +The total run time in seconds. + +..... + Idle CPU Run time + -------- -------- +CPU 0 idle: 1.011_667 (%99) +CPU 1 idle: 1.015_180 (%100) +..... + +How long each CPU was idle for. + +..... + + Task name PID Run time + --------- --- -------- + trace-cmd 1116 0.002_285 (%0) + trace-cmd 1115 0.000_395 (%0) + trace-cmd 1114 0.000_382 (%0) + NetworkManager 580 0.000_181 (%0) + rtkit-daemon 618 0.000_088 (%0) + rcu_sched 12 0.000_045 (%0) + runaway-killer- 635 0.000_043 (%0) + kworker/u4:1 56 0.000_025 (%0) + rtkit-daemon 619 0.000_020 (%0) + kcompactd0 29 0.000_020 (%0) + kworker/0:4 408 0.000_015 (%0) + migration/0 13 0.000_009 (%0) + trace-cmd 1113 0.000_000 (%0) +..... + +A list of all tasks in the trace and their run times along with the percentage of time they +were running with respect to the total time. + + +..... +CPU 0 +------- +idle: 1.011_667 (%99) +Idleness Total (cnt) Avg Longest Where +-------- ----- ----- --- ------- ----- + 1.011667 (6252) 0.000161 0.001021 184.420132 + Task name PID Run time + --------- --- -------- + trace-cmd 1116 0.002_285 (%0) + trace-cmd 1115 0.000_395 (%0) + trace-cmd 1114 0.000_382 (%0) + NetworkManager 580 0.000_181 (%0) + rtkit-daemon 618 0.000_088 (%0) + rcu_sched 12 0.000_045 (%0) + runaway-killer- 635 0.000_043 (%0) + kworker/u4:1 56 0.000_025 (%0) + rtkit-daemon 619 0.000_020 (%0) + kcompactd0 29 0.000_020 (%0) + kworker/0:4 408 0.000_015 (%0) + migration/0 13 0.000_009 (%0) + trace-cmd 1113 0.000_000 (%0) +..... + +Each CPU is show, again showing its total time (which could be different than the total +time of the system, if events were dropped before the first event on the CPU). + +The "Idleness" is the time between events for the CPU's idle task. This is useful for knowing +if the CPU can make it into deep sleep if interrupts are being traced as well. Note, currently +it does not remove the time of an interrupt entering to when it leaves, but that may change in the +future. + +..... +Task: 1116 : trace-cmd: +Runtime: 0.002_285 +Faulted: 52 +Type Total (cnt) Avg Longest Where +---- ----- ----- --- ------- ----- +Wakeup: 0.000090 (3) 0.000030 0.000056 184.989032 +Blocked: 0.012737 (2) 0.006368 0.012149 183.974451 +Sleeping: 1.000157 (1) 1.000157 1.000157 183.988932 +..... + +Each task is traced. It will show the total run time of the task, the number of times +tha task migrated (not shown if the task never migrated during the trace). The wake up +latency (total time it was in waiting to be woken up), the number of times it was woken up (cnt), +the adverage time it took to wake it up, the longest time it took to wake up, along with the +time stamp in the report of where it woke up with that longest time. + +Then the same timings for how long the task was preempted (scheduled out in the running +state), blocked (scheduled out in an uninterruptible state), sleeping (scheduled out +in an interruptible state), and "other" for all other states the task was in when +scheduling out. + +SEE ALSO +-------- +trace-cmd(1), trace-cmd-record(1), trace-cmd-report(1), trace-cmd-start(1), +trace-cmd-stop(1), trace-cmd-reset(1), trace-cmd-split(1), +trace-cmd-list(1), trace-cmd-listen(1) + +AUTHOR +------ +Written by Steven Rostedt, + +RESOURCES +--------- +https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/ + +COPYING +------- +Copyright \(C) 2022 Google, Inc. Free use of this software is granted under +the terms of the GNU Public License (GPL). + diff --git a/tracecmd/trace-usage.c b/tracecmd/trace-usage.c index 20995fabed73..53d3159f0903 100644 --- a/tracecmd/trace-usage.c +++ b/tracecmd/trace-usage.c @@ -274,6 +274,13 @@ static struct usage_help usage_help[] = { " -H Allows users to hook two events together for timings\n" " --verbose 'level' Set the desired log level\n" }, + { + "analyze", + "Analyze a trace file and extract various information about it", + " %s analyze [-i input][-t]\n" + " -i Specify the input file to read, otherwise read the first non option\n" + " -t Show time stamps in nanoseconds instead of microseconds\n" + }, { "hist", "show a histogram of the trace.dat information",