From dd9f75ef24de08de5b5e47f9b1fd9759f90e0acf Mon Sep 17 00:00:00 2001
From: Stephen Brennan <stephen.s.brennan@oracle.com>
Date: Wed, 10 Jul 2024 14:35:55 -0700
Subject: [PATCH] fsnotify: print time spent waiting for each task

This will pretty quickly help identify problematic fsnotify groups.

Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
---
 drgn_tools/fsnotify.py | 21 +++++++++++++++------
 1 file changed, 15 insertions(+), 6 deletions(-)

diff --git a/drgn_tools/fsnotify.py b/drgn_tools/fsnotify.py
index e53642ea..cf457121 100644
--- a/drgn_tools/fsnotify.py
+++ b/drgn_tools/fsnotify.py
@@ -5,8 +5,10 @@
 subsystem.
 """
 import argparse
+from datetime import timedelta
 from typing import Dict
 from typing import Iterator
+from typing import Optional
 from typing import Tuple
 
 from drgn import cast
@@ -30,6 +32,7 @@
 from drgn_tools.dentry import dentry_path_any_mount
 from drgn_tools.dentry import sb_first_mount_point
 from drgn_tools.task import is_group_leader
+from drgn_tools.task import task_lastrun2now
 from drgn_tools.util import type_has_member
 
 FSNOTIFY_FLAGS = {
@@ -196,6 +199,16 @@ def fsnotify_summarize_object(kind: str, obj: Object) -> str:
         return "(not implemented)"
 
 
+def _print_waiter(task: Object, kind: str, pfx: Optional[str]):
+    if not pfx:
+        pfx = ""
+    wait_time = task_lastrun2now(task)
+    wait_time_fmt = str(timedelta(seconds=wait_time / 1000000000))
+    print(
+        f"{pfx}[PID: {task.pid.value_()} COMM: {task.comm.string_().decode()}] WAIT: {kind} DURATION: {wait_time_fmt}"
+    )
+
+
 def print_waitqueue(
     wq: Object, indent: int = 2, stack_trace: bool = False
 ) -> None:
@@ -229,9 +242,7 @@ def print_waitqueue(
         if func == "pollwake":
             wqueues = cast("struct poll_wqueues *", entry.private)
             task = wqueues.polling_task
-            print(
-                f"{pfx}[PID: {task.pid.value_()} COMM: {task.comm.string_().decode()} WAIT: select]"
-            )
+            _print_waiter(task, "select", pfx)
             if stack_trace:
                 bt(task, indent=indent + 2)
         elif func == "ep_poll_callback":
@@ -255,9 +266,7 @@ def print_waitqueue(
             info = slab_object_info(entry.private)
             if info and info.slab_cache.name.string_() == b"task_struct":
                 task = cast("struct task_struct *", entry.private)
-                print(
-                    f"{pfx}[PID: {task.pid.value_()} COMM: {task.comm.string_().decode()} WAIT: direct]"
-                )
+                _print_waiter(task, "direct", pfx)
                 if stack_trace:
                     bt(task, indent=indent + 2)