レスポンス遅延の原因調査

[yonaka15]

レスポンスが異常に遅い件について、原因を調査中です。

ユーザーからの追加情報 (2025/06/10):

• どのようなリクエストでも時間がかかる。
• 常に発生する。
• 10数秒程度の遅延が発生する。
• Redmine以外のMCPサーバーでも同様の遅延が発生するため、DockerもしくはRust側の問題である可能性が高い。

ログ分析結果 (2025/06/11):

提供いただいたログを分析した結果、以下の点が明らかになりました。

1. MCPサーバーリクエストのタイムアウト:
   [1749558410005] [ERROR] [MCP_PROCESS] Query #43 timed out after 30.003534472s
   MCPサーバー（Node.jsやPython等で実装された実際の処理部分）へのリクエストが30秒のタイムアウト設定を超過しています。

2. プロセスロック取得の遅延:
   [1749558410005] [DEBUG] [HTTP_HANDLER] Acquired process lock in 8.374173754s
   HTTPリクエストハンドラがMCPサーバープロセスへのアクセス権（ロック）を取得するのに約8.37秒かかっています。これがレスポンス遅延の主な原因と考えられます。

3. MCPサーバー自体の応答速度:
   タイムアウトが発生した後、次のリクエスト（Query #44）はMCPサーバープロセス自体は非常に高速に応答しています（約11.7ms）。
   このことから、MCPサーバー（Node.jsやPythonで記述されたエージェントなど）自体の処理は遅くないと考えられます。

4. HTTPハンドラ全体の処理時間:
   正常に完了したリクエスト（Query #44）でも、HTTPハンドラ全体としては約8.38秒かかっており、これはプロセスロック取得の遅延時間とほぼ一致します。

結論:

レスポンスが10数秒かかる主な原因は、Rust側のHTTPハンドラがMCPサーバープロセスへのアクセスロックを取得するのに非常に時間がかかっていることである可能性が極めて高いです。
これは、前のリクエストがタイムアウトした際に、ロックが適切に解放されない、あるいはプロセスが不安定な状態になり、後続のリクエストがロックを取得できるまで長時間待たされる、といったシナリオが考えられます。

開発者への依頼:

Rust側のロック管理機構、特にリクエストタイムアウト発生時のロック解放処理やプロセスの状態管理に問題がないか、コードレビューをお願いします。

ユーザーへの追加確認事項:

1. 環境変数 RESPONSE_TIMEOUT_SECS と PROCESS_INIT_WAIT_SECS の現在の設定値を改めて教えてください。
2. もし可能であれば、RESPONSE_TIMEOUT_SECS の値を一時的に変更（例: 10秒や60秒）した場合、ロック取得の遅延時間や全体のレスポンス時間に変化が見られるか確認していただけると助かります。

引き続き、上記について情報提供をお願いします。

[yonaka15]

Thank you for the information regarding the environment variables.

It is now confirmed that RESPONSE_TIMEOUT_SECS is using its default value of 30 seconds, and PROCESS_INIT_WAIT_SECS is using its default value of 2 seconds, as these environment variables are not explicitly set.

Based on the logs and this information, the primary suspect for the excessive response time remains the significant delay in acquiring the process lock within the Rust HTTP handler, especially after a preceding request times out.

Could you please conduct a detailed code review focusing on:

1. Lock Release Mechanism: Ensure that the process lock is correctly and promptly released when a request to the MCP server times out.
2. Process State Management: Verify how the system handles the state of the MCP server process after a timeout. Is it possible that the process enters an unstable state that prevents or delays new lock acquisitions?
3. Concurrency Handling: Review how concurrent requests are managed and how the lock contention is resolved, particularly in scenarios involving timeouts.

The previously observed log entries (Acquired process lock in X.Xs after a timeout) strongly suggest an issue in this area.

ユーザーより、環境変数 RESPONSE_TIMEOUT_SECS と PROCESS_INIT_WAIT_SECS は設定されていないとの情報をいただきました。これにより、これらの変数はデフォルト値で動作していることが確定しました。

引き続き、Rustコードのロック管理機構（特にタイムアウト時の処理）とプロセスの安定性について調査をお願いします。

[yonaka15]

The investigation into the response delay has continued.

Summary of Findings:
As previously determined, the primary cause of the delay appears to be the significant time taken to acquire the process lock in the Rust HTTP handler (mcp_process.lock().await), as evidenced by the log: [1749558410005] [DEBUG] [HTTP_HANDLER] Acquired process lock in 8.374173754s.
This typically means that the preceding request (Query #43, which timed out) held onto the lock for an unexpectedly long duration or did not release it promptly.

The timeout mechanism within McpServerProcess::query (tokio::time::timeout) seems to be functioning correctly, as Query #43 logged a timeout: [1749558410005] [ERROR] [MCP_PROCESS] Query #43 timed out after 30.003534472s.

In Rust, MutexGuards are designed to release locks automatically when they go out of scope (due to RAII), whether the function returns normally or due to an error. The handle_request function in src/main.rs should adhere to this.

Potential Problem Area:
The most likely scenario is that the Tokio task handling the timed-out request (Query #43) did not terminate cleanly or promptly after the timeout was detected. This could lead to a delay in the MutexGuard being dropped, thus preventing subsequent requests from acquiring the lock quickly.
The exact point of this hang or extended processing within the handle_request task, after a query timeout, is not apparent from the current code and logs.

Recommendations for Further Investigation by Developers:

1. Trace Task Completion: Verify that the Tokio task for handle_request consistently and quickly completes all its operations (especially the dropping of the MutexGuard) even when an internal query times out.
2. Enhanced Logging: Implement more detailed logging within handle_request and McpServerProcess::query. This should include timestamps and potentially task IDs at critical points such as:
   • Before and after acquiring/releasing the Arc<Mutex<McpServerProcess>> lock.
   • Before and after every .await call, especially those involving I/O with the child process or the tokio::time::timeout itself.
   • Immediately before the handle_request function returns (both for Ok and Err paths).
3. Investigate I/O Operation Behavior on Timeout: Examine how the underlying I/O operations with the child process (e.g., stdin.write_all, stdout.read_line) behave when the tokio::time::timeout wrapper interrupts them. Ensure that these operations don't leave the child process or the communication pipes in an unstable state that could affect subsequent lock release or process interactions.

Without more detailed tracing, pinpointing the exact cause of the lock contention post-timeout is challenging. The issue likely lies in the intricate details of asynchronous operations, task lifecycle management after timeouts, or interactions with the Axum framework during error handling.

We will await further insights from the developers based on these points.