diff mbox series

[v4,09/25] fsverity: add tracepoints

Message ID 20240212165821.1901300-10-aalbersh@redhat.com (mailing list archive)
State Superseded, archived
Headers show
Series fs-verity support for XFS | expand

Commit Message

Andrey Albershteyn Feb. 12, 2024, 4:58 p.m. UTC
fs-verity previously had debug printk but it was removed. This patch
adds trace points to the same places where printk were used (with a
few additional ones).

Signed-off-by: Andrey Albershteyn <aalbersh@redhat.com>
---
 fs/verity/enable.c              |   3 +
 fs/verity/fsverity_private.h    |   2 +
 fs/verity/init.c                |   1 +
 fs/verity/signature.c           |   2 +
 fs/verity/verify.c              |  10 ++
 include/trace/events/fsverity.h | 184 ++++++++++++++++++++++++++++++++
 6 files changed, 202 insertions(+)
 create mode 100644 include/trace/events/fsverity.h

Comments

Eric Biggers Feb. 23, 2024, 5:31 a.m. UTC | #1
On Mon, Feb 12, 2024 at 05:58:06PM +0100, Andrey Albershteyn wrote:
> fs-verity previously had debug printk but it was removed. This patch
> adds trace points to the same places where printk were used (with a
> few additional ones).

Are all of these actually useful?  There's a maintenance cost to adding all of
these.

- Eric
Andrey Albershteyn Feb. 23, 2024, 1:23 p.m. UTC | #2
On 2024-02-22 21:31:56, Eric Biggers wrote:
> On Mon, Feb 12, 2024 at 05:58:06PM +0100, Andrey Albershteyn wrote:
> > fs-verity previously had debug printk but it was removed. This patch
> > adds trace points to the same places where printk were used (with a
> > few additional ones).
> 
> Are all of these actually useful?  There's a maintenance cost to adding all of
> these.
> 

Well, they were useful for me while testing/working on this
patchset. Especially combining -e xfs -e fsverity was quite good for
checking correctness and debugging with xfstests tests. They're
probably could be handy if something breaks.

Or you mean if each of them is useful? The ones which I added to
signature verification probably aren't as useful as other; my
intention adding them was to also cover these code paths.
Eric Biggers Feb. 23, 2024, 6:27 p.m. UTC | #3
On Fri, Feb 23, 2024 at 02:23:52PM +0100, Andrey Albershteyn wrote:
> On 2024-02-22 21:31:56, Eric Biggers wrote:
> > On Mon, Feb 12, 2024 at 05:58:06PM +0100, Andrey Albershteyn wrote:
> > > fs-verity previously had debug printk but it was removed. This patch
> > > adds trace points to the same places where printk were used (with a
> > > few additional ones).
> > 
> > Are all of these actually useful?  There's a maintenance cost to adding all of
> > these.
> > 
> 
> Well, they were useful for me while testing/working on this
> patchset. Especially combining -e xfs -e fsverity was quite good for
> checking correctness and debugging with xfstests tests. They're
> probably could be handy if something breaks.
> 
> Or you mean if each of them is useful? The ones which I added to
> signature verification probably aren't as useful as other; my
> intention adding them was to also cover these code paths.

Well, I'll have to maintain all of these, including reviewing them, keeping them
working as code gets refactored, and fixing any bugs that exist or may get
introduced later in them.  They also increase the icache footprint of the code.
I'd like to make sure that it will be worthwhile.  The pr_debug messages that I
had put in fs/verity/ originally were slightly useful when writing fs/verity/
originally, but after that I never really used them.  Instead I found they
actually made patching fs/verity/ a bit harder, since I had to make sure to keep
all the pr_debug statements updated as code changed around them.

Maybe I am an outlier and other people really do like having these tracepoints
around.  But I'd like to see a bit more feedback along those lines first.  If we
could keep them to a more minimal set, that would also be helpful.

- Eric
Dave Chinner Feb. 26, 2024, 2:24 a.m. UTC | #4
On Fri, Feb 23, 2024 at 10:27:35AM -0800, Eric Biggers wrote:
> On Fri, Feb 23, 2024 at 02:23:52PM +0100, Andrey Albershteyn wrote:
> > On 2024-02-22 21:31:56, Eric Biggers wrote:
> > > On Mon, Feb 12, 2024 at 05:58:06PM +0100, Andrey Albershteyn wrote:
> > > > fs-verity previously had debug printk but it was removed. This patch
> > > > adds trace points to the same places where printk were used (with a
> > > > few additional ones).
> > > 
> > > Are all of these actually useful?  There's a maintenance cost to adding all of
> > > these.
> > > 
> > 
> > Well, they were useful for me while testing/working on this
> > patchset. Especially combining -e xfs -e fsverity was quite good for
> > checking correctness and debugging with xfstests tests. They're
> > probably could be handy if something breaks.
> > 
> > Or you mean if each of them is useful? The ones which I added to
> > signature verification probably aren't as useful as other; my
> > intention adding them was to also cover these code paths.
> 
> Well, I'll have to maintain all of these, including reviewing them, keeping them
> working as code gets refactored, and fixing any bugs that exist or may get
> introduced later in them.  They also increase the icache footprint of the code.
> I'd like to make sure that it will be worthwhile.  The pr_debug messages that I
> had put in fs/verity/ originally were slightly useful when writing fs/verity/
> originally, but after that I never really used them.  Instead I found they
> actually made patching fs/verity/ a bit harder, since I had to make sure to keep
> all the pr_debug statements updated as code changed around them.

pr_debug is largely useless outside of code development purposes.

The value in tracepoints is that they are available for diagnosing
problems on production systems and should be thought of as such.
Yes, you can also use them to debug development code, but in that
environment they are no substitute for custom trace_printk() debug
output.

However, when you have extensive tracepoints coverage, the amount of
custom trace_printk() stuff you need to add to a kernel to debug an
issue ends up being limited, because most of the key state and
object changes in the code are already covered by tracepoints.

> Maybe I am an outlier and other people really do like having these tracepoints
> around.  But I'd like to see a bit more feedback along those lines first.  If we
> could keep them to a more minimal set, that would also be helpful.

For people who are used to subsystems with extensive tracepoint
coverage (like XFS), the lack of tracepoints in all the surrounding
code is jarring. It makes the rest of the system feel like a black
hole where detailed runtime introspection is almost completely
impossible without a *lot* of work.

Extensive tracepoints help everyone in the production support
and diagnosis chain understand what is going on by providing easy to
access runtime introspection for the code. i.e. they provide
benefit to far more people than just the one kernel developer who
enables pr_debug on the subsystem when developing new code...

-Dave.
diff mbox series

Patch

diff --git a/fs/verity/enable.c b/fs/verity/enable.c
index 04e060880b79..945eba0092ab 100644
--- a/fs/verity/enable.c
+++ b/fs/verity/enable.c
@@ -227,6 +227,8 @@  static int enable_verity(struct file *filp,
 	if (err)
 		goto out;
 
+	trace_fsverity_enable(inode, desc, &params);
+
 	/*
 	 * Start enabling verity on this file, serialized by the inode lock.
 	 * Fail if verity is already enabled or is already being enabled.
@@ -255,6 +257,7 @@  static int enable_verity(struct file *filp,
 		fsverity_err(inode, "Error %d building Merkle tree", err);
 		goto rollback;
 	}
+	trace_fsverity_tree_done(inode, desc, &params);
 
 	/*
 	 * Create the fsverity_info.  Don't bother trying to save work by
diff --git a/fs/verity/fsverity_private.h b/fs/verity/fsverity_private.h
index 2bf1f94d437c..4ac9786235b5 100644
--- a/fs/verity/fsverity_private.h
+++ b/fs/verity/fsverity_private.h
@@ -181,4 +181,6 @@  int fsverity_read_merkle_tree_block(struct inode *inode,
 				    unsigned int log_blocksize,
 				    u64 ra_bytes);
 
+#include <trace/events/fsverity.h>
+
 #endif /* _FSVERITY_PRIVATE_H */
diff --git a/fs/verity/init.c b/fs/verity/init.c
index cb2c9aac61ed..3769d2dc9e3b 100644
--- a/fs/verity/init.c
+++ b/fs/verity/init.c
@@ -5,6 +5,7 @@ 
  * Copyright 2019 Google LLC
  */
 
+#define CREATE_TRACE_POINTS
 #include "fsverity_private.h"
 
 #include <linux/ratelimit.h>
diff --git a/fs/verity/signature.c b/fs/verity/signature.c
index 90c07573dd77..c1f08bb32ed1 100644
--- a/fs/verity/signature.c
+++ b/fs/verity/signature.c
@@ -53,6 +53,8 @@  int fsverity_verify_signature(const struct fsverity_info *vi,
 	struct fsverity_formatted_digest *d;
 	int err;
 
+	trace_fsverity_verify_signature(inode, signature, sig_size);
+
 	if (sig_size == 0) {
 		if (fsverity_require_signatures) {
 			fsverity_err(inode,
diff --git a/fs/verity/verify.c b/fs/verity/verify.c
index 6f4ff420c075..4375b0cd176e 100644
--- a/fs/verity/verify.c
+++ b/fs/verity/verify.c
@@ -57,6 +57,7 @@  verify_data_block(struct inode *inode, struct fsverity_info *vi,
 		/* Byte offset of the wanted hash relative to @addr */
 		unsigned int hoffset;
 	} hblocks[FS_VERITY_MAX_LEVELS];
+	trace_fsverity_verify_block(inode, data_pos);
 	/*
 	 * The index of the previous level's block within that level; also the
 	 * index of that block's hash within the current level.
@@ -129,6 +130,9 @@  verify_data_block(struct inode *inode, struct fsverity_info *vi,
 		if (is_hash_block_verified(vi, block, hblock_idx)) {
 			memcpy(_want_hash, block->kaddr + hoffset, hsize);
 			want_hash = _want_hash;
+			trace_fsverity_merkle_tree_block_verified(inode,
+					hblock_idx,
+					FSVERITY_TRACE_DIR_ASCEND);
 			fsverity_drop_block(inode, block);
 			goto descend;
 		}
@@ -160,6 +164,8 @@  verify_data_block(struct inode *inode, struct fsverity_info *vi,
 		block->verified = true;
 		memcpy(_want_hash, haddr + hoffset, hsize);
 		want_hash = _want_hash;
+		trace_fsverity_merkle_tree_block_verified(inode, hblock_idx,
+				FSVERITY_TRACE_DIR_DESCEND);
 		fsverity_drop_block(inode, block);
 	}
 
@@ -334,6 +340,8 @@  void fsverity_invalidate_range(struct inode *inode, loff_t offset,
 		return;
 	}
 
+	trace_fsverity_invalidate_blocks(inode, index, blocks);
+
 	for (i = 0; i < blocks; i++)
 		clear_bit(index + i, vi->hash_block_verified);
 }
@@ -440,6 +448,8 @@  int fsverity_read_merkle_tree_block(struct inode *inode,
 	int err = 0;
 	unsigned long index = pos >> PAGE_SHIFT;
 
+	trace_fsverity_read_merkle_tree_block(inode, pos, log_blocksize);
+
 	if (inode->i_sb->s_vop->read_merkle_tree_block)
 		return inode->i_sb->s_vop->read_merkle_tree_block(
 			inode, pos, block, log_blocksize, ra_bytes);
diff --git a/include/trace/events/fsverity.h b/include/trace/events/fsverity.h
new file mode 100644
index 000000000000..3cc429d21443
--- /dev/null
+++ b/include/trace/events/fsverity.h
@@ -0,0 +1,184 @@ 
+// SPDX-License-Identifier: GPL-2.0
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM fsverity
+
+#if !defined(_TRACE_FSVERITY_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_FSVERITY_H
+
+#include <linux/tracepoint.h>
+
+struct fsverity_descriptor;
+struct merkle_tree_params;
+struct fsverity_info;
+
+#define FSVERITY_TRACE_DIR_ASCEND	(1ul << 0)
+#define FSVERITY_TRACE_DIR_DESCEND	(1ul << 1)
+#define FSVERITY_HASH_SHOWN_LEN		20
+
+TRACE_EVENT(fsverity_enable,
+	TP_PROTO(struct inode *inode, struct fsverity_descriptor *desc,
+		struct merkle_tree_params *params),
+	TP_ARGS(inode, desc, params),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__field(u64, data_size)
+		__field(unsigned int, block_size)
+		__field(unsigned int, num_levels)
+		__field(u64, tree_size)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		__entry->data_size = desc->data_size;
+		__entry->block_size = params->block_size;
+		__entry->num_levels = params->num_levels;
+		__entry->tree_size = params->tree_size;
+	),
+	TP_printk("ino %lu data size %llu tree size %llu block size %u levels %u",
+		(unsigned long) __entry->ino,
+		__entry->data_size,
+		__entry->tree_size,
+		__entry->block_size,
+		__entry->num_levels)
+);
+
+TRACE_EVENT(fsverity_tree_done,
+	TP_PROTO(struct inode *inode, struct fsverity_descriptor *desc,
+		struct merkle_tree_params *params),
+	TP_ARGS(inode, desc, params),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__field(unsigned int, levels)
+		__field(unsigned int, tree_blocks)
+		__field(u64, tree_size)
+		__array(u8, tree_hash, 64)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		__entry->levels = params->num_levels;
+		__entry->tree_blocks =
+			params->tree_size >> params->log_blocksize;
+		__entry->tree_size = params->tree_size;
+		memcpy(__entry->tree_hash, desc->root_hash, 64);
+	),
+	TP_printk("ino %lu levels %d tree_blocks %d tree_size %lld root_hash %s",
+		(unsigned long) __entry->ino,
+		__entry->levels,
+		__entry->tree_blocks,
+		__entry->tree_size,
+		__print_hex(__entry->tree_hash, 64))
+);
+
+TRACE_EVENT(fsverity_verify_block,
+	TP_PROTO(struct inode *inode, u64 offset),
+	TP_ARGS(inode, offset),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__field(u64, offset)
+		__field(unsigned int, block_size)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		__entry->offset = offset;
+		__entry->block_size =
+			inode->i_verity_info->tree_params.block_size;
+	),
+	TP_printk("ino %lu data offset %lld data block size %u",
+		(unsigned long) __entry->ino,
+		__entry->offset,
+		__entry->block_size)
+);
+
+TRACE_EVENT(fsverity_merkle_tree_block_verified,
+	TP_PROTO(struct inode *inode, u64 index, u8 direction),
+	TP_ARGS(inode, index, direction),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__field(u64, index)
+		__field(u8, direction)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		__entry->index = index;
+		__entry->direction = direction;
+	),
+	TP_printk("ino %lu block index %llu %s",
+		(unsigned long) __entry->ino,
+		__entry->index,
+		__entry->direction == 0 ? "ascend" : "descend")
+);
+
+TRACE_EVENT(fsverity_invalidate_blocks,
+	TP_PROTO(struct inode *inode, u64 index, size_t blocks),
+	TP_ARGS(inode, index, blocks),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__field(unsigned int, block_size)
+		__field(u64, offset)
+		__field(u64, index)
+		__field(size_t, blocks)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		__entry->block_size = inode->i_verity_info->tree_params.log_blocksize;
+		__entry->offset = index << __entry->block_size;
+		__entry->index = index;
+		__entry->blocks = blocks;
+	),
+	TP_printk("ino %lu tree offset %llu block index %llu num blocks %zx",
+		(unsigned long) __entry->ino,
+		__entry->offset,
+		__entry->index,
+		__entry->blocks)
+);
+
+TRACE_EVENT(fsverity_read_merkle_tree_block,
+	TP_PROTO(struct inode *inode, u64 offset, unsigned int log_blocksize),
+	TP_ARGS(inode, offset, log_blocksize),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__field(u64, offset)
+		__field(u64, index)
+		__field(unsigned int, block_size)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		__entry->offset = offset;
+		__entry->index = offset >> log_blocksize;
+		__entry->block_size = 1 << log_blocksize;
+	),
+	TP_printk("ino %lu tree offset %llu block index %llu block hize %u",
+		(unsigned long) __entry->ino,
+		__entry->offset,
+		__entry->index,
+		__entry->block_size)
+);
+
+TRACE_EVENT(fsverity_verify_signature,
+	TP_PROTO(const struct inode *inode, const u8 *signature, size_t sig_size),
+	TP_ARGS(inode, signature, sig_size),
+	TP_STRUCT__entry(
+		__field(ino_t, ino)
+		__dynamic_array(u8, signature, sig_size)
+		__field(size_t, sig_size)
+		__field(size_t, sig_size_show)
+	),
+	TP_fast_assign(
+		__entry->ino = inode->i_ino;
+		memcpy(__get_dynamic_array(signature), signature, sig_size);
+		__entry->sig_size = sig_size;
+		__entry->sig_size_show = (sig_size > FSVERITY_HASH_SHOWN_LEN ?
+			FSVERITY_HASH_SHOWN_LEN : sig_size);
+	),
+	TP_printk("ino %lu sig_size %lu %s%s%s",
+		(unsigned long) __entry->ino,
+		__entry->sig_size,
+		(__entry->sig_size ? "sig " : ""),
+		__print_hex(__get_dynamic_array(signature),
+			__entry->sig_size_show),
+		(__entry->sig_size ? "..." : ""))
+);
+
+#endif /* _TRACE_FSVERITY_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>