Oracle RAC Study之--Cache Fusion

q36988

15:56:13 SYS@ prod2>select instance_name from v$instance;　　
INSTANCE_NAME
　　
----------------
　　
prod2
　　

　　
15:46:28 SYS@ prod2>alter session set events '10046 trace name context forever,level 12';
　　
Session altered.
　　

　　
15:46:44 SYS@ prod2>select /*+ on_the_other_node */ count(*) from t1;
　　
  COUNT(*)
　　
----------
　　
     50392
　　

　　
15:47:24 SYS@ prod2>alter session set events '10046 trace name context off';
　　
Session altered.
　　

　　
[oracle@aix212@ ~]$ls -lt /u01/app/oracle/admin/prod/udump/|more
　　
total 344
　　
-rw-r-----    1 oracle   oinstall       3920 Nov 17 15:47 prod2_ora_606458.trc
　　
-rw-r-----    1 oracle   oinstall       6220 Nov 17 15:39 prod2_ora_393270.trc
　　

　　
查看trace结果：
　　
[oracle@aix212@ ~]$tkprof /u01/app/oracle/admin/prod/udump/prod2_ora_606458.trc /home/oracle/trc.txt
　　
TKPROF: Release 10.2.0.1.0 - Production on Mon Nov 17 15:48:03 2014
　　
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
　　
select /*+ on_the_other_node */ count(*)
　　
from
　　
t1
　　
call     count       cpu    elapsed       disk      query    current        rows
　　
------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　
Parse        1      0.00       0.00          0          0          0           0
　　
Execute      1      0.00       0.00          0          0          0           0
　　
Fetch        2      0.05       0.35        693        697          0           1
　　
------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　
total        4      0.05       0.35        693        697          0           1
　　
Misses in library cache during parse: 0
　　
Optimizer mode: ALL_ROWS
　　
Parsing user id: SYS
　　
Rows     Row Source Operation
　　
-------  ---------------------------------------------------
　　
      1  SORT AGGREGATE (cr=697 pr=693 pw=0 time=356121 us)
　　
  50392   TABLE ACCESS FULL T1 (cr=697 pr=693 pw=0 time=12651 us)
　　
Elapsed times include waiting on following events:
　　
  Event waited on                             Times   Max. Wait  Total Waited
　　
  ----------------------------------------   Waited  ----------  ------------
　　
  SQL*Net message to client                       2        0.00          0.00
　　
  gc cr grant 2-way                               1        0.00          0.00
　　
  db file sequential read                         1        0.00          0.00
　　
  gc cr multi block request                      46        0.00          0.03
　　
  db file scattered read                         52        0.05          0.27
　　
  SQL*Net message from client                     2        0.00          0.00
　　
********************************************************************************
　　
   可以看到，在Instance 2上出现了大量‘gc cr multi block request'事件，说明大部分数据块是从node 1（Instance 1）上传递过来的。
　　
   但也在node 2上有一部分磁盘I/O（disk=693）,说明一部分数据从本地读取。
　　

　　
通过trace源文件，查看：
　　
select /*+ on_the_other_node */ count(*) from t1
　　
END OF STMT
　　
PARSE #1:c=0,e=339,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=26779237777
　　
BINDS #1:
　　
EXEC #1:c=0,e=135,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=26779237991
　　
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=26779238042
　　
WAIT #1: nam='gc cr grant 2-way' ela= 670 p1=1 p2=60945 p3=4 obj#=52686 tim=26779239211
　　
WAIT #1: nam='db file sequential read' ela= 5910 file#=1 block#=60945 blocks=1 obj#=52686 tim=26779245166
　　
WAIT #1: nam='gc cr multi block request' ela= 898 file#=1 block#=60952 class#=1 obj#=52686 tim=26779246461
　　
WAIT #1: nam='db file scattered read' ela= 4083 file#=1 block#=60946 blocks=7 obj#=52686 tim=26779250635
　　
WAIT #1: nam='gc cr multi block request' ela= 720 file#=1 block#=60960 class#=1 obj#=52686 tim=26779251880
　　
WAIT #1: nam='gc cr multi block request' ela= 182 file#=1 block#=60960 class#=1 obj#=52686 tim=26779252115
　　
WAIT #1: nam='db file scattered read' ela= 4897 file#=1 block#=60953 blocks=8 obj#=52686 tim=26779257069
　　
WAIT #1: nam='gc cr multi block request' ela= 880 file#=1 block#=60968 class#=1 obj#=52686 tim=26779258422
　　
WAIT #1: nam='db file scattered read' ela= 7796 file#=1 block#=60961 blocks=8 obj#=52686 tim=26779266300
　　
WAIT #1: nam='gc cr multi block request' ela= 877 file#=1 block#=60976 class#=1 obj#=52686 tim=26779267650
　　
WAIT #1: nam='db file scattered read' ela= 8525 file#=1 block#=60969 blocks=8 obj#=52686 tim=26779276258
　　
WAIT #1: nam='gc cr multi block request' ela= 948 file#=1 block#=60984 class#=1 obj#=52686 tim=26779277666
　　
WAIT #1: nam='gc cr multi block request' ela= 78 file#=1 block#=60984 class#=1 obj#=52686 tim=26779277795
　　
WAIT #1: nam='db file scattered read' ela= 4645 file#=1 block#=60977 blocks=8 obj#=52686 tim=26779282501
　　
WAIT #1: nam='gc cr multi block request' ela= 757 file#=1 block#=60992 class#=1 obj#=52686 tim=26779283757
　　
WAIT #1: nam='db file scattered read' ela= 7600 file#=1 block#=60985 blocks=8 obj#=52686 tim=26779291441
　　
WAIT #1: nam='gc cr multi block request' ela= 862 file#=1 block#=61000 class#=1 obj#=52686 tim=26779292778
　　
WAIT #1: nam='db file scattered read' ela= 4774 file#=1 block#=60993 blocks=8 obj#=52686 tim=26779297636
　　
WAIT #1: nam='gc cr multi block request' ela= 873 file#=1 block#=61008 class#=1 obj#=52686 tim=26779298953
　　
WAIT #1: nam='db file scattered read' ela= 4615 file#=1 block#=61001 blocks=8 obj#=52686 tim=26779303648
　　
WAIT #1: nam='gc cr multi block request' ela= 870 file#=1 block#=61016 class#=1 obj#=52686 tim=26779304979
　　
WAIT #1: nam='db file scattered read' ela= 2009 file#=1 block#=61009 blocks=8 obj#=52686 tim=26779307065
　　
WAIT #1: nam='gc cr multi block request' ela= 741 file#=1 block#=61024 class#=1 obj#=52686 tim=26779308335
　　
WAIT #1: nam='db file scattered read' ela= 2562 file#=1 block#=61017 blocks=8 obj#=52686 tim=26779310984
　　
WAIT #1: nam='gc cr multi block request' ela= 871 file#=1 block#=61032 class#=1 obj#=52686 tim=26779312325
　　
WAIT #1: nam='db file scattered read' ela= 2115 file#=1 block#=61025 blocks=8 obj#=52686 tim=26779314521
　　
WAIT #1: nam='gc cr multi block request' ela= 857 file#=1 block#=61040 class#=1 obj#=52686 tim=26779315819
　　
WAIT #1: nam='db file scattered read' ela= 2060 file#=1 block#=61033 blocks=8 obj#=52686 tim=26779317956
　　
WAIT #1: nam='gc cr multi block request' ela= 845 file#=1 block#=61048 class#=1 obj#=52686 tim=26779319241
　　
WAIT #1: nam='db file scattered read' ela= 2770 file#=1 block#=61041 blocks=8 obj#=52686 tim=26779322090
　　
WAIT #1: nam='gc cr multi block request' ela= 586 file#=1 block#=61055 class#=1 obj#=52686 tim=26779323145
　　
WAIT #1: nam='gc cr multi block request' ela= 94 file#=1 block#=61054 class#=1 obj#=52686 tim=26779323281
　　
WAIT #1: nam='db file scattered read' ela= 9974 file#=1 block#=61049 blocks=8 obj#=52686 tim=26779333323
　　
WAIT #1: nam='db file scattered read' ela= 5632 file#=1 block#=61057 blocks=8 obj#=52686 tim=26779339348
　　
WAIT #1: nam='db file scattered read' ela= 2081 file#=1 block#=61065 blocks=8 obj#=52686 tim=26779341785
　　
WAIT #1: nam='gc cr multi block request' ela= 1438 file#=1 block#=61208 class#=1 obj#=52686 tim=26779343792
　　
WAIT #1: nam='db file scattered read' ela= 4347 file#=1 block#=61193 blocks=16 obj#=52686 tim=26779348250
　　
WAIT #1: nam='gc cr multi block request' ela= 715 file#=1 block#=61224 class#=1 obj#=52686 tim=26779349686
　　
WAIT #1: nam='gc cr multi block request' ela= 407 file#=1 block#=61224 class#=1 obj#=52686 tim=26779350147
　　
WAIT #1: nam='db file scattered read' ela= 3475 file#=1 block#=61209 blocks=16 obj#=52686 tim=26779353704
　　
WAIT #1: nam='gc cr multi block request' ela= 1351 file#=1 block#=61240 class#=1 obj#=52686 tim=26779355740
　　
WAIT #1: nam='db file scattered read' ela= 3359 file#=1 block#=61225 blocks=16 obj#=52686 tim=26779359216
　　
WAIT #1: nam='gc cr multi block request' ela= 713 file#=1 block#=61256 class#=1 obj#=52686 tim=26779360637
　　
WAIT #1: nam='gc cr multi block request' ela= 403 file#=1 block#=61256 class#=1 obj#=52686 tim=26779361094
　　
WAIT #1: nam='db file scattered read' ela= 2935 file#=1 block#=61241 blocks=16 obj#=52686 tim=26779364111
　　
WAIT #1: nam='gc cr multi block request' ela= 1307 file#=1 block#=61272 class#=1 obj#=52686 tim=26779366106
　　
WAIT #1: nam='db file scattered read' ela= 8885 file#=1 block#=61257 blocks=16 obj#=52686 tim=26779375104
　　
WAIT #1: nam='gc cr multi block request' ela= 754 file#=1 block#=61288 class#=1 obj#=52686 tim=26779376579
　　
WAIT #1: nam='gc cr multi block request' ela= 370 file#=1 block#=61288 class#=1 obj#=52686 tim=26779377005
　　
WAIT #1: nam='db file scattered read' ela= 3442 file#=1 block#=61273 blocks=16 obj#=52686 tim=26779380530
　　
WAIT #1: nam='gc cr multi block request' ela= 1323 file#=1 block#=61304 class#=1 obj#=52686 tim=26779382541
　　
WAIT #1: nam='db file scattered read' ela= 2887 file#=1 block#=61289 blocks=16 obj#=52686 tim=26779385540
　　
WAIT #1: nam='gc cr multi block request' ela= 746 file#=1 block#=61311 class#=1 obj#=52686 tim=26779386964
　　
WAIT #1: nam='db file scattered read' ela= 3422 file#=1 block#=61305 blocks=16 obj#=52686 tim=26779390477
　　
WAIT #1: nam='db file scattered read' ela= 3364 file#=1 block#=61321 blocks=16 obj#=52686 tim=26779394422
　　
WAIT #1: nam='db file scattered read' ela= 3418 file#=1 block#=61337 blocks=16 obj#=52686 tim=26779398408
　　
WAIT #1: nam='db file scattered read' ela= 7254 file#=1 block#=61353 blocks=16 obj#=52686 tim=26779406214
　　
WAIT #1: nam='db file scattered read' ela= 3403 file#=1 block#=61369 blocks=16 obj#=52686 tim=26779410176
　　
WAIT #1: nam='db file scattered read' ela= 7044 file#=1 block#=61385 blocks=16 obj#=52686 tim=26779417779
　　
WAIT #1: nam='db file scattered read' ela= 7282 file#=1 block#=61401 blocks=16 obj#=52686 tim=26779425628
　　
WAIT #1: nam='db file scattered read' ela= 3874 file#=1 block#=61417 blocks=16 obj#=52686 tim=26779430050
　　
WAIT #1: nam='gc cr multi block request' ela= 967 file#=1 block#=61448 class#=1 obj#=52686 tim=26779431766
　　
WAIT #1: nam='db file scattered read' ela= 3433 file#=1 block#=61433 blocks=16 obj#=52686 tim=26779435300
　　
WAIT #1: nam='gc cr multi block request' ela= 1315 file#=1 block#=61464 class#=1 obj#=52686 tim=26779437308
　　
WAIT #1: nam='db file scattered read' ela= 3388 file#=1 block#=61449 blocks=16 obj#=52686 tim=26779440806
　　
WAIT #1: nam='gc cr multi block request' ela= 727 file#=1 block#=61480 class#=1 obj#=52686 tim=26779442228
　　
WAIT #1: nam='gc cr multi block request' ela= 419 file#=1 block#=61480 class#=1 obj#=52686 tim=26779442701
　　
WAIT #1: nam='db file scattered read' ela= 5163 file#=1 block#=61465 blocks=16 obj#=52686 tim=26779447957
　　
WAIT #1: nam='gc cr multi block request' ela= 1319 file#=1 block#=61496 class#=1 obj#=52686 tim=26779449987
　　
WAIT #1: nam='db file scattered read' ela= 2761 file#=1 block#=61481 blocks=16 obj#=52686 tim=26779452861
　　
WAIT #1: nam='gc cr multi block request' ela= 715 file#=1 block#=61512 class#=1 obj#=52686 tim=26779454292
　　
WAIT #1: nam='gc cr multi block request' ela= 405 file#=1 block#=61512 class#=1 obj#=52686 tim=26779454753
　　
WAIT #1: nam='db file scattered read' ela= 3434 file#=1 block#=61497 blocks=16 obj#=52686 tim=26779458272
　　
WAIT #1: nam='gc cr multi block request' ela= 1308 file#=1 block#=61528 class#=1 obj#=52686 tim=26779460269
　　
WAIT #1: nam='db file scattered read' ela= 2761 file#=1 block#=61513 blocks=16 obj#=52686 tim=26779463140
　　
WAIT #1: nam='gc cr multi block request' ela= 727 file#=1 block#=61544 class#=1 obj#=52686 tim=26779464570
　　
WAIT #1: nam='gc cr multi block request' ela= 402 file#=1 block#=61544 class#=1 obj#=52686 tim=26779465029
　　
WAIT #1: nam='db file scattered read' ela= 3372 file#=1 block#=61529 blocks=16 obj#=52686 tim=26779468487
　　
WAIT #1: nam='gc cr multi block request' ela= 1337 file#=1 block#=61560 class#=1 obj#=52686 tim=26779470506
　　
WAIT #1: nam='db file scattered read' ela= 2804 file#=1 block#=61545 blocks=16 obj#=52686 tim=26779473420
　　
WAIT #1: nam='gc cr multi block request' ela= 741 file#=1 block#=61567 class#=1 obj#=52686 tim=26779474836
　　
WAIT #1: nam='db file scattered read' ela= 7761 file#=1 block#=61561 blocks=16 obj#=52686 tim=26779482689
　　
WAIT #1: nam='db file scattered read' ela= 3177 file#=1 block#=61577 blocks=16 obj#=52686 tim=26779486442
　　
WAIT #1: nam='db file scattered read' ela= 3289 file#=1 block#=61593 blocks=16 obj#=52686 tim=26779490280
　　
WAIT #1: nam='db file scattered read' ela= 2727 file#=1 block#=61609 blocks=16 obj#=52686 tim=26779493546
　　
WAIT #1: nam='db file scattered read' ela= 2709 file#=1 block#=61625 blocks=16 obj#=52686 tim=26779496825
　　
WAIT #1: nam='db file scattered read' ela= 3334 file#=1 block#=61641 blocks=16 obj#=52686 tim=26779500720
　　
WAIT #1: nam='db file scattered read' ela= 3257 file#=1 block#=61657 blocks=16 obj#=52686 tim=26779504537
　　
WAIT #1: nam='db file scattered read' ela= 2735 file#=1 block#=61673 blocks=16 obj#=52686 tim=26779507829
　　
WAIT #1: nam='gc cr multi block request' ela= 954 file#=1 block#=61704 class#=1 obj#=52686 tim=26779509463
　　
WAIT #1: nam='db file scattered read' ela= 8587 file#=1 block#=61689 blocks=16 obj#=52686 tim=26779518146
　　
WAIT #1: nam='gc cr multi block request' ela= 1386 file#=1 block#=61720 class#=1 obj#=52686 tim=26779520274
　　
WAIT #1: nam='db file scattered read' ela= 57988 file#=1 block#=61705 blocks=16 obj#=52686 tim=26779578384
　　
WAIT #1: nam='gc cr multi block request' ela= 907 file#=1 block#=61736 class#=1 obj#=52686 tim=26779580432
　　
WAIT #1: nam='gc cr multi block request' ela= 323 file#=1 block#=61736 class#=1 obj#=52686 tim=26779580830
　　
WAIT #1: nam='db file scattered read' ela= 3431 file#=1 block#=61721 blocks=16 obj#=52686 tim=26779584371
　　
WAIT #1: nam='gc cr multi block request' ela= 2595 file#=1 block#=61752 class#=1 obj#=52686 tim=26779587917
　　
WAIT #1: nam='db file scattered read' ela= 3418 file#=1 block#=61737 blocks=16 obj#=52686 tim=26779591482
　　
WAIT #1: nam='gc cr multi block request' ela= 757 file#=1 block#=61757 class#=1 obj#=52686 tim=26779592898
　　
WAIT #1: nam='db file scattered read' ela= 928 file#=1 block#=61753 blocks=5 obj#=52686 tim=26779593962
　　
FETCH #1:c=50000,e=356115,p=693,cr=697,cu=0,mis=0,r=1,dep=0,og=1,tim=26779594203
　　
WAIT #1: nam='SQL*Net message from client' ela= 485 driver id=1650815232 #bytes=1 p3=0 obj#=52686 tim=26779594899
　　
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=26779594986
　　
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=52686 tim=26779595018
　　
WAIT #1: nam='SQL*Net message from client' ela= 490 driver id=1650815232 #bytes=1 p3=0 obj#=52686 tim=26779595585
　　
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=697 pr=693 pw=0 time=356121 us)'
　　
STAT #1 id=2 cnt=50392 pid=1 pos=1 obj=52686 op='TABLE ACCESS FULL T1 (cr=697 pr=693 pw=0 time=12651 us)'
　　
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=52686 tim=26779595906
　　
*** 2014-11-17 15:53:32.816
　　
WAIT #0: nam='SQL*Net message from client' ela= 22469814 driver id=1650815232 #bytes=1 p3=0 obj#=52686 tim=26802065757
　　
=====================