btrfs: add a trace point for reserve tickets

While debugging a ENOSPC related performance problem I needed to see the
time difference between start and end of a reserve ticket, so add a
trace point to report when we handle a reserve ticket.

I opted to spit out start_ns itself without calculating the difference
because there could be a gap between enabling the tracepoint and setting
start_ns.  Doing it this way allows us to filter on 0 start_ns so we
don't get bogus entries, and we can easily calculate the time difference
with bpftrace or something else.

Reviewed-by: Nikolay Borisov <nborisov@suse.com>
Signed-off-by: Josef Bacik <josef@toxicpanda.com>
Reviewed-by: David Sterba <dsterba@suse.com>
Signed-off-by: David Sterba <dsterba@suse.com>

diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
index 4eab581..d879e3f 100644 (file)
--- a/fs/btrfs/space-info.c
+++ b/fs/btrfs/space-info.c
@@ -1220,6 +1220,8 @@ static void wait_reserve_ticket(struct btrfs_fs_info *fs_info,
  * @fs_info:    the filesystem
  * @space_info: space info for the reservation
  * @ticket:     ticket for the reservation
+ * @start_ns:   timestamp when the reservation started
+ * @orig_bytes: amount of bytes originally reserved
  * @flush:      how much we can flush
  *
  * This does the work of figuring out how to flush for the ticket, waiting for
@@ -1228,6 +1230,7 @@ static void wait_reserve_ticket(struct btrfs_fs_info *fs_info,
 static int handle_reserve_ticket(struct btrfs_fs_info *fs_info,
                                 struct btrfs_space_info *space_info,
                                 struct reserve_ticket *ticket,
+                                u64 start_ns, u64 orig_bytes,
                                 enum btrfs_reserve_flush_enum flush)
 {
        int ret;
@@ -1283,6 +1286,8 @@ static int handle_reserve_ticket(struct btrfs_fs_info *fs_info,
         * space wasn't reserved at all).
         */
        ASSERT(!(ticket->bytes == 0 && ticket->error));
+       trace_btrfs_reserve_ticket(fs_info, space_info->flags, orig_bytes,
+                                  start_ns, flush, ticket->error);
        return ret;
 }
 
@@ -1317,6 +1322,7 @@ static int __reserve_bytes(struct btrfs_fs_info *fs_info,
 {
        struct work_struct *async_work;
        struct reserve_ticket ticket;
+       u64 start_ns = 0;
        u64 used;
        int ret = 0;
        bool pending_tickets;
@@ -1369,6 +1375,9 @@ static int __reserve_bytes(struct btrfs_fs_info *fs_info,
                space_info->reclaim_size += ticket.bytes;
                init_waitqueue_head(&ticket.wait);
                ticket.steal = (flush == BTRFS_RESERVE_FLUSH_ALL_STEAL);
+               if (trace_btrfs_reserve_ticket_enabled())
+                       start_ns = ktime_get_ns();
+
                if (flush == BTRFS_RESERVE_FLUSH_ALL ||
                    flush == BTRFS_RESERVE_FLUSH_ALL_STEAL ||
                    flush == BTRFS_RESERVE_FLUSH_DATA) {
@@ -1405,7 +1414,8 @@ static int __reserve_bytes(struct btrfs_fs_info *fs_info,
        if (!ret || flush == BTRFS_RESERVE_NO_FLUSH)
                return ret;
 
-       return handle_reserve_ticket(fs_info, space_info, &ticket, flush);
+       return handle_reserve_ticket(fs_info, space_info, &ticket, start_ns,
+                                    orig_bytes, flush);
 }
 
 /**

diff --git a/include/trace/events/btrfs.h b/include/trace/events/btrfs.h
index b9896fc..b0ea2a1 100644 (file)
--- a/include/trace/events/btrfs.h
+++ b/include/trace/events/btrfs.h
@@ -2026,6 +2026,35 @@ TRACE_EVENT(btrfs_convert_extent_bit,
                  __print_flags(__entry->clear_bits, "|", EXTENT_FLAGS))
 );
 
+TRACE_EVENT(btrfs_reserve_ticket,
+       TP_PROTO(const struct btrfs_fs_info *fs_info, u64 flags, u64 bytes,
+                u64 start_ns, int flush, int error),
+
+       TP_ARGS(fs_info, flags, bytes, start_ns, flush, error),
+
+       TP_STRUCT__entry_btrfs(
+               __field(        u64,    flags           )
+               __field(        u64,    bytes           )
+               __field(        u64,    start_ns        )
+               __field(        int,    flush           )
+               __field(        int,    error           )
+       ),
+
+       TP_fast_assign_btrfs(fs_info,
+               __entry->flags          = flags;
+               __entry->bytes          = bytes;
+               __entry->start_ns       = start_ns;
+               __entry->flush          = flush;
+               __entry->error          = error;
+       ),
+
+       TP_printk_btrfs("flags=%s bytes=%llu start_ns=%llu flush=%s error=%d",
+                       __print_flags(__entry->flags, "|", BTRFS_GROUP_FLAGS),
+                       __entry->bytes, __entry->start_ns,
+                       __print_symbolic(__entry->flush, FLUSH_ACTIONS),
+                       __entry->error)
+);
+
 DECLARE_EVENT_CLASS(btrfs_sleep_tree_lock,
        TP_PROTO(const struct extent_buffer *eb, u64 start_ns),