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 Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by smtp.lore.kernel.org (Postfix) with ESMTP id 18949C3DA45 for ; Thu, 11 Jul 2024 16:50:08 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id 9624E6B009D; Thu, 11 Jul 2024 12:50:07 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 912756B009E; Thu, 11 Jul 2024 12:50:07 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 8019B6B009F; Thu, 11 Jul 2024 12:50:07 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from relay.hostedemail.com (smtprelay0017.hostedemail.com [216.40.44.17]) by kanga.kvack.org (Postfix) with ESMTP id 620DB6B009D for ; Thu, 11 Jul 2024 12:50:07 -0400 (EDT) Received: from smtpin24.hostedemail.com (a10.router.float.18 [10.200.18.1]) by unirelay02.hostedemail.com (Postfix) with ESMTP id 80A5312078F for ; Thu, 11 Jul 2024 16:49:59 +0000 (UTC) X-FDA: 82328058918.24.58D629D Received: from sin.source.kernel.org (sin.source.kernel.org [145.40.73.55]) by imf18.hostedemail.com (Postfix) with ESMTP id F00DA1C0017 for ; Thu, 11 Jul 2024 16:49:56 +0000 (UTC) Authentication-Results: imf18.hostedemail.com; dkim=pass header.d=kernel.org header.s=k20201202 header.b="Vv/+KMwm"; spf=pass (imf18.hostedemail.com: domain of djwong@kernel.org designates 145.40.73.55 as permitted sender) smtp.mailfrom=djwong@kernel.org; dmarc=pass (policy=none) header.from=kernel.org ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=hostedemail.com; s=arc-20220608; t=1720716581; h=from:from:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:cc:mime-version:mime-version: content-type:content-type:content-transfer-encoding: in-reply-to:in-reply-to:references:references:dkim-signature; bh=SRgUBBQ5/Je2biOZ6zcw323C1jD6//2KA5m8+2YtjgI=; b=K3Sqvnynrhac8UaV9917X0S5gaqDS/4BPc1JUi5/hbU/Wsk0TSP+NzKBgDTj+Wq/XxqvvC IYxSZGZ8ThZjYcr4FZ9I96/n2K20RlUsZaUNA7h+QNLgiaBH91pr7PZkZtNv44gXcLcPqx uEqlVViYOjp0CO0bG2iRq8DD3jcsSpo= ARC-Authentication-Results: i=1; imf18.hostedemail.com; dkim=pass header.d=kernel.org header.s=k20201202 header.b="Vv/+KMwm"; spf=pass (imf18.hostedemail.com: domain of djwong@kernel.org designates 145.40.73.55 as permitted sender) smtp.mailfrom=djwong@kernel.org; dmarc=pass (policy=none) header.from=kernel.org ARC-Seal: i=1; s=arc-20220608; d=hostedemail.com; t=1720716581; a=rsa-sha256; cv=none; b=KeiB5upK1zm853hC46tSdbgZDJMVsb/HGhgOu7QVN1u4YvL7y551jdxT+9hc1J34DIH543 BAjAXop/IvfGBRRh91/+wcDpcoAtwKPjy/DXlb+ACkY0gQC77WOlPU0afWgDtgbmPKDUPU JZLbHxcS6Qq09ZSqQpw/94wksRVDrMY= Received: from smtp.kernel.org (transwarp.subspace.kernel.org [100.75.92.58]) by sin.source.kernel.org (Postfix) with ESMTP id 1545BCE1961; Thu, 11 Jul 2024 16:49:52 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 9C392C32786; Thu, 11 Jul 2024 16:49:51 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1720716591; bh=nWhL6EXYhTkVqK9dFWpYTLeNOOo5aCjD/1lHMwkWh+0=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=Vv/+KMwm3A+1L8H7wRVjO0quMqAC2RPxeHrKzqk3F5O1xzjrykIITxwF0c5BBIRlV +nsO+MOsO3n9Vxcy2Oib9socUnIGKDGe5CAwEtasHiPMPnBC/s6IY1Xg2WrZYpZxAd iTjSAD09XwaDN9wCiSuzt1IsSnKhplzvF01rPA1/06sT/m2oPn59VtnH39Ei5t/hoU 00auPqDi1rNPJQP6LDhgb8eLR5JrP2dAFFj6A4NEptuoAReMTXqQysBu6EwyIAp4DJ 6kdMqU1jfBJgrnBsuSPirRgGTikbMcFL4F05wbr/iLvgI88NlKqWoP1OVWd4b8CATV anlgPNgJXHwFQ== Date: Thu, 11 Jul 2024 09:49:50 -0700 From: "Darrick J. Wong" To: Jeff Layton Cc: Alexander Viro , Christian Brauner , Jan Kara , Steven Rostedt , Masami Hiramatsu , Mathieu Desnoyers , Chandan Babu R , Theodore Ts'o , Andreas Dilger , Chris Mason , Josef Bacik , David Sterba , Hugh Dickins , Andrew Morton , Jonathan Corbet , Dave Chinner , Andi Kleen , Christoph Hellwig , Uros Bizjak , Kent Overstreet , Arnd Bergmann , Randy Dunlap , kernel-team@fb.com, linux-fsdevel@vger.kernel.org, linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org, linux-xfs@vger.kernel.org, linux-ext4@vger.kernel.org, linux-btrfs@vger.kernel.org, linux-mm@kvack.org, linux-nfs@vger.kernel.org, linux-doc@vger.kernel.org Subject: Re: [PATCH v5 2/9] fs: tracepoints around multigrain timestamp events Message-ID: <20240711164950.GO612460@frogsfrogsfrogs> References: <20240711-mgtime-v5-0-37bb5b465feb@kernel.org> <20240711-mgtime-v5-2-37bb5b465feb@kernel.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20240711-mgtime-v5-2-37bb5b465feb@kernel.org> X-Rspamd-Server: rspam03 X-Rspam-User: X-Rspamd-Queue-Id: F00DA1C0017 X-Stat-Signature: cf5bz3c6g619k1utdesu1hf4e5tfuwwj X-HE-Tag: 1720716596-661363 X-HE-Meta: U2FsdGVkX19c/14TKVZfj1NKzZXzC3+pw/eyEdFbWE+vnWd8xp2aKQxS+js6r5MOMGBM/equKGTREhSSldoVU/alXRhrJeJ96sXUQ6donk5nM4FlJRZ42QUcy4yIaWdmP89KpPbToYFyeN9CoxjBU4j8sFfeg3BGegtsyhQrLnoUeQ7IX5KZmNexRU317jz+wGSCArCgfI9TmeNL3E1YOcRnXlg31+LWoRBIcA/71fvO9f9A7BniJkuXLZ6rNcaO8NbEhBKLBbslVqQKhb/Xd8vgasmRCc+1zy79t104SdeROFA174cpAzMI7sqlqF4hwoWWo6acNi+8SsQo/WO4YO1hd8qvQ01BHp25arZUZDrohCfnu+Vg72DRj5giCP7Z01iz8UibsdZGXE556uY4mVpYIzkCSTmsRQsFNrG0MSa8V1Uvj17FZjQV90gEvBkD1RcHhm7SY6WkhrcO1Qs7+D5KZ861QoQzuJtxqcoouSusBPqggnVkAnHDmzoUJY0MVab3rFykYFjWOrZQtcHuZyBPwPQl/c/mKUb5UPCxwZNsIfZKzrL6Ef6SFsgwxtw0WJmgj123wX38GzseBSwlbK1krFzmLDxTz9M1imxfQMnCD6hEZudKeFFCcHCeuycWlLPCg2O5flNXokjJ3/TZro87H9L52yfCakIWvQUudWYSPegBu9BLnqnsDeMRp5f5rpORLcdo8DdMs+IFXgI/uxoce5dn2HfH0NsOHUlx5k2Ld7qnHxt6WVuOw1aznJ7n01cBFGkmotD0sBTKT430VWIqyURIwkQy+GDrcWnxVVc7FLYv/v+SxxYGCo/asjJufv1sHMRjm+A9+AWg1dDOrJp/FHT7Was9/xogMyBgV4i6hgjiqrTdLfpGSlpdHNzfPoVdn4JR2tSAUSod8qCAca8cmuZblqcmN2Jyiuyz5IzFYyME6YxQgYkl8tI6sPRQyF3+UPHOMy5eSRp8wQb mUYnrswS fcpm8kXr1QWgZj8Q45yc0PTBCevQcbqcDPyv/LHEpRg34trO1vUKyr9qMXDSFSNmAZdu5g1vo6xkhgR8ZwwNILxKKfDDOTCIN5HRgA3ed/dJwIXiBumc5OOV+0nqldsGkQ5chyumil9dax5Z6UFnZX2frChbDruYGf0YRfuuafgvUKLVN1thfmc3s017LZTQuS+UWWf0mw3aT4BKdMPWn0MCpuau4yTC2Khh9fCTOFGqjh3rkgUt1bciPiK7r9B9pcAUH8G8265nJv4lHuIkAJ3HvaA== 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: List-Subscribe: List-Unsubscribe: On Thu, Jul 11, 2024 at 07:08:06AM -0400, Jeff Layton wrote: > Add some tracepoints around various multigrain timestamp events. > > Signed-off-by: Jeff Layton > --- > fs/inode.c | 5 ++ > fs/stat.c | 3 ++ > include/trace/events/timestamp.h | 109 +++++++++++++++++++++++++++++++++++++++ > 3 files changed, 117 insertions(+) > > diff --git a/fs/inode.c b/fs/inode.c > index 2b5889ff7b36..81b45e0a95a6 100644 > --- a/fs/inode.c > +++ b/fs/inode.c > @@ -22,6 +22,9 @@ > #include > #include > #include > +#define CREATE_TRACE_POINTS > +#include > + > #include "internal.h" > > /* > @@ -2571,6 +2574,7 @@ struct timespec64 inode_set_ctime_to_ts(struct inode *inode, struct timespec64 t > { > inode->i_ctime_sec = ts.tv_sec; > inode->i_ctime_nsec = ts.tv_nsec & ~I_CTIME_QUERIED; > + trace_inode_set_ctime_to_ts(inode, &ts); > return ts; > } > EXPORT_SYMBOL(inode_set_ctime_to_ts); > @@ -2670,6 +2674,7 @@ struct timespec64 inode_set_ctime_current(struct inode *inode) > if (try_cmpxchg(&inode->i_ctime_nsec, &cur, now_ts.tv_nsec)) { > /* If swap occurred, then we're (mostly) done */ > inode->i_ctime_sec = now_ts.tv_sec; > + trace_ctime_ns_xchg(inode, cns, now_ts.tv_nsec, cur); > } else { > /* > * Was the change due to someone marking the old ctime QUERIED? > diff --git a/fs/stat.c b/fs/stat.c > index df7fdd3afed9..552dfd67688b 100644 > --- a/fs/stat.c > +++ b/fs/stat.c > @@ -23,6 +23,8 @@ > #include > #include > > +#include > + > #include "internal.h" > #include "mount.h" > > @@ -49,6 +51,7 @@ void fill_mg_cmtime(struct kstat *stat, u32 request_mask, struct inode *inode) > stat->mtime = inode_get_mtime(inode); > stat->ctime.tv_sec = inode->i_ctime_sec; > stat->ctime.tv_nsec = ((u32)atomic_fetch_or(I_CTIME_QUERIED, pcn)) & ~I_CTIME_QUERIED; > + trace_fill_mg_cmtime(inode, &stat->ctime, &stat->mtime); > } > EXPORT_SYMBOL(fill_mg_cmtime); > > diff --git a/include/trace/events/timestamp.h b/include/trace/events/timestamp.h > new file mode 100644 > index 000000000000..3a603190b46c > --- /dev/null > +++ b/include/trace/events/timestamp.h > @@ -0,0 +1,109 @@ > +/* SPDX-License-Identifier: GPL-2.0 */ > +#undef TRACE_SYSTEM > +#define TRACE_SYSTEM timestamp > + > +#if !defined(_TRACE_TIMESTAMP_H) || defined(TRACE_HEADER_MULTI_READ) > +#define _TRACE_TIMESTAMP_H > + > +#include > +#include > + > +TRACE_EVENT(inode_set_ctime_to_ts, > + TP_PROTO(struct inode *inode, > + struct timespec64 *ctime), > + > + TP_ARGS(inode, ctime), > + > + TP_STRUCT__entry( > + __field(dev_t, dev) > + __field(ino_t, ino) > + __field(time64_t, ctime_s) > + __field(u32, ctime_ns) > + __field(u32, gen) > + ), > + > + TP_fast_assign( > + __entry->dev = inode->i_sb->s_dev; Odd indenting of the second columns between the struct definition above and the assignment code here. > + __entry->ino = inode->i_ino; > + __entry->gen = inode->i_generation; > + __entry->ctime_s = ctime->tv_sec; > + __entry->ctime_ns = ctime->tv_nsec; > + ), > + > + TP_printk("ino=%d:%d:%ld:%u ctime=%lld.%u", > + MAJOR(__entry->dev), MINOR(__entry->dev), __entry->ino, __entry->gen, > + __entry->ctime_s, __entry->ctime_ns > + ) > +); > + > +TRACE_EVENT(ctime_ns_xchg, > + TP_PROTO(struct inode *inode, > + u32 old, > + u32 new, > + u32 cur), > + > + TP_ARGS(inode, old, new, cur), > + > + TP_STRUCT__entry( > + __field(dev_t, dev) > + __field(ino_t, ino) > + __field(u32, gen) > + __field(u32, old) > + __field(u32, new) > + __field(u32, cur) > + ), > + > + TP_fast_assign( > + __entry->dev = inode->i_sb->s_dev; > + __entry->ino = inode->i_ino; > + __entry->gen = inode->i_generation; > + __entry->old = old; > + __entry->new = new; > + __entry->cur = cur; > + ), > + > + TP_printk("ino=%d:%d:%ld:%u old=%u:%c new=%u cur=%u:%c", > + MAJOR(__entry->dev), MINOR(__entry->dev), __entry->ino, __entry->gen, > + __entry->old & ~I_CTIME_QUERIED, __entry->old & I_CTIME_QUERIED ? 'Q' : '-', > + __entry->new, > + __entry->cur & ~I_CTIME_QUERIED, __entry->cur & I_CTIME_QUERIED ? 'Q' : '-' This /might/ be overkill for a single flag, but anything you put in the TP_printk seems to end up in the format file: # cat /sys/kernel/debug/tracing/events/xfs/xfbtree_create_root_buf/format name: xfbtree_create_root_buf ID: 1644 format: field:unsigned short common_type; offset:0; size:2; signed:0; field:unsigned char common_flags; offset:2; size:1; signed:0; field:unsigned char common_preempt_count; offset:3; size:1; signed:0; field:int common_pid; offset:4; size:4; signed:1; field:unsigned long xfino; offset:8; size:8; signed:0; field:xfs_daddr_t bno; offset:16; size:8; signed:1; field:int nblks; offset:24; size:4; signed:1; field:int hold; offset:28; size:4; signed:1; field:int pincount; offset:32; size:4; signed:1; field:unsigned int lockval; offset:36; size:4; signed:0; field:unsigned int flags; offset:40; size:4; signed:0; print fmt: "xfino 0x%lx daddr 0x%llx bbcount 0x%x hold %d pincount %d lock %d flags %s", REC->xfino, (unsigned long long)REC->bno, REC->nblks, REC->hold, REC->pincount, REC->lockval, __print_flags(REC->flags, "|", { (1u << 0), "READ" }, { (1u << 1), "WRITE" }, { (1u << 2), "READ_AHEAD" }, { (1u << 3), "NO_IOACCT" }, { (1u << 4), "ASYNC" }, { (1u << 5), "DONE" }, { (1u << 6), "STALE" }, { (1u << 7), "WRITE_FAIL" }, { (1u << 16), "INODES" }, { (1u << 17), "DQUOTS" }, { (1u << 18), "LOG_RECOVERY" }, { (1u << 20), "PAGES" }, { (1u << 21), "KMEM" }, { (1u << 22), "DELWRI_Q" }, { (1u << 28), "LIVESCAN" }, { (1u << 29), "INCORE" }, { (1u << 30), "TRYLOCK" }, { (1u << 31), "UNMAPPED" }) I /think/ all that code gets compiled (interpreted?) as if it were C code, but a more compact format might be: #define CTIME_QUERIED_FLAGS \ { I_CTIME_QUERIED, "queried" } TP_printk("ino=%d:%d:%ld:%u old=%u:%s new=%u cur=%u:%c", MAJOR(__entry->dev), MINOR(__entry->dev), __entry->ino, __entry->gen, __entry->old & ~I_CTIME_QUERIED, __print_flags(__entry->old & I_CTIME_QUERIED, "|", CTIME_QUERIED_FLAGS), ... But, again, that could be overkill for a single flag. Aside from my minor bikeshedding, this all looks good, and I like that we can now monitor what's going on wrt ctime. :) --D > + ) > +); > + > +TRACE_EVENT(fill_mg_cmtime, > + TP_PROTO(struct inode *inode, > + struct timespec64 *ctime, > + struct timespec64 *mtime), > + > + TP_ARGS(inode, ctime, mtime), > + > + TP_STRUCT__entry( > + __field(dev_t, dev) > + __field(ino_t, ino) > + __field(time64_t, ctime_s) > + __field(time64_t, mtime_s) > + __field(u32, ctime_ns) > + __field(u32, mtime_ns) > + __field(u32, gen) > + ), > + > + TP_fast_assign( > + __entry->dev = inode->i_sb->s_dev; > + __entry->ino = inode->i_ino; > + __entry->gen = inode->i_generation; > + __entry->ctime_s = ctime->tv_sec; > + __entry->mtime_s = mtime->tv_sec; > + __entry->ctime_ns = ctime->tv_nsec; > + __entry->mtime_ns = mtime->tv_nsec; > + ), > + > + TP_printk("ino=%d:%d:%ld:%u ctime=%lld.%u mtime=%lld.%u", > + MAJOR(__entry->dev), MINOR(__entry->dev), __entry->ino, __entry->gen, > + __entry->ctime_s, __entry->ctime_ns, > + __entry->mtime_s, __entry->mtime_ns > + ) > +); > +#endif /* _TRACE_TIMESTAMP_H */ > + > +/* This part must be outside protection */ > +#include > > -- > 2.45.2 > >