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