Skip to Main Content
  • Questions

  • How to detect if insert transactions in oracle db are really slow?

Breadcrumb

Question and Answer

Chris Saxon

Thanks for the question, Azu.

Asked: June 18, 2018 - 2:30 pm UTC

Last updated: December 06, 2019 - 3:01 pm UTC

Version: 11g Enterprise Edition Release 11.2.0.1.0

Viewed 10K+ times! This question is

You Asked

At work, I have an Oracle DB (11g) in which I want to detect if there's slow performance while inserting data. Here's the situation:

Some production devices send data results from tests to Server A, this server is a important server and it replicates the info to server B, which is the one that processes the data (files) to then insert it into the database with the problem, the database is in another server (Server C).

Now, the problem that I'm facing is that the data in server B is getting stuck there, a queue starts to form and it keeps growing and growing. Apparently the insertion is to slow, to give you an idea, in the Server A (which inserts data in a DB also in server A) the time to insert a single set of data goes from 133 ms to (very rarely) 2300 ms; while in server B it goes from 171 to 11900 (most likely to be above 2 seconds).

There're a lot of factors here, the capacity between Server A and Server B are also different, Server A has 96 GB of memory and server B has 32; Server A 24 CPU's, GenuineIntel, CPU MHz 1596; and Server B 16 CPU's, AutenticAMD, CPU MHz 3200. I think it could be a problem of capacity in Server B; but I'd like to rule out a problem in the database; that's why I would like to find out if the insertion of data in the DB is really slow, because when my applications connect to it to read data, it does really okay, it's not slow. Also, server B is the only one that inserts data into the DB in server C. I have no access to the insides of the applications that processes the data in Server B, and unfortunately there's almost not documentation to read.
I tried inserting a couple of rows manually (SQL Developer) from my personal computer and it worked just fine, although I understand it's not the same inserting hundreds of rows and inserting one.
Now, I'm not DBA, but I'd like to find a way to spy on the inserts and find out how long are they taking to finish. Does anyone know how I can achieve something like this?


I hope you can help me, thank you!

and Connor said...

Active session history (ASH) should be good enough to catch waits like that. Here's an example of what you could expect to see

--
-- Session 1
--
SQL> create table t ( x int primary key );

Table created.

SQL> insert into t values (100000 );

1 row created.


That uncommitted row above is important because I'm going to use it to slow down an insert test to simulate your issue. So here is my heavy insert code:

SQL> begin
  2  for i in 1 .. 200000 loop
  3    insert into t values (i);
  4    commit;
  5  end loop;
  6  end;
  7  /


Now it will churn through those 200,000 inserts very fast *until* it hits i=100,000 because it will be blocked by the uncommitted insert. After a few second, I went back to the first session and did a commit, so the my 200,000 insert loop finished.

Let's look at v$active_session_history for that time period:

SQL> select sample_time, sql_id, sql_exec_id, time_waited, event
  2  from v$active_session_history
  3  where sample_time > timestamp '2018-06-19 15:08:21'
  4  and user_id = 107
  5  order by sample_time;

SAMPLE_TIME                    SQL_ID        SQL_EXEC_ID TIME_WAITED EVENT
------------------------------ ------------- ----------- ----------- -------------------------------
19-JUN-18 03.08.22.347 PM      gqbqxgth0a4nt    16777216           0
19-JUN-18 03.08.23.347 PM      gqbqxgth0a4nt    16777216           0
19-JUN-18 03.08.24.348 PM      2n9c7yuww4dx4    17032961           0
19-JUN-18 03.08.25.348 PM      2n9c7yuww4dx4    17054907           0
19-JUN-18 03.08.26.348 PM      gqbqxgth0a4nt    16777216           0
19-JUN-18 03.08.27.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.28.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.29.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.30.349 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.31.349 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.32.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.33.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.34.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.35.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.36.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.37.347 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.38.347 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.39.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.40.347 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.41.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.42.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.43.348 PM      2n9c7yuww4dx4    17077819           0 enq: TX - row lock contention
19-JUN-18 03.08.44.349 PM      2n9c7yuww4dx4    17077819    18711197 enq: TX - row lock contention
19-JUN-18 03.08.45.350 PM      2n9c7yuww4dx4    17083622           0
19-JUN-18 03.08.46.350 PM      2n9c7yuww4dx4    17106949           0
19-JUN-18 03.08.47.350 PM      gqbqxgth0a4nt    16777216           0
19-JUN-18 03.08.48.351 PM      gqbqxgth0a4nt    16777216           0
19-JUN-18 03.08.49.351 PM      gqbqxgth0a4nt    16777216           0


The combination of SQL_ID/SQL_EXEC_ID is an instance of an insert statement. You can see we don't catch *all* 200,000 thousand, because ASH only samples active sessions once per second. But you can the *problem* insert very clearly (sql_exec_id=17077819). Each row = one second, so we can see that it was stuck on a TX lock for about 18 seconds.

So if you have any single inserts taking more than 1 second, they should stand out in your ASH data.

Rating

  (4 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

And this time waited relates to ?

A reader, June 20, 2018 - 7:48 am UTC

Hi,
am I correct saying that time_waited column tells us about this 18 second delay as well by showing value 18711197 which is supposed to be in microseconds ?
Or is it a coincidence?
Regards.
G

Connor McDonald
June 22, 2018 - 2:25 am UTC

Nope, thats right - it was around 18 seconds.

Workarround

A reader, June 22, 2018 - 5:03 am UTC

Does differred constraint reduce the impact? what infra workarounds are to consider?
Connor McDonald
June 24, 2018 - 10:36 am UTC

I think you're misinterpreting my answer. I gave you an *example* of a slow insert, and how to track it with ASH.

The *cause* of the slowness could be *anything* - you need to find out what it is first, before what the considering potential solutions could be.

No I did understand

A reader, June 25, 2018 - 5:46 am UTC

Connor I did perfectly understand and interpret t
Your example. It was about a contention on uncommitted dml. And my question is still for this particular case. So suppose session 1 is inserting that table and the constraint is DIFFERRED , still I got same behavior when session2 also insert? and what workaround could be to reduce the contention and waits?
Connor McDonald
June 25, 2018 - 9:33 am UTC

Yes, you'll still block. Deferrable is not about cross session, but more that the constraint can be temporarily 'broken' in a session.

create table t ( x int );
create index ix on t ( x ) ;
alter table t add constraint pk primary key (x) deferrable initially deferred;
set constraints pk deferred;
insert into t values (100000 );


Try the last 2 lines in 2 sessions and you'll see one block

Sequence ID as PK

Subrat, December 05, 2019 - 7:25 pm UTC

Hi Conor,

In my case, we are using a sequence ID column as PK for a table and that table is used heavily as part of a high transactional webservice call.

As per my understanding, the database should manage the sequence value generation internally, but still can it create the similar issue, if I have a 10 TPS web service call which invokes a procedure with an insert to this table with a sequence ID as PK
Chris Saxon
December 06, 2019 - 3:01 pm UTC

What exactly is the issue you see? TX - row lock contention? Are you sure it's on the sequence assigned PK and not some other unique constraint?
more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.