※ 本記事は、Martin Bachによる”Performance Monitoring for In-Database JavaScript in Oracle Database 23c“を翻訳したものです。
2023年12月15日
Oracle Database 23cは、別のサーバーサイド・プログラミング言語としてJavaScriptを備えています。GraalVMを搭載したMultilingual Engineのおかげで、PL/SQL、JavaおよびJavaScriptを使用してデータベースにビジネス・ロジックを作成できるようになりました。
すべての現代語における重要な点の1つは、可観測性です。Oracle Databaseのコンテキストでは、ほとんどの開発者は、SQL文の実行方法に関するインサイトを評価しています。幸いなことに、これはPL/SQLの場合とほぼ同じ方法でJavaScriptを使用して可能です。
ちなみに、サーバーサイドのJavaScriptの提供に関心がある場合は、すでにOracle Database 23c Freeを使用して行うことができます。
サンプル・コード
まずはコードから始めましょう。まず、いくつかのメッセージを格納するテーブルを作成します
create table messages (
id number generated always as identity not null,
msg varchar2(256) not null,
constraint pk_messages primary key (id)
);
次に、表に挿入してメッセージを更新する小さなAPIを作成します
create or replace mle module blogpost_module
language javascript as
let savedModule;
let savedAction;
/**
* Insert a row into the messages table
* @param {string} msg - the message to insert
* @returns {number} - the newly inserted message ID
*/
export function insertMessage(msg) {
// tell Oracle what we're about to do
setModuleAction(`blogpost_module`, `add message`);
// get the new ID, initialise to an incorrect value to detect errors
let id = -1;
// insert the message. Since the id is an out-bind it needs to be
// declared as such
const result = session.execute(
`insert into messages (msg) values (:msg)
returning id into :id`,
{
msg: { dir: oracledb.BIND_IN, val: msg, type: oracledb.STRING },
id: { dir: oracledb.BIND_OUT, type: oracledb.NUMBER }
}
);
// check if the insert succeeded
if (result.rowsAffected != 1) {
throw new Error(`unexpected error trying to insert into t1`);
}
id = result.outBinds.id[0];
if (id === -1) {
throw new Error(`unable to obtain the message ID`);
}
// restore module and action from what they were set to before
setModuleAction(savedModule, savedAction);
// return the message ID to the caller
return id;
}
/**
* update an existing message in the messages table
* @param {string} msg - the message to be updated
* @param {number} id - the message ID to be updated
*/
export function updateMessage(id, msg) {
// tell Oracle what we're about to do
setModuleAction(`blogpost_module`, `update message`);
// perform the update. Both bind variables are in-binds,
// the simplified array-syntax can be used instead of the
// slightly more flexible but more verbose JavaScript object
const result = session.execute(
`update messages set msg = :msg where id = :id`,
[ msg, id ]
);
// make sure the update succeeded. It might fail if you provide the
// wrong message ID
if (result.rowsAffected != 1) {
throw new Error(`unexpected error trying to update message ${id}`);
}
// restore module and action from what they were set to before
setModuleAction(savedModule, savedAction);
}
/**
* code instrumentation: set database module and action
*/
function setModuleAction(module, action) {
// preserve current module (m) and action (a)
let result = session.execute(
`begin dbms_application_info.read_module(:m, :a); end;`,
{
m: {
dir: oracledb.BIND_OUT, type: oracledb.STRING
},
a: {
dir: oracledb.BIND_OUT, type: oracledb.STRING
}
}
);
savedModule = result.outBinds.m;
savedAction = result.outBinds.a;
result = session.execute(
`begin dbms_application_info.set_module(:m, :a); end;`,
[module, action]
);
}
/
呼び出しの仕様はパズルの最後のピースです:
create or replace package blogpost_pkg as
function insert_message(p_msg varchar2)
return number
as mle module blogpost_module
signature 'insertMessage(string)';
procedure update_message(p_id number, p_msg varchar2)
as mle module blogpost_module
signature 'updateMessage(number, string)';
end blogpost_pkg;
/
問題の原因
2つの異なるセッションで同じメッセージを更新して、アクティブ・セッション履歴(ASH)イベントを生成し、いくつかの問題を引き起こしましょう。
セッション1に接続すると、最初のユーザーが次のメッセージを作成します:
12:06:53 SESSION 1> select userenv('sid');
USERENV('SID')
--------------
52
12:07:56 SESSION 1> var id number
12:08:00 SESSION 1> l
1 begin
2 :id := blogpost_pkg.insert_message('message 1');
3* end;
12:08:01 SESSION 1> /
PL/SQL procedure successfully completed.
12:08:02 SESSION 1> print :id
ID
----------
21
12:08:05 SESSION 1> commit;
Commit complete.
これで、ユーザー2がこのメッセージを更新します:
12:09:07 SESSION 2> select userenv('sid');
USERENV('SID')
--------------
262
12:10:07 SESSION 2> begin
12:10:08 2 blogpost_pkg.update_message(21, 'this is user 2');
12:10:11 3 end;
12:10:12 4 /
PL/SQL procedure successfully completed.
ユーザー2はまだ更新をコミットしていないことに注意してください。ユーザー1は、より良いメッセージを考え、メッセージ21も更新しようとします。
12:11:07 SESSION 1> begin
12:11:08 2 blogpost_pkg.update_message(:id, 'this is user 1 again');
12:11:13 3 end;
12:11:14 4 /
予想どおり、ユーザー1のセッションがハングします。もちろん、ユーザー2がコミットされると、そのターンを待っているわけではありません。v$sessionでは、次のように簡単に確認できます:
SQL> select
2 s.sid,
3 s.serial#,
4 s.module,
5 s.action,
6 s.state,
7 s.event,
8 s.sql_id,
9 sq.sql_text
10 from
11 v$session s
12 left join v$sqlstats sq on (s.sql_id = sq.sql_id)
13 where
14 s.username = 'EMILY' and
15* s.program like 'sqlplus%';
SID SERIAL# MODULE ACTION STATE EVENT SQL_ID SQL_TEXT
______ __________ __________________ _________________ __________ ________________________________ ________________ ________________________________________________
52 14255 blogpost_module update message WAITING enq: TX - row lock contention 0nuh8kg895szk update messages set msg = :msg where id = :id
262 63657 SQL*Plus WAITING SQL*Net message from client
Oracleは、ユーザー2 (セッションID 262)が離れていることを通知します(クライアントからのSQL*Netメッセージは、sqlplusが入力を待機していることを意味します)。残念ながら、ユーザー2はトランザクションをコミットしませんでした。行ロック・ユーザー1が待機しているのは十分な証拠です。NB: この長期にわたるロックの問題は、データベース・リソース・マネージャを使用して回避できます。
アクティブ・セッション履歴(ASH)
前述の擬似的なもののような同時実行性の問題は、v$active_session_historyの一部のエントリに対して発生する必要があります。DIAGNOSTICS PACKを使用するライセンスがある場合は、次に示すようにASHを問い合せることができます:
SQL> select
2 count(*),
3 event,
4 session_id,
5 blocking_session
6 from
7 v$active_session_history
8 where
9 sql_id = '0nuh8kg895szk'
10 group by
11 event,
12 session_id,
13 blocking_session
14 /
COUNT(*) EVENT SESSION_ID BLOCKING_SESSION
___________ ________________________________ _____________ ___________________
2333 enq: TX - row lock contention 52 262
PL/SQLと同様に、多くのツールをJavaScriptで使用できます。ASHレポートの例:
ASH Report For FREE/FREE
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
FREE 2625275352 FREE 1 23.3.0.23.0 NO oracle23cfre
CPUs SGA Size Buffer Cache Shared Pool ASH Buffer Size
---- ------------------ ------------------ ------------------ ------------------
2 1,081M (100%) 624M (57.7%) 76M (7.0%) Not Available
In-memory Area Size
------------------
0.0M (0.0%)
Analysis Begin Time: 08-Oct-23 12:10:15
Analysis End Time: 08-Oct-23 12:25:14
Elapsed Time: 15.0 (mins)
Begin Data Source: V$ACTIVE_SESSION_HISTORY
End Data Source: V$ACTIVE_SESSION_HISTORY
Sample Count: 844
Average Active Sessions: 0.94
Avg. Active Session per CPU: 0.47
Report Target: None specified
Top User Events DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
Avg Active
Event Event Class % Event Sessions
----------------------------------- --------------- ---------- ----------
enq: TX - row lock contention Application 99.41 0.93
-------------------------------------------------------------
[snip]
Top Containers DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
Container Name Count % Activity Avg Active
---------------------------------------- ---------- ---------- ----------
FREEPDB1 844 100.00 0.94
-------------------------------------------------------------
Top Service/Module DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
Service Module % Activity Action % Action
-------------- ------------------------ ---------- ------------------ ----------
freepdb1 blogpost_module 99.41 update message 99.41
-------------------------------------------------------------
[snip]
Top SQL Command Types DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
-> 'Distinct SQLIDs' is the count of the distinct number of SQLIDs
with the given SQL Command Type found over all the ASH samples
in the analysis period
Distinct Avg Active
SQL Command Type SQLIDs % Activity Sessions
---------------------------------------- ---------- ---------- ----------
UPDATE 1 99.41 0.93
-------------------------------------------------------------
Top Phases of Execution DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
Avg Active
Phase of Execution % Activity Sessions
------------------------------ ---------- ----------
SQL Execution 100.00 0.94
-------------------------------------------------------------
Top SQL with Top Events DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
SQL ID FullPlanhash Planhash
----------------------- -------------------- --------------------
Sampled #
of Executions % Activity Event
-------------------- -------------- ------------------------------
% Event Top Row Source % RwSrc
------- --------------------------------- -------
Container Name
-------------------------------------------
0nuh8kg895szk N/A 3749799
1 99.41 enq: TX - row lock contention
99.41 UPDATE 99.41
update messages set msg = :msg where id = :id
FREEPDB1
-------------------------------------------------------------
[snip]
Top PL/SQL Procedures DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
-> 'PL/SQL entry subprogram' represents the application's top-level
entry-point(procedure, function, trigger, package initialization
or RPC call) into PL/SQL.
-> 'PL/SQL current subprogram' is the pl/sql subprogram being executed
at the point of sampling . If the value is 'SQL', it represents
the percentage of time spent executing SQL for the particular
plsql entry subprogram
PLSQL Entry Subprogram % Activity
----------------------------------------------------------------- ----------
PLSQL Current Subprogram % Current
----------------------------------------------------------------- ----------
Container Name
-------------------------------------------
EMILY.BLOGPOST_PKG.UPDATE_MESSAGE 99.41
SQL 99.41
FREEPDB1
-------------------------------------------------------------
[snip]
Activity Over Time DB/Inst: FREE/FREE (Oct 08 12:10 to 12:25)
-> Analysis period is divided into smaller time slots
-> Top 3 events are reported in each of those slots
-> 'Slot Count' shows the number of ASH samples in that slot
-> 'Event Count' shows the number of ASH samples waiting for
that event in that slot
-> '% Event' is 'Event Count' over all ASH samples in the analysis period
Slot Event
Slot Time (Duration) Count Event Count % Event
-------------------- -------- ------------------------------ -------- -------
12:10:15 (1.8 min) 46 enq: TX - row lock contention 46 5.45
12:12:00 (2.0 min) 120 enq: TX - row lock contention 120 14.22
12:14:00 (2.0 min) 120 enq: TX - row lock contention 120 14.22
12:16:00 (2.0 min) 119 enq: TX - row lock contention 119 14.10
12:18:00 (2.0 min) 120 enq: TX - row lock contention 120 14.22
12:20:00 (2.0 min) 120 enq: TX - row lock contention 120 14.22
12:22:00 (2.0 min) 125 enq: TX - row lock contention 120 14.22
CPU + Wait for CPU 5 0.59
12:24:00 (1.2 min) 74 enq: TX - row lock contention 74 8.77
-------------------------------------------------------------
JavaScriptは、モジュール、アクション、文タイプおよびテキスト、およびID 21のロックがコミットまたはロールバックによって解放されるのを待機しているカーソルのSQL IDを指定しました。さらに、どのカーソルで問題が発生しているか、およびコールの仕様も確認できます。
データがASHにある場合、自動ワークロード・リポジトリ(AWR)に永続化される可能性もあります。
まとめ
データベース内JavaScriptを使用してコードを記述することを選択している開発者は、instrumentationについて心配する必要はありません。JavaScriptファンクション内の各カーソルは、SQLトレース(別名10046トレース)を使用してトレースできます。