RE: Perl script excessively executing statement
Actually, we don't know that it hasn't occurred previously, it may have
happened previously, but this is the 1st time we noticed it.
There has been no DB patching recently
Only OS package updated on the day the issue occurred were curl and libcurl,
and that was 14 hours before the incident occurred.
So only change on system would be customer data.
Problem is, we are only aware of the one instance when this behavior occurred.
Ever since that one incident, the script has run without issue, running once
every 5 minutes, and executing the SQL only once, working as it should.
As suggested by Steven Lembark, I've been stepping through the script with the
perl debugger. Initially this was with the modified script containing the
additions for DBIx::Log4perl, but I was finding all the calls to log4pel adding
excessive steps making it difficult to find the DBI and DBD::Oracle calls, so I
removed the additions, and tried debugging with the original script, only to
discover the perl debugger won't step into the execute call.
So still no nearer to knowing why we experienced the strange behavior. And now
it has returned to working normally - there was only 1 execution of the script
when it misbehaved - making it difficult to know why it broke once or how to
prevent it happening again in the future. Using the debugger doesn't seem to
help at the moment because all I see in the debugger is it working the way it
is supposed to work.
All I can think of to do now, is to have debugging code in the script and hope
I have enough there so that if the incident does happen again, I have enough
info to understand what was happening at that time.
-Original Message-
From: Fennell, Brian
Sent: Wednesday, 19 February 2020 2:45 AM
To: JohnD Blackburn ; dbi-users@perl.org
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,
The part of the story that troubles me is this:
"it was working fine - nothing changed - then it broke".
It is the middle part - something must have changed.
If I were in your shoes I would be looking for the "what changed".
I had a piece of perl / Oracle code break when we upgraded the OS. When the OS
changed the version of Perl 5 changed, the version of the Oracle module had to
change along with the version of perl changing, because there were changes in
perl to that made certain "only once" internal variables part of a structure
which could be instantiated once per thread. The Oracle C code for the version
of the module which worked, relied on there only being one, with the old naming
convention. The new version of the Oracle Perl Module had a bug related to
buffering n-byte charter sets (which the OS, perl, C, Oracle Client and Oracle
Server all had to agree on in order to keep certain buffers from over flowing
and causing a seg-fault core dump. Finding the buffer overflow bug we like
trying to find a needle in a haystack - I didn't have the time to re-ramp up on
C-buffer overflow kung-fu and the free and very-not-free tools which are needed
to hunt down the bug. The version on CPAN was abandon-ware, but the few people
who wanted to adopt it couldn't get CPAN to break control of the owner - so
there were non-official forks in GIT - rebuilding from them was non-trivial. I
tried rolling back the version of the Oracle Perl Module to the one that had
been working but it was not incompatible with the new version of perl 5 which
came with the OS. Finally I had to roll back the version of perl 5, building
from source and making a second perl install on my box - then change all the
code which ran perl-scripts from perl-scripts from perl-scipts (with system and
qx) to make sure none of the legacy code "fell off" the new version of perl 5.
Then it all worked again - the n-byte character bug was not exposed, the buffer
overflow did not occur and the legacy code wen back to working, but the OS
could be upgraded (a security concern).
But - I had to ask "what changed" - then hunt down the root cause.
Because "nothing changed" is never the root cause.
Brian Fennell
-Original Message-
From: JohnD Blackburn
Sent: Tuesday, February 18, 2020 2:57 AM
To: dbi-users@perl.org
Subject: RE: Perl script excessively executing statement
After reviewing the log4perl output from DBIx when running this script I found
the following perl module being executed:
/usr/local/lib64/perl5/DBD/Oracle.pm
Which contains the following subroutine:
sub execute_for_fetch {
my ($sth, $fetch_tuple_sub, $tuple_status) = @_;
my $row_count = 0;
my $err_total = 0;
my $tuple_count="0E0";
my $tuple_batch_status;
my $dbh = $sth->{Database};
my $batch_size =($dbh->{'ora_array_chunk_size'}||= 1000);
if(defined($tuple_status)) {
RE: Perl script excessively executing statement
John,
The part of the story that troubles me is this:
"it was working fine - nothing changed - then it broke".
It is the middle part - something must have changed.
If I were in your shoes I would be looking for the "what changed".
I had a piece of perl / Oracle code break when we upgraded the OS. When the OS
changed the version of Perl 5 changed, the version of the Oracle module had to
change along with the version of perl changing, because there were changes in
perl to that made certain "only once" internal variables part of a structure
which could be instantiated once per thread. The Oracle C code for the version
of the module which worked, relied on there only being one, with the old naming
convention. The new version of the Oracle Perl Module had a bug related to
buffering n-byte charter sets (which the OS, perl, C, Oracle Client and Oracle
Server all had to agree on in order to keep certain buffers from over flowing
and causing a seg-fault core dump. Finding the buffer overflow bug we like
trying to find a needle in a haystack - I didn't have the time to re-ramp up on
C-buffer overflow kung-fu and the free and very-not-free tools which are needed
to hunt down the bug. The version on CPAN was abandon-ware, but the few people
who wanted to adopt it couldn't get CPAN to break control of the owner - so
there were non-official forks in GIT - rebuilding from them was non-trivial. I
tried rolling back the version of the Oracle Perl Module to the one that had
been working but it was not incompatible with the new version of perl 5 which
came with the OS. Finally I had to roll back the version of perl 5, building
from source and making a second perl install on my box - then change all the
code which ran perl-scripts from perl-scripts from perl-scipts (with system and
qx) to make sure none of the legacy code "fell off" the new version of perl 5.
Then it all worked again - the n-byte character bug was not exposed, the buffer
overflow did not occur and the legacy code wen back to working, but the OS
could be upgraded (a security concern).
But - I had to ask "what changed" - then hunt down the root cause.
Because "nothing changed" is never the root cause.
Brian Fennell
-Original Message-
From: JohnD Blackburn
Sent: Tuesday, February 18, 2020 2:57 AM
To: dbi-users@perl.org
Subject: RE: Perl script excessively executing statement
After reviewing the log4perl output from DBIx when running this script I found
the following perl module being executed:
/usr/local/lib64/perl5/DBD/Oracle.pm
Which contains the following subroutine:
sub execute_for_fetch {
my ($sth, $fetch_tuple_sub, $tuple_status) = @_;
my $row_count = 0;
my $err_total = 0;
my $tuple_count="0E0";
my $tuple_batch_status;
my $dbh = $sth->{Database};
my $batch_size =($dbh->{'ora_array_chunk_size'}||= 1000);
if(defined($tuple_status)) {
@$tuple_status = ();
$tuple_batch_status = [ ];
}
my $finished;
while (1) {
my @tuple_batch;
for (my $i = 0; $i < $batch_size; $i++) {
$finished = $fetch_tuple_sub->();
push @tuple_batch, [@{$finished || last}];
}
last unless @tuple_batch;
my $err_count = 0;
my $res = ora_execute_array($sth,
\@tuple_batch,
scalar(@tuple_batch),
$tuple_batch_status,
$err_count );
if (defined($res)) { #no error
$row_count += $res;
}
else {
$row_count = undef;
}
$err_total += $err_count;
$tuple_count+=@tuple_batch;
push @$tuple_status, @$tuple_batch_status
if defined($tuple_status);
last if !$finished;
}
#error check here
return $sth->set_err($DBI::stderr, "executing $tuple_count generated
$err_total errors")
if $err_total;
return wantarray
? ($tuple_count, defined $row_count ? $row_count : undef)
: $tuple_count;
}
Is that "while(1)" loop a potential contender for causing this?
-Original Message-
From: JohnD Blackburn
Sent: Tuesday, 18 February 2020 8:51 AM
To: Steven Lembark ; dbi-users@perl.org
Subject: RE: Perl script excessively executing statement
The problem is not about how well the SQL runs. It runs in less than a second,
and it should only be getting executed 12 times an hour.
What I'm trying to do is to figure out how the SQL statement got executed 1000
times more than it should have done (which brought the db to its knees for 50
minutes with nothing being able to connect). If there is something in DBI that
is automatically re-executing for some unknown reason, I need to be able
DBD::Oracle install issue on CentOS 8 missing libnsl
Just a heads up for those of you on the close-to-the-bleeding-edge. libnsl is no longer included with the standard glibc libs with CentOS (and I'm guessing also in RHEL 8, and whatever the current Fedora build is) , and the DBD::Oracle install fails during make test: Can't load '/root/.cpan/build/DBD-Oracle-1.80-1/blib/arch/auto/DBD/Oracle/Oracle.so' for module DBD::Oracle: libnsl.so.1: cannot open shared object file: No such file or directory at /usr/lib64/perl5/DynaLoader.pm line 193. at -e line 1. Compilation failed in require at -e line 1. fortunately it’s still in the repo, so yum install libnsl fixes it. -- Bruce Johnson University of Arizona College of Pharmacy Information Technology Group Institutions do not have opinions, merely customs
Re: Perl script excessively executing statement
On 18/02/2020 07:57, JohnD Blackburn wrote:
After reviewing the log4perl output from DBIx when running this script I found
the following perl module being executed:
/usr/local/lib64/perl5/DBD/Oracle.pm
Which contains the following subroutine:
sub execute_for_fetch {
my ($sth, $fetch_tuple_sub, $tuple_status) = @_;
my $row_count = 0;
my $err_total = 0;
my $tuple_count="0E0";
my $tuple_batch_status;
my $dbh = $sth->{Database};
my $batch_size =($dbh->{'ora_array_chunk_size'}||= 1000);
if(defined($tuple_status)) {
@$tuple_status = ();
$tuple_batch_status = [ ];
}
my $finished;
while (1) {
my @tuple_batch;
for (my $i = 0; $i < $batch_size; $i++) {
$finished = $fetch_tuple_sub->();
push @tuple_batch, [@{$finished || last}];
}
last unless @tuple_batch;
my $err_count = 0;
my $res = ora_execute_array($sth,
\@tuple_batch,
scalar(@tuple_batch),
$tuple_batch_status,
$err_count );
if (defined($res)) { #no error
$row_count += $res;
}
else {
$row_count = undef;
}
$err_total += $err_count;
$tuple_count+=@tuple_batch;
push @$tuple_status, @$tuple_batch_status
if defined($tuple_status);
last if !$finished;
}
#error check here
return $sth->set_err($DBI::stderr, "executing $tuple_count generated
$err_total errors")
if $err_total;
return wantarray
? ($tuple_count, defined $row_count ? $row_count : undef)
: $tuple_count;
}
Is that "while(1)" loop a potential contender for causing this?
Not unless you are using execute_array. The code you posted didn't look
like it was.
Martin
--
Martin J. Evans
Wetherby, UK
