OEM: Metric “Tablespace Allocation Metric” not Collected – Agent is Running but Not Ready

Hi all,

That’s an interesting case with OEM. A client reported the metric “Tablespace Allocation Metric” is not being updated on OEM for a specific database. In this case, the last gathering was in Nov/2020, as you’ll see.

When checking for it, the first try as usual was checking on the OEM agent status, and here is what I got:

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, that’s interesting.
Trying then to clear the agent state as this has 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

Now running 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

Ok, trying to just 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

Maybe something is stuck, so let’s 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.

Making sure we have no agent process running:

oracle:dbserver02@c1test2 /u01/app/oracle:  ps -ef | grep java | agent
oracle:dbserver02@c1test2 /u01/app/oracle:

Also adjusting the threshod 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 starting 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.

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), a few changes were made:

$/AGENT_INST/bin/emctl setproperty agent -allow_new -name MaxInComingConnections -value 150
$/AGENT_INST/bin/emctl setproperty agent -allow_new -name _cancelThread  -value 210

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 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 is 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

On 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

Ok, so in summary: After fixing all issues on OEM side, everything running fine, still the database metrics are not being updated.

Long story short: After some investigation, bumped in MOS Database Hangs With Simple Queries like on view dba_data_files & dba_free_space (Doc ID 2665935.1)
Turns out this seemed to be a match. So proceeding with the recommendation:

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.

Once done, all issues solved and metric being collected again:

Some additional reference:

  • 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 it helps!

OEM 12.5: Tablespace Allocation Metric Not Collected—Agent Is Running but Not Ready

Hi all,

First of all, accept our apologies for the long period without posts. We are about to resolve it and restart with posts. 2021 was such a crazy year, but all is settling down.

Jumping to what you are here for: So, 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:

Tablespace allocation metric.

 

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.

 

 

OEM Metric “Memory Utilization” Different on 12c and 13c

So, as rollout strategy we created a new OEM13c to decommission a 12c. However during the testes, noticed Memory Utilization metric was a lot different between 12c and 13c. Why?

Happens that the Memory Utilization is calculated differently between 12c and 13c, but also seems 13c is more accurate, as per MOS The Host Memory Utilization Percentage Calculation in Enterprise Manager Cloud Control (Doc ID 1908853.1)

Well, those who are familiar with memory use computations in the operating system might become confused when examining the memory use metric data from Enterprise Manager 12c and 13c Cloud Control. Metrics such as Memory Utilization (%) do not have an equivalent in the OS, but OS data will be used in its derivation.

This is the formula used by Enterprise Manager 12.1.0.3 for Linux Memory Utilization (%), for example:

Memory Utilization (%) = (100.0 * (activeMem) / realMem)
 = 100 * 25046000/99060536
 = 25.28
EM Shows : 25.5

* On this, activeMem is Active Memory (Active), and realMem is Total Memory (MemTotal).

Comparing this with MemFree, which is not valid, might provide an impression that utilization is not being accurately represented.

Also, the “OEM13c value” was already collected in OEM12c, but under metric name “Used Logical Memory”. And basically “Memory Utilization” in 12c uses “activeMem” instead of “realMem-(freeMem+Buffers+Cached)”. As per image below.

OEM12_grep_mem

The formula in place on 13c is exactly the same as used to fix MOS EM 13c: Incorrect Memory Utilization Reported for Linux Hosts in Enterprise Manager 13.1.0.0.0 Cloud Control (Doc ID 2144976.1)

Example:

[root@greporasrv ~]# free
             total       used       free     shared    buffers     cached
Mem:     264087460  257669460    6418000    7657500     461088   11008128
-/+ buffers/cache:  246200244   17887216
Swap:     25165820    3365104   21800716

(100.0 * (realMem-(freeMem+Buffers+Cached)) / realMem)
100*(264087460-(6418000+461088+11008128))/264087460) = 93,22678328

As per OEM13c:

OEM13_grep_mem.jpg

Also, by checking on server using SAR, seems value in OEM 13c is more accurate, indeed:

[root@greporasrv ~]# sar -r
Linux 2.6.39-400.294.4.el6uek.x86_64 (greporasrv) 	08/29/2017 	_x86_64_	(44 CPU)

12:00:01 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
12:10:01 AM   5377540 258709920     97.96    719080  10775828  83876744     29.00
12:20:01 AM   6131220 257956240     97.68    719504  10721084  82467712     28.51
12:30:01 AM   5623060 258464400     97.87    719700  10720972  83456216     28.85
12:40:01 AM   5606572 258480888     97.88    719836  10779108  83228440     28.77
12:50:01 AM   5783256 258304204     97.81    719860  10848644  82925908     28.67
01:00:01 AM   4151148 259936312     98.43    719888  11589048  84400040     29.18
01:10:01 AM   3717000 260370460     98.59    719904  11534336  84838784     29.33
01:20:01 AM   4282412 259805048     98.38    720164  11480792  84047568     29.06
01:30:01 AM   4473128 259614332     98.31    720184  11483604  83857348     28.99
01:40:01 AM   5113136 258974324     98.06    720256  11528492  83036284     28.71
01:50:01 AM   4971036 259116424     98.12    720284  11587956  82955128     28.68
02:00:01 AM   4026540 260060920     98.48    720344  11663184  86489692     29.90
02:10:01 AM   4312916 259774544     98.37    720380  11678316  83834592     28.98
02:20:01 AM   5058980 259028480     98.08    720408  11624028  82876972     28.65
02:30:01 AM   4609908 259477552     98.25    720556  11541392  83871244     29.00
02:40:01 AM   5020668 259066792     98.10    720592  11574912  82887808     28.66
02:50:01 AM   5175916 258911544     98.04    720748  11619572  82725252     28.60
03:00:01 AM   4701236 259386224     98.22    720780  11687100  83421624     28.84
03:10:01 AM   4757976 259329484     98.20    721204  11648864  83298716     28.80
03:20:01 AM   4485280 259602180     98.30    721248  11719272  83299472     28.80
03:30:01 AM   4267068 259820392     98.38    721264  11794688  83683344     28.93
03:40:01 AM   4080264 260007196     98.45    721404  11856796  83863540     28.99
03:50:01 AM   4864276 259223184     98.16    721676  11975372  82735744     28.60
04:00:01 AM   4427284 259660176     98.32    721696  12056676  83450524     28.85
04:10:01 AM   4868184 259219276     98.16    721736  11863420  82860464     28.65
04:20:01 AM   4711608 259375852     98.22    721760  11877192  83205684     28.77
04:30:01 AM   4452764 259634696     98.31    721928  11945108  83515596     28.87
04:40:01 AM   4800700 259286760     98.18    722072  12015444  82681320     28.58
04:50:01 AM   4796588 259290872     98.18    722212  12075496  82703948     28.59
05:00:01 AM   4320164 259767296     98.36    722372  12164956  83390596     28.83
05:10:01 AM   3350940 260736520     98.73    722488  12120116  84525028     29.22
05:20:01 AM   4200236 259887224     98.41    722628  11965996  83510580     28.87
05:30:01 AM   4028020 260059440     98.47    722640  12019516  83720748     28.94
05:40:01 AM   3929740 260157720     98.51    722720  12069520  83632964     28.91
05:50:01 AM   2719452 261368008     98.97    723460  14408924  83745112     28.95
06:00:01 AM   1530448 262557012     99.42    723644  14943264  84618304     29.25
06:10:01 AM   2925268 261162192     98.89    605748  13363596  84792452     29.31
06:20:02 AM   3235532 260851928     98.77    605916  13811664  83516740     28.87
06:30:01 AM   3265640 260821820     98.76    606072  13848028  83385196     28.83
06:40:01 AM   2102756 261984704     99.20    606232  14745508  83638764     28.92
06:50:01 AM   2386376 261701084     99.10    606644  14821232  83118484     28.74
07:00:01 AM   5343496 258743964     97.98    186908  12019804  84375032     29.17
07:10:01 AM   5073472 259013988     98.08    219044  12597104  83579876     28.90
07:20:01 AM   5380380 258707080     97.96    241300  12600412  83107160     28.73
07:30:01 AM   5063504 259023956     98.08    253984  12653840  83373804     28.82
07:40:01 AM   8241032 255846428     96.88    269960   9772232  83072188     28.72
07:50:01 AM   8549616 255537844     96.76    278472   9853288  82646916     28.57
08:00:01 AM   8185864 255901596     96.90    287296   9938816  83179808     28.76
08:10:01 AM   7797504 256289956     97.05    295856  10029904  83464160     28.86
08:20:01 AM   8813696 255273764     96.66    302620   9930672  82081220     28.38
08:30:01 AM   8574984 255512476     96.75    309156   9880124  82557600     28.54
08:40:01 AM   8010072 256077388     96.97    314804   9912220  83241764     28.78
08:50:01 AM   8791112 255296348     96.67    319568   9980532  81787424     28.28

OEM: The number of hanging transactions are hang_trans is %

Hi all!
So, today is quickie one, just to make the links. Seems this message from OEM is not clear enough for some people, specially regarding non-specialists in Oracle: This means something is in lock in your database!

If this is the case, contact a DBA.

If you ARE a DBA, you may want to read this post about easy locating and solving locks: Solving Simple Locks Through @lock2s and @killlocker.

Also, if the session if from DBLink, is always useful to read this: Lock by DBLink – How to locate the remote session?

There is also some additional/specific material about some issues and bugs in this regard here: Tag: LOCK.

I hope it helps!
Cheers!

Oracle TPS: Evaluating Transaction per Second

Sometimes this information has some ‘myth atmosphere’… Maybe because of that Oracle doesn’t have this information very clear and it’s not the most useful metric.
But for comparison to another systems and also to performance/’throughput’ with different infrastructure/database configuration, it can be useful.

It can be seen by AWR on “Report Summary” section, on “Load Profile”, “Transactions” item:

awr_tps

But if you want to calculate it through SQL query?
And if you want to have a historic from this metric?

I found a reference for this calculation here, using v$sysstat.
It’s the only reference I found, and it on 10g documentation… It refers this metric as:

Number of Transactions = (DeltaCommits+DeltaRollbacks)/Time

It also refers as DeltaCommits and DeltaRollbacks, respectively, “user commits” and user “rollbacks”.

Where it goes a possible SQL to do that:

WITH hist_snaps
AS (SELECT instance_number,
snap_id,
round(begin_interval_time,'MI') datetime,
(  begin_interval_time + 0 - LAG (begin_interval_time + 0)
OVER (PARTITION BY dbid, instance_number ORDER BY snap_id)) * 86400 diff_time
FROM dba_hist_snapshot), hist_stats
AS (SELECT dbid,
instance_number,
snap_id,
stat_name,
VALUE - LAG (VALUE) OVER (PARTITION BY dbid,instance_number,stat_name ORDER BY snap_id)
delta_value
FROM dba_hist_sysstat
WHERE stat_name IN ('user commits', 'user rollbacks'))
SELECT datetime,
ROUND (SUM (delta_value) / 3600, 2) "Transactions/s"
FROM hist_snaps sn, hist_stats st
WHERE     st.instance_number = sn.instance_number
AND st.snap_id = sn.snap_id
AND diff_time IS NOT NULL
GROUP BY datetime
ORDER BY 1 desc;

I like to use PL/SQL Developer to see this kind of data. And it regards us to make very good charts very quickly. I try it in a small database here, just for example:

7days_tps

Jedi Master Jonathan Lewis wrote a good post about Transactions and this kind of AWR metric here.

See ya!
Matheus.