Slow SQL in RPG Application

Hi!

I have e strange phenomenon on my machine. sometimes (every some days)
even the simplest embedded sql statements takes 100+ ms to execute. For
example getting the next value of es sequence like:

exec sql set :newid = next value for eerp.sqzb;

I attached the Jobdebuglog bellow


As you can see from the logs the query starts at 11:22:42.221170 and ends
at 11:22:42.347587
this is 120ms later


The machine specs are bekow - very very small Power S812

There is no load on the machine. its idle the whole day with only two
users working some time. there are not running significat processes which
do lots of IO.

I had similar problems and involved the IBMi Support. They told me that
this may be normal for a machine which is idle the whole day.

But reading a sequence (which has been read on the same day) cannot take
120ms in my opinion.

Can someon tell me wahts going on here and why this is sometimes so slow


greetings,
Franz

--------------
Specs: Power S812 IBMi 7.3TR5 with 32GB RAM, no VIOS, 2 x 10k Disks


Logs: ------------------------------------------
SQL7964 Completion 00 03/15/19 11:22:42.221170 QSQRUN2
QSYS *STMT QSQRUN2 QSYS *STMT
From module . . . . . . . . :
QSQFETCH
From procedure . . . . . . :
CK_DEBUG
Statement . . . . . . . . . : 24004
To module . . . . . . . . . :
QSQFETCH
To procedure . . . . . . . :
CK_DEBUG
Statement . . . . . . . . . : 24004
Message . . . . : Embedded SELECT
completed.
CPI4339 Information 00 03/15/19 11:22:42.221399 QQQSRVI1
QSYS *STMT QQQSETUP QSYS *STMT
From module . . . . . . . . : QQQAINI
From procedure . . . . . . :
GETMSGTXT
Statement . . . . . . . . . : 11261
To module . . . . . . . . . :
QQQSETUP
To procedure . . . . . . . : SETQIS
Statement . . . . . . . . . : 13389
Message . . . . : Query options
retrieved file QAQQINI in library QUSRSYS.
Recovery . . . : Query options
retrieved file QAQQINI in library QUSRSYS.
CPI434A Information 00 03/15/19 11:22:42.221475 QQQQUERY
QSYS *STMT QSQRUN3 QSYS *STMT
From module . . . . . . . . :
QQQQUERY
From procedure . . . . . . :
QQQQUERY
Statement . . . . . . . . . : 13764
To module . . . . . . . . . : QSQOPEN
To procedure . . . . . . . :
FULL_OPEN
Statement . . . . . . . . . : 40487
Message . . . . : **** Starting
optimizer debug message for query .
Cause . . . . . : The optimizer
debug messages that follow provide query
optimization information about how
the query was implemented. This message
is the first debug message for the
query and indicates the start of a set of
debug messages. Debug message
CPI434B marks the end of the debug messages
for this specific query. All the
debug messages in between this message and
CPI434B describe the overall
implementation for this query.
CPI434B Information 00 03/15/19 11:22:42.300360 QQQQUERY
QSYS *STMT QSQRUN3 QSYS *STMT
From module . . . . . . . . :
QQQQUERY
From procedure . . . . . . : CLEANUP
Statement . . . . . . . . . : 34691
To module . . . . . . . . . : QSQOPEN
To procedure . . . . . . . :
FULL_OPEN
Statement . . . . . . . . . : 40487
Message . . . . : **** Ending debug
message for query .
Cause . . . . . : This message
marks the end of the debug messages for this
specific query. All the debug
messages in between this message and CPI434A
describe the overall implementation
for the query.
SQL7912 Information 00 03/15/19 11:22:42.300414 QSQRUN3
QSYS *STMT QSQRUN2 QSYS *STMT
From module . . . . . . . . : QSQOPEN
From procedure . . . . . . :
SNDINFOMSG
Statement . . . . . . . . . : 42401
To module . . . . . . . . . :
QSQVALUE
To procedure . . . . . . . :
F_ASSIGNL
Statement . . . . . . . . . : 15996
Message . . . . : ODP created.
Cause . . . . . : An Open Data Path
(ODP) has been created. No reusable ODP
could be found. This occurs in the
following cases: -- This is the first
time the statement has been run. --
A RCLRSC has been issued since the last
run of this statement. -- The last
run of the statement caused the ODP to be
deleted. -- If this is an OPEN
statement, the last CLOSE of this cursor
caused the ODP to be deleted. --
The Application Server (AS) has been
changed by a CONNECT statement.
Recovery . . . : If a cursor is being
opened many times in an
application, it is more efficient to use a reusable
ODP, and not create an ODP every
time. This also applies to repeated runs of
INSERT, UPDATE, DELETE, and SELECT
INTO statements. If ODPs are being
created on every open, see the
close message to determine why the ODP is
being deleted.
SQL7916 Information 00 03/15/19 11:22:42.300439 QSQRUN3
QSYS *STMT QSQRUN2 QSYS *STMT
From module . . . . . . . . : QSQOPEN
From procedure . . . . . . :
SNDINFOMSG
Statement . . . . . . . . . : 42401
To module . . . . . . . . . :
QSQVALUE
To procedure . . . . . . . :
F_ASSIGNL
Statement . . . . . . . . . : 15996
Message . . . . : Blocking used for
query.
Cause . . . . . : Blocking has been
used in the implementation of this
query. SQL will retrieve a block of
records from the database manager on the
first FETCH statement. Additional
FETCH statements have to be issued by the
calling program, but they do not
require SQL to request more records, and
therefore will run faster. Recovery
. . . : SQL attempts to utilize
blocking whenever possible. In
cases where the cursor is not update
capable, and commitment control is
not active, there is a possibility that
blocking will be used.
SQL7914 Information 00 03/15/19 11:22:42.347546 QSQSBAS
QSYS *STMT QSQSBAS QSYS *STMT
From module . . . . . . . . :
QSQCLSCR
From procedure . . . . . . :
SQPSUCLS
Statement . . . . . . . . . : 6942
To module . . . . . . . . . :
QSQCLSCR
To procedure . . . . . . . :
SQCLSCSR
Statement . . . . . . . . . : 6509
Message . . . . : ODP not deleted.
Cause . . . . . : The Open Data
Path (ODP) for this statement or cursor has
not been deleted. This ODP can be
reused on a subsequent run of the
statement. This will not generate
an entry in the journal.
SQL7948 Completion 00 03/15/19 11:22:42.347587 QSQRUN2
QSYS *STMT QSQRUN2 QSYS *STMT
From module . . . . . . . . :
QSQVALUE
From procedure . . . . . . :
F_CLEANUP
Statement . . . . . . . . . : 28092
To module . . . . . . . . . :
QSQVALUE
To procedure . . . . . . . :
F_CLEANUP
Statement . . . . . . . . . : 28092
Message . . . . : SET statement
complete.
Cause . . . . . : The variable was
successfully set.