記事
Tomoko Furuzono · 2020年9月17日
Caché 2017以降のSQLエンジンには新しい統計一式が含まれています。 これらの統計は、クエリの実行回数とその実行所要時間を記録します。
これは、多くのSQLステートメントを含むアプリケーションのパフォーマンスを監視する人や最適化を試みる人にとっては宝物のような機能ですが、一部の人々が望むほどデータにアクセスするのは簡単ではありません。
この記事と関連するサンプルコードでは、このような情報の使用方法と、日次統計の概要を定期的に抽出してアプリケーションのSQLパフォーマンス履歴記録を保持する方法について説明します。
※詳細については、下記ドキュメントページもご参考になさってください。
https://docs.intersystems.com/iris20201/csp/docbook/DocBook.UI.Page.cls?KEY=GSQLOPT_sqlstmts
記録内容
SQLステートメントが実行されるたびに、所要時間が記録されます。 この処理は非常に軽量であり、オフにすることはできません。 コストを最小限に抑えるため、統計はメモリに保持されてから定期的にディスクに書き込まれます。 このデータには当日にクエリが実行された回数と、その平均所要時間と合計所要時間が含まれます。
データはすぐにはディスクに書き込まれません。ただし、統計はデータが書き込まれた後に通常は1時間ごとに実行されるようにスケジュールされている「SQLクエリ統計の更新」タスクによって更新されます。 このタスクは手動で起動できますが、クエリをテスト中にリアルタイムで統計を表示したい場合は、プロセス全体の実行時間が若干長くなります。
警告：InterSystems IRIS 2019以前では、%Studio.Project:Deploy メカニズムを使用して配置されたクラスやルーチンに埋め込まれたSQLのこれらの統計は収集されません。 サンプルコードを破壊するものは何もありませんが、コストがかかるものが何も表示されないため、すべてが正常であると思い込んでしまう可能性があります（私はそう思い込んでしまいました）。
確認できる情報
クエリのリストを管理ポータルで確認できます。 [SQL] ページに移動し、[SQLステートメント] タブをクリックしてください。 これは実行中および調査中の新しいクエリには適していますが、膨大な数のクエリが実行中の場合は管理しきれなくなる可能性があります。
別の方法として、SQLを使用してクエリを検索することができます。 情報は、INFORMATION_SCHEMAスキーマのテーブルに保存されます。 このスキーマには多数のテーブルが含まれていますが、この記事の最後にいくつかのサンプルSQLクエリを掲載しています。
統計が削除されるタイミング
クエリのデータは、クエリが再コンパイルされるたびに削除されます。 そのため、動的クエリの場合はキャッシュ済みのクエリがパージされる可能性があります。 埋め込みSQLの場合、それはSQLが埋め込まれているクラスやルーチンが再コンパイルされるタイミングになります 。
※IRIS2020.1 以降では、埋め込みSQLも動的クエリと同様に、クエリが再コンパイルされるたびにデータが削除されます。
稼働中のサイトでは1日以上統計が保持されると思われますが、統計を保持しているテーブルは、レポートや長期分析を実行するための長期参照ソースには使用できません。
情報を要約するには
パフォーマンスレポートを生成する際は、作業しやすい永続的なテーブルに毎晩データを抽出することをお勧めします。 クラスが日中にコンパイルされる場合は一部の情報が失われる可能性がありますが、それによってスロークエリの分析に実質的な違いが出ることはほとんどありません。
以下のコードは、各クエリの日次概要に統計を抽出する方法の例です。 このコードには3つの短いクラスが含まれています。
毎晩実行する必要があるタスク。
DRL.MonitorSQLは、INFORMATION_SCHEMAテーブルからデータを抽出して保存するメインクラスです。
3番目のクラスであるDRL.MonitorSQLTextは（長い可能性がある）クエリテキストを1回だけ保存し、毎日の統計にクエリのハッシュのみを保存する最適化です。
サンプルに関する注意
このタスクは前日分のデータを抽出するため、午前0時を過ぎた直後にスケジュールする必要があります。
履歴データが存在する場合は、それをエクスポートできます。 過去120日間を抽出するには以下を実行します。
Do ##class(DRL.MonitorSQL).Capture($h-120,$h-1)
最も古いバージョンの統計ではDateがSQLに公開されていなかったため、サンプルコードでは^rIndexグローバルを直接読み取っています。
私が含めたバリエーションはインスタンス内のすべての名前空間を通ってループしますが、それが常に適切であるとは限りません。
抽出されたデータに対してクエリを実行するには
データを抽出したあと、以下のクエリを実行することで最も重いクエリを見つけることができます。
SELECT top 20
S.RunDate,S.RoutineName,S.TotalHits,S.SumpTIme,S.Hash,t.QueryText
from DRL.MonitorSQL S
left join DRL.MonitorSQLText T on S.Hash=T.Hash
where RunDate='08/25/2019'
order by SumpTime desc
また、高コストなクエリのハッシュを選択すると、そのクエリの履歴を表示できます。
SELECT S.RunDate,S.RoutineName,S.TotalHits,S.SumpTIme,S.Hash,t.QueryText
from DRL.MonitorSQL S
left join DRL.MonitorSQLText T on S.Hash=T.Hash
where S.Hash='CgOlfRw7pGL4tYbiijYznQ84kmQ='
order by RunDate
私は今年の初めに本番サイトからデータを収集し、最も高コストなクエリを調べました。 1つのクエリの平均実行時間は6秒未満でしたが、1日あたり14,000回呼び出されており、毎日合計で24時間近くかかっていました。 事実上、この1つのクエリで1つのコアが完全に占有されていました。 さらに悪いことに、1時間かかる2番目のクエリは1番目のクエリのバリエーションでした。
RunDate
RoutineName
Total Hits
Total Time
Hash
QueryText（略記）
03/16/2019
14,576
85,094
5xDSguu4PvK04se2pPiOexeh6aE=
DECLARE C CURSOR FOR SELECT * INTO :%col(1) , :%col(2) , :%col(3) , :%col(4) …
03/16/2019
15,552
3,326
rCQX+CKPwFR9zOplmtMhxVnQxyw=
DECLARE C CURSOR FOR SELECT * INTO :%col(1) , :%col(2) , :%col(3) , :%col(4) , …
03/16/2019
16,892
597
yW3catzQzC0KE9euvIJ + o4mDwKc =
DECLARE C CURSOR FOR SELECT * INTO :%col(1) , :%col(2) , :%col(3) , :%col(4) , :%col(5) , :%col(6) , :%col(7) ,
03/16/2019
16,664
436
giShyiqNR3K6pZEt7RWAcen55rs=
DECLARE C CURSOR FOR SELECT * , TKGROUP INTO :%col(1) , :%col(2) , :%col(3) , ..
03/16/2019
74,550
342
4ZClMPqMfyje4m9Wed0NJzxz9qw=
DECLARE C CURSOR FOR SELECT …
表1：顧客サイトでの実際の結果
INFORMATION_SCHEMAスキーマのテーブル
このスキーマのテーブルは統計だけでなく、使用されているクエリ、カラム、インデックスなどを 追跡しています。 通常はそのSQLステートメントが最初のテーブルになり、"Statements.Hash = OtherTable.Statement" のような形で結合されます。
これらのテーブルに直接アクセスし、1日で最も高コストなクエリを見つけるための対応するクエリは以下のようになります。
SELECT DS.Day,Loc.Location,DS.StatCount,DS.StatTotal,S.Statement,S.Hash
FROM INFORMATION_SCHEMA.STATEMENT_DAILY_STATS DS
left join INFORMATION_SCHEMA.STATEMENTS S
on S.Hash=DS.Statement
left join INFORMATION_SCHEMA.STATEMENT_LOCATIONS Loc
on S.Hash=Loc.Statement
where Day='08/26/2019'
order by DS.stattotal desc
より体系的なプロセスのセットアップを検討しているかどうかに関係なく、SQLを使用する大規模アプリケーションを持つすべての方に今すぐこのクエリを実行することをお勧めします。
特定のクエリが高コストであると表示される場合は、次を実行して履歴を取得できます。
SELECT DS.Day,Loc.Location,DS.StatCount,DS.StatTotal,S.Statement,S.Hash
FROM INFORMATION_SCHEMA.STATEMENT_DAILY_STATS DS
left join INFORMATION_SCHEMA.STATEMENTS S
on S.Hash=DS.Statement
left join INFORMATION_SCHEMA.STATEMENT_LOCATIONS Loc
on S.Hash=Loc.Statement
where S.Hash='jDqCKaksff/4up7Ob0UXlkT2xKY='
order by DS.Day
日次統計を週出するためのコードサンプル
Class DRL.MonitorSQLTask Extends %SYS.Task.Definition
{
Parameter TaskName = "SQL Statistics Summary";
Method OnTask() As %Status
{
set tSC=$$$OK
TRY {
do ##class(DRL.MonitorSQL).Run()
}
CATCH exp {
set tSC=$SYSTEM.Status.Error("Error in SQL Monitor Summary Task")
}
quit tSC
}
}
Class DRL.MonitorSQLText Extends %Persistent
{
/// Hash of query text
Property Hash As %String;
/// query text for hash
Property QueryText As %String(MAXLEN = 9999);
Index IndHash On Hash [ IdKey, Unique ];
}
/// Summary of very low cost SQL query statistics collected in Cache 2017.1 and later. <br/>
/// Refer to documentation on "SQL Statement Details" for information on the source data. <br/>
/// Data is stored by date and time to support queries over time. <br/>
/// Typically run to summarise the SQL query data from the previous day.
Class DRL.MonitorSQL Extends %Persistent
{
/// RunDate and RunTime uniquely identify a run
Property RunDate As %Date;
/// Time the capture was started
/// RunDate and RunTime uniquely identify a run
Property RunTime As %Time; /// Count of total hits for the time period for
Property TotalHits As %Integer; /// Sum of pTime
Property SumPTime As %Numeric(SCALE = 4); /// Routine where SQL is found
Property RoutineName As %String(MAXLEN = 1024); /// Hash of query text
Property Hash As %String; Property Variance As %Numeric(SCALE = 4); /// Namespace where queries are run
Property Namespace As %String; /// Default run will process the previous days data for a single day.
/// Other date range combinations can be achieved using the Capture method.
ClassMethod Run()
{
//Each run is identified by the start date / time to keep related items together
set h=$h-1
do ..Capture(+h,+h)
} /// Captures historic statistics for a range of dates
ClassMethod Capture(dfrom, dto)
{
set oldstatsvalue=$system.SQL.SetSQLStatsJob(-1)
set currNS=$znspace
set tSC=##class(%SYS.Namespace).ListAll(.nsArray)
set ns=""
set time=$piece($h,",",2)
kill ^||TMP.MonitorSQL
do {
set ns=$o(nsArray(ns))
quit:ns=""
use 0 write !,"processing namespace ",ns
zn ns
for dateh=dfrom:1:dto {
set hash=""
set purgedun=0
do {
set hash=$order(^rINDEXSQL("sqlidx",1,hash))
continue:hash=""
set stats=$get(^rINDEXSQL("sqlidx",1,hash,"stat",dateh))
continue:stats=""
set ^||TMP.MonitorSQL(dateh,ns,hash)=stats
&SQL(SELECT Location into :tLocation FROM INFORMATION_SCHEMA.STATEMENT_LOCATIONS WHERE Statement=:hash)
if SQLCODE'=0 set Location=""
set ^||TMP.MonitorSQL(dateh,ns,hash,"Location")=tLocation
&SQL(SELECT Statement INTO :Statement FROM INFORMATION_SCHEMA.STATEMENTS WHERE Hash=:hash)
if SQLCODE'=0 set Statement=""
set ^||TMP.MonitorSQL(dateh,ns,hash,"QueryText")=Statement
} while hash'=""
}
} while ns'=""
zn currNS
set dateh=""
do {
set dateh=$o(^||TMP.MonitorSQL(dateh))
quit:dateh=""
set ns=""
do {
set ns=$o(^||TMP.MonitorSQL(dateh,ns))
quit:ns=""
set hash=""
do {
set hash=$o(^||TMP.MonitorSQL(dateh,ns,hash))
quit:hash=""
set stats=$g(^||TMP.MonitorSQL(dateh,ns,hash))
continue:stats=""
// The first time through the loop delete all statistics for the day so it is re-runnable
// But if we run for a day after the raw data has been purged, it will wreck eveything
// so do it here, where we already know there are results to insert in their place.
if purgedun=0 {
&SQL(DELETE FROM websys.MonitorSQL WHERE RunDate=:dateh )
set purgedun=1
}
set tObj=##class(DRL.MonitorSQL).%New() set tObj.Namespace=ns
set tObj.RunDate=dateh
set tObj.RunTime=time
set tObj.Hash=hash
set tObj.TotalHits=$listget(stats,1)
set tObj.SumPTime=$listget(stats,2)
set tObj.Variance=$listget(stats,3)
set tObj.Variance=$listget(stats,3)
set queryText=^||TMP.MonitorSQL(dateh,ns,hash,"QueryText")
set tObj.RoutineName=^||TMP.MonitorSQL(dateh,ns,hash,"Location")
&SQL(Select ID into :TextID from DRL.MonitorSQLText where Hash=:hash)
if SQLCODE'=0 {
set textref=##class(DRL.MonitorSQLText).%New()
set textref.Hash=tObj.Hash
set textref.QueryText=queryText
set sc=textref.%Save()
}
set tSc=tObj.%Save()
//avoid dupicating the query text in each record because it can be very long. Use a lookup
//table keyed on the hash. If it doesn't exist add it.
if $$$ISERR(tSc) do $system.OBJ.DisplayError(tSc)
if $$$ISERR(tSc) do $system.OBJ.DisplayError(tSc)
}while hash'=""
} while ns'=""
} while dateh'=""
do $system.SQL.SetSQLStatsJob(0)
} Query Export(RunDateH1 As %Date, RunDateH2 As %Date) As %SQLQuery
{
SELECT S.Hash,RoutineName,RunDate,RunTime,SumPTime,TotalHits,Variance,RoutineName,T.QueryText
FROM DRL.MonitorSQL S LEFT JOIN DRL.MonitorSQLText T on S.Hash=T.Hash
WHERE RunDate>=:RunDateH1 AND RunDate<=:RunDateH2
}
}
記事
Toshihiko Minamoto · 2021年8月31日
[最初の記事](https://jp.community.intersystems.com/node/501166)では、Caché Webアプリケーションのテストとデバッグを外部ツールを用いて行うことについて説明しました。 2回目となるこの記事では、Cachéツールの使用について説明します。
以下について説明します。
* CSP GatewayとWebappの構成
* CSP Gatewayのロギング
* CSP Gatewayのトレース
* ISCLOG
* カスタムロギング
* セッションイベント
* デバイスへの出力
### CSP GatewayとWebappの構成
まず初めに、フロントエンドアプリケーションをデバッグする場合、特にそれを開発している場合は、キャッシュは必要ありません。 本番システムでは役立ちますが、開発中には不要です。 Webアプリケーションのロギングを無効にするには、システム管理ポータル → メニュー → Webアプリケーションの管理 → <あなたのWebアプリ>に移動して、Serve Files Timeoutを0に設定します。 そして［保存］ボタンを押します。
次に、webアプリケーションの既存のキャッシュを消去する必要があります。 これを行うには、システム管理ポータル → システム管理 → 構成 → CSP Gatewayの管理 → システムステータスに移動します。 「Cached Forms」テーブルを探し、その最後の行にある「Total」の消去ボタン（ドット）を押してWebアプリケーションのキャッシュを消去します。
### CSP Gatewayのロギング
CSP Gatewayに関しては、受信リクエストのロギングがサポートされています（ドキュメント）。 ［デフォルトのパラメーター］タブで、希望するログレベル（v9aなど）を指定して、変更を保存します。 v9aは、すべてのHTTPリクエストをGatewayホームディレクトリのhttp.logに記録します（ほかのオプションについてはドキュメントをご覧ください）。 リクエストは次のようにキャプチャされます。
GET /forms/form/info/Form.Test.Person HTTP/1.1
Host: localhost:57772
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:53.0) Gecko/20100101 Firefox/53.0
Accept: application/json, text/plain, */*
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate
Referer: http://localhost:57772/formsui/index.html
Cookie: CSPSESSIONID-SP-57772-UP-forms-=001000000000yxiocLLb8bbc9SVXQJC5WMU831n2sENf4OGeGa; CSPWSERVERID=144zwBTP
Dnt: 1
Connection: keep-alive
Cache-Control: max-age=0
また、パフォーマンスを記録するオプションもあります。 結果はファイルに出力されるか、［イベントログの表示］タブで閲覧することができます。
### CSP Gatewayのトレース
そして最後に、CSP Gatewayの［HTTPトレースの表示］タブでリクエストとレスポンスをトレースすることができます。 トレースを有効にすると、リクエストのキャプチャがすぐに開始します。 デバッグを終えたら、忘れずに無効にしてください。 デバッグセッションは次のように行われます。
注意: トレースのやり方がわかっている場合は、エラーを簡単に理解し、問題を再現することができます。 ロギングは統計収集、パフォーマンスプロファイリングなどに使用します。
また、ほとんどのWebサーバーにも、ロギングとパフォーマンス追跡ツールが備わっています。
### ISCLOG
CSP Gatewayは、ネットワークの問題の特定とパフォーマンスの追跡には役立ちますが、Caché内で起きていることをログするにほかのツールが必要となります。 そのようなツールの中でも汎用性に優れているのがISCLOGです。 [ドキュメント](http://docs.intersystems.com/latestj/csp/docbook/DocBook.UI.Page.cls?KEY=GCSP_logging)をご覧ください。
これは、現在のリクエスト処理に関する情報を保存できるグローバル変数です。 ロギングを開始するには、以下を実行します。
set ^%ISCLOG = 2
ロギングを終了するには、以下を実行します。
set ^%ISCLOG = 0
リクエストは次のようにロギングされます。
^%ISCLOG=0
^%ISCLOG("Data")=24
^%ISCLOG("Data",1)=$lb(2,"CSPServer","Header from CSP Size:3744 CMD:h IdSource:3","4664","FORMS","2017-06-07 10:49:21.341","%SYS.cspServer2","","")
^%ISCLOG("Data",1,0)="^h30000 "_$c(14,0,0)_"A"
^%ISCLOG("Data",2)=$lb(2,"CSPServer","[UpdateURL] Looking up: //localhost/forms/form/info path found: //localhost/forms/ Appl= "_$c(2,1,3,4)_"@"_$c(3,4,1,2,1,9,1)_"/forms/"_$c(2,1,3,4,1,2,1,2,1,2,4,3,4,1,2,1,9,1,7,1)_":%All"_$c(8,1)_"/forms"_$c(7,1)_"FORMS"_$c(2,1,2,1,3,4,1,2,1,2,1,3,4,1,2,1,4,4,132,3,3,4,2,3,4,2,2,1,4,4,16,14,2,4,3,4,1,3,4,1,2,1,3,4,1,2,1,16,1)_"Form.REST.Main"_$c(2,4,2,4),"4664","FORMS","2017-06-07 10:49:21.342","%CSP.Request.1","124","L3DfNILTaE")
^%ISCLOG("Data",3)=$lb(2,"CSPServer","[UpdateURL] Found cls: Form.REST.Main nocharsetconvert: charset:UTF-8 convert charset:UTF8","4664","FORMS","2017-06-07 10:49:21.342","%CSP.Request.1","124","L3DfNILTaE")
^%ISCLOG("Data",4)=$lb(2,"CSPServer","[HTML] Determined request type","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer2","124","L3DfNILTaE")
^%ISCLOG("Data",4,0)=$lb("usesession",1,"i%Class","Form.REST.Main","i%Service","REST","NOLOCKITEM","","i%GatewayError","")
^%ISCLOG("Data",5)=$lb(2,"CSPSession","[%LoadData] Loading CSP session, nosave=0","4664","FORMS","2017-06-07 10:49:21.342","%CSP.Session.1","","L3DfNILTaE")
^%ISCLOG("Data",5,0)=$lb(900,,0,5567742244,$c(149)_"Ù"_$c(3)_"ó»à"_$c(127)_",½"_$c(149,10)_"\"_$c(18)_"v"_$c(128,135)_"3Vô"_$c(11)_"*"_$c(154)_"PÏG¥"_$c(140,157,145,10,131)_"*",2,"FORMS","001000000000L3DfNILTaE1cDBJNjyQdyLwKq4wCXP82ld8gic",,0,"ru","L3DfNILTaE",2,1,"/forms/",$lb("UnknownUser","%All,%Developer","%All,%Developer",64,-559038737),"","","","2017-06-07 10:48:51","2017-06-07 10:49:04","Basic ZGV2OjEyMw==","Mozilla/5.0 (Windows NT 10.0; WOW64; rv:53.0) Gecko/20100101 Firefox/53.0","","",0,"/forms/","","","",4,"","","","","http://localhost:57772/formsui/index.html")
^%ISCLOG("Data",6)=$lb(2,"CSPServer","[CSPDispatch]Requested GET /forms/form/info","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",7)=$lb(2,"CSPServer","[CSPDispatch] ** Start processing request newSes=0","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",7,0)="/forms/form/info"
^%ISCLOG("Data",8)=$lb(2,"CSPServer","[CSPDispatch] Service type is REST has-soapaction=0 nosave=0","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",9)=$lb(2,"CSPServer","[CSPDispatch]About to run page: Form.REST.Main","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",9,0)=$lb("UnknownUser","%All,%Developer","%All,%Developer",64,-559038737)
^%ISCLOG("Data",10)=$lb(2,"CSPServer","[callPage] url=/forms/form/info ; Appl: /forms/ newsession=0","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",11)=$lb(2,"CSPServer","[callPage]Imported security context ; User: UnknownUser ; Roles: %All,%Developer","4664","FORMS","2017-06-07 10:49:21.342","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",12)=$lb(2,"CSPServer","[OutputCSPGatewayData]: chd=1;","4664","FORMS","2017-06-07 10:49:21.431","%CSP.Response.1","","L3DfNILTaE")
^%ISCLOG("Data",13)=$lb(2,"CSPResponse","[WriteHTTPHeaderCookies] Session cookie: CSPSESSIONID-SP-57772-UP-forms-=001000000000L3DfNILTaE1cDBJNjyQdyLwKq4wCXP82ld8gic; path=/forms/; httpOnly;","4664","FORMS","2017-06-07 10:49:21.431","%CSP.Response.1","124","L3DfNILTaE")
^%ISCLOG("Data",14)=$lb(2,"CSPServer","[callPage] Return Status","4664","FORMS","2017-06-07 10:49:21.431","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",14,0)=1
^%ISCLOG("Data",15)=$lb(2,"CSPServer","[OutputCSPGatewayData]: chd=1;","4664","FORMS","2017-06-07 10:49:21.431","%CSP.Response.1","","L3DfNILTaE")
^%ISCLOG("Data",16)=$lb(2,"CSPServer","[Cleanup]Page EndSession=0; needToGetALicense=-1; nosave=0; loginredirect=0; sessionContext=1","4664","FORMS","2017-06-07 10:49:21.431","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",17)=$lb(2,"CSPSession","[Cleanup] EndSession=0 nosave=0","4664","FORMS","2017-06-07 10:49:21.431","%SYS.cspServer","124","L3DfNILTaE")
^%ISCLOG("Data",18)=$lb(2,"CSPSession","[%SaveData] Saved: ","4664","FORMS","2017-06-07 10:49:21.431","%CSP.Session.1","","L3DfNILTaE")
^%ISCLOG("Data",18,0)=$lb(900,,0,5567742261,$c(149)_"Ù"_$c(3)_"ó»à"_$c(127)_",½"_$c(149,10)_"\"_$c(18)_"v"_$c(128,135)_"3Vô"_$c(11)_"*"_$c(154)_"PÏG¥"_$c(140,157,145,10,131)_"*",2,"FORMS","001000000000L3DfNILTaE1cDBJNjyQdyLwKq4wCXP82ld8gic",,0,"ru","L3DfNILTaE",2,1,"/forms/",$lb("UnknownUser","%All,%Developer","%All,%Developer",64,-559038737),"","","","2017-06-07 10:48:51","2017-06-07 10:49:21","Basic ZGV2OjEyMw==","Mozilla/5.0 (Windows NT 10.0; WOW64; rv:53.0) Gecko/20100101 Firefox/53.0","","",0,"/forms/","","","",5,"","","","","http://localhost:57772/formsui/index.html")
^%ISCLOG("Data",19)=$lb(2,"CSPServer","[Cleanup] Restoring roles before running destructor","4664","FORMS","2017-06-07 10:49:21.431","%SYS.cspServer","","L3DfNILTaE")
^%ISCLOG("Data",19,0)=$lb("UnknownUser","%All,%Developer","%All,%Developer",64,-559038737)
^%ISCLOG("Data",20)=$lb(2,"CSPServer","[Cleanup] End","4664","FORMS","2017-06-07 10:49:21.431","%SYS.cspServer","","L3DfNILTaE")
^%ISCLOG("Data",20,0)=""
^%ISCLOG("Data",21)=$lb(2,"GatewayRequest","[CSPGWClientRequest] GWID: ed-pc:57772; Request: sys_get_system_metricsTimeout: 5","11112","%SYS","2017-06-07 10:49:23.141","%SYS.cspServer3","","")
^%ISCLOG("Data",22)=$lb(2,"GatewayRequest","[CSPGWClientRequest] GWID: 127.0.0.1:57772; Request: sys_get_system_metricsTimeout: 5","11112","%SYS","2017-06-07 10:49:23.141","%SYS.cspServer3","","")
^%ISCLOG("Data",23)=$lb(2,"GatewayRequest","[SendSimpleCmd:Server:Failed] WebServer: 127.0.0.1:57772; Gateway Server Request Failed","11112","%SYS","2017-06-07 10:49:23.141","%CSP.Mgr.GatewayMgrImpl.1","","")
^%ISCLOG("Data",23,0)=0
^%ISCLOG("Data",24)=$lb(2,"GatewayRequest","[GetMetrics]","11112","%SYS","2017-06-07 10:49:23.141","%CSP.Mgr.GatewayMgrImpl.1","","")
^%ISCLOG("Data",24,0)=""
また、以下のような簡単なスクリプトを使用して、グローバルをファイルに出力することができます。
set p="c:\temp\isclog.txt"
open p:"NW"
use p zw ^%ISCLOG
close p
### カスタムロギング
デフォルトのロギングツールも非常に優れていますが、いくつかの問題があります。
* 内容が一般的であり、アプリケーションが認識されない
* より詳細なオプションを使うと、パフォーマンスに影響する
* 構造化されていないため、情報の抽出が困難な場合がある
そのため、より具体的なケースを網羅するために、独自のカスタムロギングシステムを作成することができます。 以下は、%requestオブジェクトの一部を記録する永続クラスのサンプルです。
/// Incoming request
Class Log.Request Extends %Persistent
{
/// A string indicating HTTP method used for this request.
Property method As %String;
/// A string containing the URL up to and including the page name
/// and extension, but not including the query string.
Property url As %String(MAXLEN = "");
/// A string indicating the type of browser from which the request
/// originated, as determined from the HTTP_USER_AGENT header.
Property userAgent As %String(MAXLEN = "");
/// A string indicating the MIME Content-Type of the request.
Property contentType As %String(MAXLEN = "");
/// Character set this request was send in, if not specified in the HTTP headers
/// it defaults to the character set of the page it is being submitted to.
Property charSet As %String(MAXLEN = "");
/// A %CSP.Stream containing the content submitted
/// with this request.
Property content As %Stream.GlobalBinary;
/// True if the communication between the browser and the web server was using
/// the secure https protocol. False for a normal http connection.
Property secure As %Boolean;
Property cgiEnvs As array Of %String(MAXLEN = "", SQLPROJECTION = "table/column");
Property data As array Of %String(MAXLEN = "", SQLPROJECTION = "table/column");
ClassMethod add() As %Status
{
set request = ..%New()
quit request.%Save()
}
Method %OnNew() As %Status [ Private, ServerOnly = 1 ]
{
#dim %request As %CSP.Request
#dim sc As %Status = $$$OK
quit:'$isObject($g(%request)) $$$ERROR($$$GeneralError, "Not a web context")
set ..charSet = %request.CharSet
if $isObject(%request.Content) {
do ..content.CopyFromAndSave(%request.Content)
} else {
set ..content = ""
}
set ..contentType = %request.ContentType
set ..method = %request.Method
set ..secure = %request.Secure
set ..url = %request.URL
set ..userAgent = %request.UserAgent
set cgi = ""
for {
set cgi=$order(%request.CgiEnvs(cgi))
quit:cgi=""
do ..cgiEnvs.SetAt(%request.CgiEnvs(cgi), cgi)
}
// Only gets first data if more than one data with the same name is present
set data = ""
for {
set data=$order(%request.Data(data))
quit:data=""
do ..data.SetAt(%request.Get(data), data)
}
quit sc
}
}
Log.Request テーブルに新しいレコードを追加するには、コードに次の呼び出しを追加します。
do ##class(Log.Request).add()
これは非常に基本的なサンプルであり、必要に応じてコメント、変数、またはほかの様々なものを記録するように拡張することができ、そうすることが推奨されます。 このアプローチの主なメリットは、記録されたデータに対してSQLクエリを実行できることにあります。 独自のロギングシステムの構築に関する詳細は、[こちらの記事](https://community.intersystems.com/post/logging-using-macros-intersystems-cach%C3%A9)をご覧ください。
### セッションイベント
イベントクラスは、[%CSP.Session](http://docs.intersystems.com/latestj/csp/documatic/%25CSP.Documatic.cls?PAGE=CLASS&LIBRARY=%25SYS&CLASSNAME=%25CSP.Session)オブジェクトの寿命中に呼び出されるインターフェースを定義するクラスです。 これを使用するには、 [%CSP.SessionEvents](http://docs.intersystems.com/latestj/csp/documatic/%25CSP.Documatic.cls?PAGE=CLASS&LIBRARY=%25SYS&CLASSNAME=%25CSP.SessionEvents)をサブクラス化して、実行するメソッドコードを実装する必要があります。 次に、CSPアプリケーション構成内で、イベントクラスを作成したクラスに設定します。
次のコールバックを利用できます。
OnApplicationChange
OnEndRequest
OnEndSession
OnLogin
OnLogout
OnStartRequest
OnStartSession
* OnTimeout
たとえば上記のカスタムロギングは、これらのメソッドから呼び出すことができます。
### デバイスへの出力
最も単純なオプションの1つは、すべてのオブジェクトをレスポンスとして出力するCSPユーティリティメソッドです。 これをコードの任意の場所に追加するだけで出力できます。
set %response.ContentType = "html"
do ##class(%CSP.Utils).DisplayAllObjects()
return $$$OK
### まとめ
Webアプリケーションのデバッグにはさまざまなツールを使用することができます。 手元のタスクに最適なものを選択するようにしてください。
皆さんは、CachéからWebアプリケーションをデバッグする際には、どのようなヒントやトリックを使用していますか？
