Print Friendly, PDF & Email

 
SYMPTOMS

In an AWR report or a Statspack report, the PL/SQL lock timer wait event is in the Top Wait Events list.
The Wait Event is consuming a large part of the database time. The average wait time of the wait event is about 60 seconds (60000 ms).
A database is monitored by the Oracle Enterprise Manager Cloud Control 13c.

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     5,812          51.2
PL/SQL lock timer                                   61       3,660  60007   32.3
db file sequential read                        683,073         594      1    5.2
gc current block 2-way                         657,725         274      0    2.4
db file scattered read                          14,748         197     13    1.7
          -------------------------------------------------------------

 
 
DIAGNOSE

 
To find a culprit application use the query – standalone database or cluster database – that helps to identify the sessions with the PL/SQL lock timer wait event.

For example, details of sessions from a cluster database

INSTANCE_HOSTNAME INST_ID DB_USER PID   SID  SERIAL# CONNECTED_FROM CONNECTED_BY PORT  APPLICATION      WAITING_SEC SQL_ID        CHILD#  EXECUTIONS SQLTEXT
----------------- ------- ------- ----- ---- ------- -------------- ------------ ----- ---------------- ----------- ------------- ------- ---------- -------------------------------
db-ec-1.local           1 SYS     14325 2025   20393 db-ec-1.local  oracle       41862 JDBC Thin Client          32 g0bggfqrddc4w       0      27954 BEGIN dbms_lock.sleep(60); END;
db-ec-2.local           2 SYS     31521  324   46296 db-ec-2.local  oracle       10176 JDBC Thin Client          12 g0bggfqrddc4w       0       1412 BEGIN dbms_lock.sleep(60); END;

 
It is clearly seen from the above output that the sessions are established from the same servers (CONNECTED_FROM) as to where instances are running (INSTANCE_HOSTNAME). The sessions are established through java clients (APPLICATION) by the operating system username oracle (CONNECTED_BY). The sessions are connected to the administrative user account SYS (DB_USER). Both sessions are executing the same query with sqlid g0bggfqrddc4w (SQL_ID) and these queries are frequently executed at the database (EXECUTIONS).

 
But still, there is not enough information about the exact name of the application and its process.
The process ID of the session (PID) is useless in this case as It just says the found process is the Oracle Server Process initiated by the Listener.

For instance, the session of the first node with SID=2025 and PID=14325

oracle@db-ec-1:<ECPROD_1> ps -fe |grep 14325 |grep -v grep
oracle   14325     1  0 Aug19 ?        00:00:01 oracleECPROD_1 (LOCAL=NO)

 
But knowing the session’s port (PORT) it’s a piece of cake to find an application process. The session on the first node is connected through the port 41862

oracle@db-ec-1:<ECPROD_1> netstat -tulpan |grep :41862 | grep ESTABLISHED

(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp        0      0 10.82.130.125:1521      10.82.130.84:41862      ESTABLISHED -
tcp6       0      0 10.82.130.84:41862      10.82.130.125:1521      ESTABLISHED 12414/java

 
So, the first row is the Oracle Server Process (14325) of the established session on the first node.
The second row is the application itself that I am looking for. So its operating system process ID is 12414.

Now having infomation about the process ID it is easy to find the application details

oracle@db-ec-1:<ECPROD_1> ps -fe |grep 12414 |grep -v grep
oracle   12414 12355  0 Aug19 ?        00:04:51 /agent13c/agent_13.3.0.0.0/oracle_common/jdk/bin/java -Xmx134M -XX:MaxPermSize=160M -server -Djava.security.egd=file:///dev/./urandom -Dsun.lang.ClassLoader.allowArraySyntax=true -XX:-UseLargePages -XX:+UseLinuxPosixThreadCPUClocks -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UseCompressedOops -Dwatchdog.pid=12355 -cp /agent13c/agent_13.3.0.0.0/jdbc/lib/ojdbc7.jar:/agent13c/agent_13.3.0.0.0/ucp/lib/ucp.jar:/agent13c/agent_13.3.0.0.0/oracle_common/modules/jsch-0.1.53.jar:/agent13c/agent_13.3.0.0.0/oracle_common/modules/com.oracle.http_client.http_client_12.1.3.jar:/agent13c/agent_13.3.0.0.0/oracle_common/modules/oracle.xdk_12.1.3/xmlparserv2.jar:/agent13c/agent_13.3.0.0.0/oracle_common/modules/oracle.dms_12.1.3/dms.jar:/agent13c/agent_13.3.0.0.0/oracle_common/modules/oracle.odl_12.1.3/ojdl.jar:/agent13c/agent_13.3.0.0.0/oracle_common/modules/oracle.odl_12.1.3/ojdl2.jar:/agent13c/agent_13.3.0.0.0/lib/optic.jar:/agent13c/agent_13.3.0.0.0/sysman/jlib/log4j-core.jar:/agent13c/agent_13.3.0.0.0/jlib/gcagent_core.jar:/agent13c/agent_13.3.0.0.0/sysman/jlib/emagentSDK-intg.jar:/agent13c/agent_13.3.0.0.0/sysman/jlib/emagentSDK.jar oracle.sysman.gcagent.tmmain.TMMain

 
Thus, It’s been confirmed that the query g0bggfqrddc4w and the PL/SQL lock timer wait event are caused by the locally running agent. And the issue is directly related to the Oracle Enterprise Manager 13c.

 
 
SOLUTION

 
According to Doc ID 2366263.1 the query g0bggfqrddc4w is executed by the Agent as part of the “DB Real Time Monitoring” feature. The agent maintains the persistnet connection with the database and executes the query every single minute. This allows the agent to know immediately if the DB goes down.

The “DB Real Time Monitoring” feature is enabled only if the monitoring user has execute privilege on the DBMS_LOCK package in the target DB (eg user SYS). The privilege can be granted by the following statement
 

GRANT EXECUTE ON SYS.DBMS_LOCK TO DBSNMP;

 
If the monitoring user does not have the execute privilege on the DBMS_LOCK package then the database status will be determined by the agent only when the Response metric is collected. By default the Response metric is collected every 15 seconds.

It’s up to you to enable or to disable the “DB Real Time Monitoring” feature but using the Response metric to monitor the database status is just enough for many cases.

To eliminate the query g0bggfqrddc4w and the related PL/SQL lock timer wait event in the database do not use administrative user accounts like SYS or SYSTEM.
For the monitoring purpose use the DBSNMP user without the execute privilege on the DBMS_LOCK package (by default it hasn’t).
 

SQL> REVOKE EXECUTE ON SYS.DBMS_LOCK FROM DBSNMP;

Revoke succeeded.

 
 
REFERENCES
 
EM 12c, EM 13c: Why does Agent execute “BEGIN Dbms_lock.sleep(60)” statement Having SQL ID “g0bggfqrddc4w” in the Target Database ? (Doc ID 2366263.1)

 
 

Version  : 15:26 20.08.2020
Database : 11.2.0.4,12.1.0.1
OEM      : 13.3.0.0.0