From patchwork Tue Jun 13 22:08:00 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 107595 Return-Path: Delivered-To: ouuuleilei@gmail.com Received: by 2002:a59:994d:0:b0:3d9:f83d:47d9 with SMTP id k13csp857428vqr; Tue, 13 Jun 2023 15:19:42 -0700 (PDT) X-Google-Smtp-Source: ACHHUZ7m1HxFx94Qd4AYR7aJFZOozrODu8lD7oH9SMTZvbYec+dTIA26CoPmgPnmRsr6jqitYQL6 X-Received: by 2002:a17:907:a0e:b0:974:32e:7de9 with SMTP id bb14-20020a1709070a0e00b00974032e7de9mr14980060ejc.56.1686694781882; Tue, 13 Jun 2023 15:19:41 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1686694781; cv=none; d=google.com; s=arc-20160816; b=po7+6RmGhjD2xG/8VpqGEa248NCjqCnKPXbxITfebYvXQQuynpQpPyqOK0bbrZBs4R ItU9RuJ8GmUWUuPrHcnbLz69eTxB8p6aXwHCCM0MHxwBe0NNug/+JUM6ljrPo8/gutl0 Q/f0NkUu4sxoex+z9qtoo+XJT/wiLF0EBV93MOGCxI+jFECtoalNMcLXqHoIY6JETx6m RKsg61GoIrkM1+5HJWQEWFb2ryqUScHdaedI7V4qsBQH2HYUoWYOiRUnPS5buHY15Do7 xoCV/CAwEFc3L1hXiInZ45XYmNEOk1QAcbXZq7IyDpCqcCC55klMiXu+LIgQY567F0gv MxYg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:mime-version:references:subject:cc:to:from:date :user-agent:message-id; bh=fGEpBWIgddHqF3B8UiiuPhA0ZA6954E5dxmeQ980vAI=; b=jZLwegChBnRlf6u4QnlSV0EnuwTW3x3wyvdmyHCZltmPM94h3jy/BTxwVE+tl6mJnH BCDs9BfmOY+EjsT5ksLIBKaI2IHDiplrlNdHibOmpAvdXtvNkTsxsgm3qak5bJE3Jh6X 8eCL3Srcf+KQDaD9rXCDp3BYPGTfoui1/27ApB2be/SpWcsLF+wOWFqJYLSLVUc8VU90 VZhTvJm+F8sUObivPoFGkgXc+VF+Qywcp4/IYPyo04Kne6FLDqqLsBwLgXZNZQLy80Hf kWe2qdeX4O8n1NLthyhW7dv8ymEZwM1jEcxfZmkV18F9kN9+erIDiiwQ/iheENulnOLy vE8g== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: from out1.vger.email (out1.vger.email. [2620:137:e000::1:20]) by mx.google.com with ESMTP id y25-20020a17090629d900b0094f335b0660si6830300eje.185.2023.06.13.15.19.16; Tue, 13 Jun 2023 15:19:41 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231848AbjFMWIw (ORCPT + 99 others); Tue, 13 Jun 2023 18:08:52 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:52720 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S234588AbjFMWIc (ORCPT ); Tue, 13 Jun 2023 18:08:32 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 0AE331711 for ; Tue, 13 Jun 2023 15:08:29 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 9B3F263B87 for ; Tue, 13 Jun 2023 22:08:26 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 53327C433C9; Tue, 13 Jun 2023 22:08:26 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.96) (envelope-from ) id 1q9CBd-000EGu-1H; Tue, 13 Jun 2023 18:08:25 -0400 Message-ID: <20230613220825.215929664@goodmis.org> User-Agent: quilt/0.66 Date: Tue, 13 Jun 2023 18:08:00 -0400 From: Steven Rostedt To: linux-kernel@vger.kernel.org Cc: Daniel Bristot de Oliveira , William White , Jonathan Corbet , Juri Lelli Subject: [for-next][PATCH 10/11] rtla/timerlat_hist: Add timerlat user-space support References: <20230613220750.330146797@goodmis.org> MIME-Version: 1.0 X-Spam-Status: No, score=-6.7 required=5.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,RCVD_IN_DNSWL_HI,SPF_HELO_NONE,SPF_PASS, T_SCC_BODY_TEXT_LINE autolearn=ham autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on lindbergh.monkeyblade.net Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org X-getmail-retrieved-from-mailbox: =?utf-8?q?INBOX?= X-GMAIL-THRID: =?utf-8?q?1768627667478120227?= X-GMAIL-MSGID: =?utf-8?q?1768627667478120227?= From: Daniel Bristot de Oliveira Add the support for running timerlat threads in user-space. In this mode, enabled with -u/--user-threads, timerlat dispatches user-space processes that will loop in the timerlat_fd, measuring the overhead for going to user-space and then returning to the kernel - in addition to the existing measurements. Here is one example of the tool's output with -u enabled: $ sudo timerlat hist -u -c 1-3 -d 600 # RTLA timerlat histogram # Time unit is microseconds (us) # Duration: 0 00:10:01 Index IRQ-001 Thr-001 Usr-001 IRQ-002 Thr-002 Usr-002 IRQ-003 Thr-003 Usr-003 0 477555 0 0 425287 0 0 474357 0 0 1 122385 7998 0 174616 1921 0 125412 3138 0 2 47 587376 492150 89 594717 447830 147 593463 454872 3 11 2549 101930 7 2682 145580 64 2530 138680 4 3 1954 2833 1 463 4917 11 548 4656 5 0 60 1037 0 138 1117 6 179 1130 6 0 26 1837 0 38 277 1 76 339 7 0 15 143 0 28 147 2 37 156 8 0 10 23 0 11 75 0 12 80 9 0 7 17 0 0 26 0 11 42 10 0 2 11 0 0 18 0 2 20 11 0 0 7 0 1 8 0 2 12 12 0 0 6 0 1 4 0 2 8 13 0 1 3 0 0 0 0 0 1 14 0 1 0 0 0 1 0 0 2 15 0 1 0 0 0 0 0 0 2 16 0 1 2 0 0 0 0 0 0 17 0 0 1 0 0 0 0 0 0 19 0 0 1 0 0 0 0 0 0 over: 0 0 0 0 0 0 0 0 0 count: 600001 600001 600001 600000 600000 600000 600000 600000 600000 min: 0 1 2 0 1 2 0 1 2 avg: 0 1 2 0 2 2 0 2 2 max: 4 16 19 4 12 14 7 12 15 The tuning setup like -p or -C work for the user-space threads as well. Link: https://lkml.kernel.org/r/b6a042d55003c4a67ff7dce28d96044b7044f00d.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google) --- tools/tracing/rtla/src/timerlat_hist.c | 129 ++++++++++++++++++++++--- 1 file changed, 118 insertions(+), 11 deletions(-) diff --git a/tools/tracing/rtla/src/timerlat_hist.c b/tools/tracing/rtla/src/timerlat_hist.c index f431cf43246c..47d3d8b53cb2 100644 --- a/tools/tracing/rtla/src/timerlat_hist.c +++ b/tools/tracing/rtla/src/timerlat_hist.c @@ -12,11 +12,13 @@ #include #include #include +#include #include "utils.h" #include "osnoise.h" #include "timerlat.h" #include "timerlat_aa.h" +#include "timerlat_u.h" struct timerlat_hist_params { char *cpus; @@ -37,6 +39,7 @@ struct timerlat_hist_params { int hk_cpus; int no_aa; int dump_tasks; + int user_hist; cpu_set_t hk_cpu_set; struct sched_attr sched_param; struct trace_events *events; @@ -53,9 +56,11 @@ struct timerlat_hist_params { struct timerlat_hist_cpu { int *irq; int *thread; + int *user; int irq_count; int thread_count; + int user_count; unsigned long long min_irq; unsigned long long sum_irq; @@ -64,6 +69,10 @@ struct timerlat_hist_cpu { unsigned long long min_thread; unsigned long long sum_thread; unsigned long long max_thread; + + unsigned long long min_user; + unsigned long long sum_user; + unsigned long long max_user; }; struct timerlat_hist_data { @@ -88,6 +97,10 @@ timerlat_free_histogram(struct timerlat_hist_data *data) if (data->hist[cpu].thread) free(data->hist[cpu].thread); + + if (data->hist[cpu].user) + free(data->hist[cpu].user); + } /* one set of histograms per CPU */ @@ -124,15 +137,21 @@ static struct timerlat_hist_data data->hist[cpu].irq = calloc(1, sizeof(*data->hist->irq) * (entries + 1)); if (!data->hist[cpu].irq) goto cleanup; + data->hist[cpu].thread = calloc(1, sizeof(*data->hist->thread) * (entries + 1)); if (!data->hist[cpu].thread) goto cleanup; + + data->hist[cpu].user = calloc(1, sizeof(*data->hist->user) * (entries + 1)); + if (!data->hist[cpu].user) + goto cleanup; } /* set the min to max */ for (cpu = 0; cpu < nr_cpus; cpu++) { data->hist[cpu].min_irq = ~0; data->hist[cpu].min_thread = ~0; + data->hist[cpu].min_user = ~0; } return data; @@ -147,7 +166,7 @@ static struct timerlat_hist_data */ static void timerlat_hist_update(struct osnoise_tool *tool, int cpu, - unsigned long long thread, + unsigned long long context, unsigned long long latency) { struct timerlat_hist_params *params = tool->params; @@ -162,18 +181,24 @@ timerlat_hist_update(struct osnoise_tool *tool, int cpu, if (data->bucket_size) bucket = latency / data->bucket_size; - if (!thread) { + if (!context) { hist = data->hist[cpu].irq; data->hist[cpu].irq_count++; update_min(&data->hist[cpu].min_irq, &latency); update_sum(&data->hist[cpu].sum_irq, &latency); update_max(&data->hist[cpu].max_irq, &latency); - } else { + } else if (context == 1) { hist = data->hist[cpu].thread; data->hist[cpu].thread_count++; update_min(&data->hist[cpu].min_thread, &latency); update_sum(&data->hist[cpu].sum_thread, &latency); update_max(&data->hist[cpu].max_thread, &latency); + } else { /* user */ + hist = data->hist[cpu].user; + data->hist[cpu].user_count++; + update_min(&data->hist[cpu].min_user, &latency); + update_sum(&data->hist[cpu].sum_user, &latency); + update_max(&data->hist[cpu].max_user, &latency); } if (bucket < entries) @@ -190,16 +215,16 @@ timerlat_hist_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *data) { struct trace_instance *trace = data; - unsigned long long thread, latency; + unsigned long long context, latency; struct osnoise_tool *tool; int cpu = record->cpu; tool = container_of(trace, struct osnoise_tool, trace); - tep_get_field_val(s, event, "context", record, &thread, 1); + tep_get_field_val(s, event, "context", record, &context, 1); tep_get_field_val(s, event, "timer_latency", record, &latency, 1); - timerlat_hist_update(tool, cpu, thread, latency); + timerlat_hist_update(tool, cpu, context, latency); return 0; } @@ -241,6 +266,9 @@ static void timerlat_hist_header(struct osnoise_tool *tool) if (!params->no_thread) trace_seq_printf(s, " Thr-%03d", cpu); + + if (params->user_hist) + trace_seq_printf(s, " Usr-%03d", cpu); } trace_seq_printf(s, "\n"); @@ -279,6 +307,10 @@ timerlat_print_summary(struct timerlat_hist_params *params, if (!params->no_thread) trace_seq_printf(trace->seq, "%9d ", data->hist[cpu].thread_count); + + if (params->user_hist) + trace_seq_printf(trace->seq, "%9d ", + data->hist[cpu].user_count); } trace_seq_printf(trace->seq, "\n"); @@ -299,6 +331,10 @@ timerlat_print_summary(struct timerlat_hist_params *params, if (!params->no_thread) trace_seq_printf(trace->seq, "%9llu ", data->hist[cpu].min_thread); + + if (params->user_hist) + trace_seq_printf(trace->seq, "%9llu ", + data->hist[cpu].min_user); } trace_seq_printf(trace->seq, "\n"); @@ -323,7 +359,15 @@ timerlat_print_summary(struct timerlat_hist_params *params, if (!params->no_thread) { if (data->hist[cpu].thread_count) trace_seq_printf(trace->seq, "%9llu ", - data->hist[cpu].sum_thread / data->hist[cpu].thread_count); + data->hist[cpu].sum_thread / data->hist[cpu].thread_count); + else + trace_seq_printf(trace->seq, " - "); + } + + if (params->user_hist) { + if (data->hist[cpu].user_count) + trace_seq_printf(trace->seq, "%9llu ", + data->hist[cpu].sum_user / data->hist[cpu].user_count); else trace_seq_printf(trace->seq, " - "); } @@ -347,6 +391,10 @@ timerlat_print_summary(struct timerlat_hist_params *params, if (!params->no_thread) trace_seq_printf(trace->seq, "%9llu ", data->hist[cpu].max_thread); + + if (params->user_hist) + trace_seq_printf(trace->seq, "%9llu ", + data->hist[cpu].max_user); } trace_seq_printf(trace->seq, "\n"); trace_seq_do_printf(trace->seq); @@ -392,6 +440,12 @@ timerlat_print_stats(struct timerlat_hist_params *params, struct osnoise_tool *t data->hist[cpu].thread[bucket]); } + if (params->user_hist) { + total += data->hist[cpu].user[bucket]; + trace_seq_printf(trace->seq, "%9d ", + data->hist[cpu].user[bucket]); + } + } if (total == 0 && !params->with_zeros) { @@ -421,6 +475,10 @@ timerlat_print_stats(struct timerlat_hist_params *params, struct osnoise_tool *t if (!params->no_thread) trace_seq_printf(trace->seq, "%9d ", data->hist[cpu].thread[data->entries]); + + if (params->user_hist) + trace_seq_printf(trace->seq, "%9d ", + data->hist[cpu].user[data->entries]); } trace_seq_printf(trace->seq, "\n"); trace_seq_do_printf(trace->seq); @@ -441,7 +499,7 @@ static void timerlat_hist_usage(char *usage) " usage: [rtla] timerlat hist [-h] [-q] [-d s] [-D] [-n] [-a us] [-p us] [-i us] [-T us] [-s us] \\", " [-t[=file]] [-e sys[:event]] [--filter ] [--trigger ] [-c cpu-list] [-H cpu-list]\\", " [-P priority] [-E N] [-b N] [--no-irq] [--no-thread] [--no-header] [--no-summary] \\", - " [--no-index] [--with-zeros] [--dma-latency us] [-C[=cgroup_name]] [--no-aa] [--dump-task]", + " [--no-index] [--with-zeros] [--dma-latency us] [-C[=cgroup_name]] [--no-aa] [--dump-task] [-u]", "", " -h/--help: print this menu", " -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit", @@ -476,6 +534,7 @@ static void timerlat_hist_usage(char *usage) " f:prio - use SCHED_FIFO with prio", " d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with runtime and period", " in nanoseconds", + " -u/--user-threads: use rtla user-space threads instead of in-kernel timerlat threads", NULL, }; @@ -532,6 +591,7 @@ static struct timerlat_hist_params {"stack", required_argument, 0, 's'}, {"thread", required_argument, 0, 'T'}, {"trace", optional_argument, 0, 't'}, + {"user-threads", no_argument, 0, 'u'}, {"event", required_argument, 0, 'e'}, {"no-irq", no_argument, 0, '0'}, {"no-thread", no_argument, 0, '1'}, @@ -550,7 +610,7 @@ static struct timerlat_hist_params /* getopt_long stores the option index here. */ int option_index = 0; - c = getopt_long(argc, argv, "a:c:C::b:d:e:E:DhH:i:np:P:s:t::T:0123456:7:8:9\1", + c = getopt_long(argc, argv, "a:c:C::b:d:e:E:DhH:i:np:P:s:t::T:u0123456:7:8:9\1", long_options, &option_index); /* detect the end of the options. */ @@ -660,6 +720,9 @@ static struct timerlat_hist_params else params->trace_output = "timerlat_trace.txt"; break; + case 'u': + params->user_hist = 1; + break; case '0': /* no irq */ params->no_irq = 1; break; @@ -744,7 +807,7 @@ static struct timerlat_hist_params static int timerlat_hist_apply_config(struct osnoise_tool *tool, struct timerlat_hist_params *params) { - int retval; + int retval, i; if (!params->sleep_time) params->sleep_time = 1; @@ -755,6 +818,9 @@ timerlat_hist_apply_config(struct osnoise_tool *tool, struct timerlat_hist_param err_msg("Failed to apply CPUs config\n"); goto out_err; } + } else { + for (i = 0; i < sysconf(_SC_NPROCESSORS_CONF); i++) + CPU_SET(i, ¶ms->monitored_cpus); } if (params->stop_us) { @@ -807,6 +873,14 @@ timerlat_hist_apply_config(struct osnoise_tool *tool, struct timerlat_hist_param auto_house_keeping(¶ms->monitored_cpus); } + if (params->user_hist) { + retval = osnoise_set_workload(tool->context, 0); + if (retval) { + err_msg("Failed to set OSNOISE_WORKLOAD option\n"); + goto out_err; + } + } + return 0; out_err: @@ -867,11 +941,13 @@ int timerlat_hist_main(int argc, char *argv[]) { struct timerlat_hist_params *params; struct osnoise_tool *record = NULL; + struct timerlat_u_params params_u; struct osnoise_tool *tool = NULL; struct osnoise_tool *aa = NULL; struct trace_instance *trace; int dma_latency_fd = -1; int return_value = 1; + pthread_t timerlat_u; int retval; params = timerlat_hist_parse_args(argc, argv); @@ -906,7 +982,7 @@ int timerlat_hist_main(int argc, char *argv[]) } } - if (params->cgroup) { + if (params->cgroup && !params->user_hist) { retval = set_comm_cgroup("timerlat/", params->cgroup_name); if (!retval) { err_msg("Failed to move threads to cgroup\n"); @@ -970,6 +1046,25 @@ int timerlat_hist_main(int argc, char *argv[]) tool->start_time = time(NULL); timerlat_hist_set_signals(params); + if (params->user_hist) { + /* rtla asked to stop */ + params_u.should_run = 1; + /* all threads left */ + params_u.stopped_running = 0; + + params_u.set = ¶ms->monitored_cpus; + if (params->set_sched) + params_u.sched_param = ¶ms->sched_param; + else + params_u.sched_param = NULL; + + params_u.cgroup_name = params->cgroup_name; + + retval = pthread_create(&timerlat_u, NULL, timerlat_u_dispatcher, ¶ms_u); + if (retval) + err_msg("Error creating timerlat user-space threads\n"); + } + while (!stop_tracing) { sleep(params->sleep_time); @@ -986,6 +1081,18 @@ int timerlat_hist_main(int argc, char *argv[]) if (trace_is_off(&tool->trace, &record->trace)) break; + + /* is there still any user-threads ? */ + if (params->user_hist) { + if (params_u.stopped_running) { + debug_msg("timerlat user-space threads stopped!\n"); + break; + } + } + } + if (params->user_hist && !params_u.stopped_running) { + params_u.should_run = 0; + sleep(1); } timerlat_print_stats(params, tool);