[20200223] optimization of latch and mutext.txt
–//I have been testing DBMS for some time_ SHARED_ POOL.MARKHOT Identify hot objects and optimize SQL statements.
–//Some people asked me that I spent a lot of energy on meaningless work. In fact, I used to optimize SQL statements more on Io and reduce logical reading of SQL statements.
–//Little attention is paid to why developers need to execute these SQL statements, and more third-party ways are involved in the optimization of the database.
–//For example, our production system 1 hour AWR report:
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, equivalent to 404.88 * 60 = 24292.8 seconds
….
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
–//The first sentence is the so-called waterproof wall product. 10279442 / 3600 = 2855.4 times per second.
–//The second statement determines whether to connect to the database. 2469226 / 3600 per second = 685.89
–//The third statement takes the current date, 2003509 / 3600 = 556.53 per second.
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
–//The execution times of the above three statements account for (2855 + 686 + 557) / 8223 = 0.498, almost 1.5%.
2. Test:
$ 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
–//About 26 seconds up and down.
–//In fact, if it is only executed once, it will take a little more than 4 seconds. I think the number of logical CPUs (hyper threading on) = 24, and if you look at the output of 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.
–//The number of B is always 0, that is, all BC computing programs are running without any blocking, but the CPU can not be scheduled, and the execution time required becomes about six times.
3. Continue to Test Oracle Application:
[email protected]> @ 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
[email protected]> @ 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));
–//Create script 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 ;
–//Create test script 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
–//You can see that the number of vmstat r does not reach 50, although B is still 0 all the time. However, it is obvious that blocking causes the number of concurrency to not reach 50
4. Continue testing:
–//Using DBMS_ shared_ pool.markhot After hot object identification:
[email protected]> exec dbms_shared_pool.markhot(‘SYS’,’DBMS_APPLICATION_INFO’,1);
PL/SQL procedure successfully completed.
[email protected]> 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
–//You can see that the number of R is close to the number of concurrent 50. So the same amount of work is done in 12 seconds.
[email protected]> 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
–//I just use this example to show that optimizing latch is as important as mutex. Many developers and even DBAs don’t have this kind of awareness, which is really terrible.
–//In other words, this kind of work is not meaningless. You can learn a lot about OS and Oracle through a simple example.