HTTP タイムアウト問題のトラブルシューティングにおいて、膨大なログを前に途方に暮れたご経験はございませんか。あるいは、Core Dump を用いてコールスタックを追跡したものの、問題発生時の真のコンテキストを特定できなかったことはございませんか。

この度、弊社ではタイムトラベルデバッガーである UDB を OpenResty XRay と連携させ、Python のネットワークリクエストが発行されてから応答を受け取るまでの全プロセスを完全に再現し、問題の根本原因を特定することに成功いたしました。

Python デバッグにおける UDB の独自の価値

UDB (Undo Debugger) は、Python 開発者に全く新しいデバッグ体験をもたらす時間遡行デバッガー (Time-travel debugger) です。pdb や PyCharm などの従来のデバッグツールと比較した際の UDB の最大の利点は、プログラムの実行過程を完全に記録し、開発者が実行履歴を自由自在に遡れる点にあります。

Python のようなインタプリタ言語において、UDB の価値は特に顕著です:

  • 実行軌跡の完全なキャプチャ:低レベルの C 拡張モジュールの呼び出しを含め、Python インタプリタの実行ステップを完全に記録します。
  • 確実な問題再現:プログラムを再起動することなく、同一のバグを何度でも再現し、分析することが可能です。
  • クロス言語のシームレスなデバッグ:Python コードと、その基盤となる C/C++ 拡張機能の実行フローを同時に追跡・観察できます。
  • 正確なパフォーマンス分析:時間遡行機能を活用し、パフォーマンスのボトルネックをピンポイントで特定します。
  • 柔軟な拡張性:GDB をベースに構築されているため、GDB の Python API と完全な互換性を有します。これにより、Python スクリプトを用いてデバッガーの機能を自由に拡張することが可能です。

OpenResty XRay との連携によるデバッグ能力の強化

OpenResty XRay は、優れた動的トレーシング (dynamic tracing) ツールです。実行中のアプリケーションを自動的に分析し、パフォーマンスのボトルネック、異常な動作、セキュリティの脆弱性を迅速に特定し、実用的な最適化の提案を行います。OpenResty XRay の基盤は、当社が独自に開発した Y 言語 によって駆動されており、Stap+、eBPF+、GDB、ODB といった多様な実行環境を容易にサポートします。

UDB は GDB バックエンドの Python 拡張機能をロードすることができるため、UDB 環境内で XRay の高度な分析ツールを直接使用することが可能になります。UDB のタイムトラベルデバッグと OpenResty XRay の詳細なパフォーマンス分析を組み合わせることで、開発者はアプリケーションの実行に関するより包括的な情報を得ることができます。マクロなパフォーマンスからミクロなコールスタックに至るまで一目で把握することができ、問題の診断と解決の効率を大幅に向上させます。

実践事例:Python のネットワークリクエストにおけるコールスタックの分析

以下では、実際の事例を通じて、UDB を用いて Python アプリケーションにおけるネットワークリクエストの実行プロセスを詳細に分析する方法をご紹介します。

ステップ 1:アプリケーション実行トレースの記録

まず、UDB の Live Record ツールを使用して、Python ネットワークアプリケーションの実行を記録する必要があります。

  1. サンプルとして、requests ライブラリを使用して HTTP リクエストを送信する Python アプリケーションを選択し、Live Record ツールでその実行プロセスを記録し、完全な実行詳細をキャプチャします。

  2. 次に、UDB ツールでこの記録サンプルをロードします:

udb -ex "set pagination off" -ex "set python print-stack full" python.rec

ステップ 2:ネットワークリクエストのキーとなるブレークポイントの設定

UDB 環境では、ネットワークリクエストの主要な段階を捕捉するために、ブレークポイントを設定する必要がございます。HTTP リクエストにおいて、最も中核となるシステムコールは connect(接続確立)と recv(データ受信)です:

start 1> break connect
Breakpoint 1 at 0x7ffff750f590: file ../sysdeps/unix/sysv/linux/connect.c, line 24.
start 1> break recv
Breakpoint 2 at 0x7ffff750f700: file ../sysdeps/unix/sysv/linux/recv.c, line 24.
start 1> c
Continuing.
[New Thread 1259245.1261346]
[Switching to Thread 1259245.1261346]

Thread 2 "python3" hit Breakpoint 1, __libc_connect (fd=fd@entry=3, addr=addr@entry=..., len=len@entry=16) at ../sysdeps/unix/sysv/linux/connect.c:24

プログラムが connect システムコールを実行すると、UDB は実行を一時停止し、現在位置を表示します。これは、Python プログラムがネットワーク接続を確立しようとしていることを示しており、HTTP リクエストの最初の段階です。これらのキーポイントにブレークポイントを設定することで、ネットワーク操作の各段階を正確に捕捉することが可能になります。

ステップ 3:低レベル C コールスタックの分析

ブレークポイントがトリガーされた後、まず bt コマンドを使用して現在の C 言語レイヤーのコールスタックを確認します:

5% 181,380> bt
#0  __libc_connect (fd=fd@entry=3, addr=addr@entry=..., len=len@entry=16) at ../sysdeps/unix/sysv/linux/connect.c:24
#1  0x00007ffff74f5b3f in try_connect (family=<optimized out>, addrlen=16, addr=0x7fffe40042a0, source_addrp=0x7fffe8d47848, afp=<synthetic pointer>, fdp=<synthetic pointer>)
    at ../sysdeps/posix/getaddrinfo.c:2272
#2  __GI_getaddrinfo (name=<optimized out>, name@entry=0x7fffe8d9a900 "localhost", service=<optimized out>, service@entry=0x7fffe8d99bb8 "8888", hints=<optimized out>, hints@entry=0x7fffe8d48070,
    pai=pai@entry=0x7fffe8d48058) at ../sysdeps/posix/getaddrinfo.c:2493
#3  0x00007ffff768e5b2 in socket_getaddrinfo (self=0x7fffe9cd7920, args=<optimized out>, kwargs=<optimized out>) at ./Modules/socketmodule.c:6763
#4  0x00007ffff79c98e8 in cfunction_call (func=0x7fffe9cd7f60, args=0x7fffe8d80400, kwargs=0x0) at Objects/methodobject.c:537
...省略部分输出...
#29 0x00007ffff7b667f8 in thread_run (boot_raw=0x7fffe4005aa0) at ./Modules/_threadmodule.c:1114
#30 0x00007ffff7aef967 in pythread_wrapper (arg=<optimized out>) at Python/thread_pthread.h:237
#31 0x00007ffff7489d22 in start_thread (arg=<optimized out>) at pthread_create.c:443
#32 0x00007ffff750ed40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

この C 言語のコールスタックから、いくつかの重要な情報を読み取れます

  1. スタックの底部(#32~#30)から、これが Python スレッド内で実行されているコードであることがわかります。
  2. #2~#0 では、システムが getaddrinfo 関数と connect 関数を実行していることが確認でき、プログラムがホスト名を解決して接続を試みていることを示唆しています。
  3. #3 から、これが Python の socket モジュールからの呼び出しであることがわかります。

しかし、この C コールスタックは主に低レベルの実装詳細を示すものであり、Python アプリケーション層のロジックを理解するには情報が十分ではありません。どの Python 関数やモジュールがこのネットワークリクエストを開始したのかを直接特定することは困難です。そこで、OpenResty XRay が提供するツールを利用して Python のコードパスを分析する必要があります。

ステップ 4:Python コールスタックの分析

C コールスタックは詳細ですが、Python 開発者にとっては直感的ではありません。より有意義な Python レベルでの呼び出し情報を取得するために、OpenResty XRay が提供する専用ツールを使用する必要があります。

  1. まず、OpenResty XRay が提供する Python コールスタック分析ツールをロードします。
5% 181,380> source python-udb.y.py

これは、OpenResty XRay が UDB 環境専用に開発した Python 拡張機能で、Python の内部構造を解析し、完全な Python コールスタックを抽出することができます。

  1. 次に、Python インタプリタがコードを実行するコア関数である _PyEval_EvalFrameDefault にジャンプします:
5% 181,380> b _PyEval_EvalFrameDefault
Breakpoint 3 at 0x7ffff790c100: file ./Include/internal/pycore_pystate.h, line 107.
5% 181,406> c
Continuing.

Thread 2 "python3" hit Breakpoint 3, _PyEval_EvalFrameDefault (tstate=0x93cb00, frame=0x7ffff73de000, throwflag=0) at ./Include/internal/pycore_pystate.h:107

この関数は Python インタプリタがバイトコードを実行する上での中核を担っており、ここにブレークポイントを設定することで Python コードの実行コンテキストをキャプチャできます。

  1. 次に python_bt コマンドを使用して、完全な Python のコールスタックを取得します:
5% 182,479> python_bt
C:_PyEval_EvalFrameDefault
@/usr/local/openresty-python3/lib/python3.12/socket.py:106
_intenum_converter
@/usr/local/openresty-python3/lib/python3.12/socket.py:978
getaddrinfo
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/util/connection.py:60
create_connection
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connection.py:199
_new_conn
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connection.py:279
connect
@/usr/local/openresty-python3/lib/python3.12/http/client.py:1035
send
@/usr/local/openresty-python3/lib/python3.12/http/client.py:1091
_send_output
@/usr/local/openresty-python3/lib/python3.12/http/client.py:1331
endheaders
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connection.py:441
request
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connectionpool.py:495
_make_request
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connectionpool.py:789
urlopen
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/adapters.py:667
send
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/sessions.py:703
send
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/sessions.py:589
request
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/api.py:59
request
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/api.py:73
get
@/opt/app/processor.py:10
make_request
@/usr/local/openresty-python3/lib/python3.12/threading.py:1012
run
@/usr/local/openresty-python3/lib/python3.12/threading.py:1075
_bootstrap_inner
@/usr/local/openresty-python3/lib/python3.12/threading.py:1032
_bootstrap

こちらの Python コールスタックは、リクエスト全体の呼び出し経路を明確に示しております:

  • 最下層は Python スレッドの起動関数 _bootstrap です。
  • 中間では requests ライブラリの各層の呼び出しを経由します。
  • 最終的に、弊社のビジネスロジックである /opt/app/processor.py の 10 行目、make_request 関数において requests.get メソッドが呼び出されます。

これは C 言語のコールスタックよりも遥かに直感的であり、ビジネスロジックから低レイヤーのネットワークオペレーションに至るまでの完全な呼び出しパスを明確に把握することが可能となります。

  1. 続いて、プログラムの実行を継続し recv のブレークポイントで停止させ、レスポンスデータ受信時のコールスタックを分析します:
5% 182,479> delete breakpoint 3
5% 182,479> c
Continuing.

Thread 4 "python3" hit Breakpoint 2, __libc_recv (fd=3, buf=buf@entry=0x7fffe400a210, len=len@entry=8192, flags=flags@entry=0) at ../sysdeps/unix/sysv/linux/recv.c:24
5% 185,730> b _PyEval_EvalFrameDefault
Breakpoint 4 at 0x7ffff790c100: file ./Include/internal/pycore_pystate.h, line 107.
5% 185,730> c
Continuing.

Thread 2 "python3" hit Breakpoint 4, _PyEval_EvalFrameDefault (tstate=0x93cb00, frame=0x7ffff73ddea0, throwflag=0) at ./Include/internal/pycore_pystate.h:107
5% 186,005> python_bt
C:_PyEval_EvalFrameDefault
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connection.py:504
getresponse
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connectionpool.py:536
_make_request
@/usr/local/openresty-python3/lib/python3.12/site-packages/urllib3/connectionpool.py:789
urlopen
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/adapters.py:667
send
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/sessions.py:703
send
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/sessions.py:589
request
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/api.py:59
request
@/usr/local/openresty-python3/lib/python3.12/site-packages/requests/api.py:73
get
@/opt/app/processor.py:10
make_request
@/usr/local/openresty-python3/lib/python3.12/threading.py:1012
run
@/usr/local/openresty-python3/lib/python3.12/threading.py:1075
_bootstrap_inner
@/usr/local/openresty-python3/lib/python3.12/threading.py:1032
_bootstrap

このコールスタックは、HTTP レスポンスを受信し処理する過程を示しています。一見すると、この呼び出しパスはリクエスト送信時と類似していますが、詳細には大きな違いがあります。重要な関数は urllib3/connection.py の 504 行目にあり、getresponse 関連のコードが実行されています。

OpenResty XRay の全自動分析機能と、UDB の「タイムトラベル」機能を組み合わせることで、ネットワークリクエストの全ライフサイクルを再現するだけでなく、接続確立、データ送信、レスポンス受信といった各段階において、コードレベルまで正確に掘り下げることが可能になりました。このような詳細な分析は、従来のデバッグツールや Core Dump では到底実現できません。

なぜこれが「時間軸」におけるデバッグの革新と言えるのでしょうか。従来の手法と比較して、UDB は真に動的かつ完全なコンテキスト情報を提供します。

  • Core Dump は、プログラムがクラッシュした瞬間の静的な状態しか確認できません。
  • UDB は、元のプロセスが既に終了していても、リクエストの全過程を再生できます。
  • リクエスト過程の任意の段階でブレークポイントを設定し、変数や関数呼び出しを観察できます。
  • さらに、Python と低レベルの C 拡張を横断し、システム全体の動作チェーンを完全に追跡することも可能です。

例えば、HTTP タイムアウト問題に直面した場合、Core Dump では通常、「最終的にどこで停止したか」しか分かりません。しかし、UDB を使用すれば、リクエストの開始時点から実行パスを一つ一つ辿り、どの時点で遅延が発生し、どの呼び出しがレスポンスを遅らせたかを正確に特定できます。

まとめ

本稿の実践的なケーススタディを通じて、UDB と OpenResty XRay を組み合わせることで、開発者が Python のネットワークリクエストの実行プロセスをいかに深く分析できるかを示しました。UDB のタイムトラベルデバッグ機能は、Python 開発者に前例のない洞察力をもたらし、以下のことを可能にします。

  1. 実行パスの完全な追跡:高レベルの Python コードから低レベルのシステムコールまで、あらゆるステップを漏れなく捕捉します。
  2. 重要ノードの正確な特定:ネットワークリクエストの各段階(接続確立、データ送信、レスポンス受信)でブレークポイントを設定し、分析を行います。
  3. 言語の壁を越えたシームレスなデバッグ:Python コードと低レベルの C 拡張の実行状況を同時に確認できます。
  4. 自由な遡及分析:実行履歴を自由に遡り、従来のデバッガの制約を受けません。

もし、皆様もネットワーク問題、パフォーマンスのボトルネック、あるいは複雑なコールスタックにお悩みでしたら、ぜひこの「タイムトラベルデバッグ」という新しい手法をお試しください。UDB と OpenResty XRay が、デバッグの泥沼から抜け出し、プログラムの各フレームを明確に把握するためのお手伝いをいたします。

OpenResty XRay について

OpenResty XRay動的トレーシング製品であり、実行中のアプリケーションを自動的に分析して、パフォーマンスの問題、動作の問題、セキュリティの脆弱性を解決し、実行可能な提案を提供いたします。基盤となる実装において、OpenResty XRay は弊社の Y 言語によって駆動され、Stap+、eBPF+、GDB、ODB など、様々な環境下で複数の異なるランタイムをサポートしております。

著者について

章亦春(Zhang Yichun)は、オープンソースの OpenResty® プロジェクトの創始者であり、OpenResty Inc. の CEO および創業者です。

章亦春(GitHub ID: agentzh)は中国江蘇省生まれで、現在は米国ベイエリアに在住しております。彼は中国における初期のオープンソース技術と文化の提唱者およびリーダーの一人であり、Cloudflare、Yahoo!、Alibaba など、国際的に有名なハイテク企業に勤務した経験があります。「エッジコンピューティング」、「動的トレーシング」、「機械プログラミング」 の先駆者であり、22 年以上のプログラミング経験と 16 年以上のオープンソース経験を持っております。世界中で 4000 万以上のドメイン名を持つユーザーを抱えるオープンソースプロジェクトのリーダーとして、彼は OpenResty® オープンソースプロジェクトをベースに、米国シリコンバレーの中心部にハイテク企業 OpenResty Inc. を設立いたしました。同社の主力製品である OpenResty XRay動的トレーシング技術を利用した非侵襲的な障害分析および排除ツール)と OpenResty XRay(マイクロサービスおよび分散トラフィックに最適化された多機能ゲートウェイソフトウェア)は、世界中の多くの上場企業および大企業から高い評価を得ております。OpenResty 以外にも、章亦春は Linux カーネル、Nginx、LuaJITGDBSystemTapLLVM、Perl など、複数のオープンソースプロジェクトに累計 100 万行以上のコードを寄与し、60 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

英語版の原文と日本語訳版(本文)をご用意しております。読者の皆様による他の言語への翻訳版も歓迎いたします。全文翻訳で省略がなければ、採用を検討させていただきます。心より感謝申し上げます!