Home » RDBMS Server » Performance Tuning » Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) (Oracle 10gR2 on AIX 6.1)
Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518706] Fri, 05 August 2011 09:22 Go to next message
eclipsis
Messages: 14
Registered: May 2011
Junior Member
Hello,

In our system, we have a PL/SQL process which runs to move data from a source table to a destination table. During the move, many validations and several calculations are performed. These validations and calculations mostly use smallish look-up tables. They either lookup a value based on key fields, or do a count to make sure a value is valid. I have checked the execution plan for these queries and they are all good. Most validation make use of only the index and don't even need to touch the data itself. All of the lookups/calculations also make use of the index.

We have 1000 partitions in the source and destination table. The above PL/SQL process takes the partition name as a parameter and processes the corresponding data. We run 30 of these jobs in parallel.

When I monitor these sessions, I see a significant amount of wait time between two wait events - "cursor: pin S wait on X" and "latch: cache buffers chains". I am focusing on the first as it has more time than the second.

Below is an example of one of the calculations. This is the SQL_TEXT from V$SQL:

SELECT col_name 
FROM LDS_TABLE_NAME 
WHERE key1 = SUBSTR (:B4 , 1, 3) 
AND key2 = SUBSTR (:B3 , 1, 3) 
AND key3 = :B2 
AND :B1 BETWEEN EFF_DT AND DISC_DT


The query itself is not a problem. The plan is good (using index) and execution time is very good. But when 30 are running together, we start to see issues. As the processes are running, I can watch v$sql and see concurrency wait time increase as well as parses.

   FETCHES EXECUTIONS END_OF_FETCH_COUNT PARSE_CALLS BUFFER_GETS CONCURRENCY_WAIT_TIME USER_IO_WAIT_TIME   CPU_TIME
---------- ---------- ------------------ ----------- ----------- --------------------- ----------------- ----------
   2112817    2112499            2112850         102    29784490               1507725          38037686  439643287


And run again about 60 seconds later I see

   FETCHES EXECUTIONS END_OF_FETCH_COUNT PARSE_CALLS BUFFER_GETS CONCURRENCY_WAIT_TIME USER_IO_WAIT_TIME   CPU_TIME
---------- ---------- ------------------ ----------- ----------- --------------------- ----------------- ----------
   2277899    2277586            2277934         108    32105322               1607383          39232922  468924597


All the while, the resource utilization is very low, making this seem like a huge bottleneck. I think it comes down to the parsing - parsing causes one session to put a lock while the others wait. So the question is, why is this statement being parsed each time?

Any tips or suggestions are greatly appreciated!
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518707 is a reply to message #518706] Fri, 05 August 2011 09:46 Go to previous messageGo to next message
BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal
Senior Member
IMO, you suffer from Compulsive Tuning Disorder

>CONCURRENCY_WAIT_TIME NUMBER Concurrency wait time (in microseconds)
CONCURRENCY_WAIT_TIME increased about 0.1 seconds in 60 second;
I seriously doubt you'd notice the difference if CONCURRENCY_WAIT_TIME went to ZERO!

a WHOPPING SIX parses were done
so where is elapsed time really being spent?
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518709 is a reply to message #518707] Fri, 05 August 2011 09:59 Go to previous messageGo to next message
eclipsis
Messages: 14
Registered: May 2011
Junior Member
Do I want things to run fast and efficient? Yes. I'm also trying to understand how Oracle works.

This is only 1 of maybe 40 or so calculations and validations. These processes are running much slower than I think they should, and are not using any resources. If I increase the number of threads running in an attempt to consume more (disk i/o, memory, etc.) the concurrency issue is even greater.

Here is another snapshop:

EXECUTIONS END_OF_FETCH_COUNT PARSE_CALLS BUFFER_GETS CONCURRENCY_WAIT_TIME USER_IO_WAIT_TIME   CPU_TIME
---------- ------------------ ----------- ----------- --------------------- ----------------- ----------
  12524058           12527758         397   176589426              10118043         131399840 1647703146


I guess I don't understand why this simple lookup query is being parsed over and over again.

Some research has led me to http://blog.tanelpoder.com/2010/04/21/cursor-pin-s-waits-sporadic-cpu-spikes-and-systematic-troubleshooting/ I do notice high CPU usage while this process is running.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518710 is a reply to message #518709] Fri, 05 August 2011 10:14 Go to previous messageGo to next message
BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal
Senior Member
http://momendba.blogspot.com/2007/06/cursor-pin-s-wait-on-x-wait-event-in.html
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518711 is a reply to message #518710] Fri, 05 August 2011 10:20 Go to previous messageGo to next message
eclipsis
Messages: 14
Registered: May 2011
Junior Member
There are not stats running. The PARSE_CALLS count continues to increase. Is this causing the exclusive lock? I'm not sure why its being parsed over and over - statement is not changing and bind variables are being used.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518718 is a reply to message #518711] Fri, 05 August 2011 11:12 Go to previous messageGo to next message
eclipsis
Messages: 14
Registered: May 2011
Junior Member
It seems like most of these are soft parses. The lookup and calculations are performed over and over for each individual record.

So my new question is, does this soft parse cause an exclusive lock on this shared sql? And if so, what's the best way to be doing these lookups and calculations to avoid locking this very quick sql statements? Seems like multiple sessions should be able to perform the same lookup at the same time.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518719 is a reply to message #518718] Fri, 05 August 2011 11:15 Go to previous messageGo to next message
BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal
Senior Member
what clues exist within AWR/STATSPACK report during 15 minutes of these parallel runs?
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518739 is a reply to message #518719] Fri, 05 August 2011 17:00 Go to previous messageGo to next message
cookiemonster
Messages: 13958
Registered: September 2008
Location: Rainy Manchester
Senior Member
Number of executions between last 2 snaps = 12524058 - 2277586 = 10,246,472
Number of parses betweem last 2 snaps = 397 - 108 = 289
Number of execs per parse = 10246472 / 289 = 35455

You're hardly doing any parsing what so ever. Is there any evidence to prove that that's where the time is being spent?
Why don't you trace the session? It'll be more informative than what you're looking at.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518752 is a reply to message #518739] Sat, 06 August 2011 01:49 Go to previous messageGo to next message
John Watson
Messages: 8960
Registered: January 2010
Location: Global Village
Senior Member
Like your other responders, I think you may be looking at the wrong thing. You said Quote:
I see a significant amount of wait time between two wait events - "cursor: pin S wait on X" and "latch: cache buffers chains".
The first is to do with mutexes, I can't make any suggestions there, but the cache buffers chains latch problem may be fixable.
Have you looked at bug 5918642 ?
There are also the parameters _db_block_hash_buckets and _db_block_hash_latches that you might want to research.
Or re-write your code to store the table in a variable, so each session scans it only once.

Any good?

Finally, can you post a statspack or AWR report, to show the evidence of the problem?
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518754 is a reply to message #518752] Sat, 06 August 2011 03:11 Go to previous messageGo to next message
LNossov
Messages: 318
Registered: July 2011
Location: Germany
Senior Member
Hello,

1. the bug 5918642 deals mainly with the other latch (simulator lru latch),
2. waits on "latch: cache buffers chains" causes the 30 processes, that access the same blocks in buffer cache,
3. defaults of "_" parameters, you mentioned, are in 10g high enough.

The problematic sql
- consumes more than 30 min. CPU,
- waits about 2 min. on io,
- waits on some concurrent event (possibly on latch) about 10 sec.

I think, it is clear, what you have to tune firstly.

I'm not sure, that just this sql causes a bad performance. As cookiemonster already suggested, eclipsis has to trace his process with event 10046 level 8 and upload the trace file.

Regards
Leonid

[Updated on: Sat, 06 August 2011 03:24]

Report message to a moderator

Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518788 is a reply to message #518754] Sat, 06 August 2011 17:51 Go to previous messageGo to next message
cookiemonster
Messages: 13958
Registered: September 2008
Location: Rainy Manchester
Senior Member
Also:
concurrency wait time between last 2 snaps = 10118043 - 1607383 = 8510660 microseconds = 8.5 seconds.
For 10,246,472 executions.
These numbers you're worrying about are all tiny.
Look at statspack/awr and run a trace if you think there's a problem with the process.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #518953 is a reply to message #518706] Mon, 08 August 2011 09:10 Go to previous messageGo to next message
BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal
Senior Member
When you start with the wrong question, no matter how good an answer you get, it won't matter very much.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519003 is a reply to message #518953] Mon, 08 August 2011 16:37 Go to previous messageGo to next message
eclipsis
Messages: 14
Registered: May 2011
Junior Member
I'm new to Oracle tuning and may not know exactly what I'm looking for or at, that is why I reached out for help. I do appreciate all of the responses and help. I will upload some concise AWR the next time the process runs. The DBA currently has the interval set at 60 minutes.

The question now is simple: Is shared SQL locked when a new session does a soft parse?

These seems odd if it is the case. Say I have 1000 threads all doing a lookup - they must all execute serially even if its a simple select from a table with only 3 records in it?
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519060 is a reply to message #519003] Tue, 09 August 2011 03:27 Go to previous messageGo to next message
John Watson
Messages: 8960
Registered: January 2010
Location: Global Village
Senior Member
In a ideal world, a statement is hard parsed once, and then soft parsed once per session that runs the statement. From then on, each session will have an open cursor pointing to the memory location in the SGA of the cursor handle. So no more parsing. That is what you are seeing. Or rather, not seeing: because there really isn't any parsing happening.

[update: typo, handling for handle]

[Updated on: Tue, 09 August 2011 03:28]

Report message to a moderator

Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519062 is a reply to message #519003] Tue, 09 August 2011 03:35 Go to previous messageGo to next message
John Watson
Messages: 8960
Registered: January 2010
Location: Global Village
Senior Member
With regard to the AWR report, you can generate it now, no need to wait. Run the $ORACLE_HOME/rdbms/admin/awrrpt.sql script, and you'll be prompted to choose the days you are interested in, then the available snapshots (by default, every hour.) Choose two snapshots that bracket a time when this process running, generate the report, and post it here. Bertter generate both the html and the txt version.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519081 is a reply to message #519062] Tue, 09 August 2011 05:46 Go to previous messageGo to next message
LNossov
Messages: 318
Registered: July 2011
Location: Germany
Senior Member
I think, that 10046 trace is more helpful than an awr report.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519082 is a reply to message #519060] Tue, 09 August 2011 05:53 Go to previous messageGo to next message
LNossov
Messages: 318
Registered: July 2011
Location: Germany
Senior Member
The best solution for parsing is using of session cached cursors, where a cursor will be used again and again without a soft parsing at all.

Apropos parse_calls in v$sql are soft parse calls. A hard parse call causes a creation of a new child cursor (a new item in v$sql).
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519088 is a reply to message #519082] Tue, 09 August 2011 06:29 Go to previous messageGo to next message
cookiemonster
Messages: 13958
Registered: September 2008
Location: Rainy Manchester
Senior Member
Considering the numbers we have so far I don't believe parsing is an issue here.
Re: Simple SQL with High Concurrency Wait Time (cursor: pin S wait on X) [message #519089 is a reply to message #519088] Tue, 09 August 2011 06:46 Go to previous message
LNossov
Messages: 318
Registered: July 2011
Location: Germany
Senior Member
Yes, neither parsing nor latch waits cause performance problem with this sql.
Previous Topic: Application slow
Next Topic: SGA_MAX_SIZE to more than 2G?
Goto Forum:
  


Current Time: Sun Nov 24 21:32:24 CST 2024