The SQL statement is only executed once within the Perl script. There is no
additional executions of the query. The query only selects from tables. It
was the entire query that was executed according to statspack 12000 times, not
sub-components of it. So seems as if some mechanism within DBI, DBD, or Oracle
was at fault.
Here is the statement that Statspack reported the excessive executions on:
select
prog_name, dstrct_code, Start_Date, Start_Time, Runtime_Minutes,
Median_Elapsed, Std_Deviation, Count_Instances, (4*Std_Deviation+Median_Elapsed
+ 5) as THRESHOLD, UUID
from
(
with history as
( select prog_name,
dstrct_code,
round(sum(elapsed_minutes),5) as Elapsed_Minutes,
round(avg(elapsed_minutes),5) as Average_Elapsed,
round(median(elapsed_minutes),5) as Median_Elapsed,
round(stddev(elapsed_minutes),5) as Std_Deviation,
count(*) as Count_Instances
from (
select prog_name,
dstrct_code,
1440 *
(to_date(stop_date||stop_time_hhmmss,'YYYYMMDDHH24MISS') -
to_date(start_date||start_time_hhmmss,'YYYYMMDDHH24MISS')) as Elapsed_Minutes
from ellipse.msf085 History
)
group by prog_name, dstrct_code
)
select Executing.prog_name, Executing.dstrct_code, Executing.start_date,
Executing.start_time,
round((1440 * ((cast(SYSTIMESTAMP at time zone
NVL(trim(tz.district_time_zone),sessiontimezone) as date))
- to_date(Executing.start_date || Executing.start_time,
'YYYYMMDDHH24MI') ) ),5) as RUNTIME_MINUTES,
History.Median_elapsed, History.Count_Instances,
History.Std_Deviation,
Executing.UUID
from Ellipse.MSF080 Executing
inner join History on (history.dstrct_code = Executing.dstrct_code and
History.prog_name = Executing.prog_name)
inner join Ellipse.msf000_dc0002 tz on (tz.dstrct_code =
Executing.dstrct_code)
where Executing.process_Status = 'E'
)
order by 1,2,3,4,5
It is not being executed inside a loop. Only loop is a while loop calling
fetchrow_array, and there is no subsequent SQL being executed by the script
inside the loop. The version of the database and Oracle client has not been
changed. Optimizer adaptive features are disabled in this database.
I will have a look at the links you provided for DBI debug. Although this was
the only instance we know about where this query was executed excessively,
maybe it is happening more frequently than we realize and debugging might
provide some answers.
Thanks for your reply
Regards,
John
-----Original Message-----
From: Fennell, Brian <[email protected]>
Sent: Saturday, 15 February 2020 5:47 AM
To: JohnD Blackburn <[email protected]>; [email protected]
Subject: RE: Perl script excessively executing statement
CAUTION: This email originated from outside of the organization. Do not click
links or open attachments unless you recognize the sender and know the content
is safe.
John,
One way for you to execute sql thousands of times from perl is to do it in your
loop.
The other way is for the Oracle server to do it for you in its loop.
Sometimes an Oracle Upgrade will cause the Oracle Optimizer to change - this
can cause SQL that "worked fine" to start behaving differently.
A SQL join is translated to one or more nested loops by the Oracle Optimizer -
SQL is an algebraic notation but computers don't really "do" algebra, they do
nested loops.
Which table is selected first and which is second (and third and so-on). If
you have functions they may execute SQL once per row, but this may be in the
outer loop (seldom) or in the inner loop (often).
The Oracle SQL Optimizer plan can also change when the table statistics are
recalculated - which doesn't require an Oracle upgrade.
EXPLAIN PLAN is your way to see which table gets looped over in which order as
the table statistics and the Oracle optimizer are RIGHT NOW.
Some more hints:
EXPLAIN PLAN
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgrokbase.com%2Ft%2Fperl%2Fdbi-users%2F094mcz7m5w%2Fan-explain-plan-for-oracle-queries-with-placeholders&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272927190&sdata=aLJqdmPbot3GZJiLhGQ9YOfFt%2F8T75SYMMoHIDkuKe0%3D&reserved=0
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.oracle.com%2Ftechnetwork%2Fdatabase%2Fbi-datawarehousing%2Ftwp-explain-the-explain-plan-052011-393674.pdf&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272927190&sdata=ws%2Fz9T0NP3RTNB7xktNLPmn38OOwQC06dADwTU4Pyug%3D&reserved=0
DBI DEBUG
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.easysoft.com%2Fdeveloper%2Flanguages%2Fperl%2Fdbi-debugging.html&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=tiWNDpHgdFW8ewLJZIHMN5WuB5J%2FuJj57ukqMS3Noy0%3D&reserved=0
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.perlmonks.org%2Fbare%2F%3Fnode_id%3D90692&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=QfuTMTNwFD2v%2BYZnKFcLoKkKi4f27Ie0lXpejVLElPQ%3D&reserved=0
DBI-trace()
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.effectiveperlprogramming.com%2F2010%2F04%2Fuse-dbi_trace-to-follow-dbis-work%2F&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=Vv8VMU7pYUrlb8XJS9Ck%2B0ydrdH%2Bodmd94IohV2kACI%3D&reserved=0
The error you are getting may be a result of a client/server incompatibility
(if the server version changed and your client version did not) - you could try
an alternate Oracle DBD plug-in / class.
Alternate Oracle DBD plugin
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fperl5-dbi%2FDBD-Oracle&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=%2F7PccI%2FmmzMBXEgFPhYSF1E5x%2FWwytbZUiS3ZZ4dbZU%3D&reserved=0
Can be installed with cpanm using a git url (but not with cpan)
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fmetacpan.org%2Fpod%2Fcpanm&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=OIjH6YjhUXkmfmSUJRTGb4lI9NYv%2BBMjQ2qtypvS5mo%3D&reserved=0
you will need oracle C libraries to build - it won't be easy
Alternate Oracle DBD plugin - Oracle JDBC
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fmetacpan.org%2Fpod%2FJDBC&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=%2FiB4%2BwQaLKvFbXrKRapwKg7BLNA%2BB21oOn3sLgjhc7U%3D&reserved=0
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fmetacpan.org%2Fpod%2Fdistribution%2FDBD-JDBC%2FJDBC.pod%23Starting-the-server&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=BifJoH2iQEcQiDWnYFvewGEH5%2F3yofe1G%2BJ8pzStWW0%3D&reserved=0
you will need a jvm installed - and oracle's jdbc jars - it might be easier (or
not) you can get a free jvm here:
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fsdkman.io%2F&data=02%7C01%7Cjohnd.blackburn%40au.abb.com%7Ce88a55c0922e4e14f3c108d7b186aad0%7C372ee9e09ce04033a64ac07073a91ecd%7C0%7C1%7C637173064272937183&sdata=%2BpdWVMtMoTYyqbBRHpfefL8QkdX4XGQRRUQYm%2BdCuI0%3D&reserved=0
From: JohnD Blackburn <[email protected]>
Sent: Wednesday, February 12, 2020 12:56 AM
To: [email protected]
Subject: [EXTERNAL] Perl script excessively executing statement
Hi all,
I have a perl script in my monitoring system that has been working for months
without an issue.
Basically, it connects to an Oracle 12c database, prepares a statement, then it
executes the statement, then it has a while loop to process the returned rows.
So under normal conditions the statement is executed once every 5 minutes.
Now on Friday last week, it did something really strange which I cannot account
for the behaviour.
According to the DBA, the statement in the script was executed 12610 times over
a 50 minute period causing the database to become non-responsive. The DBAs
also stated that the script only connected to the database once at the
beginning of the 50 minute period. Average execution time of the statement was
0.26 seconds.
According to the log for my script, the script only executed once at the
beginning of the 50 minute period, and then after that, returned to executing
every 5 minutes.
Since that incident, the statememt in question has only executed the expected
12 times per hour.
I have yet to find a satisfactory reason the SQL statement from this perl
script executed so many times in the 50 minute period.
Script is running on an Oracle Linux 7.7 server with;
* oracle 12c client installed
* perl 5.16.3
* perl-DBI 1.627-4 ( from Oracle Linix Latest yum repository)
* perl-DBD-ODBC 1.50.-3 (from EPEL)
* DBD::Oracle 1.80 (from CPAN)
Oracle 12 database is on a remote server.
Anyone have any ideas why the SQL statement would have been executed 12000+
times in a 50minute period, when the script and its schedule should not have
executed the SQL any more frequiently than 12 times an hour?
Regards,
John
The information contained in this electronic mail transmission is intended only
for the use of the individual or entity named in this transmission. If you are
not the intended recipient of this transmission, you are hereby notified that
any disclosure, copying or distribution of the contents of this transmission is
strictly prohibited and that you should delete the contents of this
transmission from your system immediately. Any comments or statements contained
in this transmission do not necessarily reflect the views or position of Radial
or its subsidiaries and/or affiliates.
