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=-11.3 required=3.0 tests=BAYES_00,DKIMWL_WL_MED, DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED,USER_IN_DEF_DKIM_WL 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 54A43C43464 for ; Fri, 18 Sep 2020 20:27:18 +0000 (UTC) Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by mail.kernel.org (Postfix) with ESMTP id D8C3D23119 for ; Fri, 18 Sep 2020 20:27:17 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=google.com header.i=@google.com header.b="pmIun508" DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org D8C3D23119 Authentication-Results: mail.kernel.org; dmarc=fail (p=reject dis=none) header.from=google.com Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=owner-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix) id 135CE6B0093; Fri, 18 Sep 2020 16:27:17 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 0BD606B0095; Fri, 18 Sep 2020 16:27:17 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id ED25E8E0001; Fri, 18 Sep 2020 16:27:16 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from forelay.hostedemail.com (smtprelay0218.hostedemail.com [216.40.44.218]) by kanga.kvack.org (Postfix) with ESMTP id D2C336B0093 for ; Fri, 18 Sep 2020 16:27:16 -0400 (EDT) Received: from smtpin21.hostedemail.com (10.5.19.251.rfc1918.com [10.5.19.251]) by forelay02.hostedemail.com (Postfix) with ESMTP id 9EEE3362D for ; Fri, 18 Sep 2020 20:27:16 +0000 (UTC) X-FDA: 77277316872.21.feast90_2314f632712e Received: from filter.hostedemail.com (10.5.16.251.rfc1918.com [10.5.16.251]) by smtpin21.hostedemail.com (Postfix) with ESMTP id 784D3180442C4 for ; Fri, 18 Sep 2020 20:27:16 +0000 (UTC) X-HE-Tag: feast90_2314f632712e X-Filterd-Recvd-Size: 9588 Received: from mail-pj1-f67.google.com (mail-pj1-f67.google.com [209.85.216.67]) by imf01.hostedemail.com (Postfix) with ESMTP for ; Fri, 18 Sep 2020 20:27:15 +0000 (UTC) Received: by mail-pj1-f67.google.com with SMTP id md22so4701203pjb.0 for ; Fri, 18 Sep 2020 13:27:15 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=PT4Tal3/t4OKAkdxZvc0uyLrxNmarJh8q2gShqXYJ/4=; b=pmIun508/ZS1R6f9q4PlAgNA4IYSUmD4tJzmeRlhljg6jvk1mQlGe035SLNdWquMFv Kn3SQp3Cl8qe1hTZWWrY2DNdkBXR0cQJl/Xhs42qc9oeBe5vnUhAqIrousaER53muSz+ CA3pEsc07hrE49dEfkcYttf24JyTg7cShw+lRDDMbUccPIfhXast+T+aheOYhXUwghO+ 2ep9wpnCAL5t1P0ZbuRYTmimhaRiu6D1d1l4ClDaaUBu6LH75TK75MM/l0qgiifE/FrD NiM+xPFAd9syCdZCqEfYoTqd5VDc4ZlfjETzq8+FM1kTUmX1R7LWzB3hWm7wFj9JDpsq SFCw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=PT4Tal3/t4OKAkdxZvc0uyLrxNmarJh8q2gShqXYJ/4=; b=oykvgZ5JsFMcpYn3ikoftOT+wp1QIyugmW9wl/YAwAhvi1E9Lygn3pF9Mwv2yekT7G 835lB3nFLHnMjR+5E2tj7UsdnuSMpJHpv4BqQbDvjcxock/jhvtuDKjthRUy9GavopdX 0GwndXXY01Det/pur/xzTnGjH0BbmtH7cbSLJOJ/2XExlleoNDtxqu62B7yCaRVlpC/7 qq0q8gXVRiaQnHw51qZU3HbLtB6cBdFnxGiKiGLQsz0fg7Rb3H2DTpAqyqr9pfB/qmGE nq9UvRaYHWm46OsfyD3SQlL7l96SR4TT/iuqYDdJg1O6mJwISApmJCK43alJnFDT4onA 2HUA== X-Gm-Message-State: AOAM530VMtJIYQyD2i1Ct3eqA49lkhnShyAGMtf5FVjy25nuh5adW9pW owHqc3FK93ZnV4YtVfRgyh+fdkTsCBmuujSPxeuboA== X-Google-Smtp-Source: ABdhPJxscdqApl2yRhXufXwxU/nGg/b3hiHHa5fv3rtIz3RK6kyP7mKvmeZ2XLtQDSa89SrqQvkX2FeuSFU4Ls4BGrs= X-Received: by 2002:a17:902:c3d3:b029:d1:e5e7:c4da with SMTP id j19-20020a170902c3d3b02900d1e5e7c4damr17771000plj.46.1600460834797; Fri, 18 Sep 2020 13:27:14 -0700 (PDT) MIME-Version: 1.0 References: <20200917181347.1359365-1-axelrasmussen@google.com> <20200917154258.1a364cdf@gandalf.local.home> In-Reply-To: <20200917154258.1a364cdf@gandalf.local.home> From: Axel Rasmussen Date: Fri, 18 Sep 2020 13:26:37 -0700 Message-ID: Subject: Re: [PATCH] mmap_lock: add tracepoints around lock acquisition To: Steven Rostedt Cc: Ingo Molnar , Andrew Morton , Vlastimil Babka , Michel Lespinasse , Daniel Jordan , Davidlohr Bueso , Yafang Shao , LKML , Linux MM Content-Type: text/plain; charset="UTF-8" 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: On Thu, Sep 17, 2020 at 12:43 PM Steven Rostedt 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 > > # 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,$dur)" > 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