2025/10/10

GNOME Terminal 逾時問題追查過程

 結果沒有解決問題...

第一階段：理解問題現象

1觀察錯誤訊息

錯誤訊息：
Error constructing proxy for org.gnome.Terminal:/org/gnome/Terminal/Factory0:
Error calling StartServiceByName for org.gnome.Terminal:
Timeout was reached
🤔 分析思路：
  • 錯誤提到 org.gnome.Terminal - 這是 D-Bus 服務名稱
  • StartServiceByName - D-Bus 正在嘗試啟動服務
  • Timeout was reached - 服務啟動時間過長，超過逾時限制
  • 但 terminal 最終有啟動 - 表示服務最終成功了，只是太慢
✅ 初步結論：

不是完全失敗，而是啟動太慢。需要找出是什麼在拖慢啟動速度。

2檢查當前系統狀態

$ echo $DBUS_SESSION_BUS_ADDRESS
unix:path=/run/user/1000/bus
$ ps aux | grep dbus-daemon | grep -v grep
charles+ 3481 /usr/bin/dbus-daemon --session ...
$ gnome-terminal --version
GNOME Terminal 3.52.0 using VTE 0.76.0
🤔 分析：
  • D-Bus 正常運作 - 排除 D-Bus 本身的問題
  • gnome-terminal 已安裝且可執行 - 排除安裝問題
  • 問題應該在啟動機制或相依服務

第二階段：追查服務啟動時間

3檢查 systemd 服務狀態

$ systemctl --user status gnome-terminal-server.service
● gnome-terminal-server.service - GNOME Terminal Server
   Active: active (running) since Fri 2025-10-10 10:34:43
Main PID: 4791
🤔 分析：
  • Terminal 是透過 systemd 的 D-Bus 啟動機制運作
  • 服務目前正在運行 - 所以之前的啟動最終成功了
  • 需要查看啟動歷史，找出為何第一次啟動很慢

4分析 systemd 服務啟動時間

$ systemd-analyze --user blame | head -20
1min 30.058s xdg-desktop-portal.service
     25.121s gnome-terminal-server.service  ⬅️ 發現問題！
      2.264s snap.snapd-desktop-integration.service
      2.139s org.gnome.Shell@x11.service
🎯 發現：

gnome-terminal-server.service 啟動花了 25.121 秒！

另外 xdg-desktop-portal.service 更慢，花了 90 秒。這兩者可能有關聯。

5檢查服務啟動日誌

$ journalctl --user -u gnome-terminal-server.service --no-pager
Oct 10 10:34:43 systemd[3444]: Starting gnome-terminal-server.service
Oct 10 10:35:08 systemd[3444]: Started gnome-terminal-server.service  ⬅️ 25秒後！
🤔 分析：
  • 10:34:43 開始啟動
  • 10:35:08 完成啟動（25 秒間隔）
  • 這 25 秒發生了什麼？需要更深入的追蹤

第三階段：分析相依性與等待原因

6檢查服務相依性鏈

$ systemd-analyze --user critical-chain gnome-terminal-server.service
gnome-terminal-server.service +25.121s
└─basic.target @146ms
  └─sockets.target @146ms
    └─gpg-agent-ssh.socket @129ms +17ms
🤔 分析：
  • 所有相依服務在 146ms 就準備好了
  • 但 terminal-server 本身花了 25 秒
  • 結論：延遲不是因為等待相依性，而是服務本身初始化慢

7查看完整的系統日誌（關鍵步驟）

$ journalctl --user --since "10:34:40" --until "10:35:10" --no-pager
Oct 10 10:34:43 dbus-daemon: Activating via systemd: org.gnome.Terminal
Oct 10 10:34:43 systemd: Starting gnome-terminal-server.service
Oct 10 10:34:45 systemd: xdg-desktop-portal.service: start operation timed out ⬅️ 重要！
Oct 10 10:34:45 systemd: Failed to start xdg-desktop-portal.service
Oct 10 10:35:08 dbus-daemon: Successfully activated service org.gnome.Terminal
🎯 重大突破：

在 terminal 啟動期間，xdg-desktop-portal.service 發生逾時失敗！

時間點很可疑：portal 在 10:34:45 失敗，terminal 在 10:35:08 完成（23 秒差異）。

第四階段：追查 Portal 與 Terminal 的關聯

8檢查更早的日誌，了解 Portal 為何失敗

$ journalctl --user --since "10:34:00" --until "10:35:15" | grep -i "portal\|timeout"
Oct 10 10:34:07 xdg-desktop-por: Failed to create settings proxy:
                 Error calling StartServiceByName for org.freedesktop.impl.portal.desktop.gnome:
                 Timeout was reached  ⬅️ GNOME portal backend 逾時！

Oct 10 10:34:30 xdg-desktop-por: Failed to create file chooser proxy:
                 Timeout was reached

Oct 10 10:34:45 systemd: xdg-desktop-portal.service: start operation timed out
🎯 找到連鎖反應：
  1. 10:34:07 - portal 嘗試啟動 GNOME 後端，逾時
  2. 10:34:30 - portal 嘗試建立 file chooser，又逾時
  3. 10:34:45 - portal 服務整個逾時失敗

GTK 應用程式（如 gnome-terminal）會嘗試連接 portal，這導致等待。

9檢查 GNOME Portal 服務狀態與相依性

$ systemctl --user cat xdg-desktop-portal-gnome.service
[Unit]
Description=Portal service (GNOME implementation)
After=graphical-session.target
Requisite=graphical-session.target  ⬅️ 關鍵！必須在圖形工作階段之後
PartOf=graphical-session.target
🤔 分析：
  • Requisite=graphical-session.target 是嚴格要求
  • 如果 graphical-session.target 未就緒，服務會立即失敗
  • 需要確認 graphical-session.target 何時就緒

第五階段：追查工作階段初始化時序

10檢查 graphical-session.target 啟動時間

$ systemd-analyze --user critical-chain graphical-session.target
graphical-session.target @4.160s  ⬅️ 工作階段開始後 4.16 秒才就緒
└─basic.target @146ms
$ journalctl --user --since "10:33:15" --until "10:33:25" | grep "graphical-session.target"
Oct 10 10:33:17 systemd: graphical-session.target is inactive  ⬅️ 還未就緒
Oct 10 10:33:19 systemd: Reached target graphical-session.target  ⬅️ 2秒後就緒
🎯 發現時序問題：
  • 10:33:15 - 使用者工作階段啟動
  • 10:33:17 - graphical-session.target 還未就緒
  • 10:33:19 - graphical-session.target 就緒

11檢查 Portal 何時嘗試啟動（關鍵發現）

$ journalctl --user --since "10:33:15" --until "10:33:20" | grep -E "desktop-portal|graphical-session"
Oct 10 10:33:17 dbus-daemon: Activating: org.freedesktop.impl.portal.desktop.gnome
                requested by fcitx5  ⬅️ fcitx5 觸發 portal 啟動！

Oct 10 10:33:17 systemd: graphical-session.target is inactive  ⬅️ 同時間 target 未就緒
Oct 10 10:33:17 systemd: Dependency failed for xdg-desktop-portal-gnome.service  ⬅️ 失敗！

Oct 10 10:33:19 systemd: Reached target graphical-session.target  ⬅️ 2秒後才就緒
🎯🎯🎯 根本原因找到了！

競態條件（Race Condition）：

  1. 10:33:17 - fcitx5（輸入法）啟動並請求 portal
  2. 10:33:17 - portal 嘗試啟動但 graphical-session.target 未就緒
  3. 10:33:17 - portal 啟動失敗（相依性未滿足）
  4. 10:33:19 - graphical-session.target 就緒（但 portal 已失敗，不會重試）
  5. 10:34:43 - 使用者啟動 terminal，嘗試連接已失敗的 portal
  6. 10:35:08 - 25 秒逾時後放棄，terminal 繼續啟動

第六階段：驗證根本原因

12確認是誰觸發了過早的 Portal 啟動

$ journalctl --user --since "10:33:17" | grep "fcitx" | head -5
Oct 10 10:33:17 dbus-update-activation-environment: setting GTK_IM_MODULE=fcitx
Oct 10 10:33:17 dbus-daemon: requested by ':1.18' (uid=1000 pid=3699 comm="/usr/bin/fcitx5 -d")
$ ps aux | grep fcitx5
charles+ 3699 /usr/bin/fcitx5 -d ⬅️ 確認 fcitx5 正在運行
✅ 驗證完成：

fcitx5 在工作階段早期（10:33:17）就啟動了，比 graphical-session.target（10:33:19）早 2 秒。

當 fcitx5 啟動時，它作為 GTK 應用程式會嘗試連接 xdg-desktop-portal，觸發了過早的啟動嘗試。

13測試修復後的行為

$ systemctl --user stop gnome-terminal-server.service
$ time gnome-terminal --version
real    0m0.045s  ⬅️ 現在很快！（之前是 25 秒）
🤔 分析思路：

如果手動重啟服務，它啟動很快。這證實問題只發生在工作階段早期的特定時間窗口。

張貼者： 於

沒有留言:

張貼留言

訂閱： 張貼留言 (Atom)