From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.8 required=3.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,MAILING_LIST_MULTI,SPF_HELO_NONE, SPF_PASS,URIBL_BLOCKED,USER_AGENT_SANE_2 autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 354E5C4727E for ; Wed, 23 Sep 2020 22:07:50 +0000 (UTC) Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by mail.kernel.org (Postfix) with ESMTP id AE53E23787 for ; Wed, 23 Sep 2020 22:07:49 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (1024-bit key) header.d=kernel.org header.i=@kernel.org header.b="LesMBUzt" DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org AE53E23787 Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=kernel.org Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=owner-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix) id 501E16B005A; Wed, 23 Sep 2020 18:07:49 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 48A1C6B005C; Wed, 23 Sep 2020 18:07:49 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 32ACC8E0001; Wed, 23 Sep 2020 18:07:49 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from forelay.hostedemail.com (smtprelay0214.hostedemail.com [216.40.44.214]) by kanga.kvack.org (Postfix) with ESMTP id 0FF326B005A for ; Wed, 23 Sep 2020 18:07:49 -0400 (EDT) Received: from smtpin06.hostedemail.com (10.5.19.251.rfc1918.com [10.5.19.251]) by forelay01.hostedemail.com (Postfix) with ESMTP id CAECC180AD802 for ; Wed, 23 Sep 2020 22:07:48 +0000 (UTC) X-FDA: 77295714216.06.cow09_3e0fbcc27159 Received: from filter.hostedemail.com (10.5.16.251.rfc1918.com [10.5.16.251]) by smtpin06.hostedemail.com (Postfix) with ESMTP id AA7E0100CAABF for ; Wed, 23 Sep 2020 22:07:48 +0000 (UTC) X-HE-Tag: cow09_3e0fbcc27159 X-Filterd-Recvd-Size: 10306 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by imf15.hostedemail.com (Postfix) with ESMTP for ; Wed, 23 Sep 2020 22:07:48 +0000 (UTC) Received: from tzanussi-mobl (c-73-211-240-131.hsd1.il.comcast.net [73.211.240.131]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPSA id 36DF52311A; Wed, 23 Sep 2020 22:07:46 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=default; t=1600898867; bh=0fg/tb6x79NpfaENSuZB9fy5mCBrCQVJCLJcpSvFpiI=; h=Subject:From:To:Cc:Date:In-Reply-To:References:From; b=LesMBUzt5w6X01kIdhbbunu2wqZKZ38mrkV+KD6mevo2h2vwmPjKVo2v/liuQ7wBZ ud6IY8Ja9ayPiAAypw/o6dD7I8TeFvYoDbV/dB+9M1zDi4o7Kwonbjti3gy9wNBBIP TfOHMAWN9htukuhtJc5flkOzZFiBZ3LlbBL6zbp4= Message-ID: <59a36732a8c09ecf31b6bc2bf6fe1629b9625b7c.camel@kernel.org> Subject: Re: [PATCH] mmap_lock: add tracepoints around lock acquisition From: Tom Zanussi To: Steven Rostedt , Axel Rasmussen Cc: Ingo Molnar , Andrew Morton , Vlastimil Babka , Michel Lespinasse , Daniel Jordan , Davidlohr Bueso , Yafang Shao , LKML , Linux MM Date: Wed, 23 Sep 2020 17:07:44 -0500 In-Reply-To: <20200918164150.5a34de1b@gandalf.local.home> References: <20200917181347.1359365-1-axelrasmussen@google.com> <20200917154258.1a364cdf@gandalf.local.home> <20200918164150.5a34de1b@gandalf.local.home> Content-Type: text/plain; charset="UTF-8" X-Mailer: Evolution 3.28.5-0ubuntu0.18.04.1 Mime-Version: 1.0 Content-Transfer-Encoding: 7bit X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: Hi Steve, Axel, On Fri, 2020-09-18 at 16:41 -0400, Steven Rostedt wrote: > On Fri, 18 Sep 2020 13:26:37 -0700 > Axel Rasmussen wrote: > > > On Thu, Sep 17, 2020 at 12:43 PM Steven Rostedt < > > rostedt@goodmis.org> wrote: > > > > > > On Thu, 17 Sep 2020 11:13:47 -0700 > > > Axel Rasmussen wrote: > > > > > > > +/* > > > > + * Trace calls must be in a separate file, as otherwise > > > > there's a circuclar > > > > + * dependency between linux/mmap_lock.h and > > > > trace/events/mmap_lock.h. > > > > + */ > > > > + > > > > +static void trace_start_locking(struct mm_struct *mm, bool > > > > write) > > > > > > Please don't use "trace_" for functions, as that should be > > > reserved for the > > > actual tracepoint functions. Please use "do_trace_" or whatever > > > so there's > > > no confusion about this being a tracepoint, even if it's just a > > > function > > > that calls the tracepoint. > > > > Done; I'll send a v2 with this change. > > > > > > > > > +{ > > > > + TRACE_MMAP_LOCK_EVENT(start_locking, mm, 0, write, true); > > > > +} > > > > + > > > > +static void trace_acquire_returned(struct mm_struct *mm, u64 > > > > start_time_ns, > > > > + bool write, bool success) > > > > +{ > > > > + TRACE_MMAP_LOCK_EVENT(acquire_returned, mm, > > > > + sched_clock() - start_time_ns, > > > > write, success); > > > > +} > > > > + > > > > +static void trace_released(struct mm_struct *mm, bool write) > > > > +{ > > > > + TRACE_MMAP_LOCK_EVENT(released, mm, 0, write, true); > > > > +} > > > > + > > > > > > > > > > +static inline void lock_impl(struct mm_struct *mm, > > > > + void (*lock)(struct rw_semaphore *), > > > > bool write) > > > > +{ > > > > + u64 start_time_ns; > > > > + > > > > + trace_start_locking(mm, write); > > > > + start_time_ns = sched_clock(); > > > > + lock(&mm->mmap_lock); > > > > + trace_acquire_returned(mm, start_time_ns, write, true); > > > > +} > > > > + > > > > > > Why record the start time and pass it in for return, when this > > > can be done > > > by simply recording the start and return and then using the > > > timestamps of > > > the trace events to calculate the duration, offline or as > > > synthetic events: > > > > First, thanks for the detailed feedback! As a newbie this is very > > helpful. :) > > > > I agree in principle, and I almost have a working version as you > > suggest, but I can't see a way to get string fields working. > > > > I believe in trace event headers the typical way to define a string > > field is as a "const char *", with the __string, __assign_str, and > > __get_str helpers. But, from reading trace_events_synth.c, this > > isn't > > really supported, in that it only supports "char []". But, the hist > > trigger code just does a strcmp() of the type string, it doesn't do > > any type conversion, so it considers these types incompatible: > > > > After this: > > # echo 'mmap_lock_latency u64 time; char memcg_path[256]' > > > /sys/kernel/tracing/synthetic_events > > > > Trying to setup the hist trigger gives (the ^ points to the > > beginning > > of keys=>m > properly in e-mail): > > # cat /sys/kernel/tracing/error_log > > [ 15.823725] hist:mmap_lock:mmap_lock_acquire_returned: error: > > Param > > type doesn't match synthetic event field type > > Command: hist:keys=memcg_path:latency=common_timestamp.usecs- > > $ts0:onmatch(mmap_lock.mmap_lock_start_locking).mmap_lock_latency($ > > latency,memcg_path) > > ^ > > > > I tried grepping "char [^\[]+\[" in include/trace/events/, and it > > seems nobody is defining fixed-length string fields like that, so I > > think that's the wrong solution. I checked the docs about defining > > variables ( > > https://www.kernel.org/doc/html/v5.2/trace/histogram.html) > > and it doesn't support anything complex like a cast, just - and +. > > > > Any advice? > > Tom, > > Do you think we could make histograms support the above somehow? > Sorry for the delayed reply - was out on vacation. Yeah, currently the synthetic events only support constant-length strings, which should match with __array()s in the tracepoints, but I think they should also be made to support variable-length arrays that would match __string() etc. I'm thinking an array field without length specifier could be used to in the synthetic event specification for that e.g.: # echo 'mmap_lock_latency u64 time; char memcg_path[]' > /sys/kernel/tracing/synthetic_events I'll work on adding that over the next couple days or so... Tom > -- Steve > > > > > > > > > > > > > > > > # cd /sys/kernel/tracing/ > > > # echo 'duration u64 time' > synthetic_events > > > # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs" > > > > events/mmap_lock/mmap_lock_start_locking/trigger > > > # echo 'hist:keys=common_pid:dur=common_timestamp.usecs- > > > $ts0:onmatch(mmap_lock.mmap_lock_start_locking).trace(duration,$d > > > ur)" > events/mmap_lock/mmap_lock_acquire_returned/trigger > > > # echo 1 > events/synthetic/duration/enable > > > # cat trace > > > # tracer: nop > > > # > > > # entries-in-buffer/entries-written: 148/148 #P:8 > > > # > > > # _-----=> irqs-off > > > # / _----=> need-resched > > > # | / _---=> hardirq/softirq > > > # || / _--=> preempt-depth > > > # ||| / delay > > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > > > # | | | |||| | | > > > bash-1613 [007] ...3 3186.431687: duration: time=3 > > > bash-1613 [007] ...3 3186.431722: duration: time=2 > > > bash-1613 [007] ...3 3186.431772: duration: time=2 > > > bash-1613 [001] ...3 3188.372001: duration: time=6 > > > bash-1613 [001] ...3 3188.372324: duration: time=6 > > > bash-1613 [001] ...3 3188.372332: duration: time=4 > > > bash-1613 [001] ...3 3188.373557: duration: time=5 > > > bash-1613 [001] ...3 3188.373595: duration: time=3 > > > cat-1868 [002] ...3 3188.373608: duration: time=8 > > > bash-1613 [001] ...3 3188.373613: duration: time=4 > > > bash-1613 [001] ...3 3188.373635: duration: time=3 > > > cat-1868 [002] ...3 3188.373646: duration: time=4 > > > bash-1613 [001] ...3 3188.373652: duration: time=3 > > > bash-1613 [001] ...3 3188.373669: duration: time=3 > > > > > > # echo 'hist:keys=time' > events/synthetic/duration/trigger > > > # cat events/synthetic/duration/hist > > > # event histogram > > > # > > > # trigger info: > > > hist:keys=time:vals=hitcount:sort=hitcount:size=2048 [active] > > > # > > > > > > { time: 114 } hitcount: 1 > > > { time: 15 } hitcount: 1 > > > { time: 11 } hitcount: 1 > > > { time: 21 } hitcount: 1 > > > { time: 10 } hitcount: 1 > > > { time: 46 } hitcount: 1 > > > { time: 29 } hitcount: 1 > > > { time: 13 } hitcount: 2 > > > { time: 16 } hitcount: 3 > > > { time: 9 } hitcount: 3 > > > { time: 8 } hitcount: 3 > > > { time: 7 } hitcount: 8 > > > { time: 6 } hitcount: 10 > > > { time: 5 } hitcount: 28 > > > { time: 4 } hitcount: 121 > > > { time: 1 } hitcount: 523 > > > { time: 3 } hitcount: 581 > > > { time: 2 } hitcount: 882 > > > > > > Totals: > > > Hits: 2171 > > > Entries: 18 > > > Dropped: 0 > > > > > > And with this I could do a bunch of things like stack trace on > > > max hits and > > > other features that the tracing histograms give us. > > > > > > -- Steve > >