[20211214]檢視檢視V$ACTIVE_SESSION_HISTORY遇到奇怪問題.txt
[20211214]檢視檢視V$ACTIVE_SESSION_HISTORY遇到奇怪問題.txt
--//生產系統遇到無法生成awr的問題，做一個分析：
1.環境：
xxxxxx> @ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- ----------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.3.0 Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
2.分析：
xxxxxx> select min(sample_time),max(sample_time),sysdate from V$ACTIVE_SESSION_HISTORY ;
MIN(SAMPLE_TIME) MAX(SAMPLE_TIME) SYSDATE
----------------------- ----------------------- -------------------
2012-10-26 08:19:21.466 2012-10-26 08:19:55.536 2021-12-14 17:20:18
--//MAX(SAMPLE_TIME) = 2012-10-26 08:19:55.536 , 而當前時間是2021-12-14 17:20:18。
xxxxxx> @ bg mm
ADDR PID SPID PROGRAM
---------------- ------- ------ --------------------------
00000000BD799A00 9 3618 oracle@xhserver (MMAN)
00000000BD79FE20 15 3630 oracle@xhserver (MMON)
00000000BD7A0ED0 16 3632 oracle@xhserver (MMNL)
--//很明顯收集ash停止收集資訊，什麼原因造成的問題呢？
xxxxxx> SELECT * FROM DBA_HIST_SNAPSHOT WHERE snap_id IN (SELECT MAX (snap_id) FROM DBA_HIST_SNAPSHOT)
2 @pr
==============================
SNAP_ID : 60089
DBID : 252262230
INSTANCE_NUMBER : 1
STARTUP_TIME : 2012-10-26 08:06:15.000
BEGIN_INTERVAL_TIME : 2021-12-05 12:00:21.235
END_INTERVAL_TIME : 2021-12-05 13:00:24.355
FLUSH_ELAPSED : +00000 00:00:00.1
SNAP_LEVEL : 1
ERROR_COUNT : 0
SNAP_FLAG : 0
SNAP_TIMEZONE : +0 08:00:00
PL/SQL procedure successfully completed.
--// 2021-12-05 13:00:24.355停止了，從來沒有遇到這個問題。為什麼呢？
--// 再次看STARTUP_TIME發現一個奇特現象時間指向了2012-10-26 08:06:15.000,不應該這麼長時間啟動資料庫而沒有關庫。
--// 也就伺服器發生了重啟,並且伺服器的時鐘走的不對.
# hwclock ;date
Sun 04 Nov 2012 10:36:20 AM CST -0.000513 seconds
Tue Dec 14 17:30:23 CST 2021
--//機器硬體的時間與伺服器存在巨大差異。檢查alert*.log 發現：(補充實際上重啟了2次)
--//實際上第1次發生在2021/8/12
Thu Aug 12 11:59:35 2021
LNS: Standby redo logfile selected for thread 1 sequence 16387 for destination LOG_ARCHIVE_DEST_2
Fri Oct 26 08:05:58 2012 --//第1次重啟資料庫。
Starting ORACLE instance (normal)
****************** Large Pages Information *****************
Total Shared Global Region in Large Pages = 1522 MB (100%)
Large Pages used by this instance: 761 (1522 MB)
Large Pages unused system wide = 39 (78 MB) (alloc incr 16 MB)
Large Pages configured system wide = 800 (1600 MB)
Large Page size = 2048 KB
***********************************************************
...
Fri Oct 26 08:10:46 2012
SMCO started with pid=85, OS id=5133
Thu Aug 12 15:18:04 2021
VKTM detected a time drift. Please check trace file for more details.
VKTM detected a time drift. Please check trace file for more details.
Thu Aug 12 15:19:16 2021
Starting background process CJQ0
Sun Dec 05 11:44:42 2021
~~~~~~~~~~~~~~~~~~~~~~~~
LNS: Standby redo logfile selected for thread 1 sequence 17237 for destination LOG_ARCHIVE_DEST_2
Fri Oct 26 08:19:10 2012 --//第2次重啟資料庫。
~~~~~~~~~~~~~~~~~~~~~~~
Starting ORACLE instance (normal)
****************** Large Pages Information *****************
Total Shared Global Region in Large Pages = 1522 MB (100%)
Large Pages used by this instance: 761 (1522 MB)
Large Pages unused system wide = 39 (78 MB) (alloc incr 16 MB)
Large Pages configured system wide = 800 (1600 MB)
Large Page size = 2048 KB
***********************************************************
.......
Fri Oct 26 08:19:50 2012
db_recovery_file_dest_size of 41220 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Setting Resource Manager plan SCHEDULER[0x318F]:DEFAULT_MAINTENANCE_PLAN via scheduler window
Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter
Fri Oct 26 08:19:53 2012
Starting background process VKRM
Fri Oct 26 08:19:53 2012
VKRM started with pid=20, OS id=3802
Sun Dec 05 15:13:58 2021
VKTM detected a time drift. Please check trace file for more details.
VKTM detected a time drift. Please check trace file for more details.
Sun Dec 05 15:14:25 2021
--//順便說一下，我沒有使用ntp服務，而是在crond裡面加入：
*/20 * * * * root /usr/sbin/ntpdate 192.168.xxx.xx > /dev/null 2>&1
--//但是VKTM到Sun Dec 05 15:13:58 2021才報VKTM detected a time drift. Please check trace file for more details.
# uptime
17:36:38 up 9 days, 2:25, 1 user, load average: 0.05, 0.11, 0.09
xxxxxx> select sysdate-9-17/24-25/24/60 from dual ;
SYSDATE-9-2/24-25/2
-------------------
2021-12-05 15:12:44
--//也就是大概2021-12-05 15:12:44上下, 伺服器重啟.
--//檢視/var/log/messages.1 檔案，也可以
Dec 5 04:03:03 xhserver syslogd 1.4.1: restart.
Oct 26 08:18:41 xhserver syslogd 1.4.1: restart.
Oct 26 08:18:42 xhserver kernel: klogd 1.4.1, log source = /proc/kmsg started.
...
--//可以大致猜測應該2021/12/5 某個時刻當機了，或者重啟伺服器.大致到了2021-12-05 15:13:XX重啟動資料庫。
--//我估計是異常重啟，沒有正常關閉資料庫。
xxxxxx> select * from DBA_HIST_DATABASE_INSTANCE
2 @ pr
==============================
DBID : 252262230
INSTANCE_NUMBER : 1
STARTUP_TIME : 2021-03-13 10:31:36.000
PARALLEL : NO
VERSION : 11.2.0.3.0
DB_NAME : HRP430
INSTANCE_NAME : hrp430
HOST_NAME : xhserver
LAST_ASH_SAMPLE_ID : 215975423
PLATFORM_NAME : Linux x86 64-bit
==============================
DBID : 252262230
INSTANCE_NUMBER : 1
STARTUP_TIME : 2012-10-26 08:06:15.000
PARALLEL : NO
VERSION : 11.2.0.3.0
DB_NAME : HRP430
INSTANCE_NAME : hrp430
HOST_NAME : xhserver
LAST_ASH_SAMPLE_ID : 0
PLATFORM_NAME : Linux x86 64-bit
==============================
DBID : 252262230
INSTANCE_NUMBER : 1
STARTUP_TIME : 2012-10-26 08:19:40.000
PARALLEL : NO
VERSION : 11.2.0.3.0
DB_NAME : HRP430
INSTANCE_NAME : hrp430
HOST_NAME : xhserver
LAST_ASH_SAMPLE_ID : 0
PLATFORM_NAME : Linux x86 64-bit
PL/SQL procedure successfully completed.
--//再次檢視alert確實重啟了2次。
--//結合前面的檢查,可以發現2021-12-05 13:00:24.355 - 2021-12-05 15:13:58 (Sun Dec 05 15:13:58 2021) 之間當機或者重啟了服
--//務器以及資料庫.
--//可以大致猜測幾種情況
--//1.伺服器的cmos電池已經沒電了,導致伺服器時間不正常.
--//2.我記憶裡linux伺服器正常關閉,應該會執行一步伺服器當前時間同步硬體時鐘的操作,很明顯沒有這步.也就是當機的可能性很大,
--// 關於一些細節要跟管理伺服器的同事確認.
--//3.我並不排除有人進入BIOS SETUP介面修改時間的可能，不過這個可能性很小。
--//剩下的如何解決這些問題:
xxxxxx> @bgx mm
PROGRAM MODULE ACTION SID PID SPID
-------------------------- ------------ ------------- ------- ------
oracle@xhserver (MMAN) 417 9 3618
oracle@xhserver (MMNL) 4 16 3632
oracle@xhserver (MMON) 1246 15 3630
# ps -elf | grep -E "UI[D]|361[8]|363[0]|363[2]"
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 S oracle 3618 1 0 78 0 - 58663 - Dec05 ? 00:00:00 ora_mman_hrp430
0 S oracle 3630 1 0 75 0 - 60125 - Dec05 ? 00:00:00 ora_mmon_hrp430
0 S oracle 3632 1 0 75 0 - 58957 - Dec05 ? 00:00:00 ora_mmnl_hrp430
# hwclock --systohc --debug
hwclock from util-linux 2.13-pre7
Using /dev interface to clock.
Last drift adjustment done at 1457145517 seconds after 1969
Last calibration done at 1457145517 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2012/11/04 17:38:38
Hw clock time : 2012/11/04 17:38:38 = 1352050718 seconds since 1969
Time elapsed since reference time has been 0.516304 seconds.
Delaying further to reach the new time.
Setting Hardware Clock to 00:32:42 = 1639528362 seconds since 1969
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
ioctl(RTC_SET_TIME) was successful.
Not adjusting drift factor because it has been less than a day since the last calibration.
--//注：加入--debug 主要看裡面執行的細節。下劃線表示什麼不懂。視乎裡面的32表示32天。
xxxxxx> select sysdate - timestamp'2012-11-04 17:38:38' from dual ;
SYSDATE-TIMESTAMP'2012-11-0417:38:38'
---------------------------------------------------------------------------
+000003327 14:58:35.000000000
# hwclock ; date
Wed 15 Dec 2021 08:37:40 AM CST -0.000560 seconds
Wed Dec 15 08:37:40 CST 2021
--//現在時間已經同步。
--//kill mmon,mmnl程式。
xxxxxx> alter system enable restricted session;
System altered.
# ps -elf | grep -E "UI[D]|361[8]|363[0]|363[2]"
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 S oracle 3618 1 0 78 0 - 58663 - Dec05 ? 00:00:00 ora_mman_hrp430
xxxxxx> alter system disable restricted session;
System altered.
xxxxxx> @ bgx mm
PROGRAM MODULE ACTION SID PID SPID
-------------------------- ------------ ------- ---- ------- ------
oracle@xhserver (MMAN) 417 9 3618
oracle@xhserver (MMNL) 4 16 18968
oracle@xhserver (MMON) 1246 15 18966
xxxxxx> select min(sample_time),max(sample_time),sysdate from V$ACTIVE_SESSION_HISTORY ;
MIN(SAMPLE_TIME) MAX(SAMPLE_TIME) SYSDATE
----------------------- ----------------------- -------------------
2012-10-26 08:19:21.466 2021-12-15 08:41:19.991 2021-12-15 08:41:20
--//MAX(SAMPLE_TIME) = 2021-12-15 08:41:19.991 ,說明開始能收集ash資訊。問題解決。
xxxxxx> select count(*) from V$ACTIVE_SESSION_HISTORY where sample_time>trunc(sysdate);
COUNT(*)
----------
737
--//繼續分析：
xxxxxx> select sql_opname,sql_id,count(*) from V$ACTIVE_SESSION_HISTORY where sample_time<=trunc(sysdate) group by sql_id,sql_opname order by 3 desc;
SQL_OPNAME SQL_ID COUNT(*)
--------------- ------------- ----------
32
ALTER DATABASE 1h50ks4ncswfn 24
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
SELECT f6cz4n8y72xdc 6
SELECT g0jvz8csyrtcf 3
ALTER DATABASE 92b382ka0qgdt 3
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
PL/SQL EXECUTE 02577v815yp77 2
SELECT 05uqdabhzncdc 1
SELECT 836b98xx998x3 1
PL/SQL EXECUTE cnq31548hb8un 1
SELECT 1p36ta7p3d7fu 1
PL/SQL EXECUTE 49s332uhbnsma 1
SELECT a1xgxtssv5rrp 1
SELECT 9dhn1b8d88dpf 1
13 rows selected.
--//sql_id=1h50ks4ncswfn出現多次，而且SQL_OPNAME 是ALTER DATABASE。
xxxxxx> @ sql_id 1h50ks4ncswfn
no rows selected
view dba_hist_sqltext
no rows selected
--//上網直接查詢1h50ks4ncswfn，
*** 2019-01-25 14:15:19.247
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=1h50ks4ncswfn) -----
ALTER DATABASE OPEN
--//視乎這個命令對應的就是ALTER DATABASE OPEN。
$ sql_id.sh "ALTER DATABASE OPEN\0"
sql_text = ALTER DATABASE OPEN\0
full_hash_value(16) = 2560c35ddf0cebbf181412c128cc71d4
hash_value(10) = 684487124
sql_id(32) = 1h50ks4ncswfn
sql_id(32) = 1h50ks4ncswfn
sql_id(32) = 1h50ks4ncswfn
--//正確。
--//查詢92b382ka0qgdt,視乎對應ALTER DATABASE MOUNT,我的測試對不上。
$ sql_id.sh "ALTER DATABASE MOUNT\0"
sql_text = ALTER DATABASE MOUNT\0
full_hash_value(16) = c74c9f84f1d0a9d569fd9ec039ac9989
hash_value(10) = 967612809
sql_id(32) = 6mzcys0wut6c9
sql_id(32) = 6mzcys0wut6c9
sql_id(32) = 6mzcys0wut6c9
--//終於找到一個連結
LibraryObjectLock: Address=f6edd440 Handle=f69b40e0 Mode=N CanBeBrokenCount=1 Incarnation=1 ExecutionCount=1
User=f7bdefd0 Session=f7bdefd0 ReferenceCount=1 Flags=CNB/[0001] SavepointNum=556c8d0e
LibraryHandle: Address=f69b40e0 Hash=940b3db9 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=ALTER DATABASE MOUNT --//這裡的MOUNT前面有3個空格。
FullHashValue=3b4263a262865c96912c6814940b3db9 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=2483764665 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=1 BucketInUse=0 HandleInUse=0 HandleReferenceCount=0
Concurrency: DependencyMutex=f69b4190(0, 1, 0, 0) Mutex=f69b4210(0, 20, 0, 0)
Flags=RON/PIN/TIM/PN0/DBN/[10012841]
WaitersLists:
Lock=f69b4170[f69b4170,f69b4170]
Pin=f69b4150[f69b4150,f69b4150]
LoadLock=f69b41c8[f69b41c8,f69b41c8]
Timestamp: Current=06-01-2015 12:49:18
HandleReference: Address=f69b4290 Handle=0 Flags=[00]
LibraryObject: Address=eeff20b0 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
ChildTable: size='16'
Child: id='0' Table=eeff2f60 Reference=eeff29b8 Handle=f69b3e90
NamespaceDump:
Parent Cursor: sql_id=92b382ka0qgdt parent=eeff2150 maxchild=1 plk=y ppn=n
$ sql_id.sh "ALTER DATABASE MOUNT\0"
sql_text = ALTER DATABASE MOUNT\0
full_hash_value(16) = 3b4263a262865c96912c6814940b3db9
hash_value(10) = 2483764665
sql_id(32) = 92b382ka0qgdt
sql_id(32) = 92b382ka0qgdt
sql_id(32) = 92b382ka0qgdt
--//終於對上了。
--//實際上自己使用10046跟蹤估計也可以獲得，有計劃嘗試看看。
3.總結：
--//很明顯我們團隊許多人根本不看awr報表。
--//另外該硬體應該到了替換的時間。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2847778/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20210418]查詢v$檢視問題.txt
- V$ACTIVE_SESSION_HISTORY檢視的使用Session
- [20190324]奇怪的GV$FILESPACE_USAGE檢視.txt
- [20211206]toad下job建立檢視問題.txt
- [20211019]V$DETACHED_SESSION檢視.txtSession
- [20210528]V$INDEXED_FIXED_COLUMN檢視.txtIndex
- [20221128]再談防水牆(檢視訪問效能問題).txt
- [20211210]優化遇到的奇怪問題.txt優化
- [20210114]toad檢視真實執行計劃問題.txt
- [20181103]12c檢視V$EVENT_NAME.txt
- [20201207]12c v$open_cursor檢視.txt
- [20180907]訪問v$檢視與一致性讀取.txt
- [20240911]檢視超長檢視的定義2.txt
- [20231026]bbed檢視索引kd_off結構的問題.txt索引
- [20211214]ezconnect輸入口令的問題.txt
- [20180503]檢視提示使用索引.txt索引
- [20190320]關於使用smem檢視記憶體使用的問題.txt記憶體
- [20210205]toad檢視真實執行計劃問題3.txt
- 檢視V$DATAGUARD_STATS
- 問題:PCB檔案PADS檢視不了
- 資料檢視的重複問題
- thinkphp6 檢視問題總結PHP
- [20221130]測試訪問檢視v$session幾種情況的效能差異.txtSession
- [20230323]ps命令檢視thread.txtthread
- 11 UML中的邏輯檢視、程序檢視、實現檢視、部署檢視
- [20190312]檢視v$datafile欄位OFFLINE_CHANGE#, ONLINE_CHANGE#.txt
- [Django REST framework - 檢視元件之檢視基類、檢視擴充套件類、檢視子類、檢視集]DjangoRESTFramework元件套件
- [20200211]檢視v$db_object_cache的CHILD_LATCH欄位.txtObject
- [20200212]使用DBMS_SHARED_POOL.MARKHOT與檢視v$open_cursor.txt
- [20200417]跟蹤特定sql語句以及v$open_cursor檢視.txtSQL
- ASP.NET Core 5.0 MVC中的檢視分類——佈局檢視、啟動檢視、具體檢視、分部檢視ASP.NETMVC
- [20230214]資料庫連線訪問asm相關檢視.txt資料庫ASM
- linux Too Many Files 問題檢視和解決方法Linux
- [20190416]檢視shared latch gets的變化.txt
- [20231012]如何檢視unicode編碼內容.txtUnicode
- [20190104]ipcs檢視共享記憶體段.txt記憶體
- [20210422]如何檢視字元的ascii編碼.txt字元ASCII
- [20210423]建立檢視以及欄位長度.txt