Break down startup terminal profiling

docs/project_docs/startup-profile-breakdown/plan.md

@@ -0,0 +1,20 @@
+# startup-profile-breakdown Plan
+
+## Goal
+
+`--startup-profile` のログで `create-terminal` の内訳を確認できるようにする。
+
+## Scope
+
+- `create-terminal` を内部的に 2 段へ分解
+  - terminal build
+  - raw mode enter
+- startup profile ログに細分化した時間を出力
+- 既存の TUI 起動挙動は変えない
+
+## Tests
+
+- `test/ceeker/tui/input_test.clj`
+  - `create-terminal-profile` が build/raw-mode/total を返すこと
+- `test/ceeker/tui/app_test.clj`
+  - startup profile ログに細分化した項目が出ること

src/ceeker/tui/app.clj

@@ -143,13 +143,21 @@
 
 (defn- log-startup-profile!
   "Logs startup profiling summary to stderr."
-  [{:keys [create-terminal create-watcher
+  [{:keys [create-terminal-build
+           create-terminal-enter-raw-mode
+           create-terminal-total
+           create-watcher
            start-pane-checker total]}]
   (binding [*out* *err*]
     (println
      (str "ceeker: startup-profile "
-          "create-terminal="
-          (format "%.2fms" create-terminal)
+          "create-terminal.build="
+          (format "%.2fms" create-terminal-build)
+          " create-terminal.enter-raw-mode="
+          (format "%.2fms"
+                  create-terminal-enter-raw-mode)
+          " create-terminal.total="
+          (format "%.2fms" create-terminal-total)
           " create-watcher="
           (format "%.2fms" create-watcher)
           " start-pane-checker="
@@ -163,18 +171,21 @@
   "Creates startup resources and optionally logs timings."
   [state-dir startup-profile?]
   (let [started-at (System/nanoTime)
-        terminal-step (timed-step input/create-terminal)
+        terminal-step (input/create-terminal-profile)
         watcher-step (timed-step
                       #(create-watcher-for state-dir))
         checker-step (timed-step
                       #(start-pane-checker! state-dir))]
     (when startup-profile?
       (log-startup-profile!
-       {:create-terminal (:elapsed-ms terminal-step)
+       {:create-terminal-build (:build-ms terminal-step)
+        :create-terminal-enter-raw-mode
+        (:enter-raw-mode-ms terminal-step)
+        :create-terminal-total (:total-ms terminal-step)
         :create-watcher (:elapsed-ms watcher-step)
         :start-pane-checker (:elapsed-ms checker-step)
         :total (elapsed-ms started-at)}))
-    {:terminal (:result terminal-step)
+    {:terminal (:terminal terminal-step)
      :watcher (:result watcher-step)
      :stop-ch (:result checker-step)}))
 

src/ceeker/tui/input.clj

@@ -3,15 +3,43 @@
   (:import [org.jline.terminal TerminalBuilder]
            [org.jline.utils NonBlockingReader]))
 
+(defn- elapsed-ms
+  "Returns elapsed milliseconds since started-at."
+  [started-at]
+  (/ (- (System/nanoTime) started-at) 1000000.0))
+
+(defn build-terminal
+  "Builds the system terminal."
+  []
+  (-> (TerminalBuilder/builder)
+      (.system true)
+      (.jansi false)
+      (.build)))
+
+(defn enter-raw-mode!
+  "Puts terminal into raw mode."
+  [^org.jline.terminal.Terminal terminal]
+  (.enterRawMode terminal)
+  terminal)
+
+(defn create-terminal-profile
+  "Creates a terminal and returns step timings."
+  []
+  (let [started-at (System/nanoTime)
+        build-started-at (System/nanoTime)
+        terminal (build-terminal)
+        build-ms (elapsed-ms build-started-at)
+        raw-started-at (System/nanoTime)]
+    (enter-raw-mode! terminal)
+    {:terminal terminal
+     :build-ms build-ms
+     :enter-raw-mode-ms (elapsed-ms raw-started-at)
+     :total-ms (elapsed-ms started-at)}))
+
 (defn create-terminal
   "Creates a JLine3 terminal and enters raw mode."
   []
-  (let [terminal (-> (TerminalBuilder/builder)
-                     (.system true)
-                     (.jansi false)
-                     (.build))]
-    (.enterRawMode terminal)
-    terminal))
+  (:terminal (create-terminal-profile)))
 
 (defn- read-escape-seq
   "Reads an escape sequence from reader. Returns keyword or nil."

test/ceeker/tui/app_test.clj

@@ -344,8 +344,12 @@
                       (fn [_] :stop-ch)
                       ceeker.tui.app/tui-loop
                       (fn [& _])
-                      ceeker.tui.input/create-terminal
-                      (fn [] :terminal)
+                      ceeker.tui.input/create-terminal-profile
+                      (fn []
+                        {:terminal :terminal
+                         :build-ms 12.0
+                         :enter-raw-mode-ms 34.0
+                         :total-ms 46.0})
                       ceeker.tui.input/close-terminal
                       (fn [_])
                       ceeker.tui.watcher/close-watcher
@@ -355,7 +359,10 @@
           (app/start-tui! nil {:startup-profile true})))
       (let [output (str err)]
         (is (str/includes? output "ceeker: startup-profile"))
-        (is (str/includes? output "create-terminal="))
+        (is (str/includes? output "create-terminal.build="))
+        (is (str/includes? output
+                           "create-terminal.enter-raw-mode="))
+        (is (str/includes? output "create-terminal.total="))
         (is (str/includes? output "create-watcher="))
         (is (str/includes? output "start-pane-checker="))
         (is (str/includes? output "total="))))))
@@ -370,8 +377,12 @@
                       (fn [_] :stop-ch)
                       ceeker.tui.app/tui-loop
                       (fn [& _])
-                      ceeker.tui.input/create-terminal
-                      (fn [] :terminal)
+                      ceeker.tui.input/create-terminal-profile
+                      (fn []
+                        {:terminal :terminal
+                         :build-ms 12.0
+                         :enter-raw-mode-ms 34.0
+                         :total-ms 46.0})
                       ceeker.tui.input/close-terminal
                       (fn [_])
                       ceeker.tui.watcher/close-watcher
@@ -466,8 +477,12 @@
                     (fn [_] nil)
                     ceeker.tui.app/start-pane-checker!
                     (fn [_] stop-ch)
-                    ceeker.tui.input/create-terminal
-                    (fn [] ::terminal)
+                    ceeker.tui.input/create-terminal-profile
+                    (fn []
+                      {:terminal ::terminal
+                       :build-ms 1.0
+                       :enter-raw-mode-ms 2.0
+                       :total-ms 3.0})
                     ceeker.tui.input/close-terminal
                     (fn [_])
                     ceeker.tui.watcher/close-watcher

test/ceeker/tui/input_test.clj

@@ -0,0 +1,26 @@
+(ns ceeker.tui.input-test
+  (:require [ceeker.tui.input :as input]
+            [clojure.test :refer [deftest is testing]]))
+
+(deftest test-create-terminal-profile-returns-breakdown
+  (testing "create-terminal-profile reports build/raw-mode/total"
+    (let [events (atom [])
+          terminal ::terminal]
+      (with-redefs [ceeker.tui.input/build-terminal
+                    (fn []
+                      (swap! events conj :build)
+                      terminal)
+                    ceeker.tui.input/enter-raw-mode!
+                    (fn [t]
+                      (swap! events conj [:raw-mode t])
+                      t)]
+        (let [profile (input/create-terminal-profile)]
+          (is (= terminal (:terminal profile)))
+          (is (number? (:build-ms profile)))
+          (is (number? (:enter-raw-mode-ms profile)))
+          (is (number? (:total-ms profile)))
+          (is (<= 0.0 (:build-ms profile)))
+          (is (<= 0.0 (:enter-raw-mode-ms profile)))
+          (is (<= 0.0 (:total-ms profile)))
+          (is (= [:build [:raw-mode terminal]]
+                 @events)))))))