Share this
by Matheus Boesing on Nov 26, 2021 12:00:00 AM
I ran across an interesting case within OEM 12 (Oracle Enterprise Manager) Release 5. A client reported the “tablespace allocation metric” was not being updated on OEM for a specific database. In this case, the most recent gathering was done in November 2020, as I’ll show you shortly. Then, we discovered the problem one month later. This post describes what we did to solve the issue.
As usual, the first thing I did was check on the Oracle Enterprise Manager (OEM) agent status. This is what it said:
oracle:dbserver@mydb02 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl status agent Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- Agent Version : 12.1.0.5.0 OMS Version : (unknown) Protocol Version : 12.1.0.1.0 Agent Home : /u01/app/oracle/product/agent12c/agent_inst Agent Log Directory : /u01/app/oracle/product/agent12c/agent_inst/sysman/log Agent Binaries : /u01/app/oracle/product/agent12c/core/12.1.0.5.0 Agent Process ID : 61641 Parent Process ID : 61394 Currently initializing component : Target Manager (2) (54 of 70) Receivelet Interaction Manager Current Activity: Outstanding receivelet event tasks ---------------------------------- TargetID = oracle_pdb.c4test_PDB1 - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c3test_CDBROOT - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c3test_PDB2 - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:30 TargetID = oracle_pdb.c4test_CDBROOT - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c6test_CDBROOT - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c3test_PDB3 - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:30 TargetID = rac_database.c1prod - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:30 Target Manager Current Activity : Compute Dynamic Properties (total operations: 37, active: 7, finished: 28) Current target operations in progress ------------------------------------- oracle_pdb.c6test_CDBROOT - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c4test_PDB1 - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c3test_PDB2 - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c3test_CDBROOT - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c4test_CDBROOT - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c3test_PDB3 - LOAD_TARGET_DYNAMIC running for 120 seconds rac_database.c1test - LOAD_TARGET_DYNAMIC running for 120 seconds Dynamic property executor tasks running ------------------------------ --------------------------------------------------------------- Agent is Running but Not Ready
“Agent not ready.” Now, that’s interesting.
Next, I tried to clear the agent state as this had solved some previous similar cases:
oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl clearstate agent Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. EMD clearstate completed successfully
Then, I ran the problematic metric manually:
oracle:dbserver02@c1test2 /u01/app/oracle: runCollection c1test_DW:oracle_pdb tbspAllocation < Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- EMD runCollection error:The agent is running but is currently not ready to accept client requests
This shows me trying to upload the case:
oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl upload Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- EMD upload error:The agent is running but is currently not ready to accept client requests
I thought maybe something was stuck, so I decided to kill the process and start all over again:
oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl stop agent Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. Stopping agent ... stopped.
Here, I made sure I had no agent process running:
oracle:dbserver02@c1test2 /u01/app/oracle: ps -ef | grep java | agent oracle:dbserver02@c1test2 /u01/app/oracle:
I also adjusted the threshold for metric running:
oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl setproperty agent -a Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. EMD setproperty succeeded oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl setproperty agent -allow_new -name _cancelThread -value 210 Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. EMD setproperty succeeded And strating the agent oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl start agent Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. Starting agent ........................................................................................................................... started but not ready.
This was on the agent log:
oracle:dbserver02@c1test2 /u01/app/oracle: tail /u01/app/oracle/product/agent12c/agent_inst/sysman/log/gcagent.log oracle:dbserver02@c1test2 /u01/app/oracle: 2020-12-20 13:15:03,457 [35:686116F5] DEBUG - StatusAgentAction: satisfyRequest Begin 2020-12-20 13:15:03,457 [35:686116F5] DEBUG - Agent Overall Health: 0 2020-12-20 13:15:03,457 [35:686116F5] DEBUG - StatusAgentAction: satisfyRequest End Response: initializing 2020-12-20 13:15:03,457 [35:686116F5] INFO - >>> Reporting response: StatusAgentResponse (initializing) (request id 1) <<< 2020-12-20 13:15:03,457 [35:686116F5] DEBUG - closing request input stream for "StatusAgentRequest (AGENT timeout:300)" 2020-12-20 13:15:03,457 [35:686116F5] DEBUG - overriding the buffer with a thread local copy (size: 8192b) 2020-12-20 13:15:03,458 [35:686116F5] DEBUG - closing request output stream for "StatusAgentRequest (AGENT timeout:300)" 2020-12-20 13:15:03,458 [35:686116F5] DEBUG - StatusAgentAction.call() is complete. 2020-12-20 13:15:03,458 [35:B5326F3F:HTTP Listener-35 - /emd/lifecycle/main/] DEBUG - removing entry for emdctl@18081@dbserver02=>[160849530330001] completely 2020-12-20 13:15:03,458 [35:B5326F3F] DEBUG - requests executed. 2020-12-20 13:15:03,458 [35:B5326F3F] DEBUG - HTTPListener Threads deallocated resource back to LifecycleRequestHandler partition 2020-12-20 13:15:03,458 [35:3C0B0663:HTTP Listener-35] DEBUG - using connection SCEP@1197017148 [d=true,io=1,w=true,b=false|false],NOT_HANDSHAKING, in/out=0/0 Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 5 bytesProduced = 26 2020-12-20 13:15:03,780 [35:3C0B0663] DEBUG - using connection SCEP@1197017148 [d=true,io=1,w=true,b=false|false],NOT_HANDSHAKING, in/out=0/0 Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 26 bytesProduced = 5 2020-12-20 13:15:06,986 [31:858161EB] DEBUG - Submitting task SchedulerHeartbeat for execution 2020-12-20 13:15:06,986 [395:1AE716D8] DEBUG - Begin task SchedulerHeartbeat on Thread: GC.SysExecutor.8 2020-12-20 13:15:06,986 [395:F944F4C8:GC.SysExecutor.8 (SchedulerHeartbeat)] DEBUG - Scheduler heartbeat 2020-12-20 13:15:06,988 [395:F944F4C8] DEBUG - Scheduling next SchedulerHeartbeat after delay 29998 including periodShift of 0 milliseconds 2020-12-20 13:15:06,988 [395:1AE716D8:GC.SysExecutor.8] DEBUG - End task SchedulerHeartbeat 2020-12-20 13:15:07,016 [31:858161EB] DEBUG - Submitting task HeapMonitorTask for execution 2020-12-20 13:15:07,017 [396:1AE716D9] DEBUG - Begin task HeapMonitorTask on Thread: GC.SysExecutor.9 2020-12-20 13:15:07,017 [396:391F60D7:GC.SysExecutor.9 (HeapMonitorTask)] DEBUG - Scheduling next HeapMonitorTask after delay 5000 including periodShift of 0 milliseconds 2020-12-20 13:15:07,017 [396:1AE716D9:GC.SysExecutor.9] DEBUG - End task HeapMonitorTask 2020-12-20 13:15:12,017 [31:858161EB] DEBUG - Submitting task HeapMonitorTask for execution 2020-12-20 13:15:12,017 [37:1AE716D0] DEBUG - Begin task HeapMonitorTask on Thread: GC.SysExecutor.0 2020-12-20 13:15:12,017 [37:FE21F10E:GC.SysExecutor.0 (HeapMonitorTask)] DEBUG - Scheduling next HeapMonitorTask after delay 5000 including periodShift of 0 milliseconds 2020-12-20 13:15:12,017 [37:1AE716D0:GC.SysExecutor.0] DEBUG - End task HeapMonitorTask 2020-12-20 13:15:12,189 [33:6D553CF6] DEBUG - HTTPListener Threads deallocated resource back to LifecycleRequestHandler partition 2020-12-20 13:15:12,190 [35:3C0B0663] DEBUG - using connection SCEP@1611645943 [d=true,io=1,w=true,b=false|false],NOT_HANDSHAKING, in/out=0/0 Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 100 bytesProduced = 121 2020-12-20 13:15:12,191 [35:7107E334:HTTP Listener-35 - /emd/persistence/main/] DEBUG - HTTPListener Threads allocated resource from LifecycleRequestHandler partition 2020-12-20 13:15:17,017 [31:858161EB] DEBUG - Submitting task HeapMonitorTask for execution 2020-12-20 13:15:17,018 [45:1AE716D1] DEBUG - Begin task HeapMonitorTask on Thread: GC.SysExecutor.1 2020-12-20 13:15:17,018 [45:CBCC52CF:GC.SysExecutor.1 (HeapMonitorTask)] DEBUG - Scheduling next HeapMonitorTask after delay 5000 including periodShift of 0 milliseconds 2020-12-20 13:15:17,018 [45:1AE716D1:GC.SysExecutor.1] DEBUG - End task HeapMonitorTask
Following MOS Enterprise Manager12c: Oracle Database Tablespace Monthly Space Usage shows no data (Doc ID 1536654.1), I made a few changes:
$/AGENT_INST/bin/emctl setproperty agent -allow_new -name MaxInComingConnections -value 150 $/AGENT_INST/bin/emctl setproperty agent -allow_new -name _cancelThread -value 210
Here’s the status before the change:
oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl status agent Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- Agent Version : 12.1.0.5.0 OMS Version : (unknown) Protocol Version : 12.1.0.1.0 Agent Home : /u01/app/oracle/product/agent12c/agent_inst Agent Log Directory : /u01/app/oracle/product/agent12c/agent_inst/sysman/log Agent Binaries : /u01/app/oracle/product/agent12c/core/12.1.0.5.0 Agent Process ID : 61641 Parent Process ID : 61394 Currently initializing component : Target Manager (2) (54 of 70) Receivelet Interaction Manager Current Activity: Outstanding receivelet event tasks ---------------------------------- TargetID = oracle_pdb.c4test_PDB1 - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c3test_CDBROOT - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c3test_PDB2 - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:30 TargetID = oracle_pdb.c4test_CDBROOT - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c6test_CDBROOT - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:29 TargetID = oracle_pdb.c3test_PDB3 - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:30 TargetID = rac_database.c1test - EventType - TARGET_EVENT for operation LOAD_TARGET submitted at 2020-12-20 12:54:30 Target Manager Current Activity : Compute Dynamic Properties (total operations: 37, active: 7, finished: 28) Current target operations in progress ------------------------------------- oracle_pdb.c6test_CDBROOT - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c4test_PDB1 - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c3test_PDB2 - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c3test_CDBROOT - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c4test_CDBROOT - LOAD_TARGET_DYNAMIC running for 120 seconds oracle_pdb.c3test_PDB3 - LOAD_TARGET_DYNAMIC running for 120 seconds rac_database.c1test - LOAD_TARGET_DYNAMIC running for 120 seconds Dynamic property executor tasks running ------------------------------ --------------------------------------------------------------- Agent is Running but Not Ready
And this was the status after the change:
oracle:dbserver02@c1test2 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl status agent Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- Agent Version : 12.1.0.5.0 OMS Version : 12.1.0.5.0 Protocol Version : 12.1.0.1.0 Agent Home : /u01/app/oracle/product/agent12c/agent_inst Agent Log Directory : /u01/app/oracle/product/agent12c/agent_inst/sysman/log Agent Binaries : /u01/app/oracle/product/agent12c/core/12.1.0.5.0 Agent Process ID : 56994 Parent Process ID : 56654 Agent URL : https://dbserver02:3872/emd/main/ Local Agent URL in NAT : https://dbserver02:3872/emd/main/ Repository URL : https://omsweb:4903/empbs/upload Started at : 2020-12-20 13:08:35 Started by user : oracle Operating System : Linux version 3.10.0-957.27.2.el7.x86_64 (amd64) Last Reload : (none) Last successful upload : 2020-12-20 13:40:41 Last attempted upload : 2020-12-20 13:40:41 Total Megabytes of XML files uploaded so far : 1.02 Number of XML files pending upload : 0 Size of XML files pending upload(MB) : 0 Available disk space on upload filesystem : 10.85% Collection Status : Collections enabled Heartbeat Status : Ok Last attempted heartbeat to OMS : 2020-12-20 13:40:40 Last successful heartbeat to OMS : 2020-12-20 13:40:40 Next scheduled heartbeat to OMS : 2020-12-20 13:41:40 --------------------------------------------------------------- Agent is Running and Ready
Great! Agent issue resolved.
However, the metric was not being gathered—not even after running it manually:
oracle:dbserver01@c1test1 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl control agent runCollection c1test_CDBROOT:oracle_pdb tbspAllocation Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- EMD runCollection completed successfully oracle:dbserver01@c1test1 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl status agent scheduler | grep tbspAllocation 2020-12-28 23:05:14.562 : rac_database:c1test:tbspAllocation_cdb 2020-12-29 03:07:21.988 : rac_database:c4prod:tbspAllocation_cdb 2020-12-29 03:08:11.888 : rac_database:c6prod:tbspAllocation_cdb 2020-12-29 03:09:39.103 : rac_database:c2prod:tbspAllocation_cdb 2020-12-29 03:09:55.372 : rac_database:c3prod:tbspAllocation_cdb oracle:dbserver01@c1test1 /u01/app/oracle: /u01/app/oracle/product/agent12c/core/12.1.0.5.0/bin/emctl control agent runCollection c1test_DW:oracle_pdb tbspAllocation Oracle Enterprise Manager Cloud Control 12c Release 5 Copyright (c) 1996, 2015 Oracle Corporation. All rights reserved. --------------------------------------------------------------- EMD runCollection completed successfully
Meanwhile, on the OEM repository database:
SQL> select TARGET_NAME,TARGET_TYPE,TARGET_GUID,max(ROLLUP_TIMESTAMP ) from mgmt$metric_daily where TARGET_NAME like '%c1test%' and TARGET_TYPE='oracle_pdb' and METRIC_NAME='tbspAllocation' group by TARGET_NAME,TARGET_TYPE,TARGET_GUID; 2 3 4 5 TARGET_NAME TARGET_TYPE TARGET_GUID MAX(ROLLUP_TIMESTAM ------------------------------ -------------------- -------------------------------- ------------------- c1test_DW oracle_pdb 7B1DF5DD4555EB978330A6D522004D44 2020-11-12 00:00:00 c1test_CDBROOT oracle_pdb 4CE72911295C0287E053837F649B7D0E 2020-11-12 00:00:00 SQL> select TARGET_NAME,TARGET_TYPE,TARGET_GUID,ROLLUP_TIMESTAMP from mgmt$metric_daily where TARGET_NAME like '%c1test%' and TARGET_TYPE='oracle_pdb' and ROLLUP_TIMESTAMP>sysdate-3 order by 4 TARGET_NAME TARGET_TYPE ROLLUP_TIMESTAMP AVERAGE ------------------------------ -------------------- ------------------- ---------- c1test_DW oracle_pdb 2020-11-06 00:00:00 1575.9375 c1test_DW oracle_pdb 2020-11-07 00:00:00 1575.9375 c1test_DW oracle_pdb 2020-11-08 00:00:00 1575.9375 c1test_DW oracle_pdb 2020-11-09 00:00:00 1575.9375 c1test_DW oracle_pdb 2020-11-10 00:00:00 1575.9375 c1test_DW oracle_pdb 2020-11-11 00:00:00 1575.9375 c1test_DW oracle_pdb 2020-11-12 00:00:00 1575.9375 c1test_CDBROOT oracle_pdb 2020-11-05 00:00:00 37581.5625 TARGET_NAME TARGET_TYPE ROLLUP_TIMESTAMP AVERAGE ------------------------------ -------------------- ------------------- ---------- c1test_CDBROOT oracle_pdb 2020-11-08 00:00:00 227138.75 c1test_CDBROOT oracle_pdb 2020-11-09 00:00:00 455087.688 c1test_CDBROOT oracle_pdb 2020-11-10 00:00:00 278230.875 c1test_CDBROOT oracle_pdb 2020-11-11 00:00:00 208727.188 c1test_CDBROOT oracle_pdb 2020-11-12 00:00:00 454964.063
In summary: After fixing all the issues on the OEM side, with everything running fine, the database metrics were still not being updated:
To make a long story short, after some investigation, I came across the following in MOS (My Oracle Support): Database Hangs With Simple Queries like on view dba_data_files & dba_free_space (Doc ID 2665935.1)
This seemed to be a match. So, I proceeded with its recommendations on OMS database:
SQL> alter session set container=DW; Session altered. SQL> show pdbs CON_ID CON_NAME OPEN MODE RESTRICTED ---------- ------------------------------ ---------- ---------- 3 DW READ WRITE NO SQL> select count(*) from dba_recyclebin; COUNT(*) ---------- 28522 SQL> purge recyclebin; Recyclebin purged. SQL> purge dba_recyclebin; DBA Recyclebin purged.
With that done, all the issues were solved and the metric was being collected again:
Here are some additional references:
- Database Tablespace Metrics: Tablespace Allocation Is Not Collected (Metric tbspAllocation) (Doc ID 404692.1)
- EM 12c : emctl start agent Fails With Error ‘Starting agent … started but not ready’ (Doc ID 1591477.1)
- EM12c : emctl start / status agent ‘Agent Running but Not Ready’ ‘ERROR – The agent is overloaded [current requests: 30]’ Reported in gcagent.log (Doc ID 1546529.1)
I hope this helps!
If you have any questions or thoughts, please leave them in the comments. And don’t forget to sign up for the next post.
No Comments Yet
Let us know what you think