トレース おそらく、痕跡について聞いていない人はいないでしょう。 誰も聞いたことがない場合、straceはシステムコールを追跡するユーティリティです。システムコールは、プロセスとオペレーティングシステム（カーネル）間のインターフェイスを提供する変換メカニズムです。 これらの呼び出しを傍受して読み取ることができます。 これにより、プロセスが特定の時間に何をしようとしているかをよりよく理解できます。 これらの課題を傍受することで、特に何かがうまくいかない場合は、プロセスの動作をよりよく理解できます。 システムコールを監視できるオペレーティングシステムの機能は、ptraceと呼ばれます。 Straceはptraceを呼び出し、プロセス動作データを読み取り、レポートを返します。 詳細はwikiまたは公式の人で読むことができます。 実際、まあ、もちろんLinuxについて話しているところです。 他のオペレーティングシステムには独自の類似物があります。
個人的には、straceは最後の手段のようなものです。 すべてのログが既に表示され、すべてのデバッグキーと詳細キーがオンになっている場合、問題の原因が見つからない
インターネットには、実行中のstraceの例を説明する入門記事がたくさんあります。 この記事では、straceを使用して特定の問題とその解決策を示します。
最初のケース。 KVM仮想マシンは 、ネットワークインターフェイスでvhost = on設定が有効になっていると起動しません。 このパラメーターを省略すると、仮想マシンは正常に起動します。
まず最初に、余分なパラメーターをすべて切り捨て、ネットワークインターフェイスを作成するために必要なオプションとパラメーターのみを残しました。 これは、straceのすでに大量の出力を増加させないために必要です。
＃qemu-system-x86_64 -m 4096 -netdev tap、ifname = tap90、id = tap90、vhost = on-service virtio-net-pci、netdev = tap90、mac = 08：77：D1：00：90：90
qemu-system-x86_64：-netdev tap、ifname = tap90、id = tap90、vhost = on： vhost-netが要求されましたが、初期化できませんでした
qemu-system-x86_64：-netdev tap、ifname = tap90、id = tap90、vhost = on： デバイス「tap」を初期化できませんでした
そのため、straceを使用して仮想マシンを起動し、出力を分析します。 ほとんどの出力を意図的に省略し、問題の原因を特定できる部分のみを示しています。
# strace -f qemu-system-x86_64 -m 4096 -netdev tap,ifname=tap90,id=tap90,vhost=on -device virtio-net-pci,netdev=tap90,mac=08:77:D1:00:90:90 ... open("/dev/vhost-net", O_RDWR) = -1 ENOMEM (Cannot allocate memory) write(2, "qemu-system-x86_64:", 19qemu-system-x86_64:) = 19 write(2, " -netdev", 8 -netdev) = 8 write(2, " tap,ifname=tap90,id=tap90"..., 65 tap,ifname=tap90,id=tap90,vhost=on) = 65 write(2, ": ", 2: ) = 2 write(2, "vhost-net requested but could no"..., 48vhost-net requested but could not be initialized) = 48 write(2, "\n", 1 ) = 1 write(2, "qemu-system-x86_64:", 19qemu-system-x86_64:) = 19 write(2, " -netdev", 8 -netdev) = 8 write(2, " tap,ifname=tap90,id=tap90"..., 65 tap,ifname=tap90,id=tap90,vhost=on) = 65 write(2, ": ", 2: ) = 2 write(2, "Device 'tap' could not be initia"..., 37Device 'tap' could not be initialized) = 37 write(2, "\n", 1 ) = 1
ご覧のとおり、 / dev / vhost-netデバイスを開こうとすると、 open（）呼び出しでエラーが発生します。 その後、仮想マシンの単純な起動で確認されたエラーメッセージが出力されます。
回避策として、 echo 3> / proc / sys / vm / drop_cachesを介してページキャッシュとバッファをリセットする必要がありました。その後、仮想マシンが正常に起動しました。 その後、マシンの一部が他のホストに転送されましたが、それは別の話です。
2番目のケース。 繰り返しますが、仮想マシンと今後の展望について、ここでもメモリの問題だと言います。 経験的に、割り当てられた大量のメモリで仮想マシンが起動しないことが明らかになりました。 この場合、 -m 10240です。 低い値を指定すると、マシンが起動します。 この場合、サーバーの空きメモリは10GB以上です。 そして再び、痕跡を発見します。 以下の例では、仮想マシンの起動オプションのリスト全体と、不要なstrace出力の一部を省略しています。
# strace -f qemu-system-x86_64 -m 10240 ... open(process_vm_readv: Bad address 0x7eff1ccf40b8, O_RDONLY) = 25 fstat(25, process_vm_readv: Bad address {...}) = 0 mmap(NULL, 26244, PROT_READ, MAP_SHARED, 25, 0) = 0x7eff1e74c000 close(25) = 0 futex(0x7eff1cf31900, FUTEX_WAKE_PRIVATE, 2147483647) = 0 mprotect(0x7eff0c021000, 24576, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory) mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7efc72bfd000 munmap(0x7efc72bfd000, 20983808) = 0 munmap(0x7efc78000000, 46125056) = 0 mprotect(0x7efc74000000, 163840, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory) munmap(0x7efc74000000, 67108864) = 0 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory) mprotect(0x7eff0c021000, 24576, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory) mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7efc72bfd000 munmap(0x7efc72bfd000, 20983808) = 0 munmap(0x7efc78000000, 46125056) = 0 mprotect(0x7efc74000000, 163840, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory) munmap(0x7efc74000000, 67108864) = 0 write(2, process_vm_readv: Bad address 0x7eff0c00e000, 77 (process:10928): GLib-ERROR **: gmem.c:230: failed to allocate 131072 bytes) = 77 --- SIGTRAP {si_signo=SIGTRAP, si_code=SI_KERNEL, si_value= int=487903808, ptr=0x7eff1d14d240}} --- <... syscall_16 resumed> ) = ? <unavailable> +++ killed by SIGTRAP +++ Trace/breakpoint trap
繰り返しますが、既に知られているメモリを割り当てることはできませんが、すでにmprotect（）にあります。 値が2のsysctlキーvm.overcommit_memoryを制限するものを検索して見つけます。0に変更すると、マシンが正常に起動します。
3番目のケース。 ここにはしばらくの間実行されていたプロセスがあり、その後突然CPUリソースを消費し始めます。 負荷平均は0.5から1.5に上昇します（システムでは、これは2つの仮想プロセッサのみを備えた仮想マシンです）。 遅延が増加し、サービスの応答性が低下します。 プロセスを再起動すると、しばらくすると状況が繰り返されます。 開始から失敗までの経過時間は常に異なります。 そのため、プロセスが正しく動作しなくなった時点で、straceをプロセスに接続します。 そして、次のような多くのメッセージが表示されます。
ppoll([{fd=10, events=POLLIN|POLLPRI}], 1, {0, 90000000}, NULL, 8) = 1 ([{fd=10, revents=POLLIN}], left {0, 90000000}) rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 epoll_wait(10, {{EPOLLIN, {u32=57661216, u64=57661216}}}, 4096, 0) = 1 rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0 accept(15, 0x7ffff8f46af0, [16]) = -1 EMFILE (Too many open files)
accept（）システムコールは、エラー「EMFILE（Too many open files）」で失敗します。 / proc / pid / limitsでプロセスの制限を確認し、 lsofで開いているファイルの数を確認します。
# grep files /proc/12345/limits Max open files 1024 1024 files # lsof -nPp 12345 |wc -l 1086
開いているファイルの制限は1024であり、プロセスによって現在開かれているファイルの数は制限よりわずかに多くなっています。 ここではすべてが明らかになっています。まずprlimitを使用して、実行中のプロセスの制限値を増やし、次に/etc/security/limits.confの編集で制限を完全に修正します。
4番目のケース 。 ここで小さな余談をする必要があります。 ここでは、 pgBouncer-PostgreSQL bunchを見てください。 アプリケーションは、pgBouncer、つまり 接続し、pgBouncerはプールからデータベースへの接続を発行し、アプリケーションは作業を行い、切断し、接続はプールに戻り、次のクライアントに発行されるまで配置されます。
そのため、問題は、アプリケーションログとpostgresログに、データベース内のトランザクションがデータを更新/削除/挿入できないというメッセージが表示され始めたためです。 トランザクションは読み取り専用モードです。
検索プロセスでは、いくつかの仮説が提示されましたが、そのうちの1つは後で正しいことが判明しました。 プーラーに接続するクライアントは、セッションを読み取り専用モードに設定します。 クライアントを切断した後、この設定はサーバー接続に固執し、pgBouncerがこの接続を強制的に終了するまでそれを維持します。 pgBouncerの設定でserver_reset_query = DISCARD ALLを指定すると、切断されると、すべてのセッションベースの設定がリセットされます。 したがって、誰かが読み取り専用セッションをセットアップし、保存された後、この接続は他のクライアントに送られました。 Vobschem DISCARD ALLは、犯人を探している間の一時的な解決策でした。 検索に時間がかかり、アプリケーションに疑念が生じましたが、開発者はコード内のすべての場所をチェックし、問題のある領域を特定しなかったと主張しました...
straceを取得し、pgBouncerに接続して待機します。
キーワードREAD ONLYをキャッチします。 また、出力は別のログに保存されます。 発見後、それを掘り下げなければならないので。
時間が経ちましたが、ここにあります：
recvfrom(10, "Q\0\0\0:SET SESSION CHARACTERISTICS AS TRANSACTION READ ONLY;\0", 2048, 0, NULL, NULL) = 59 sendto(11, "Q\0\0\0:SET SESSION CHARACTERISTICS AS TRANSACTION READ ONLY;\0", 59, 0, NULL, 0) = 59 sendto(10, "C\0\0\0\10SET\0Z\0\0\0\5T", 15, 0, NULL, 0) = 15
しばらく待って（同じクライアントの他のリクエストをキャッチします）、straceをオフにしてログを開きます。
ここで最も重要な記述子番号、特に記述子番号10（ recvfrom（10 ）に注意してください。キャッチされたメッセージの前にこれらの記述子を開いた人、少しgrep 、そしてここにあります。システムコールaccept（） （ accept（...） = 10 ）番号10の同じ記述子を開きます。
accept(8, {sa_family=AF_INET, sin_port=htons(58952), sin_addr=inet_addr("192.168.10.1")}, [16]) = 10 getpeername(10, {sa_family=AF_INET, sin_port=htons(58952), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0 getsockname(10, {sa_family=AF_INET, sin_port=htons(6432), sin_addr=inet_addr("192.168.10.10")}, [16]) = 0
開発者との会話で、アドレス192.168.10.1は開発者が接続したVPNサーバーに属していることが判明しました。 教育的な議論と組織的な措置の後、問題はもはや現れませんでした。
これらは物です。 ご清聴ありがとうございました。