複雑なWebアプリケーションのデバッグ-運用サーバーでの効果的なバグクラッシャー

みなさんこんにちは!



今日は、ロード中のバトルサーバー上のPHPでの大規模なWebアプリケーションのパフォーマンス、埃や汚れのボトルネックを効率的にキャッチし、「非標準」エラーを探して修正する方法を説明します。 Bitrix24クラウドサービスでは、説明されている多くの手法を使用しています。

情報は、複雑なWebプロジェクトを提供するシステム管理者や開発者、そしてPHPでボトルネックやプロジェクトエラーを見つけて排除するための効果的で迅速なプロセスを構築したいマネージャーにとって役立つと思います。







完全なテストの神話





XP / TDDには、100%のモジュールテストと機能テストでWebアプリケーションをカバーし、外部からシステムをクリックし、システムを改善することを恐れずにシステムを改善し、 継続的なインテグレーションプロセスで戦いを繰り広げるSeleniumテストの束を書くことができる、 とても親切で明るい神話があります :-)これは「死に至るまでの愛と死」というカテゴリからのロマンスであり、幸いなことに現実にはほど遠いので、それが理由です。

  1. Webプロジェクトの要件は、立ち上げまで常に変化します(一定)。 理論的には、もちろん修正できますが、ローンチ前に、マネージャーは確かにナチスの笑顔と「今日、急いで」という言葉で笑顔を描くでしょう。
  2. すべてが正直にテストでカバーされている場合、十分なプログラマと時間がないでしょう、信じてください。 多くの場合、Amazon APIに モックオブジェクトを書き込むなどの逸脱がありますが、それでもオペレーティングシステムのシステムコールをテストできます:-)
  3. Webプロジェクトでレイアウトが頻繁に変更されると、 Seleniumテストを最新の状態に保つことが難しくなります。
  4. 負荷時のサイトの安定性など、いくつかのテストは簡単ではありません。 頭を壊して、本物のように見える負荷スキームを考え出す必要がありますが、それはまだ異なります。
  5. 私たちは...プログラミング言語を直感的に信頼しており、突然突然現れるバグを含む可能性があります。 したがって、PHPテストはカバーしませんか?
  6. など


一般に、テストが問題から100%を保護し、コードの2倍以上あるはずだとまだ信じているなら、これ以上読むことはできません-プログラミングはロマンチックではありません:-)



それでも、誰もがこれを理解しているので、テストを作成する必要があります。 重要なこと、システムモジュール-を作成し、最新の状態に保つ必要があります。 他のタスクについては、テスター部門による各更新の前にWebソリューションのページをクリックし、ログのエラーの出現を注意深く監視し、ユーザーからフィードバックを収集することにより、テスト計画を作成し、「ヒューマンファクター」でテストできます。

したがって、プロジェクトがまだ生きており、ネットワーク上で正常に動作している場合、ユニットテスト、機能テスト、およびSeleniumを使用する可能性が高く、バージョン管理システムとテスターの作業との継続的な統合プロセスのバリアントを使用します。 同時に、間違いは間違いなくバトルサーバーに漏れることを理解しており、それらをすばやく見つけて修正する方法を学ぶ必要があります。 ここでの主なアイデアは、合理的な量のストローを敷設し、効果的な武器を準備しておくことです。これにより、バグやパフォーマンスの問題の頭を即座に切り離すことができます。



PHPデバッグツール



多くのプロジェクトはvar_dumpコマンドとechoコマンドをバイパスします:-)、しかし、それらがより複雑になると、開発者はローカルサーバーにXDebugZend Debuggerのようなものをインストールする可能性が高くなります。これらのものを賢く使用してください。

非常に多くの場合、XDebug はコレクションモードで役立ちます 。 トレースなしでエラーやパフォーマンスのボトルネックをキャッチすることが不可能な場合があります。

それにも関わらず、重要なものが1つありますが、これらのツールはWebプロジェクトに深刻な負担をかけ、バトルサーバーに含めることは危険です。 ツールは、ローカルサーバー上のコードを「なめる」のに役立ちますが、残念ながら「戦いで生き残る」ことは役に立ちません。



戦闘中のデバッグ





すべてを記録する


負荷により、バトルサーバーにnginx、apache、php-fpmログファイルを含めたり、ビジネスオペレーションログファイルを保守したり(特別注文の作成、1C-BitrixからSAPへのエクスポートなど)できる場合に非常に便利です。

WebクラスターまたはPHPを備えたサーバーが多数ある場合は、これらのマシンからログを1台のマシンで収集してみてください。ログは中央で監視できます。 Bitrix24では、これにsyslog-ngを使用します。 同じマシン上のすべてのクラスターサーバーから1つのファイルでPHPエラーログを取得します。事故が発生した場合、マシンを目で見ながら実行する必要はありません。 画面を実行すると、最新の状態になります。



「バトル」プロファイラー-xhprof


幸いなことに、PHPの開発者と管理者にとって、Facebookの同僚は、共通の利益のために、優れた便利な「バトル」プロファイラー-xhprofを書いて投稿しました。 このツールにまだ慣れていない場合は、調べてください。 2回のクリックで構成可能で、5トンの利点があります。



最も重要なのは、戦闘でオンにすることができることです。 実際には、PHP(パーセント)に負荷をかけることはありません。

ヒット実行プロファイルを確認できます。



また、クリティカルパス-戦闘の妨げとなったもの:



さらに、Bitrixプラットフォームのビルトインデバッグツール(このプラットフォームでWebソリューションを使用している場合)にも適しています-ピーク負荷でxhprofを実行できます。また、負荷がスケール外または開発/テストサーバーで実行されない場合、 パフォーマンスモニターを実行できます。



動的トレース


Webクラスターがある場合は、動的プロファイリングプロセスを自動化すると便利なことがよくあります。 一番下の行は単純です-プロファイラーは常にオンです。ページが実行された後、ヒット時間をチェックし、それがより長い場合、たとえば2秒の場合、トレースをファイルに保存します。 はい、これにより余分な50〜100ミリ秒が追加されるため、必要に応じてシステムの電源を入れたり、10回目のヒットなどごとに電源を入れたりできます。

auto_prepend_file.php: //     ,     if (isset($_GET['profile']) && $_GET['profile']=='Y') { setcookie("my_profile", "Y"); } if (isset($_GET['profile']) && $_GET['profile']=='N') { setcookie("my_profile", "",time() - 3600); } if ( !( isset($_GET['profile']) && $_GET['profile']=='N') && ( $_COOKIE['my_profile']=='Y' || ( isset($_GET['profile']) && $_GET['profile']=='Y') ) && extension_loaded('xhprof') ) { xhprof_enable(); }
      
      







 dbconn.php: //     ,       PHP (http://php.net/manual/ru/function.microtime.php) //Forcing storing trace, if req.time > N secs $profile_force_store = false; $ar_pinba = pinba_get_info(); if ($ar_pinba['req_time']>2) $profile_force_store=true; ... if ($profile_force_store || ( !(isset($_GET['profile']) && $_GET['profile']=='N') && ( $_COOKIE['my_profile']=='Y' || ( isset($_GET['profile']) && $_GET['profile']=='Y' )) && extension_loaded('xhprof') ) { $xhprof_data = xhprof_disable(); $XHPROF_ROOT = realpath(dirname(__FILE__)."/perf_stat"); include_once $XHPROF_ROOT . "/xhprof_lib/utils/xhprof_lib.php"; include_once $XHPROF_ROOT . "/xhprof_lib/utils/xhprof_runs.php"; // save raw data for this profiler run using default // implementation of iXHProfRuns. $xhprof_runs = new XHProfRuns_Default(); // save the run under a namespace "xhprof_foo" $run_id = $xhprof_runs->save_run($xhprof_data, "xhprof_${_SERVER["HTTP_HOST"]}_".str_replace('/','_',$_SERVER["REQUEST_URI"]));
      
      





したがって、ヒットが2秒より長いことが判明した場合、サーバー上の一時フォルダーに保存します。 次に、監視マシンで、サーバーをバイパスして、集中分析のためにそれらからトレースを取得できます(Amazonの仮想ホストの例)。



 #!/bin/bash HOSTS=`as-describe-auto-scaling-groups mygroup | grep -i 'INSTANCE' | awk '{ print $2}' | xargs ec2-describe-instances | grep 'INSTANCE' | awk '{print $4}'` for HOST in $HOSTS ; do scp -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no -p -i /home/trace_loader/.ssh/id_rsa "trace_loader@${HOST}:/tmp/*xhprof*" /my_profiles done
      
      





これで、クエリトレースを1か所で2秒以上収集できます-日付順に並べたWebインターフェイスを表示するには、約30分かかります。ビジネスプロセスの一部は準備完了です-各トレースは、実際にWebアプリケーションを最適化するためのTKです。彼は開発の専門家です。



より深く潜る-strace



プロファイラーとログファイルでは、問題の原因を特定できない場合があります。 ただし、開発サーバーでデバッグ(XDebug)を実行すると、問題の再現は機能しません。 戦闘サーバーでのイベントの時点で何が起こっているかを理解することは1つ残っています。 ここで、 straceなどのシステムコールトレーサーは、しばしば非常に貴重な支援を提供します。 Linuxシステムコールを目にする必要はありません。ちょっと待ってください。2〜3杯のコーヒーを飲むと、アイデアを理解し、バトルサーバーで最も微妙なエラーとボトルネックをキャッチできます。

PHPプロセスにトレーサーを適切に「アタッチ」する必要があります。 多くの場合、多くのプロセスが異なるプールで実行されており、絶えず急冷され、引き上げられます(多くの場合、メモリリークを防ぐために、プロセスのライフタイムを100ヒットに設定します)。

ps aux | grep php

root 24166 0.0 0.0 391512 4128 ? Ss 11:47 0:00 php-fpm: master process (/etc/php-fpm.conf)

nobody 24167 0.0 0.6 409076 48168 ? S 11:47 0:00 php-fpm: pool www1

nobody 24168 0.0 0.4 401736 30780 ? S 11:47 0:00 php-fpm: pool www1

nobody 24169 0.0 0.5 403276 39816 ? S 11:47 0:00 php-fpm: pool www1

nobody 24170 0.0 1.0 420504 83376 ? S 11:47 0:01 php-fpm: pool www1

nobody 24171 0.0 0.6 408396 49884 ? S 11:47 0:00 php-fpm: pool www1

nobody 24172 0.0 0.5 404476 40348 ? S 11:47 0:00 php-fpm: pool www2

nobody 24173 0.0 0.4 404124 35992 ? S 11:47 0:00 php-fpm: pool www2

nobody 24174 0.0 0.5 404852 42400 ? S 11:47 0:00 php-fpm: pool www2

nobody 24175 0.0 0.4 402400 35576 ? S 11:47 0:00 php-fpm: pool www2

nobody 24176 0.0 0.4 403576 35804 ? S 11:47 0:00 php-fpm: pool www2

nobody 24177 0.0 0.7 410676 55488 ? S 11:47 0:00 php-fpm: pool www3

nobody 24178 0.0 0.6 409912 53432 ? S 11:47 0:00 php-fpm: pool www3

nobody 24179 0.1 1.3 435216 106892 ? S 11:47 0:02 php-fpm: pool www3

nobody 24180 0.0 0.7 413492 59956 ? S 11:47 0:00 php-fpm: pool www3

nobody 24181 0.0 0.4 402760 35852 ? S 11:47 0:00 php-fpm: pool www3

nobody 24182 0.0 0.4 401464 37040 ? S 11:47 0:00 php-fpm: pool www4

nobody 24183 0.0 0.5 404476 40268 ? S 11:47 0:00 php-fpm: pool www4

nobody 24184 0.0 0.9 409564 72888 ? S 11:47 0:01 php-fpm: pool www4

nobody 24185 0.0 0.5 404048 40504 ? S 11:47 0:00 php-fpm: pool www4

nobody 24186 0.0 0.5 403004 40296 ? S 11:47 0:00 php-fpm: pool www4







PHPプロセスの変化するプロセスを追いかけないように、一時的に短いライフタイムを設定できます。

pm.max_children = 5

pm.start_servers = 5

pm.min_spare_servers = 5

pm.max_spare_servers = 5



pm.max_requests = 100







そして、次のようにstraceを実行します。



strace -p 24166 -f -s 128 -tt -o trace.log



つまり ルートプロセスにハングアップし、新しい子孫が表示されると、それらも自動的にトレースを開始します。 シンプル。

PHPログファイルにプロセスのPIDの書き込みを開始して、ログからの長いヒットをトレースの特定のプロセスとすばやく比較できるようにすることをお勧めします。

access.log = /opt/php/var/log/www.access.log

access.format = "%R # %{HTTP_HOST}e # %{HTTP_USER_AGENT}e # %t # %m # %r # %Q%q # %s # %f # %{mili}d # %{kilo}M # %{user}C+%{system}C # %p "







今では、被害者が現れるのを待つことが残っています。例えば、長いヒットです。

[24-May-2012 11:43:49] WARNING: [pool www1] child 22722, script '/var/www/html/myfile.php' (request: "POST /var/www/html/myfile.php") executing too slow (38.064443 sec), logging



- # mysite.ru # Mozilla/5.0 (Windows NT 6.1; WOW64; rv:12.0) Gecko/20100101 Firefox/12.0 # 24/May/2012:11:43:11 +0400 # POST # /var/www/html/myfile.php # # 200 # /var/www/html/myfile.php # 61131.784 # 6656 # 0.03+0.03 # 22722









システムコールの解釈





1つ目は、システムコールは、プログラムがオペレーティングシステムと通信する低レベルの「基本」操作です。これらは、さまざまなプログラミング言語とテクノロジを備えたITユニバース全体に基づいており、あまり多くありません(少数のプロセッサコマンドや無数の言語や方言に類似)スタック)。 2番目に理解すべきことは、1つのプロセスのフレームワーク内でPHP Webプロジェクトのコマンドが厳密に次々に実行されることです。 したがって、トレースでは、不審なヒットのプロセス-22722を除外する必要があります。



猫trace.log | grep '22722' | 少ない



ヒットの時間はログからわかります。ページの構築中に何が起こったのか、なぜ長い間ハングしたのかを見るために残っています(トレースはわずかに編集されています)。

表示されるデータベースクエリと回答:

24167 12:47:50.252654 write(6, "u\0\0\0\3select name, name, password ...", 121) = 121

24167 12:47:50.252915 read(6, "pupkin, 123456"..., 16384) = 458







ファイルアクセス:



24167 12:47:50.255299 open("/var/www/html/myfile.php", O_RDONLY) = 7









memcachedとの相互作用:



24167 12:47:50.262654 sendto(9, "add mykey 0 55 1\r\n1\r\n", 65, MSG_DONTWAIT, NULL, 0) = 65

24167 12:47:50.263151 recvfrom(9, "STORED\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 8

...

24167 12:47:50.282681 sendto(9, "delete mykey 0\r\n", 60, MSG_DONTWAIT, NULL, 0) = 60

24167 12:47:50.283998 recvfrom(9, "DELETED\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 9









そして、ここで、たとえば、ヒットがフリーズする理由がわかります。

22722 11:43:11.487757 sendto(10, "delete mykey 0\r\n", 55, MSG_DONTWAIT, NULL, 0) = 55

22722 11:43:11.487899 poll([{fd=10, events=POLLIN|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=10, revents=POLLIN}])

22722 11:43:11.488420 recvfrom(10, "DELETED\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 9

22722 11:43:11.488569 sendto(10, "delete mykey2 0\r\n", 60, MSG_DONTWAIT, NULL, 0) = 60

22722 11:43:11.488714 poll([{fd=10, events=POLLIN|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=10, revents=POLLIN}])

22722 11:43:11.489215 recvfrom(10, "DELETED\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 9

22722 11:43:11.489351 close(10) = 0

22722 11:43:11.489552 gettimeofday({1337845391, 489591}, NULL) = 0

22722 11:43:11.489695 gettimeofday({1337845391, 489727}, NULL) = 0

22722 11:43:11.489855 nanosleep({0, 100000}, NULL) = 0

22722 11:43:11.490155 nanosleep({0, 200000}, NULL) = 0

22722 11:43:11.490540 nanosleep({0, 400000}, NULL) = 0

22722 11:43:11.491121 nanosleep({0, 800000}, NULL) = 0

22722 11:43:11.492103 nanosleep({0, 1600000}, NULL) = 0

22722 11:43:11.493887 nanosleep({0, 3200000}, NULL) = 0

22722 11:43:11.497269 nanosleep({0, 6400000}, NULL) = 0

22722 11:43:11.503852 nanosleep({0, 12800000}, NULL) = 0

22722 11:43:11.516836 nanosleep({0, 25600000}, NULL) = 0

22722 11:43:11.542620 nanosleep({0, 51200000}, NULL) = 0

22722 11:43:11.594019 nanosleep({0, 102400000}, NULL) = 0

22722 11:43:11.696619 nanosleep({0, 204800000}, NULL) = 0

22722 11:43:11.901622 nanosleep({0, 409600000}, NULL) = 0

22722 11:43:12.311430 nanosleep({0, 819200000}, <unfinished ...>

22722 11:43:13.130867 <... nanosleep resumed> NULL) = 0

22722 11:43:13.131025 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:14.769688 <... nanosleep resumed> NULL) = 0

22722 11:43:14.770104 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:16.408860 <... nanosleep resumed> NULL) = 0

22722 11:43:16.409048 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:18.047808 <... nanosleep resumed> NULL) = 0

22722 11:43:18.048103 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:19.686947 <... nanosleep resumed> NULL) = 0

22722 11:43:19.687085 nanosleep({1, 638400000}, <unfinished ...>

22724 11:43:20.227224 <... lstat resumed> 0x7fff00adb080) = -1 ENOENT (No such file or directory)

22722 11:43:21.325824 <... nanosleep resumed> NULL) = 0

22722 11:43:21.326219 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:22.964830 <... nanosleep resumed> NULL) = 0

22722 11:43:22.965126 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:24.603692 <... nanosleep resumed> NULL) = 0

22722 11:43:24.604117 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:26.250371 <... nanosleep resumed> NULL) = 0

22722 11:43:26.250580 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:27.889372 <... nanosleep resumed> NULL) = 0

22722 11:43:27.889614 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:29.534127 <... nanosleep resumed> NULL) = 0

22722 11:43:29.534313 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:31.173004 <... nanosleep resumed> NULL) = 0

22722 11:43:31.173273 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:32.812113 <... nanosleep resumed> NULL) = 0

22722 11:43:32.812531 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:34.451236 <... nanosleep resumed> NULL) = 0

22722 11:43:34.451554 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:36.090229 <... nanosleep resumed> NULL) = 0

22722 11:43:36.090317 nanosleep({1, 638400000}, <unfinished ...>

22724 11:43:36.522722 fstat(12, <unfinished ...>

22723 11:43:36.622833 <... gettimeofday resumed> {1337845416, 622722}, NULL) = 0

22722 11:43:37.729696 <... nanosleep resumed> NULL) = 0

22722 11:43:37.730033 nanosleep({1, 638400000}, <unfinished ...>

22724 11:43:39.322722 gettimeofday( <unfinished ...>

22722 11:43:39.368671 <... nanosleep resumed> NULL) = 0

22722 11:43:39.368930 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:41.007574 <... nanosleep resumed> NULL) = 0

22722 11:43:41.007998 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:42.646895 <... nanosleep resumed> NULL) = 0

22722 11:43:42.647140 nanosleep({1, 638400000}, <unfinished ...>

22720 11:43:43.022722 fstat(12, <unfinished ...>

22720 11:43:43.622722 munmap(0x7fa1e736a000, 646) = 0

22722 11:43:44.285702 <... nanosleep resumed> NULL) = 0

22722 11:43:44.285973 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:45.926593 <... nanosleep resumed> NULL) = 0

22722 11:43:45.926793 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:47.566124 <... nanosleep resumed> NULL) = 0

22722 11:43:47.566344 nanosleep({1, 638400000}, <unfinished ...>

22722 11:43:49.205103 <... nanosleep resumed> NULL) = 0

22722 11:43:49.205311 nanosleep({1, 638400000}, <unfinished ...>

22719 11:43:49.440580 ptrace(PTRACE_ATTACH, 22722, 0, 0 <unfinished ...>







最初に、memcachedの呼び出しがありました:ソケット10の書き込み/読み取り、次にソケットが正常に閉じられ(「close」= 0)、ループ内でusleepと呼ばれるコードおよびループを終了する条件が、以前に閉じられたソケットのために機能しませんでした。 その結果、理由が特定されました-コードを迅速に修正します。



UNIXシステムコールと混同しないでください。それらは単純で簡単です。 システム内の多くのオブジェクトは、ファイルとソケットとして表されます。 どの通話でも、組み込みの情報をすばやく取得できます。

男2を開く

男2 sendto

男2ナノスリープ



これらのマニュアルがない場合は、次のように配置できます(CentOS6上)。

yumインストールのマンページ



また、 Webまたはコンソールからシステムコールに関する最新のドキュメント「man syscalls」を表示することもできます。

PHPがオペレーティングシステムレベルでどのように機能するかを少し理解した後、手に秘密兵器を手に入れると、負荷の高いWebプロジェクトのほとんどすべてのボトルネックをすばやく見つけて排除できます。



合計



  1. PHPでWebアプリケーションをデバッグするための基本的な方法とツールは、どの程度複雑でも繰り返しました。
  2. 戦闘サーバーで問題を見つけるためのシンプルで効果的なビジネスプロセスを編成するためのオプションを検討しました。
  3. 「戦闘」サーバーでxhprofとstraceを使用して、「複雑な」ケースとボトルネックをキャッチする方法を学びました。
  4. Linuxシステムコールを試飲し、それらの解釈方法を学びました。




皆様の幸運、安定したWebプロジェクト、信頼できるホスティング、リラックスした穏やかな休暇をお楽しみください! そして、もちろん、Amazonで開始された新しいクラウドプロジェクトBitrix24に皆さんを招待します!



All Articles