Kernel+ProfileViewer: Display additional filesystem events

Userland/DevTools/Profiler/FilesystemEventModel.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, Jakub Berkop <jakub.berkop@gmail.com>
+ * Copyright (c) 2022-2023, Jakub Berkop <jakub.berkop@gmail.com>
  *
  * SPDX-License-Identifier: BSD-2-Clause
  */
@@ -22,11 +22,20 @@ FileEventModel::~FileEventModel()
 {
 }
 
+u64 FileEventNode::total_count() const
+{
+    return m_open.count + m_close.count + m_readv.count + m_read.count + m_pread.count;
+}
+
+Duration FileEventNode::total_duration() const
+{
+    return m_open.duration + m_close.duration + m_readv.duration + m_read.duration + m_pread.duration;
+}
+
 FileEventNode& FileEventNode::find_or_create_node(DeprecatedString const& searched_path)
 {
     // TODO: Optimize this function.
-
-    if (searched_path == ""sv) {
+    if (searched_path == ""sv || searched_path == "/"sv) {
         return *this;
     }
 
@@ -67,7 +76,7 @@ FileEventNode& FileEventNode::create_recursively(DeprecatedString new_path)
     auto parts = lex_path.parts();
 
     if (parts.size() == 1) {
-        auto new_node = FileEventNode::create(new_path, this);
+        auto new_node = FileEventNode::create(parts.take_first(), this);
         m_children.append(new_node);
         return *new_node.ptr();
     } else {
@@ -147,10 +156,30 @@ ErrorOr<String> FileEventModel::column_name(int column) const
     switch (column) {
     case Column::Path:
         return "Path"_string;
-    case Column::Count:
-        return "Event Count"_string;
-    case Column::Duration:
-        return "Duration [ms]"_string;
+    case Column::TotalCount:
+        return "Total Count"_string;
+    case Column::TotalDuration:
+        return "Total Duration [ms]"_string;
+    case Column::OpenCount:
+        return "Open Count"_string;
+    case Column::OpenDuration:
+        return "Open Duration [ms]"_string;
+    case Column::CloseCount:
+        return "Close Count"_string;
+    case Column::CloseDuration:
+        return "Close Duration [ms]"_string;
+    case Column::ReadvCount:
+        return "Readv Count"_string;
+    case Column::ReadvDuration:
+        return "Readv Duration [ms]"_string;
+    case Column::ReadCount:
+        return "Read Count"_string;
+    case Column::ReadDuration:
+        return "Read Duration [ms]"_string;
+    case Column::PreadCount:
+        return "Pread Count"_string;
+    case Column::PreadDuration:
+        return "Pread Duration [ms]"_string;
     default:
         VERIFY_NOT_REACHED();
     }
@@ -167,19 +196,36 @@ GUI::Variant FileEventModel::data(GUI::ModelIndex const& index, GUI::ModelRole r
     auto* node = static_cast<FileEventNode*>(index.internal_data());
 
     if (role == GUI::ModelRole::Display) {
-        if (index.column() == Column::Count) {
-            return node->count();
-        }
-
-        if (index.column() == Column::Path) {
+        switch (index.column()) {
+        case Column::Path:
             return node->path();
+        case Column::TotalCount:
+            return node->total_count();
+        case Column::TotalDuration:
+            return static_cast<f32>(node->total_duration().to_nanoseconds()) / 1'000'000;
+        case Column::OpenCount:
+            return node->open().count;
+        case Column::OpenDuration:
+            return static_cast<f32>(node->open().duration.to_nanoseconds()) / 1'000'000;
+        case Column::CloseCount:
+            return node->close().count;
+        case Column::CloseDuration:
+            return static_cast<f32>(node->close().duration.to_nanoseconds()) / 1'000'000;
+        case Column::ReadvCount:
+            return node->readv().count;
+        case Column::ReadvDuration:
+            return static_cast<f32>(node->readv().duration.to_nanoseconds()) / 1'000'000;
+        case Column::ReadCount:
+            return node->read().count;
+        case Column::ReadDuration:
+            return static_cast<f32>(node->read().duration.to_nanoseconds()) / 1'000'000;
+        case Column::PreadCount:
+            return node->pread().count;
+        case Column::PreadDuration:
+            return static_cast<f32>(node->pread().duration.to_nanoseconds()) / 1'000'000;
+        default:
+            return {};
         }
-
-        if (index.column() == Column::Duration) {
-            return node->duration();
-        }
-
-        return {};
     }
 
     return {};

Userland/DevTools/Profiler/FilesystemEventModel.h

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, Jakub Berkop <jakub.berkop@gmail.com>
+ * Copyright (c) 2022-2023, Jakub Berkop <jakub.berkop@gmail.com>
  *
  * SPDX-License-Identifier: BSD-2-Clause
  */
@@ -9,6 +9,7 @@
 #include <AK/DeprecatedString.h>
 #include <AK/Function.h>
 #include <AK/LexicalPath.h>
+#include <AK/Time.h>
 #include <LibGUI/Model.h>
 
 namespace Profiler {
@@ -35,22 +36,32 @@ public:
 
     DeprecatedString const& path() const { return m_path; }
 
-    void increment_count() { m_count++; }
-    u64 count() const { return m_count; }
+    u64 total_count() const;
+    Duration total_duration() const;
 
-    void add_to_duration(u64 duration) { duration += duration; }
-    u64 duration() const { return m_duration; }
+    struct FileEventType {
+        u64 count = 0;
+        Duration duration = {};
+    };
+
+    FileEventType& open() { return m_open; }
+    FileEventType& close() { return m_close; }
+    FileEventType& readv() { return m_readv; }
+    FileEventType& read() { return m_read; }
+    FileEventType& pread() { return m_pread; }
 
 private:
     FileEventNode(DeprecatedString const& path, FileEventNode* parent = nullptr)
         : m_path(path)
-        , m_count(0)
-        , m_duration(0)
         , m_parent(parent) {};
 
     DeprecatedString m_path;
-    u64 m_count;
-    u64 m_duration;
+
+    FileEventType m_open;
+    FileEventType m_close;
+    FileEventType m_readv;
+    FileEventType m_read;
+    FileEventType m_pread;
 
     Vector<NonnullRefPtr<FileEventNode>> m_children;
     FileEventNode* m_parent = nullptr;
@@ -65,8 +76,18 @@ public:
 
     enum Column {
         Path,
-        Count,
-        Duration,
+        TotalCount,
+        TotalDuration,
+        OpenCount,
+        OpenDuration,
+        CloseCount,
+        CloseDuration,
+        ReadvCount,
+        ReadvDuration,
+        ReadCount,
+        ReadDuration,
+        PreadCount,
+        PreadDuration,
         __Count
     };
 

Userland/DevTools/Profiler/Profile.cpp

@@ -1,5 +1,6 @@
 /*
  * Copyright (c) 2018-2021, Andreas Kling <kling@serenityos.org>
+ * Copyright (c) 2023, Jakub Berkop <jakub.berkop@gmail.com>
  *
  * SPDX-License-Identifier: BSD-2-Clause
  */
@@ -206,19 +207,51 @@ void Profile::rebuild_tree()
                 }
             }
         }
+        if (event.data.has<Event::FilesystemEventData>()) {
+            auto const& filesystem_event = event.data.get<Event::FilesystemEventData>();
+            auto const& path = filesystem_event.data.visit(
+                [&](Event::OpenEventData const& data) {
+                    return data.path;
+                },
+                [&](Event::CloseEventData const& data) {
+                    return data.path;
+                },
+                [&](Event::ReadvEventData const& data) {
+                    return data.path;
+                },
+                [&](Event::ReadEventData const& data) {
+                    return data.path;
+                },
+                [&](Event::PreadEventData const& data) {
+                    return data.path;
+                });
 
-        if (event.data.has<Event::ReadData>()) {
-            auto const& read_event = event.data.get<Event::ReadData>();
-            auto& event_node = m_file_event_nodes->find_or_create_node(read_event.path);
+            auto& event_node = m_file_event_nodes->find_or_create_node(path);
 
             event_node.for_each_parent_node([&](FileEventNode& node) {
-                node.increment_count();
+                auto const duration = filesystem_event.duration;
 
-                // Fixme: Currently events record 'timestamp' and 'start_timestamp' in ms resolution,
-                //        which results in most durations equal to zero. Increasing the resolution should
-                //        make the information more accurate.
-                auto const duration = event.timestamp - read_event.start_timestamp;
-                node.add_to_duration(duration);
+                filesystem_event.data.visit(
+                    [&](Event::OpenEventData const&) {
+                        node.open().duration += duration;
+                        node.open().count++;
+                    },
+                    [&](Event::CloseEventData const&) {
+                        node.close().duration += duration;
+                        node.close().count++;
+                    },
+                    [&](Event::ReadvEventData const&) {
+                        node.readv().duration += duration;
+                        node.readv().count++;
+                    },
+                    [&](Event::ReadEventData const&) {
+                        node.read().duration += duration;
+                        node.read().count++;
+                    },
+                    [&](Event::PreadEventData const&) {
+                        node.pread().duration += duration;
+                        node.pread().count++;
+                    });
             });
         }
     }
@@ -385,15 +418,55 @@ ErrorOr<NonnullOwnPtr<Profile>> Profile::load_from_perfcore_file(StringView path
             if (it != current_processes.end())
                 it->value->handle_thread_exit(event.tid, event.serial);
             continue;
-        } else if (type_string == "read"sv) {
-            auto const string_index = perf_event.get_addr("filename_index"sv).value_or(0);
-            event.data = Event::ReadData {
-                .fd = perf_event.get_integer<int>("fd"sv).value_or(0),
-                .size = perf_event.get_integer<size_t>("size"sv).value_or(0),
-                .path = profile_strings.get(string_index).value(),
-                .start_timestamp = perf_event.get_integer<size_t>("start_timestamp"sv).value_or(0),
-                .success = perf_event.get_bool("success"sv).value_or(false)
+        } else if (type_string == "filesystem"sv) {
+            Event::FilesystemEventData fsdata {
+                .duration = Duration::from_nanoseconds(perf_event.get_integer<u64>("durationNs"sv).value_or(0)),
+                .data = Event::OpenEventData {},
             };
+            auto const filesystem_event_type = perf_event.get("fs_event_type"sv).value_or("").as_string();
+            if (filesystem_event_type == "open"sv) {
+                auto const string_index = perf_event.get_addr("filename_index"sv).value_or(0);
+                auto const filename = profile_strings.get(string_index).value_or("").view();
+                fsdata.data = Event::OpenEventData {
+                    .dirfd = perf_event.get_integer<int>("dirfd"sv).value_or(0),
+                    .path = filename,
+                    .options = perf_event.get_integer<int>("options"sv).value_or(0),
+                    .mode = perf_event.get_integer<u64>("mode"sv).value_or(0),
+                };
+            } else if (filesystem_event_type == "close"sv) {
+                auto const string_index = perf_event.get_addr("filename_index"sv).value_or(0);
+                auto const filename = profile_strings.get(string_index).value_or("").view();
+                fsdata.data = Event::CloseEventData {
+                    .fd = perf_event.get_integer<int>("fd"sv).value_or(0),
+                    .path = filename,
+                };
+            } else if (filesystem_event_type == "readv"sv) {
+                auto const string_index = perf_event.get_addr("filename_index"sv).value_or(0);
+                auto const filename = profile_strings.get(string_index).value().view();
+                fsdata.data = Event::ReadvEventData {
+                    .fd = perf_event.get_integer<int>("fd"sv).value_or(0),
+                    .path = filename,
+                };
+            } else if (filesystem_event_type == "read"sv) {
+                auto const string_index = perf_event.get_addr("filename_index"sv).value_or(0);
+                auto const filename = profile_strings.get(string_index).value().view();
+                fsdata.data = Event::ReadEventData {
+                    .fd = perf_event.get_integer<int>("fd"sv).value_or(0),
+                    .path = filename,
+                };
+            } else if (filesystem_event_type == "pread"sv) {
+                auto const string_index = perf_event.get_addr("filename_index"sv).value_or(0);
+                auto const filename = profile_strings.get(string_index).value().view();
+                fsdata.data = Event::PreadEventData {
+                    .fd = perf_event.get_integer<int>("fd"sv).value_or(0),
+                    .path = filename,
+                    .buffer_ptr = perf_event.get_integer<FlatPtr>("buffer_ptr"sv).value_or(0),
+                    .size = perf_event.get_integer<size_t>("size"sv).value_or(0),
+                    .offset = perf_event.get_integer<off_t>("offset"sv).value_or(0),
+                };
+            }
+
+            event.data = fsdata;
         } else {
             dbgln("Unknown event type '{}'", type_string);
             VERIFY_NOT_REACHED();

Userland/DevTools/Profiler/Profile.h

@@ -1,5 +1,6 @@
 /*
  * Copyright (c) 2018-2021, Andreas Kling <kling@serenityos.org>
+ * Copyright (c) 2023, Jakub Berkop <jakub.berkop@gmail.com>
  *
  * SPDX-License-Identifier: BSD-2-Clause
  */
@@ -20,6 +21,7 @@
 #include <AK/JsonObject.h>
 #include <AK/JsonValue.h>
 #include <AK/OwnPtr.h>
+#include <AK/Time.h>
 #include <AK/Variant.h>
 #include <LibCore/MappedFile.h>
 #include <LibELF/Image.h>
@@ -222,15 +224,45 @@ public:
             pid_t parent_tid {};
         };
 
-        struct ReadData {
-            int fd;
-            size_t size;
+        // Based on Syscall::SC_open_params
+        struct OpenEventData {
+            int dirfd;
             DeprecatedString path;
-            size_t start_timestamp;
-            bool success;
+            int options;
+            u64 mode;
         };
 
-        Variant<nullptr_t, SampleData, MallocData, FreeData, SignpostData, MmapData, MunmapData, ProcessCreateData, ProcessExecData, ThreadCreateData, ReadData> data { nullptr };
+        struct CloseEventData {
+            int fd;
+            DeprecatedString path;
+        };
+
+        struct ReadvEventData {
+            int fd;
+            DeprecatedString path;
+            // struct iovec* iov; // TODO: Implement
+            // int iov_count; // TODO: Implement
+        };
+
+        struct ReadEventData {
+            int fd;
+            DeprecatedString path;
+        };
+
+        struct PreadEventData {
+            int fd;
+            DeprecatedString path;
+            FlatPtr buffer_ptr;
+            size_t size;
+            off_t offset;
+        };
+
+        struct FilesystemEventData {
+            Duration duration;
+            Variant<OpenEventData, CloseEventData, ReadvEventData, ReadEventData, PreadEventData> data;
+        };
+
+        Variant<nullptr_t, SampleData, MallocData, FreeData, SignpostData, MmapData, MunmapData, ProcessCreateData, ProcessExecData, ThreadCreateData, FilesystemEventData> data { nullptr };
     };
 
     Vector<Event> const& events() const { return m_events; }

Userland/DevTools/Profiler/SamplesModel.cpp

@@ -1,6 +1,7 @@
 /*
  * Copyright (c) 2018-2021, Andreas Kling <kling@serenityos.org>
  * Copyright (c) 2022, the SerenityOS developers.
+ * Copyright (c) 2023, Jakub Berkop <jakub.berkop@gmail.com>
  *
  * SPDX-License-Identifier: BSD-2-Clause
  */
@@ -90,9 +91,24 @@ GUI::Variant SamplesModel::data(GUI::ModelIndex const& index, GUI::ModelRole rol
         }
 
         if (index.column() == Column::Path) {
-            if (!event.data.has<Profile::Event::ReadData>())
-                return "";
-            return event.data.get<Profile::Event::ReadData>().path;
+            if (event.data.has<Profile::Event::FilesystemEventData>()) {
+                return event.data.get<Profile::Event::FilesystemEventData>().data.visit(
+                    [&](Profile::Event::OpenEventData const& data) {
+                        return data.path;
+                    },
+                    [&](Profile::Event::CloseEventData const& data) {
+                        return data.path;
+                    },
+                    [&](Profile::Event::ReadvEventData const& data) {
+                        return data.path;
+                    },
+                    [&](Profile::Event::ReadEventData const& data) {
+                        return data.path;
+                    },
+                    [&](Profile::Event::PreadEventData const& data) {
+                        return data.path;
+                    });
+            }
         }
 
         return {};

Userland/DevTools/Profiler/main.cpp

@@ -2,6 +2,7 @@
  * Copyright (c) 2018-2021, Andreas Kling <kling@serenityos.org>
  * Copyright (c) 2021, Julius Heijmen <julius.heijmen@gmail.com>
  * Copyright (c) 2023, Jelle Raaijmakers <jelle@gmta.nl>
+ * Copyright (c) 2023, Jakub Berkop <jakub.berkop@gmail.com>
  *
  * SPDX-License-Identifier: BSD-2-Clause
  */
@@ -264,6 +265,11 @@ ErrorOr<int> serenity_main(Main::Arguments arguments)
     filesystem_events_tree_view->set_column_headers_visible(true);
     filesystem_events_tree_view->set_selection_behavior(GUI::TreeView::SelectionBehavior::SelectRows);
     filesystem_events_tree_view->set_model(profile->file_event_model());
+    filesystem_events_tree_view->set_column_visible(FileEventModel::Column::OpenDuration, false);
+    filesystem_events_tree_view->set_column_visible(FileEventModel::Column::CloseDuration, false);
+    filesystem_events_tree_view->set_column_visible(FileEventModel::Column::ReadvDuration, false);
+    filesystem_events_tree_view->set_column_visible(FileEventModel::Column::ReadDuration, false);
+    filesystem_events_tree_view->set_column_visible(FileEventModel::Column::PreadDuration, false);
 
     auto file_menu = window->add_menu("&File"_string);
     file_menu->add_action(GUI::CommonActions::make_quit_action([&](auto&) { app->quit(); }));