[20210804]oracle rac執行命令crs_stat -t -v緩慢的分析.txt

[20210804]oracle rac執行命令crs_stat -t -v緩慢的分析.txt

--//連結 http://www.itpub.net/thread-2142454-1-1.html的問題:

有一套11.2.0.4的oracle rac上，執行命令 [grid@rac1 ~]$ time crs_stat -t -v 耗時近30秒，有沒有兄弟支個招。資料庫正常使用，
日誌也沒有報錯，zabbix agent有時候會 agent.ping 超時。網路裝置已經檢查，沒有什麼大的異常環境：2臺物理機 centos 6.10 ，
oracle rac 11.2.0.4.透過光纖交換機相連，掛載的儲存大家有沒有排查思路給一個呢？

--//我建議使用 strace -o aa.txt  -r -tT -f  crs_stat -t -v跟蹤.
--//真心講沒有看別人的解答，實際上jieyancai已經找到問題根源，/u01/app/11.2.0/grid/log/${HOSTNAME}/client/目錄下
--//clscNNN.log檔案太多。

$ strace -o aa.txt  -r -tT -f  crs_stat -t -v
...

--//我們生產系統的情況。
$ grep "open" aa.txt | grep clsc|wc
   1288    9018  134173

--//檢查aa.txt跟蹤檔案:
......
20553      0.000031 getcwd("/tmp", 4096) = 5 <0.000008>
20553      0.000025 chdir("/u01/app/11.2.0/grid/log/fyhis1/client") = 0 <0.000008>
20553      0.000026 getcwd("/u01/app/11.2.0/grid/log/fyhis1/client", 4096) = 39 <0.000006>
20553      0.000024 chdir("/tmp")       = 0 <0.000007>
20553      0.000067 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1.log", {st_mode=S_IFREG|0644, st_size=279, ...}) = 0 <0.000012>
20553      0.000051 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1.log", {st_mode=S_IFREG|0644, st_size=279, ...}) = 0 <0.000008>
20553      0.000040 access("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1.log", F_OK) = 0 <0.000009>
20553      0.000029 statfs("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1.log", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=114046550, f_bfree=52695397, f_bavail=46902169, f_files=28966912, f_ffree=28834037, f_fsid={-969085044, 169166933}, f_namelen=255, f_frsize=4096}) = 0 <0.000010>
20553      0.000040 open("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1.log", O_RDONLY) = 3 <0.000010>
20553      0.000044 close(3)            = 0 <0.000007>
......
20553      0.000060 getcwd("/tmp", 4096) = 5 <0.000018>
20553      0.000048 chdir("/u01/app/11.2.0/grid/log/fyhis1/client") = 0 <0.000014>
20553      0.000049 getcwd("/u01/app/11.2.0/grid/log/fyhis1/client", 4096) = 39 <0.000013>
20553      0.000046 chdir("/tmp")       = 0 <0.000013>
20553      0.000096 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1280.log", {st_mode=S_IFREG|0644, st_size=260, ...}) = 0 <0.000017>
20553      0.000080 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1280.log", {st_mode=S_IFREG|0644, st_size=260, ...}) = 0 <0.000015>
20553      0.000072 access("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1280.log", F_OK) = 0 <0.000016>
20553      0.000053 statfs("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1280.log", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=114046550, f_bfree=52695397, f_bavail=46902169, f_files=28966912, f_ffree=28834037, f_fsid={-969085044, 169166933}, f_namelen=255, f_frsize=4096}) = 0 <0.000018>
20553      0.000073 open("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1280.log", O_RDONLY) = 3 <0.000017>
20553      0.000058 close(3)            = 0 <0.000012>
20553      0.000047 getcwd("/tmp", 4096) = 5 <0.000013>
20553      0.000041 chdir("/u01/app/11.2.0/grid/log/fyhis1/client") = 0 <0.000014>
20553      0.000048 getcwd("/u01/app/11.2.0/grid/log/fyhis1/client", 4096) = 39 <0.000014>
20553      0.000048 chdir("/tmp")       = 0 <0.000014>
20553      0.000099 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1281.log", {st_mode=S_IFREG|0644, st_size=262, ...}) = 0 <0.000018>
20553      0.000079 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1281.log", {st_mode=S_IFREG|0644, st_size=262, ...}) = 0 <0.000023>
20553      0.000091 access("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1281.log", F_OK) = 0 <0.000015>
20553      0.000052 statfs("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1281.log", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=114046550, f_bfree=52695397, f_bavail=46902169, f_files=28966912, f_ffree=28834037, f_fsid={-969085044, 169166933}, f_namelen=255, f_frsize=4096}) = 0 <0.000018>
20553      0.000073 open("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1281.log", O_RDONLY) = 3 <0.000017>
20553      0.000058 close(3)            = 0 <0.000012>
...
20553      0.000041 chdir("/u01/app/11.2.0/grid/log/fyhis1/client") = 0 <0.000015>
20553      0.000048 getcwd("/u01/app/11.2.0/grid/log/fyhis1/client", 4096) = 39 <0.000012>
20553      0.000046 chdir("/tmp")       = 0 <0.000012>
20553      0.000092 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1285.log", {st_mode=S_IFREG|0644, st_size=262, ...}) = 0 <0.000017>
20553      0.000080 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1285.log", {st_mode=S_IFREG|0644, st_size=262, ...}) = 0 <0.000015>
20553      0.000072 access("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1285.log", F_OK) = 0 <0.000016>
20553      0.000052 statfs("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1285.log", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=114046550, f_bfree=52695397, f_bavail=46902169, f_files=28966912, f_ffree=28834037, f_fsid={-969085044, 169166933}, f_namelen=255, f_frsize=4096}) = 0 <0.000017>
20553      0.000073 open("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1285.log", O_RDONLY) = 3 <0.000016>
20553      0.000058 close(3)            = 0 <0.000012>
.....
20553      0.000045 getcwd("/tmp", 4096) = 5 <0.000014>
20553      0.000043 chdir("/u01/app/11.2.0/grid/log/fyhis1/client") = 0 <0.000015>
20553      0.000054 getcwd("/u01/app/11.2.0/grid/log/fyhis1/client", 4096) = 39 <0.000012>
20553      0.000046 chdir("/tmp")       = 0 <0.000012>
20553      0.000092 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", 0x7fff0541f8e0) = -1 ENOENT (No such file or directory) <0.000043>
--//執行時/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log檔案不存在。
20553      0.000132 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", 0x7fff0541fcd0) = -1 ENOENT (No such file or directory) <0.000015>
20553      0.000151 getrlimit(RLIMIT_NOFILE, {rlim_cur=64*1024, rlim_max=64*1024}) = 0 <0.000012>
20553      0.000122 open("/u01/app/11.2.0/grid/lib/libnque11.so", O_RDONLY) = 3 <0.000019>
20553      0.000056 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\24\0\0\0\0\0\0"..., 832) = 832 <0.000013>
20553      0.000056 fstat(3, {st_mode=S_IFREG|0644, st_size=59021, ...}) = 0 <0.000012>
20553      0.000071 mmap(NULL, 1090528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f786390d000 <0.000022>
20553      0.000055 mprotect(0x7f7863917000, 1044480, PROT_NONE) = 0 <0.000019>
20553      0.000051 mmap(0x7f7863a16000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x7f7863a16000 <0.000018>
20553      0.000060 mmap(0x7f7863a17000, 992, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7863a17000 <0.000015>
20553      0.000045 close(3)            = 0 <0.000012>
...
--//執行程式碼把/u01/app/11.2.0/grid/log/fyhis1/client目錄下clscNNNN.log檔案從N=1到1285探查1遍。
20553      0.000225 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", 0x7fff05420190) = -1 ENOENT (No such file or directory) <0.000022>
20553      0.000201 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", 0x7fff054200f0) = -1 ENOENT (No such file or directory) <0.000026>
20553      0.000078 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", 0x7fff0541fb60) = -1 ENOENT (No such file or directory) <0.000015>
20553      0.000065 access("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", F_OK) = -1 ENOENT (No such file or directory) <0.000032>
20553      0.000076 statfs("/u01/app/11.2.0/grid/log/fyhis1/client/", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=114046550, f_bfree=52695397, f_bavail=46902169, f_files=28966912, f_ffree=28834037, f_fsid={-969085044, 169166933}, f_namelen=255, f_frsize=4096}) = 0 <0.000019>
20553      0.000078 open("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5 <0.000066>
20553      0.000125 close(5)            = 0 <0.000015>
20553      0.000059 chmod("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", 0644) = 0 <0.000022>
20553      0.000066 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000030>
20553      0.000100 access("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", F_OK) = 0 <0.000017>
20553      0.000054 statfs("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=114046550, f_bfree=52695397, f_bavail=46902169, f_files=28966912, f_ffree=28834036, f_fsid={-969085044, 169166933}, f_namelen=255, f_frsize=4096}) = 0 <0.000017>
20553      0.000076 open("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5 <0.000022>
20553      0.000074 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000016>
20553      0.000077 stat("/u01/app/11.2.0/grid/log/fyhis1/client/clsc1286.log", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000015>
20553      0.000114 write(5, "Oracle Database 11g Clusterware "..., 114) = 114 <0.000044>
20553      0.000134 write(5, "2021-08-03 11:46:42.136: [ CRSCO"..., 73) = 73 <0.000017>
20553      0.000110 write(5, "2021-08-03 11:46:42.136: [ CRSCO"..., 75) = 75 <0.000017>
--//寫入資訊。時間也和下面的一致。

$ ls -ltr clsc[0-9]*.log  | grep oinstall | head
-rw-r--r-- 1 grid   oinstall  279 2016-12-24 12:18:53 clsc1.log
-rw-r--r-- 1 grid   oinstall 9893 2016-12-24 12:25:39 clsc3.log
-rw-r--r-- 1 oracle oinstall 9893 2016-12-24 12:32:08 clsc4.log
-rw-r--r-- 1 grid   oinstall  358 2016-12-29 11:16:04 clsc28.log
-rw-r--r-- 1 grid   oinstall  359 2016-12-30 11:58:17 clsc37.log
-rw-r--r-- 1 grid   oinstall  358 2016-12-30 11:59:55 clsc38.log
-rw-r--r-- 1 grid   oinstall  358 2016-12-30 12:09:19 clsc39.log
-rw-r--r-- 1 grid   oinstall  362 2016-12-30 12:09:22 clsc40.log
-rw-r--r-- 1 grid   oinstall  362 2016-12-30 12:09:23 clsc41.log
-rw-r--r-- 1 grid   oinstall  260 2016-12-30 12:09:35 clsc42.log

$ ls -ltr clsc[0-9]*.log  | grep oinstall | tail -30
-rw-r--r-- 1 grid   oinstall  262 2021-07-21 07:59:58 clsc1257.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-21 08:19:58 clsc1258.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-22 07:59:58 clsc1259.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-22 08:19:59 clsc1260.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-23 08:00:01 clsc1261.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-23 08:20:01 clsc1262.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-24 07:59:55 clsc1263.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-24 08:19:57 clsc1264.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-25 07:59:51 clsc1265.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-25 08:19:50 clsc1266.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-26 07:59:54 clsc1267.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-26 08:19:52 clsc1268.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-27 07:59:55 clsc1269.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-27 08:19:54 clsc1270.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-28 07:59:57 clsc1271.log
-rw-r--r-- 1 grid   oinstall  260 2021-07-28 08:19:55 clsc1272.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-29 07:59:58 clsc1273.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-29 08:19:57 clsc1274.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-30 08:00:00 clsc1275.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-30 08:19:59 clsc1276.log
-rw-r--r-- 1 grid   oinstall  262 2021-07-31 07:59:56 clsc1277.log
-rw-r--r-- 1 grid   oinstall  260 2021-07-31 08:19:54 clsc1278.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-01 07:59:51 clsc1279.log
-rw-r--r-- 1 grid   oinstall  260 2021-08-01 08:19:50 clsc1280.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-02 07:59:53 clsc1281.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-02 08:19:52 clsc1282.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 07:59:55 clsc1283.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 08:19:54 clsc1284.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 11:45:31 clsc1285.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 11:46:42 clsc1286.log
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
--//你還可以發現1個規律，就是正常情況下1天執行2次，我估計oracle自己檢查的，時間非常固定。
--//07:59,08:19上下。最後2次時我手動執行的。
--//從時間上看從上線以來我們從來沒有刪除過。假設從2016-12-24開始每天產生2個。
--//(8+365+365+365+366+215)*2 = 3368
--//恩，數量相差很大啊。放棄，不探究了。

$ cat clsc125[78].log
Oracle Database 11g Clusterware Release 11.2.0.4.0 - Production Copyright 1996, 2011 Oracle. All rights reserved.
2021-07-21 07:59:58.263: [ CRSCOMM][4154296096] NAME: `UI_DATA` length=7
2021-07-21 07:59:58.263: [ CRSCOMM][4154296096] Successfully read response

Oracle Database 11g Clusterware Release 11.2.0.4.0 - Production Copyright 1996, 2011 Oracle. All rights reserved.
2021-07-21 08:19:58.462: [ CRSCOMM][4097627936] NAME: `UI_DATA` length=7
2021-07-21 08:19:58.462: [ CRSCOMM][4097627936] Successfully read response

$ crs_stat -t -v
...

$ ls -ltr clsc[0-9]*.log  | grep oinstall | tail -4
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 08:19:54 clsc1284.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 11:45:31 clsc1285.log
-rw-r--r-- 1 grid   oinstall  262 2021-08-03 11:46:42 clsc1286.log
-rw-r--r-- 1 grid   oinstall  258 2021-08-03 12:00:29 clsc1287.log
--//你只要執行1次就產生1個.
--//解決方法很簡單刪除該目錄下log檔案。估計對方是執行zabbix 之類的監控執行了這個命令。
--//好像11g不主張使用這個命令，而是使用crsctl。
$ crsctl status res -t