From patchwork Wed Aug 29 12:17:07 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Motai.Hirotaka@aj.MitsubishiElectric.co.jp" X-Patchwork-Id: 10580259 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 50086175A for ; Wed, 29 Aug 2018 12:44:05 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 3FB9428A10 for ; Wed, 29 Aug 2018 12:44:05 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 33A602AFB5; Wed, 29 Aug 2018 12:44:05 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.1 required=2.0 tests=BAYES_00,DKIM_SIGNED, MAILING_LIST_MULTI,RCVD_IN_DNSWL_MED,T_DKIM_INVALID autolearn=ham version=3.3.1 Received: from mail.linuxfoundation.org (mail.linuxfoundation.org [140.211.169.12]) (using TLSv1.2 with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 86A7028A10 for ; Wed, 29 Aug 2018 12:44:04 +0000 (UTC) Received: from mail.linux-foundation.org (localhost [127.0.0.1]) by mail.linuxfoundation.org (Postfix) with ESMTP id 74C86DC4; Wed, 29 Aug 2018 12:36:55 +0000 (UTC) X-Original-To: ltsi-dev@lists.linuxfoundation.org Delivered-To: ltsi-dev@mail.linuxfoundation.org Received: from smtp2.linuxfoundation.org (smtp2.linux-foundation.org [172.17.192.36]) by mail.linuxfoundation.org (Postfix) with ESMTPS id E0A24DBA for ; Wed, 29 Aug 2018 12:36:50 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from mx06.melco.co.jp (mx06.melco.co.jp [192.218.140.146]) by smtp2.linuxfoundation.org (Postfix) with ESMTPS id 867AA1DD59 for ; Wed, 29 Aug 2018 12:36:40 +0000 (UTC) Received: from mr06.melco.co.jp (mr06 [133.141.98.164]) by mx06.melco.co.jp (Postfix) with ESMTP id 7DEB93A2E91 for ; Wed, 29 Aug 2018 21:17:28 +0900 (JST) Received: from mr06.melco.co.jp (unknown [127.0.0.1]) by mr06.imss (Postfix) with ESMTP id 420l4S2wSFzRkBT for ; Wed, 29 Aug 2018 21:17:28 +0900 (JST) Received: from mf03_second.melco.co.jp (unknown [192.168.20.183]) by mr06.melco.co.jp (Postfix) with ESMTP id 420l4S2crCzRk5W for ; Wed, 29 Aug 2018 21:17:28 +0900 (JST) Received: from mf03.melco.co.jp (unknown [133.141.98.183]) by mf03_second.melco.co.jp (Postfix) with ESMTP id 420l4S2VWjzRk8v for ; Wed, 29 Aug 2018 21:17:28 +0900 (JST) Received: from JPN01-OS2-obe.outbound.protection.outlook.com (unknown [23.103.139.144]) by mf03.melco.co.jp (Postfix) with ESMTP id 420l4S215tzRk38 for ; Wed, 29 Aug 2018 21:17:28 +0900 (JST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mitsubishielectricgroup.onmicrosoft.com; s=selector1-mitsubishielectricgroup-onmicrosoft-com; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=e8ErRdPsGEhPE1UxtyN5ZWJByf8ol+I+cTiU0ZZ4PRw=; b=T4pkwl8ScjrL15zQ8hLfP6NJhBzFtFOYs4bYrDpwFr9wMGzgN2l00fiGlbtkjUIUeyULGyh+BgDURixzxSvAQ2XAxCYlN2Bt4kanuhTT5BA9+HMAPq8b843wlEbBBqqc+bgE+IUyp5zB9865qJyyAMTQufleP04oEbZPwVLscjY= Received: from TY1PR01MB1692.jpnprd01.prod.outlook.com (52.133.160.145) by TY1PR01MB1708.jpnprd01.prod.outlook.com (52.133.160.149) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.1080.15; Wed, 29 Aug 2018 12:17:27 +0000 Received: from TY1PR01MB1692.jpnprd01.prod.outlook.com ([fe80::d04e:e6f6:c782:22fa]) by TY1PR01MB1692.jpnprd01.prod.outlook.com ([fe80::d04e:e6f6:c782:22fa%2]) with mapi id 15.20.1080.015; Wed, 29 Aug 2018 12:17:27 +0000 From: "Motai.Hirotaka@aj.MitsubishiElectric.co.jp" To: "ltsi-dev@lists.linuxfoundation.org" Thread-Topic: [LTSI-dev] [PATCH 18/54] tracing: Add usecs modifier for hist trigger timestamps Thread-Index: AdQ/jWkzCR89M/m/TquJUML14Khwyw== Date: Wed, 29 Aug 2018 12:17:07 +0000 Deferred-Delivery: Wed, 29 Aug 2018 12:15:00 +0000 Message-ID: Accept-Language: ja-JP, en-US Content-Language: ja-JP X-MS-Has-Attach: X-MS-TNEF-Correlator: x-melpop: 1 authentication-results: spf=none (sender IP is ) smtp.mailfrom=Motai.Hirotaka@aj.MitsubishiElectric.co.jp; x-originating-ip: [153.231.200.201] x-ms-publictraffictype: Email x-microsoft-exchange-diagnostics: 1; TY1PR01MB1708; 6:sUtw+Z1iprS4/VV2w2Z4FxxZdI4uwruHFBgQl06Doz6CtvKHi+adOn/PF01fkNGatbIDKa/XVLAIYtgs0d09D3TxaRki3yz5kkiR9UHE4gCXCt4SAUWSj0bkDxTSdhtc4h1fNaiOGjt24WqaZ5sa2lpKcW9LFm9o/Yh4TQGQSx37N9yYHSyvWXPMB4r8RlRfu4dH4CW14NBzES2d4Xeu441W1gAwlQA5XA7E9nX9HwHGclJLhvsiLkem/8E+Xe2gCQ4mHtmOdDwPHQDxgn+SgBu8pVroP//1Gx3QDVODI5IdtvnkG65E/SK78GVUougN+WKnIUQ2Wx+pDiVzqIoaFS/o8nsSi3m88S7NT5hq4cwRBzYfaLMEk3Qd59xxJGKdbEfORndYvd+vxdRfyOguJmRgFC/IwAzD9NBUjJeFmpeH0Fv9Xhr/VeOLpXbj6Z8US1+6gLoRVtfqbtCQLAmViA==; 5:ci5cEWTmvDxEGhEnFnd/eqXaP8UrHzl5H0UynngR5sw+fbltxOPQzEYMxFlHh3wAs7iZ6Q8P91Z4SvZbMC2znBXUQhCAhnV0mGTjWcyHRscwhrO7ojxkE1OH3lbWUypeX4GYfg/lCzGutbic2np6l9ZLC68rYsrbW7bmDSCWfOw=; 7:BFCk0dDq0zkLrdcDM8GKc9BkL73yGO9RyEPUGqw2xr1MS2bfi9IG9Z6LWiKVFLJmrz6Is/xX45pGPVZBkik4pxPjOxjIBYbxtmxtBPArZQvqIBomsEMn1nsDROtwub8tiAiDl9Hu/k78S8zZfDjnvPVm+u5Y/hEyI/TsNzDBQh6epDsasW9CNB161RBIF5UCg36vvfIB6hSfCihBIWaZR6av5A1KMeCKkIgZhyVEO8q3YBzczCFoAkHGkmMzAwXg x-ms-office365-filtering-correlation-id: 55da38e8-d0aa-4b47-f5db-08d60da962c1 x-microsoft-antispam: BCL:0; PCL:0; RULEID:(7020095)(4652040)(8989137)(4534165)(4627221)(201703031133081)(201702281549075)(8990107)(5600074)(711020)(2017052603328)(7153060)(7193020); SRVR:TY1PR01MB1708; x-ms-traffictypediagnostic: TY1PR01MB1708: x-microsoft-antispam-prvs: x-exchange-antispam-report-test: UriScan:(42068640409301)(228905959029699); x-ms-exchange-senderadcheck: 1 x-exchange-antispam-report-cfa-test: BCL:0; PCL:0; RULEID:(6040522)(2401047)(5005006)(8121501046)(3002001)(10201501046)(93006095)(93001095)(3231311)(944501410)(52105095)(149027)(150027)(6041310)(20161123560045)(201703131423095)(201702281528075)(20161123555045)(201703061421075)(201703061406153)(20161123562045)(20161123558120)(20161123564045)(201708071742011)(7699016); SRVR:TY1PR01MB1708; BCL:0; PCL:0; RULEID:; SRVR:TY1PR01MB1708; x-forefront-prvs: 077929D941 x-forefront-antispam-report: SFV:NSPM; SFS:(10019020)(136003)(366004)(396003)(39860400002)(346002)(376002)(189003)(199004)(966005)(25786009)(74482002)(81156014)(8676002)(106356001)(5660300001)(105586002)(6506007)(14454004)(81166006)(33656002)(26005)(7736002)(74316002)(186003)(72206003)(305945005)(66066001)(68736007)(97736004)(478600001)(476003)(102836004)(2906002)(8936002)(6666003)(6916009)(486006)(6116002)(1857600001)(316002)(7696005)(2900100001)(5640700003)(3846002)(55016002)(99286004)(53936002)(14444005)(86362001)(256004)(6436002)(6306002)(2501003)(5250100002)(9686003)(575784001)(2351001); DIR:OUT; SFP:1102; SCL:1; SRVR:TY1PR01MB1708; H:TY1PR01MB1692.jpnprd01.prod.outlook.com; FPR:; SPF:None; LANG:en; PTR:InfoNoRecords; MX:1; A:0; received-spf: None (protection.outlook.com: aj.MitsubishiElectric.co.jp does not designate permitted sender hosts) x-microsoft-antispam-message-info: HTKPSnP7k/8mg3XgiAX1itvU4WxkvedO5OIIRckYgEvGDTyMZ2q+LUDIkkmggHFjR6WLmH7Lm05Mb120MRCMfWcd/2ae+s+/Xr9cUB+W+WkVOJr+aFkZas3UndM9GxVp+Bnjlg6rDYSP2IX6pwdFz2432RGf948aJRCmd7woaWUmW+DP7AcNtXUXzH3gBrlXBjUyUx9lt/XWicMHYR9qWnxYM+i16PiZoIaLzKHHY4g/zeW6XqM/F80AXBmzLrdqd1Mxv6r5DtpzG4QssyOJvDOg+2GJVMdszkhXFsybGjdx/opcouU2/sctwlaWsU8KXHAUOutT/x263rtIwVGddi6bfeRSGB8WdmrCK3eb+Qo= spamdiagnosticoutput: 1:99 spamdiagnosticmetadata: NSPM MIME-Version: 1.0 X-OriginatorOrg: aj.MitsubishiElectric.co.jp X-MS-Exchange-CrossTenant-Network-Message-Id: 55da38e8-d0aa-4b47-f5db-08d60da962c1 X-MS-Exchange-CrossTenant-originalarrivaltime: 29 Aug 2018 12:17:22.6327 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: c5a75b62-4bff-4c96-a720-6621ce9978e5 X-MS-Exchange-Transport-CrossTenantHeadersStamped: TY1PR01MB1708 Subject: [LTSI-dev] [PATCH 18/54] tracing: Add usecs modifier for hist trigger timestamps X-BeenThere: ltsi-dev@lists.linuxfoundation.org X-Mailman-Version: 2.1.12 Precedence: list List-Id: "A list to discuss patches, development, and other things related to the LTSI project" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: ltsi-dev-bounces@lists.linuxfoundation.org Errors-To: ltsi-dev-bounces@lists.linuxfoundation.org X-Virus-Scanned: ClamAV using ClamSMTP Appending .usecs onto a common_timestamp field will cause the timestamp value to be in microseconds instead of the default nanoseconds. A typical latency histogram using usecs would look like this: # echo 'hist:keys=pid,prio:ts0=common_timestamp.usecs ... # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 ... This also adds an external trace_clock_in_ns() to trace.c for the timestamp conversion. Link: http://lkml.kernel.org/r/4e813705a170b3e13e97dc3135047362fb1a39f3.1516069914.git.tom.zanussi@linux.intel.com Signed-off-by: Tom Zanussi Signed-off-by: Steven Rostedt (VMware) (cherry picked from commit 860f9f6b02e9e846c4cfb3505efed331a910d0b7) Signed-off-by: Hirotaka MOTAI --- Documentation/trace/histogram.txt | 1 + kernel/trace/trace.c | 13 +++++++++++-- kernel/trace/trace.h | 2 ++ kernel/trace/trace_events_hist.c | 28 ++++++++++++++++++++++------ 4 files changed, 36 insertions(+), 8 deletions(-) diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt index a4143f04a..25c94730 100644 --- a/Documentation/trace/histogram.txt +++ b/Documentation/trace/histogram.txt @@ -69,16 +69,17 @@ name: .hex display a number as a hex value .sym display an address as a symbol .sym-offset display an address as a symbol and offset .syscall display a syscall id as a system call name .execname display a common_pid as a program name .log2 display log2 value rather than raw number + .usecs display a common_timestamp in microseconds Note that in general the semantics of a given field aren't interpreted when applying a modifier to it, but there are some restrictions to be aware of in this regard: - only the 'hex' modifier can be used for values (because values are essentially sums, and the other modifiers don't make sense in that context). diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index ef1489d4..f743fe19 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -1165,16 +1165,24 @@ static struct { { trace_clock_jiffies, "uptime", 0 }, { trace_clock, "perf", 1 }, { ktime_get_mono_fast_ns, "mono", 1 }, { ktime_get_raw_fast_ns, "mono_raw", 1 }, { ktime_get_boot_fast_ns, "boot", 1 }, ARCH_TRACE_CLOCKS }; +bool trace_clock_in_ns(struct trace_array *tr) +{ + if (trace_clocks[tr->clock_id].in_ns) + return true; + + return false; +} + /* * trace_parser_get_init - gets the buffer for trace parser */ int trace_parser_get_init(struct trace_parser *parser, int size) { memset(parser, 0, sizeof(*parser)); parser->buffer = kmalloc(size, GFP_KERNEL); @@ -4697,18 +4705,19 @@ static const char readme_msg[] = "\t trigger will be the same as any other instance having the\n" "\t same name. The default format used to display a given field\n" "\t can be modified by appending any of the following modifiers\n" "\t to the field name, as applicable:\n\n" "\t .hex display a number as a hex value\n" "\t .sym display an address as a symbol\n" "\t .sym-offset display an address as a symbol and offset\n" "\t .execname display a common_pid as a program name\n" - "\t .syscall display a syscall id as a syscall name\n\n" - "\t .log2 display log2 value rather than raw number\n\n" + "\t .syscall display a syscall id as a syscall name\n" + "\t .log2 display log2 value rather than raw number\n" + "\t .usecs display a common_timestamp in microseconds\n\n" "\t The 'pause' parameter can be used to pause an existing hist\n" "\t trigger or to start a hist trigger but not log any events\n" "\t until told to do so. 'continue' can be used to start or\n" "\t restart a paused hist trigger.\n\n" "\t The 'clear' parameter will clear the contents of a running\n" "\t hist trigger and leave its current paused/active state\n" "\t unchanged.\n\n" "\t The enable_hist and disable_hist triggers can be used to\n" diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 5f1d4ae5..a94cc69b 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -284,16 +284,18 @@ extern struct list_head ftrace_trace_arrays; extern struct mutex trace_types_lock; extern int trace_array_get(struct trace_array *tr); extern void trace_array_put(struct trace_array *tr); extern int tracing_set_time_stamp_abs(struct trace_array *tr, bool abs); +extern bool trace_clock_in_ns(struct trace_array *tr); + /* * The global tracer (top) should be the first trace array added, * but we check the flag anyway. */ static inline struct trace_array *top_trace_array(void) { struct trace_array *tr; diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index 77ebe6b4..7f5f0b8f 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -85,22 +85,16 @@ static u64 hist_field_log2(struct hist_field *hist_field, void *event, { struct hist_field *operand = hist_field->operands[0]; u64 val = operand->fn(operand, event, rbe); return (u64) ilog2(roundup_pow_of_two(val)); } -static u64 hist_field_timestamp(struct hist_field *hist_field, void *event, - struct ring_buffer_event *rbe) -{ - return ring_buffer_event_time_stamp(rbe); -} - #define DEFINE_HIST_FIELD_FN(type) \ static u64 hist_field_##type(struct hist_field *hist_field, \ void *event, \ struct ring_buffer_event *rbe) \ { \ type *addr = (type *)(event + hist_field->field->offset); \ \ return (u64)(unsigned long)*addr; \ @@ -138,26 +132,28 @@ enum hist_field_flags { HIST_FIELD_FL_HEX = 1 << 3, HIST_FIELD_FL_SYM = 1 << 4, HIST_FIELD_FL_SYM_OFFSET = 1 << 5, HIST_FIELD_FL_EXECNAME = 1 << 6, HIST_FIELD_FL_SYSCALL = 1 << 7, HIST_FIELD_FL_STACKTRACE = 1 << 8, HIST_FIELD_FL_LOG2 = 1 << 9, HIST_FIELD_FL_TIMESTAMP = 1 << 10, + HIST_FIELD_FL_TIMESTAMP_USECS = 1 << 11, }; struct hist_trigger_attrs { char *keys_str; char *vals_str; char *sort_key_str; char *name; bool pause; bool cont; bool clear; + bool ts_in_usecs; unsigned int map_bits; }; struct hist_trigger_data { struct hist_field *fields[TRACING_MAP_FIELDS_MAX]; unsigned int n_vals; unsigned int n_keys; unsigned int n_fields; @@ -165,16 +161,30 @@ struct hist_trigger_data { struct tracing_map_sort_key sort_keys[TRACING_MAP_SORT_KEYS_MAX]; unsigned int n_sort_keys; struct trace_event_file *event_file; struct hist_trigger_attrs *attrs; struct tracing_map *map; bool enable_timestamps; }; +static u64 hist_field_timestamp(struct hist_field *hist_field, void *event, + struct ring_buffer_event *rbe) +{ + struct hist_trigger_data *hist_data = hist_field->hist_data; + struct trace_array *tr = hist_data->event_file->tr; + + u64 ts = ring_buffer_event_time_stamp(rbe); + + if (hist_data->attrs->ts_in_usecs && trace_clock_in_ns(tr)) + ts = ns2usecs(ts); + + return ts; +} + static const char *hist_field_name(struct hist_field *field, unsigned int level) { const char *field_name = ""; if (level > 1) return field_name; @@ -629,25 +639,29 @@ static int create_key_field(struct hist_trigger_data *hist_data, flags |= HIST_FIELD_FL_SYM_OFFSET; else if ((strcmp(field_str, "execname") == 0) && (strcmp(field_name, "common_pid") == 0)) flags |= HIST_FIELD_FL_EXECNAME; else if (strcmp(field_str, "syscall") == 0) flags |= HIST_FIELD_FL_SYSCALL; else if (strcmp(field_str, "log2") == 0) flags |= HIST_FIELD_FL_LOG2; + else if (strcmp(field_str, "usecs") == 0) + flags |= HIST_FIELD_FL_TIMESTAMP_USECS; else { ret = -EINVAL; goto out; } } if (strcmp(field_name, "common_timestamp") == 0) { flags |= HIST_FIELD_FL_TIMESTAMP; hist_data->enable_timestamps = true; + if (flags & HIST_FIELD_FL_TIMESTAMP_USECS) + hist_data->attrs->ts_in_usecs = true; key_size = sizeof(u64); } else { field = trace_find_event_field(file->event_call, field_name); if (!field || !field->size) { ret = -EINVAL; goto out; } @@ -1236,16 +1250,18 @@ static const char *get_hist_field_flags(struct hist_field *hist_field) else if (hist_field->flags & HIST_FIELD_FL_SYM_OFFSET) flags_str = "sym-offset"; else if (hist_field->flags & HIST_FIELD_FL_EXECNAME) flags_str = "execname"; else if (hist_field->flags & HIST_FIELD_FL_SYSCALL) flags_str = "syscall"; else if (hist_field->flags & HIST_FIELD_FL_LOG2) flags_str = "log2"; + else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP_USECS) + flags_str = "usecs"; return flags_str; } static void hist_field_print(struct seq_file *m, struct hist_field *hist_field) { const char *field_name = hist_field_name(hist_field, 0);