4D Japan
テクニカルサポートブログ-
デバッグ・ログ解析ツール
4D v17 R5 では新規メソッドが追加されたほか、プロセスの個別トレースも可能になり、デバッグ・ログが改良されました。今回は 4D v17 R6 の BETAリリースとともに、プロセスの監視を助ける簡単なログ解析ツールを提供することになりました。このツールを使って、時間のかかるプロセスを確認したり、コール・チェーンとその処理時間を調べたりすることができます。
ここではサンプルシナリオとして、動的なWebページを提供するデータベースのレスポンスが遅い、という問題を調べることにします。
Webサイトが時々重いという指摘を複数のユーザーからもらいましたが、それ以上の詳細はわかりません。さっそく、何が問題なのか調査してみましょう。
デバッグ・ログの生成
問題を調査するにあたって、まずデバッグ・ログを生成します。この解析ツールは 4D v14 のデバッグ・ログ形式に基づいているため、ログ生成を有効にする際にオプションを指定する必要があります:
// デバッグ・ログをアクティブにし、3つのオプションを指定します。2:引数付き, 4:4D v14 形式 (タブ付き), 8:逐次記録
SET DATABASE PARAMETER (Debug log recording;2+4+8)4D v17 R5 以降は個別プロセスのデバッグができるため、遅延の原因として疑われるプロセスがあれば、それをピンポイントで調査することもできます:
SET DATABASE PARAMETER (Current process debug log recording;2+4+8)プロジェクト新規作成
この解析ツールでは、「プロジェクト」単位でデバッグ・ログ・ファイルを管理します。
解析ツールを起動すると、既存のプロジェクトが表示されます。「新規作成」ボタンで新しいプロジェクトを作成します。解析するログ・ファイルを、ファイルまたはフォルダーで選択し、プロジェクトの名称を指定します。
解析処理はプリエンプティブに実行されますが、解析するファイルの数やマシンの処理能力によって時間がかかる場合があります。
プロジェクトの分析
一覧からプロジェクトを選択すると、期間や行数などのログの基本情報が右に表示されます。右下のボタンをクリックして、プロジェクトのコール・チェーンや詳細を見ることができます。
コール・チェーン
この画面では、プロセスとその実行時間が一覧できます。リストの並び順は、もっとも時間を消費するプロセスが上にくるようになっています。
プロセスのコール・チェーンを展開していくと、各階層で一番時間がかかっている処理が確認できます。ALTキーを押しながら展開すると、一番処理の重いコール・チェーンを展開します。タスクやメソッドの行をダブルクリックすると、当該処理がコール・チェーン・エクスプローラーに表示されます。このリストの任意の階層をダブルクリックすると、それが単独で表示されます。コマンドを選択すると、そのコマンドのコール回数、総所要時間、平均所要時間が表示されます。
サンプルシナリオにおいて、一番時間のかかるプロセスとコマンドを探しました。RELATE MANY SELECTION コマンドの処理に1分以上かかることがあるのがわかりました。では、今度は詳細画面を開いて、このコマンドがどこでコールされたのか調べてみましょう。
詳細画面
- 範囲の選択
詳細画面では分刻みのアクティビティ・タイムラインが表示されます。範囲を指定してズームアイコンをクリックすると、拡大表示されます。これにより、対象を限定して調査していけるため、アクティビティが高い箇所を重点的に調べる方法がとれます。
範囲を変更するたびに解析が実行され、結果が下に表示されます。
- サマリー
「サマリー」タブには選択した範囲に関する処理の統計が表示されます。
- トップ
「トップ」タブには選択範囲あるいは選択プロセスに関わる、すべての処理のコール数と所要時間が表示されます。このリストはフィルターを使って、コマンドやメソッド、メンバーメソッドなどに絞り込むことができるため、処理タイプ別の調査に便利です。
サンプルシナリオの調査では範囲を限定したうえで、コマンドでフィルターをかけました。コール・チェーン画面でも確認したように、RELATE MANY SELECTION コマンドが複数回コールされており、処理時間もかかっているようです。
- オペレーション
「オペレーション」タブには、特定の1分に開始された処理の詳細が表示されます。このリストは任意の検索ワードで絞り込むか、ハイライト表示することができます。パフォーマンスの都合上、このタブの情報は1分の内容に限られています。任意の1分は紫のバーで変更できます。
処理されたすべてのコードが表示されているため、このリストはたいへん便利です。ヘッダーをクリックすることで並べ替えることもできます。
サンプルシナリオでは、すでにアタリを付けた RELATE MANY SELECTION コマンドで絞り込み検索し、所要時間の長い順に並べ替えました。一番時間のかかっている2回のコールは同じフィールドを引数として受け取っているようです。データベースのストラクチャーを確認したところ、原因がわかりました: このフィールドはインデックスされていませんでした。
おわりに
この解析ツールはコードの問題を発見し、データベースのパフォーマンスを改善する意図でデザインされています。ぜひツールをダウンロードして実際に使ってみてください！
-
4D v17.3 修正リスト
-
一般Webユーザーのアクセス権
データベース設定 > Web > オプション ⑴ では，一般Webユーザーのデータアクセス権が選択できるようになっています。デフォルト値は，Designerです。「なし」に設定されている場合，一般Webユーザーには，アクセス権が何もありません。これは仕様です。
WebまたはSOAPプロセスからレコードの更新ができない場合，一般Webユーザーが有効なユーザー名であることを確認してください。クライアント側Webサーバーの一般Webユーザーは，クライアント側で設定する必要があります。
-
シートの保護とセルのロック
一部のセルがロックされた4D ViewスプレッドシートをView Proに変換した場合，シートはデフォルトで「保護」された設定になります。これは仕様です。
4D Viewにシートを「保護」するという概念はなく，個別にセルがロックできるようになっています。View Pro（SpreadJS）でユーザーに特定のセルだけの編集を許可する場合，シートを保護してから，ユーザーに編集を許可するセルだけをロック解除します。
https://docs.grapecity.com/help/spread-js-9/celllock.html
一部のセルがロックされた4D Viewスプレッドシートを変換した場合，シート全体が保護された上で，特定のセルだけがロックされるようになっています。その他のセルはデフォルトでアンロックされています。これにより，ロックされたセルの設定は継承されますが，１点，問題があります。デフォルトですべてのセルがアンロックされているため，ユーザーに編集を許可するセルを除き，シート全体を保護することができない，という問題です。
SpreadJSのシステム，つまり，特定のセルをロックするのではなく，特定のセルを除いて入力を禁止する方式に移行したいのであれば，デフォルトのスタイルシートから
"locked":falseの指定を取り除ことができます。$defaultStyle:=$spreadDocument.spreadJS.namedStyle[1] OB REMOVE($defaultStyle;"locked")
-
PHPとGDライブラリ
v13以前のバージョンで
PHP Executeを実行した場合，アプリケーションのResourcesフォルダーに作成されるphp.iniファイルには，下記の１行が存在します。当時のPHPは，GDライブラリが外部DLLとしてコンパイルされており，起動時にロードする必要がありました。extension=php_gd2.dll17r5では，PHPがバージョン
4（32ビット版）から7（64ビット版）にアップデートされました。このバージョンでは，GDライブラリが実行ファイルに埋め込まれているため，上記の１行は不要となりました。v13で作成されたアプリケーションを17r5に変換した場合，
PHP Executeでエラー500が返されるかもしれません。Windows 10 (1903) 以降，無効なDLLロードで例外が返されるようになったことが関係しているようです。php.iniファイルの前述した行を削除またはコメントアウトすることにより，問題を回避することができます。
-
ボタンにFormは設定できない
ボタン型のフォームオブジェクトに
Form.buttonのような数式を設定することはできません。これは仕様です。チェックボックス等とは違い，ボタンに標準アクションとオブジェクトメソッドの両方が設定できることが関係しています。内部的なコードが見直された影響で，Form.buttonのような数式はボタンに設定できないことになりました。
-
Apple Event ManagerとMESSAGE
On System Eventは，アプリケーションが最前面から移動したときなどに発生するデータベースイベントです。On System Eventデータベースメソッドが存在する場合，システムイベントを監視するためにウィンドウを表示しない常駐プロセスが作成されます。このプロセスでMESSAGEコマンドを実行した場合，「Apple Event Manager」ウィンドウが表示され，閉じることができません。これは仕様です。なお，「Apple」という名称は歴史的な経緯によるものであり，オペレーションシステムとは無関係です。MESSAGEを使用する場合，明示的にウィンドウを作成することが推奨されています。ウィンドウを作成せずにMESSAGEを使用した場合，カレントプロセスの非表示ウィンドウが暗黙的に使用され，プロセスが消滅すると同時にそのウィンドウが閉じられます。それが常駐プロセスだった場合，プロセスとMESSAGEコマンドは互いに相手が終了するまで待機することになり，ウィンドウ/プロセスを閉じることができません。MESSAGEコマンドを使用していないのにも関わらず「Apple Event Manager」ウィンドウが表示される場合，空のOn System Eventデータベースメソッドが存在する可能性があります。システムイベントを監視する必要がある場合，イベント処理ループがブロックしないよう，新規プロセスを作成することができます。
-
オブジェクトとドット記法の力
4D v17 R5では、オブジェクトを操作してファイルあるいはフォルダの属性を検索するのがいかに簡単かをご紹介しました。この機能はオブジェクト記法のおかげでさらに簡単になっています！このブログ投稿では、ファイルとフォルダを関するインターフェイスを使った例題を公開しています。これは、4Dでは新しいことではなく、これまでの4Dコマンドでも可能でした。しかし、このバージョンからより簡単にわずかんコードでできるようになりました。
このTipでは、オブジェクトを操作してファイルやフォルダの属性を検索するのがいかに簡単かをご覧いただきます。さらに良いことに、新しい機能を組み合わせることでより強力になることもお見せしています。File とfolder コマンド、オブジェクト記法や新しいリストボックス 機能などです。例えば、リストボックス に表示するファイルやフォルダのコレクションを検索するには：
Form.docs:=Form.curfolder.folders().concat(Form.curfolder.files())
あなた自身がサンプルを試してみてください。ディスクファイル・ブラウザーのように動くことが分かるでしょう。あなたならこの機能のためにリストボックス の裏でどのようにコードを書くのか、ちょっと考えてみてください。最後に、デザインモードに移ってコードを見てみると、いかに短いコードが使われているかに驚くことでしょう。オブジェクト記法を使わずに同じことをしてみると、オブジェクトには10倍以上のコーディングが必要です。まだ、オブジェクト記法を試していないのなら、今こそその時です！
-
リクエストログを使ってORDAコードを最適化
これまでにクライアントと4D Server間で送信されるORDAのリクエストのトラフィックを分析する必要を感じたことはありませんか？時にサーバーからレスポンスを受け取るまでに間があることがあります。それがネットワークのトラフィックのせいなのか、あるいは最適化されていないリクエストを書いたせいなのか考えさせられる場合があります。幸いなことに、4D V17 R6は、ds オブジェクトで使用可能な新しいORDAメソッドを使って、この遅延の原因を特定することができます。これらはデバッギング機能であるだけではなく、送信されたリクエストをよりよく理解してORDAコードを最適化することもできるようになりました。
ORDAでロギングをリクエストする
startRequestLog()メンバー・メソッドはとてもフレキシブルです。ORDAリクエストログをファイルもしくはメモリに取ることができます。
ファイルにログを取る
ファイルにログを取るには、シンプルにstartRequestLog()を、ORDAリクエストがログインする場所を示すFileオブジェクトとともにコールするだけです。以下の例では、時々クエリーをインデックス化されていないフィールド上で走らせます。この新しい機能のおかげで、リクエストの継続時間をチェックできます：
C_OBJECT($first;$e)
C_COLLECTION($log)
ds.startRequestLog(10) // Only the last 10 requests will be kept in memory
$first:=ds.Persons.all().first()
$e:=ds.Persons.query("name=:1";"Brown")
$log:=ds.getRequestLog()
ALERT("The longest request lasted: "+String($log.max("duration"))+" ms")
ds.stopRequestLog()各リクエストはオブジェクトのJSON表現としてログを取られます。
以下はORDARequests.txtファイルの内容です：
[
{
...
"startTime":"2019-07-02T12:33:25.922Z",
"endTime":"2019-07-02T12:33:27.681Z",
"duration":4200,
"response":{ ...}
...
}
]
メモリーにログを取る
各リクエストはコレクションの中にオブジェクトとしてログを取られます。getRequestLog() メンバー・メソッドを使って検索することができます。
コレクションを返すので、可能なコレクション・メソッドは全て使用できます。
C_OBJECT($first;$e)
C_COLLECTION($log)
ds.startRequestLog(10) // Only the last 10 requests will be kept in memory
$first:=ds.Persons.all().first()
$e:=ds.Persons.query("name=:1";"Brown")
$log:=ds.getRequestLog()
ALERT("The longest request lasted: "+String($log.max("duration"))+" ms")
ds.stopRequestLog()ORDAリクエストのログを不可にする
上記のサンプルが示す通り、ORDAリクエストのログを止めるには、stopRequestLog() メンバー・メソッドをコールするだけです。
-
ダイナミックフォームの入力順を簡単にカスタマイズ
ダイナミックフォームの機能は、4D v16 R6で導入され、オブジェクト内でフォームを構築したり、テキストファイルからフォームをロードしたりすることで、その場でフォームを構築できます。これは、アプリケーションのニーズに合わせてフォームが頻繁に変更される世界ではとても便利です。
4Dでは、バイナリーフォームでもダイナミックフォームでも、入力順は典型的なz順に従います。4D v17 R6を使うと、z順に関連づけることなく入力順を定義できるようになりました。
フォーム定義の各ページには、z順に従って配置されたフォーム要素のリストを含む”object”属性があります。新しい”entryOrder”属性が追加され、独自のカスタマイズした入力順を指定できるようになりました。もしこの属性が未定義の場合は、4Dはz順（”objects”属性で定義された順序）を使います。
以下は、二つの入力フィールドとボタンを使ったダイナミックフォームの例です：
// Create inputs and button
$text1:=New object("type";"input"; "top";20; "left";140; "width";100; "height";18)
$text2:=New object("type";"input"; "top";20; "left";20; "width";100; "height";18)
$button:=New object("type";"button"; "text";"OK"; "top";60; "left";140; "width";100; "height";20)
// Create entry order collection
$entryOrder:=New Collection("text2";"text1")
// Create page with form objects and entry order
$page:=New object("objects";New object("text1";$text1; "text2";$text2; "button";$button); "entryOrder";$entryOrder)
// Create form
$form:=New object("pages"; New collection(Null;$page); "windowTitle";"My form"; "rightMargin";20; "bottomMargin";20)
// Load the form
$w:=Open form window($form)
DIALOG($form)これは次のように表すことができます：
{ "pages": [ null, { "objects": { "text1": { "type": "input", "top": 20, "left": 140, "width": 100, "height": 18, "events": ["onClick"] }, "text2": { "type": "input", "top": 20, "left": 20, "width": 20, "height": 18, "events": ["onClick"] }, "button": { "type": "button", "text": "OK", "top": 60, "left": 140, "width": 20, "height": 20, "events": ["onClick"] } }, "entryOrder": [ "text2", "text1" ] } ] }