2022年3月9日水曜日

画面の表示に時間がかかるときのデバッグ作業

 APEXで作ったアプリの画面の表示に時間がかかる、という相談を受けた時に行った作業を紹介します。

確認作業にAlways FreeのAutonomous Transaction Processingのインスタンスを使用しています。ただし、相談を受けたインスタンスはExadataではありませんでした。

元の画面はもっと複雑なようですが、結果として問題だったのはページ・アイテムの選択リストでした。以下のように選択リストのページ・アイテムがひとつだけ作成されている、簡素化したページを例に取ります。

最初にデバッグを有効にします。

開発者ツール・バーのデバッグをクリックします。

デバッグを有効にしたのち、パフォーマンスに問題のあるページを開きます。

画面が表示されたら、開発者ツール・バーのデバッグの表示をクリックし、デバッグ画面を開きます。


デバッグ画面が開いたら、アプリケーション、ページやタイムスタンプなどより、デバッグの対象にした処理に当たりをつけて、ビュー識別子をクリックします。


デバッグ・メッセージの一覧が表示されます。グラフを見ると、突出して実行時間が長い処理があることが分かります。


また、デバッグ・メッセージの一覧は対話モード・レポートなので、例えば実行時間が10秒以上かかっている処理といった条件でも検索できます。


デバッグ・メッセージの一覧より、実行時間の長い部分の近辺を確認します。

ページ・アイテムP2_DATEの処理に時間がかかっている、ということ以外は分かりません。


デバッグ・レベルを完全トレースまで上げて、ログを取得します。

開発者ツール・バー・オプションを開き、デフォルト・デバッグ・レベルを完全トレースに変更します。


デバッグ・レベルを上げたのち、パフォーマンスが問題となっている操作を再度行います。

デバッグ・メッセージの中から、実行時間の長い処理を確認します。

メッセージとしてfetch_rowsの実行時間が長い場合があります。これは直前のSELECT文の実行時間です。SELECT文の実行時間は、実際の実行時間ではなく実行計画の表示にかかった時間と思われます。


fetch_rowsの直前に表示されているSELECT文に時間がかかっていることが分かるので、このSELECT文をSQLコマンドで実行します。

選択リストのLOVのソースとして、最初は以下のSELECT文が使われていました。

検索対象の表PERFTESTには列UPDATE_DATEがあります。131,072,000行のデータが投入されています。

select
distinct
case
when trunc(update_date) = trunc(
(select max(update_date) from perftest)
)
then
to_char(trunc(update_date),'YYYY-MM-DD') || ' (latest)'
else
to_char(trunc(update_date),'YYYY-MM-DD')
end as d
, to_char(trunc(update_date),'YYYY-MM-DD') as r
from perftest
order by 1 desc

SELECT文の実行に88.16秒かかったことが分かります。


実行計画を確認することもできます。


SELECT文が意図しているのは以下です。
  1. 列UPDATE_DATEの内容を、日付を単位として選択リストに表示する。
  2. 降順で表示する。
  3. 最も最近の日付に、ラベル(latest)を付加する。
若干、SELECT文が複雑すぎるようです。ファンクションto_charやtruncといった処理が呼び出される回数が減るようにSELECT文を書き直します。

select
case when rownum = 1 then
update_date || ' (latest)'
else
update_date
end as d,
update_date r
from
(
select update_date from
(
select
to_char(update_date,'YYYY-MM-DD') update_date
from perftest
)
group by update_date order by update_date desc
)

実行時間は43.44秒まで改善されました。


（確認した結果）to_charよりtruncの方がCPU負荷が低かったので、表PERFTESTの全行に対して実行するファンクションをto_charからtruncに変え、集計した結果にto_charを適用するようにSELECT文を変更しました。

select
case when rownum = 1 then
update_date || ' (latest)'
else
update_date
end as d,
update_date as r
from
(
select to_char(update_date,'YYYY-MM-DD') update_date from
(
select
trunc(update_date) update_date
from perftest
)
group by update_date order by update_date desc
)

実行結果が0.13秒まで改善しました。


これで解決かと思ったのですが、Autonomous DatabaseだとCPUを使う処理を減らすと（それ以外が高速なので）結果は良くなるのですが、Exadataでない場合はそこまで改善しないようです。

比較のため、手元のVirtualBoxで構成したOracle Database 21c Express EditionのAPEXで実行してみました。

最初のSELECT文の実行は141.86秒でした。


２つめのSELECT文の実行は68.25秒でした。

最後のSELECT文の実行は16.33秒で、実用に耐えられる実行時間ではありません。

これ以上の改善は難しいだろうということで、選択リストが使うマテリアライズド・ビューを作り、定期的にリフレッシュすることにします。

create materialized view perftest_days
build immediate
refresh complete on demand
as
select to_char(update_date,'YYYY-MM-DD') update_date from
(
select
    trunc(update_date) update_date
from perftest
) 
group by update_date;

以下のSQLでマテリアライズド・ビューのリフレッシュを行います。

begin
    dbms_mview.refresh('PERFTEST_DAYS','C');
end;
マテリアライズド・ビューのリフレッシュには時間がかかりますが、１日に１回実行すればことが足ります。

選択リストのSQL問合せは、マテリアライズド・ビューを使う前提だと以下になります。
select
    case
    when rownum = 1 then
        update_date || ' (latest)'
    else
        update_date
    end as d
    , update_date as r
from (
    select update_date 
    from perftest_days 
    order by update_date desc
)
実行時間は0.00秒となり、ほとんど無視できるようになりました。


デバッグ作業の紹介は以上になります。

Oracle APEXのアプリケーション作成の参考になれば幸いです。

追記

対話グリッドや対話モード・レポートなど、リージョンで遅延ロードというプロパティを持つものがあります。


遅延ロードが有効なリージョンのソースとなるSQLは、ページのロードとは別に実行されます。デバッグ・メッセージの一覧を見ると、パス情報がajax pluginになっているものが、遅延ロードがONのリージョンのソースとなるSQLの実行です。


デバッグをするときは、遅延ロードをOFFにするとデバッグが容易になるでしょう。

完
投稿者 時刻:
ラベル: , ,