- SQL*Net message from client
- SQL*Net message from dblink
SQL*Net message from client待機イベントは代表的なアイドルイベントです。するとSQL*Net message from dblinkイベントはどうでしょうか。
UKJA@ukja1106> @event 'SQL*Net message from'
UKJA@ukja1106> set serveroutput on
UKJA@ukja1106>
UKJA@ukja1106> exec print_table('select * from v$event_name where name like ''%&
1%''');
EVENT# : 289
EVENT_ID : 1421975091
NAME : SQL*Net message from client
PARAMETER1 : driver id
PARAMETER2 : #bytes
PARAMETER3 :
WAIT_CLASS_ID : 2723168908
WAIT_CLASS# : 6
WAIT_CLASS : Idle
-----------------
EVENT# : 291
EVENT_ID : 4093028837
NAME : SQL*Net message from dblink
PARAMETER1 : driver id
PARAMETER2 : #bytes
PARAMETER3 :
WAIT_CLASS_ID : 2000153315
WAIT_CLASS# : 7
WAIT_CLASS : Network
-----------------
SQL*Net message from clientイベントはアイドルで分類されるけど、SQL*Net message from dblinkイベントはNetworkで分類されます。そうだったらSQL*Net message from dblinkイベントを待機するというのはネットワークの性能に問題があるという意味でしょうか。
SQL*Net message from dblinkイベントを待機すると言うことは次の意味です。
- ローカルデータベースがSQLをリモートデータベースに転送要請します。
- この時ローカルデータベースはOSのAPIを呼んで該当SQL文章をネットワーク転送バッファに入れます。この短い時間の間SQL*Net message to dblinkイベントを待機します。実際のネットワーク転送にかかわらず転送バッファに入れるだけで待機イベントは終わります。
- ローカルデータベースは今OSのAPIを呼んでネットワーク受信バッファからデータを引き出そうとします。まだリモートデータベースがデータを送らない状態なのでSQL*Net message from dblinkイベントを待機します。
- リモートデータベースがデータを転送したからローカルOSがそのデータを受けてネットワーク受信バッファに入れるとローカルデータベースのSQL*Net message from dblinkイベントが終わります。
上の内容をよく理解すればSQL*Net message from dblinkイベントを待機したと言ってネットワーク転送が遅いのだと判断できないということがよく分かります。
長期間のSQL*Net message from dblinkイベントがネットワーク性能と全然構わない簡単な例を作ってみます。
1. UKJA1021データベースに次のように10,000件の件数を持つテーブルを作ります。
-- UKJA1021
drop table t1 purge;
create table t1
as
select level as c1
from dual connect by level <= 10000
;
2. 次のようにUKJA1106 --> UKJA1201データベースリンクを作ります。
create database link UKJA1021
connect to ukja identified by ukja
using 'UKJA1021'
;
3. 実行計画を見ればリモートデータベースで100％実行されるのが分かります。
explain plan for
select count(*)
from t1@ukja1021, t1@ukja1021
;
@plan
--------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time | Inst |
--------------------------------------------------------------------------------
| 0 | SELECT STATEMENT REMOTE| | 1 | 68860 (5)| 00:13:47 | |
| 1 | SORT AGGREGATE | | 1 | | | |
| 2 | MERGE JOIN CARTESIAN | | 100M| 68860 (5)| 00:13:47 | |
| 3 | TABLE ACCESS FULL | T1 | 10000 | 8 (0)| 00:00:01 | UKJA1~ |
| 4 | BUFFER SORT | | 10000 | 68851 (5)| 00:13:47 | |
| 5 | TABLE ACCESS FULL | T1 | 10000 | 7 (0)| 00:00:01 | UKJA1~ |
--------------------------------------------------------------------------------
Note
-----
- fully remote statement
- dynamic sampling used for this statement
4. 今次のようにSQL文を実行すれば長い時間の間待機状態に落ち込んでしまいます。
-- UKJA1106
UKJA@ukja1106>
UKJA@ukja1106> select count(*)
2 from t1@ukja1021, t1@ukja1021, t1@ukja1021
3 ;
............
5. 待機イベントを見れば次のようにSQL*Net message from dblinkイベントを待機します。
SID EVENT P1 P2 P3
----- ------------------------- --------------- --------------- ----------
SECONDS_IN_WAIT
---------------
133 SQL*Net message from dbli 1413697536(0000 1(0000000000000 0(00)
nk 000054435000) 001)
9626
該当SQL文はCOUNT(*)を修行するから結果が出る前には全然データ転送が発生しません。すなわち、まだ1バイトのデータもネットワークを通じて転送されていない状態です。ネットワークでなんのデータも転送されないのでこの場合にはネットワークの性能がすっかり論外と言えます。
6. リモートデータベースでは次のようにリモートセッションがモニタリングされます。
-- UKJA1021
SID SERIAL# PROGRAM EVENT SQL_TEXT
----- ------- ---------- -------------------- ------------------------------
136 745 ORACLE.EXE SQL*Net message to c SELECT COUNT(*) FROM "T1" "A3"
lient ,"T1" "A2","T1" "A1"
7. 133番のセッションを詳しくモニタリングしてみれば次のようです。
UKJA@ukja1021> set echo off
01. basic session info
SID : 136
SERIAL# : 745
SPID : 15304
MACHINE : XXXX-3C2E2AF808
PROGRAM : ORACLE.EXE
PGA : 1154000
UGA : 680088
LAST_CALL_ET : 9696
LOGON_TIME : 2009/09/18 09:59:53
-----------------
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
02. session wait
SID : 136
EVENT : SQL*Net message to client
P1 : 1413697536
P1RAW : 54435000
P2 : 1
P2RAW : 00000001
P3 : 0
P3RAW : 00
SECONDS_IN_WAIT : 9696
STATE : WAITED SHORT TIME
-----------------
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
03. process info
PID : 20
PROGRAM : ORACLE.EXE (SHAD)
PGA_USED_MEM : 1037021
PGA_ALLOC_MEM : 1118413
PGA_MAX_MEM : 3245293
-----------------
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
04. sql info
SID : 136
SHARABLE_MEM : 12759
PERSISTENT_MEM : 6304
RUNTIME_MEM : 5752
EXECUTIONS : 1
FETCHES : 0
BUFFER_GETS : 97
SQL_TEXT : SELECT COUNT(*) FROM "T1" "A3","T1" "A2","T1"
"A1"
-----------------
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.03
05. sql plan info
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID 6t0k52rdrw388, child number 0
-------------------------------------
SELECT COUNT(*) FROM "T1" "A3","T1" "A2","T1" "A1"
Plan hash value: 2643210548
-----------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-----------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | 688M(100)| |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | MERGE JOIN CARTESIAN | | 1000G| 688M (5)|999:59:59 |
| 3 | MERGE JOIN CARTESIAN| | 100M| 68860 (5)| 00:13:47 |
| 4 | TABLE ACCESS FULL | T1 | 10000 | 8 (0)| 00:00:01 |
| 5 | BUFFER SORT | | 10000 | 68851 (5)| 00:13:47 |
| 6 | TABLE ACCESS FULL | T1 | 10000 | 7 (0)| 00:00:01 |
| 7 | BUFFER SORT | | 10000 | 688M (5)|999:59:59 |
| 8 | TABLE ACCESS FULL | T1 | 10000 | 7 (0)| 00:00:01 |
-----------------------------------------------------------------------
Note
-----
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
- dynamic sampling used for this statement
24 rows selected.
Elapsed: 00:00:00.07
06. workarea info
SID : 136
OPERATION_TYPE : BUFFER
ACTIVE_TIME : 9696154331
WORK_AREA_SIZE : 131072
ACTUAL_MEM_USED : 131072
MAX_MEM_USED : 131072
-----------------
SID : 136
OPERATION_TYPE : BUFFER
ACTIVE_TIME : 9696150509
WORK_AREA_SIZE : 131072
ACTUAL_MEM_USED : 131072
MAX_MEM_USED : 131072
-----------------
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
07. transaction info
PL/SQL procedure successfully completed.
待機状態がWAITED SHORT TIMEだというのは現在待機状態ではなくてCPUを占有して忙しく作業をしている状態だと言う意味です。どんな作業をしているのかはプロセス情報によく現れています。
03. process info
PID : 20
PROGRAM : ORACLE.EXE (SHAD)
PGA_USED_MEM : 1037021
PGA_ALLOC_MEM : 1118413
PGA_MAX_MEM : 3245293
上の情報をみれば現在1Gバイト以上のPGAを使用していて、最大3Gバイト以上のPGAを使用したことが分かります。すなわち大容量のCartesian Merge Joinを処理しながら忙しく働いているし、そのせいでリモートデータベースに応答できないという状態です。
待機イベントというのはその名前のために逆に誤解しやすい場合が多いです。こんな場合にはCarry Millsapのポスト(Dang It, People, they're syscalls not wait)を見れば誤解を解けることができるでしょう。
Posts
No comments:
Post a Comment