[20200223]关于latch and mutext的优化.txt
[20200223]关于latch and mutext的优化.txt
--//前一段时间一直在测试使用DBMS_SHARED_POOL.MARKHOT标识热对象以及sql语句的优化。
--//有别人问感觉我花很大的精力做一件无意义的工作，实际上我以前优化sql语句更多的放在IO上，SQL语句减少逻辑读上。
--//很少关注开发人员为什么要执行这些sql语句，更多地第三方的方式介入数据库的优化工作。
--//比如我们生产系统1小时 awr报表：
Snap Id Snap Time Sessions Cursors/Session Instances
Begin Snap: 43914 01-Nov-19 10:00:32 4283 2.2 2
End Snap: 43915 01-Nov-19 11:00:53 4522 2.2 2
Elapsed: 60.36 (mins)
DB Time: 404.88 (mins)
--//db_time = 404.88,相当于 404.88*60 = 24292.8秒
....
SQL ordered by Executions
%CPU - CPU Time as a percentage of Elapsed Time
%IO - User I/O Time as a percentage of Elapsed Time
Total Executions: 29,779,711
Captured SQL account for 29.9% of Total
Executions Rows Processed Rows per Exec Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text
10,279,442 10,276,526 1.00 2,671.78 97.1 0 190q1sz3ywrd7 PPPQQQ.EXE begin :con := "XXXXXXACL"."QUE..."
2,469,226 2,469,184 1.00 990.07 96.1 0 g7ytdh9mxt1s0 PPPQQQ.EXE select count ( :"SYS_B_0" ) fr...
2,003,509 2,003,261 1.00 69.14 99.8 0 f8733rs2f3bng PPPQQQ.EXE SELECT sysdate FROM Dual
--//第1条语句是所谓的防水墙产品。每秒有10279442/3600 = 2855.4次。
--//第2条语句判断是否连接数据库的语句。每秒2469226/3600 = 685.89
--//第3条语句取当前日期，每秒2003509/3600 = 556.53。
Report Summary
Load Profile
Per Second Per Transaction Per Exec Per Call
DB Time(s): 6.7 0.1 0.00 0.00
DB CPU(s): 6.1 0.1 0.00 0.00
Redo size (bytes): 259,680.1 2,047.8
Logical read (blocks): 539,587.6 4,255.0
Block changes: 1,322.0 10.4
Physical read (blocks): 47,972.4 378.3
Physical write (blocks): 548.1 4.3
Read IO requests: 565.7 4.5
Write IO requests: 58.8 0.5
Read IO (MB): 374.8 3.0
Write IO (MB): 4.3 0.0
Global Cache blocks received: 12.1 0.1
Global Cache blocks served: 0.8 0.0
User calls: 8,826.6 69.6
Parses (SQL): 7,458.3 58.8
Hard parses (SQL): 16.8 0.1
SQL Work Area (MB): 158.8 1.3
Logons: 7.6 0.1
Executes (SQL): 8,222.7 64.8
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Rollbacks: 2.7 0.0
Transactions: 126.8
--//以上3条语句的执行次数占了 (2855+686+557)/8223 = 0.498,几乎占了1半。
2.测试：
$ seq 100 | xargs -IQ -P 100 bash -c "echo 2^1000000 | bc > /dev/null "
$ vmstat -w 1 100 | tw.awk
[2020-02-24 10:20:51] procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
[2020-02-24 10:20:51] r b swpd free buff cache si so bi bo in cs us sy id wa st
[2020-02-24 10:20:51] 0 0 0 118995152 417284 10254324 0 0 0 0 112 130 0 0 100 0 0
[2020-02-24 10:20:52] 100 0 0 118939296 417284 10254324 0 0 0 0 2664 1075 4 1 96 0 0
[2020-02-24 10:20:53] 100 0 0 118925288 417284 10254324 0 0 0 0 24176 3785 100 0 0 0 0
[2020-02-24 10:20:54] 100 0 0 118913328 417284 10254324 0 0 0 0 24114 3737 100 0 0 0 0
[2020-02-24 10:20:55] 100 0 0 118894976 417284 10254324 0 0 0 0 24118 3718 100 0 0 0 0
[2020-02-24 10:20:56] 100 0 0 118892728 417284 10254324 0 0 0 0 24111 3729 100 0 0 0 0
[2020-02-24 10:20:57] 100 0 0 118888264 417284 10254324 0 0 0 0 24133 3764 100 0 0 0 0
[2020-02-24 10:20:58] 100 0 0 118884768 417284 10254324 0 0 0 0 24109 3737 100 0 0 0 0
[2020-02-24 10:20:59] 100 0 0 118879528 417284 10254324 0 0 0 0 24096 3714 100 0 0 0 0
[2020-02-24 10:21:00] 100 0 0 118873224 417284 10254324 0 0 0 0 24112 3727 100 0 0 0 0
[2020-02-24 10:21:01] 100 0 0 118865984 417284 10254324 0 0 0 0 24133 3774 100 0 0 0 0
[2020-02-24 10:21:02] 100 0 0 118866032 417284 10254328 0 0 0 0 24109 3711 100 0 0 0 0
[2020-02-24 10:21:03] 100 0 0 118864464 417284 10254328 0 0 0 0 24121 3677 100 0 0 0 0
[2020-02-24 10:21:04] 100 0 0 118862608 417284 10254328 0 0 0 0 24116 3699 100 0 0 0 0
[2020-02-24 10:21:05] 100 0 0 118861008 417284 10254328 0 0 0 0 24158 3795 100 0 0 0 0
[2020-02-24 10:21:06] 100 0 0 118860608 417284 10254328 0 0 0 16 24120 3767 100 0 0 0 0
[2020-02-24 10:21:07] 100 0 0 118855024 417284 10254328 0 0 0 32 24104 3764 100 0 0 0 0
[2020-02-24 10:21:08] 100 0 0 118849600 417284 10254328 0 0 0 0 24121 3743 100 0 0 0 0
[2020-02-24 10:21:09] 100 0 0 118844696 417284 10254328 0 0 0 0 24139 3727 100 0 0 0 0
[2020-02-24 10:21:10] 100 0 0 118842544 417284 10254328 0 0 0 0 24128 3749 100 0 0 0 0
[2020-02-24 10:21:11] 100 0 0 118838200 417284 10254328 0 0 0 0 24093 3732 100 0 0 0 0
[2020-02-24 10:21:12] procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
[2020-02-24 10:21:12] r b swpd free buff cache si so bi bo in cs us sy id wa st
[2020-02-24 10:21:12] 101 0 0 118830832 417284 10254328 0 0 0 24 24129 3747 100 0 0 0 0
[2020-02-24 10:21:13] 100 0 0 118826608 417284 10254328 0 0 0 0 24159 3764 100 0 0 0 0
[2020-02-24 10:21:14] 100 0 0 118822136 417284 10254328 0 0 0 0 24098 3763 100 0 0 0 0
[2020-02-24 10:21:15] 100 0 0 118821040 417284 10254328 0 0 0 0 24112 3709 100 0 0 0 0
[2020-02-24 10:21:16] 94 0 0 118825536 417284 10254328 0 0 0 0 24165 3695 100 0 0 0 0
[2020-02-24 10:21:17] 67 0 0 118864688 417284 10254328 0 0 0 0 24209 3283 100 0 0 0 0
[2020-02-24 10:21:18] 0 0 0 118967936 417284 10254328 0 0 0 0 17636 1150 82 1 18 0 0
[2020-02-24 10:21:19] 0 0 0 118969400 417284 10254328 0 0 0 0 92 38 0 0 100 0 0
--//大约26秒上下完成。
--//实际上如果仅仅执行1次大约4秒多一点。我逻辑cpu数量(打开超线程)=24,而如果你看vmstat的输出。
$ time echo 2^1000000 | bc > /dev/null
real 0m4.058s
user 0m4.048s
sys 0m0.001s
$ man vmstat
..
Procs
r: The number of processes waiting for run time.
b: The number of processes in uninterruptible sleep.
--//b的数量一直是0，也就是全部bc计算程序都在运行，没有任何阻塞，只不过cpu调度不过来，需要的执行时间变成6倍上下。
3.继续测试oracle应用程序的情况：
SCOTT@book> @ ver1
PORT_STRING VERSION BANNER
------------------- ---------- ----------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
SYS@book> @ hide _kgl_hot_object_copies
NAME DESCRIPTION DEFAULT_VALUE SESSION_VALUE SYSTEM_VALUE ISSES ISSYS_MOD
---------------------- ----------------------------------- ------------- ------------- ------------ ----- ---------
_kgl_hot_object_copies Number of copies for the hot object TRUE 0 0 FALSE FALSE
--//rename job_times to job_times_20200224;
create table job_times (sid number, sessionid number,time_ela number,method varchar2(20));
--//建立脚本bb.txt:
$ cat bb.txt
SELECT owner
,name
,hash_value
,full_hash_value
,namespace
,child_latch
,property hot_flag
,executions
,invalidations
FROM v$db_object_cache
WHERE name = 'DBMS_APPLICATION_INFO' AND owner = 'SYS'
order by executions desc ;
--//建立测试脚本m3.txt
set verify off
--//host sleep $(echo &&3/50 | bc -l )
insert into job_times values ( sys_context ('userenv', 'sid') ,sys_context ('userenv', 'sessionid'),dbms_utility.get_time ,'&&2') ;
commit ;
declare
v_id number;
v_d date;
begin
for i in 1 .. &&1 loop
execute immediate 'begin dbms_application_info.set_client_info(''mutex'');end;';
end loop;
end ;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and sessionid=sys_context ('userenv', 'sessionid') and method='&&2';
commit;
quit
$ seq 50 | xargs -I{} -P 50 sqlplus -s -l scott/book @m3.txt 1e5 p=50 {} >/dev/null
$ vmstat -w 1 100 | ts.awk
[2020-02-24 10:32:31] procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
[2020-02-24 10:32:31] r b swpd free buff cache si so bi bo in cs us sy id wa st
[2020-02-24 10:32:31] 1 0 0 118890760 417300 10255360 0 0 0 0 0 0 0 0 100 0 0
[2020-02-24 10:32:32] 0 0 0 118888768 417300 10255360 0 0 0 0 1254 2110 0 0 100 0 0
[2020-02-24 10:32:33] 0 0 0 118889032 417300 10255360 0 0 0 0 1111 2026 0 0 100 0 0
[2020-02-24 10:32:34] 0 0 0 118889032 417300 10255360 0 0 0 0 1054 2003 0 0 100 0 0
[2020-02-24 10:32:35] 17 0 0 118534208 417300 10255360 0 0 0 0 18130 14789 22 6 72 0 0
[2020-02-24 10:32:36] 15 0 0 118530112 417300 10255388 0 0 0 12 17428 12406 53 7 40 0 0
[2020-02-24 10:32:37] 18 0 0 118530112 417300 10255388 0 0 0 0 17481 12502 54 6 40 0 0
[2020-02-24 10:32:38] 16 0 0 118528264 417300 10255388 0 0 0 0 17684 12112 54 7 39 0 0
[2020-02-24 10:32:39] 17 0 0 118528448 417300 10255388 0 0 0 0 17777 12436 54 7 39 0 0
[2020-02-24 10:32:40] 15 0 0 118528576 417300 10255388 0 0 0 0 17650 11967 54 6 39 0 0
[2020-02-24 10:32:41] 21 0 0 118528584 417300 10255388 0 0 0 32 17776 12917 55 6 38 0 0
[2020-02-24 10:32:42] 21 0 0 118529824 417300 10255388 0 0 0 0 17640 13795 54 7 39 0 0
[2020-02-24 10:32:43] 15 0 0 118529920 417300 10255388 0 0 0 0 17631 11054 54 7 39 0 0
[2020-02-24 10:32:44] 16 0 0 118529936 417300 10255388 0 0 0 0 17705 12744 54 7 39 0 0
[2020-02-24 10:32:45] 19 0 0 118530448 417300 10255388 0 0 0 0 17915 13821 55 6 39 0 0
[2020-02-24 10:32:46] 18 0 0 118530464 417300 10255388 0 0 0 0 17670 11483 54 7 39 0 0
[2020-02-24 10:32:47] 23 0 0 118530464 417300 10255388 0 0 0 12 18050 13022 55 7 38 0 0
[2020-02-24 10:32:48] 20 0 0 118530760 417300 10255388 0 0 0 0 17829 12484 55 7 38 0 0
[2020-02-24 10:32:49] 16 0 0 118530760 417300 10255388 0 0 0 0 17682 13121 55 7 38 0 0
[2020-02-24 10:32:50] 18 0 0 118530792 417300 10255388 0 0 0 0 17866 12203 55 7 38 0 0
[2020-02-24 10:32:51] 16 0 0 118530992 417300 10255388 0 0 0 0 17410 11298 54 7 39 0 0
[2020-02-24 10:32:52] procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
[2020-02-24 10:32:52] r b swpd free buff cache si so bi bo in cs us sy id wa st
[2020-02-24 10:32:52] 15 0 0 118530992 417300 10255388 0 0 0 0 17880 11685 55 7 38 0 0
[2020-02-24 10:32:53] 22 0 0 118530992 417300 10255388 0 0 0 0 17547 11065 54 7 40 0 0
[2020-02-24 10:32:54] 16 0 0 118531072 417300 10255388 0 0 0 0 17727 11844 54 7 39 0 0
[2020-02-24 10:32:55] 11 0 0 118531072 417300 10255388 0 0 0 0 17781 11598 55 7 39 0 0
[2020-02-24 10:32:56] 17 0 0 118531072 417300 10255388 0 0 0 0 17756 11906 54 7 39 0 0
[2020-02-24 10:32:57] 21 0 0 118531072 417300 10255388 0 0 0 0 17685 13743 55 6 39 0 0
[2020-02-24 10:32:58] 23 0 0 118531104 417300 10255388 0 0 0 0 17969 12060 56 6 37 0 0
[2020-02-24 10:32:59] 5 0 0 118531104 417300 10255388 0 0 0 8 17948 11292 55 7 38 0 0
[2020-02-24 10:33:00] 17 0 0 118531104 417300 10255388 0 0 0 16 17791 12828 55 7 38 0 0
[2020-02-24 10:33:01] 17 0 0 118531088 417300 10255388 0 0 0 0 17634 12162 54 7 39 0 0
[2020-02-24 10:33:02] 16 0 0 118531088 417300 10255388 0 0 0 0 18026 13306 56 7 37 0 0
[2020-02-24 10:33:03] 17 0 0 118531088 417300 10255388 0 0 0 0 17766 11976 55 7 38 0 0
[2020-02-24 10:33:04] 7 0 0 118530968 417300 10255388 0 0 0 0 17951 11757 56 7 37 0 0
[2020-02-24 10:33:05] 18 0 0 118530952 417300 10255388 0 0 0 0 17921 11570 55 7 38 0 0
[2020-02-24 10:33:06] 21 0 0 118530976 417300 10255388 0 0 0 0 17241 12085 52 6 42 0 0
[2020-02-24 10:33:07] 11 0 0 118530976 417300 10255388 0 0 0 0 17623 11839 54 6 39 0 0
[2020-02-24 10:33:08] 23 0 0 118530976 417300 10255388 0 0 0 0 17609 11634 55 6 39 0 0
[2020-02-24 10:33:09] 17 0 0 118530976 417300 10255388 0 0 0 0 17609 11607 54 7 39 0 0
[2020-02-24 10:33:10] 16 0 0 118530992 417300 10255388 0 0 0 32 17803 12065 55 7 38 0 0
[2020-02-24 10:33:11] 6 0 0 118530976 417300 10255388 0 0 0 0 17912 11454 56 7 37 0 0
[2020-02-24 10:33:12] 17 0 0 118531112 417300 10255388 0 0 0 0 17869 11916 55 7 39 0 0
[2020-02-24 10:33:13] procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
[2020-02-24 10:33:13] r b swpd free buff cache si so bi bo in cs us sy id wa st
[2020-02-24 10:33:13] 19 0 0 118531112 417300 10255388 0 0 0 0 17746 11633 54 6 39 0 0
[2020-02-24 10:33:14] 18 0 0 118531112 417300 10255388 0 0 0 0 17887 11629 56 7 37 0 0
[2020-02-24 10:33:15] 18 0 0 118531112 417300 10255388 0 0 0 0 17715 12068 55 7 39 0 0
[2020-02-24 10:33:16] 17 0 0 118537576 417300 10255388 0 0 0 12 17589 11460 54 7 39 0 0
[2020-02-24 10:33:17] 16 0 0 118675928 417300 10255392 0 0 0 0 18894 9604 55 7 38 0 0
[2020-02-24 10:33:18] 1 0 0 118857304 417300 10255392 0 0 0 0 10522 3468 33 5 62 0 0
[2020-02-24 10:33:19] 0 0 0 118859728 417300 10255392 0 0 0 0 1092 1997 0 0 100 0 0
[2020-02-24 10:33:20] 0 0 0 118860720 417300 10255392 0 0 0 0 1121 2066 0 0 100 0 0
[2020-02-24 10:33:21] 0 0 0 118861048 417300 10255392 0 0 0 0 1173 2034 0 0 100 0 0
[2020-02-24 10:33:22] 1 0 0 118861712 417300 10255392 0 0 0 0 1082 2004 0 0 100 0 0
^C
--//你看到vmstat r数量并没有达到50，虽然b一直还是0.但是明显出现阻塞导致并发数量没有达到50.
4.继续测试：
--//使用dbms_shared_pool.markhot标识热对象后:
SYS@book> exec dbms_shared_pool.markhot('SYS','DBMS_APPLICATION_INFO',1);
PL/SQL procedure successfully completed.
SYS@book> exec dbms_shared_pool.markhot('SYS','DBMS_APPLICATION_INFO',2);
PL/SQL procedure successfully completed.
$ seq 50 | xargs -I{} -P 50 sqlplus -s -l scott/book @m3.txt 1e5 mp=50 {} >/dev/null
$ vmstat -w 1 100 | ts.awk
[2020-02-24 10:37:10] procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
[2020-02-24 10:37:10] r b swpd free buff cache si so bi bo in cs us sy id wa st
[2020-02-24 10:37:10] 1 0 0 118873072 417300 10255404 0 0 0 0 0 0 0 0 100 0 0
[2020-02-24 10:37:11] 0 0 0 118870936 417300 10255404 0 0 0 0 1233 2056 0 0 100 0 0
[2020-02-24 10:37:12] 47 0 0 118521648 417300 10255404 0 0 0 8 21133 8990 30 7 63 0 0
[2020-02-24 10:37:13] 50 0 0 118518544 417300 10255404 0 0 0 0 24557 4843 86 11 3 0 0
[2020-02-24 10:37:14] 48 0 0 118518424 417300 10255404 0 0 0 0 24649 4801 87 11 2 0 0
[2020-02-24 10:37:15] 50 0 0 118518672 417300 10255404 0 0 0 0 24765 4696 87 11 2 0 0
[2020-02-24 10:37:16] 47 0 0 118519896 417300 10255404 0 0 0 0 24773 4860 87 11 2 0 0
[2020-02-24 10:37:17] 22 0 0 118520016 417300 10255404 0 0 0 0 24476 5224 86 11 3 0 0
[2020-02-24 10:37:18] 50 0 0 118520408 417300 10255404 0 0 0 16 24638 4950 87 11 2 0 0
[2020-02-24 10:37:19] 49 0 0 118521280 417300 10255404 0 0 0 0 24770 4946 88 11 2 0 0
[2020-02-24 10:37:20] 45 0 0 118521376 417300 10255404 0 0 0 0 24936 4901 88 11 1 0 0
[2020-02-24 10:37:21] 46 0 0 118521552 417300 10255404 0 0 0 0 24884 4875 88 11 1 0 0
[2020-02-24 10:37:22] 48 0 0 118521992 417300 10255404 0 0 0 0 24634 5066 86 11 3 0 0
[2020-02-24 10:37:23] 42 0 0 118538432 417300 10255404 0 0 0 4 24639 4868 86 11 3 0 0
[2020-02-24 10:37:24] 0 0 0 118847888 417300 10255404 0 0 0 0 18070 3752 66 9 26 0 0
[2020-02-24 10:37:25] 0 0 0 118849808 417300 10255404 0 0 0 0 1142 2047 0 0 100 0 0
[2020-02-24 10:37:26] 0 0 0 118849808 417300 10255404 0 0 0 0 1098 1993 0 0 100 0 0
[2020-02-24 10:37:27] 0 0 0 118851008 417300 10255404 0 0 0 0 1127 2049 0 0 100 0 0
[2020-02-24 10:37:28] 0 0 0 118851312 417300 10255404 0 0 0 0 1085 1994 0 0 100 0 0
[2020-02-24 10:37:29] 0 0 0 118851632 417300 10255404 0 0 0 0 1214 2078 0 0 100 0 0
[2020-02-24 10:37:30] 0 0 0 118852688 417300 10255404 0 0 0 16 1216 2024 0 0 100 0 0
^C
--//你可以发现r数量接近并发50的数量。这样相同的工作量12秒就完成了。
SYS@book> Select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from scott.job_times group by method order by 3 ;
METHOD COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
-------------------- ---------- ---------------------- -------------
mp=50 50 1197 59852
p=50 50 4270 213485
--//我仅仅通过这个建立的例子说明优化latch和mutex一样重要。许多开发甚至dba都没有这种意识其实很可怕的。
--//也就是这样的工作并非没有意思，你通过一个简单的例子学习到许多OS与oracle的许多相关知识。
