Home » RDBMS Server » Performance Tuning » Different way of execute
| Different way of execute [message #64956] |
Wed, 17 March 2004 21:11  |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
Hello folks!
I have a one interest problem. I my database is excessive 'log file sync' (25-35%) waits. But this is only day, at night this wait is very low. I am traced some sessions night and day and have observe some difference in the mode of appearances of this wait. At day this wait appear after 'FETCH' operation but at night after 'EXEC' operation. How possible to interpret this difference? At night most of user are locked and batch oprations are performed(and some users performe read-only operations).
|
|
|
|
| Re: Different way of execute [message #64965 is a reply to message #64956] |
Thu, 18 March 2004 04:47  |
Thiru
Messages: 1089
Registered: May 2002
|
Senior Member |
|
|
Log file sync waits happen on LGWR writes(and not on reads). I do not know how you are tracing or interpreting the waits. Are you getting this on v$system_event, v$session_event ? or trace files ?
They usually happen on commits and rollbacks,when the server process has posted LGWR to flush the redo entries from the log_buffer into the online redolog files and waits for it ,to complete.
Possible remedies are
i) Reduce unnecessary commits. Batch the operations and reduce the frequency of commits.
ii) Use NOLOGGGING if possible , to minimize redo generation.
iii) Use Raw devices/forcedirectIO ,if possible for online redolog files
-Thiru
|
|
|
|
| Re: Different way of execute [message #64973 is a reply to message #64965] |
Sun, 21 March 2004 22:07 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
Here are a example of this difference(from trace files of event 10046 level 8):
This is the first query
=====================
PARSING IN CURSOR #3 len=247 dep=0 uid=218 oct=3 lid=420 tim=568738369 hv=3405152917 ad='b5a980dc'
Fisrt query
END OF STMT
PARSE #3:c=1,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=568738369
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=5,mis=0,r=1,dep=1,og=3,tim=568738369
EXEC #1:c=0,e=0,p=0,cr=0,cu=3,mis=0,r=1,dep=1,og=3,tim=568738370
EXEC #3:c=0,e=1,p=0,cr=0,cu=9,mis=0,r=0,dep=0,og=3,tim=568738370
WAIT #3: nam='log file sync' ela= 0 p1=195 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='db file sequential read' ela= 1 p1=184 p2=49044 p3=1
WAIT #3: nam='db file sequential read' ela= 2 p1=173 p2=19328 p3=1
WAIT #3: nam='db file sequential read' ela= 1 p1=174 p2=102087 p3=1
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #3:c=1,e=4,p=3,cr=8,cu=0,mis=0,r=1,dep=0,og=3,tim=568738374
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 9 p1=1413697536 p2=1 p3=0
=====================
This is the second query
=====================
PARSING IN CURSOR #3 len=58 dep=0 uid=218 oct=3 lid=313 tim=562501826 hv=4135805257 ad='b286c034'
Second query
END OF STMT
PARSE #3:c=1,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,tim=562501826
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #1:c=0,e=1,p=0,cr=0,cu=6,mis=0,r=1,dep=1,og=3,tim=562501827
EXEC #3:c=0,e=1,p=0,cr=0,cu=7,mis=0,r=0,dep=0,og=3,tim=562501827
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #3:c=0,e=0,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=3,tim=562501827
WAIT #3: nam='log file sync' ela= 1 p1=287 p2=0 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=562501828
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1 p3=0
STAT #3 id=1 cnt=1 pid=0 pos=0 obj=17634 op='TABLE ACCESS BY INDEX ROWID SUMCON '
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=17908 op='INDEX UNIQUE SCAN '
=====================
A wait 'log file sync' occur in trace, where are first query forever after a EXEC #1,EXEC #3 but in trace where are second query after EXEC #1,EXEC #3 and FETCH #3. I understand that this wait occur when log entries from process are posted to log buffer and at this time LGWR are writing a contents of log buffer to log files and process must to wait but i don't understand why this wait event occur at different level of processing of query.
|
|
|
|
|
|
| Re: Different way of execute [message #64982 is a reply to message #64976] |
Mon, 22 March 2004 22:07 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
I don't understand to you. Where are thes fetches?
Please copy my trace output and show with arrows where are the fisrt fetch, where are the second and where are really happen this wait. And other question: In documentation are write that this waitevent must occur when issue a commit(XCTEND marker in trace files) but in my trace this event occur(especially when are large amount of work) almost in every query - for that me such punishment???
|
|
|
|
| Re: Different way of execute [message #64983 is a reply to message #64982] |
Wed, 24 March 2004 05:22 |
Thiru
Messages: 1089
Registered: May 2002
|
Senior Member |
|
|
Look at the trace file carefully .
1st query:
EXEC #3:c=0,e=1,p=0,cr=0,cu=9,mis=0,r=0,dep=0,og=3,<B>tim=568738370</B>
<B>WAIT #3: nam='log file sync' ela= 0 p1=195 p2=0 p3=0</B>
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='db file sequential read' ela= 1 p1=184 p2=49044 p3=1
WAIT #3: nam='db file sequential read' ela= 2 p1=173 p2=19328 p3=1
WAIT #3: nam='db file sequential read' ela= 1 p1=174 p2=102087 p3=1
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
<B>FETCH #3:c=1,e=4,p=3,cr=8,cu=0,mis=0,r=1,dep=0,og=3,tim=568738374</B>
-- 2nd query
FETCH #3:c=0,e=0,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=3,<B>tim=562501827
WAIT #3: nam='log file sync' ela= 1 p1=287 p2=0 p3=0</B>
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
<B>FETCH #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=562501828</B>
|
|
|
|
| Re: Different way of execute [message #64984 is a reply to message #64983] |
Wed, 24 March 2004 05:48 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
|
Yes, of course, Thiru you are right - in both traces are and waits and fetches. BUT in first query at first are 'FETCH' and AFTER THAT occur waitevent 'log file sync'. In second query first are waitevent and after this waitevent are 'FETCH'. This is the principal problem - at night and day are running different queries but they are common sign - all queries that are running day ALWAYS have at first waitevent 'log file sync' and after that 'FETCH' and all queries that running night make contrar. I have a expression that from some point database start to procede with all queries on other kind.
|
|
|
|
| Re: Different way of execute [message #64987 is a reply to message #64984] |
Wed, 24 March 2004 09:10 |
Thiru
Messages: 1089
Registered: May 2002
|
Senior Member |
|
|
Anatol,
the waits that appear before the FETCH in the trace file, actually 'happen during' the FETCH call and not 'before' the FETCH. Thats the reason I highlighted time information also.
for eg)
EXEC #3:c=0,e=1,p=0,cr=0,cu=9,mis=0,r=0,dep=0,og=3,tim=568738370
WAIT #3: nam='log file sync' ela= 0 p1=195 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #3: nam='db file sequential read' ela= 1 p1=184 p2=49044 p3=1
WAIT #3: nam='db file sequential read' ela= 2 p1=173 p2=19328 p3=1
WAIT #3: nam='db file sequential read' ela= 1 p1=174 p2=102087 p3=1
WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #3:c=1,e=4,p=3,cr=8,cu=0,mis=0,r=1,dep=0,og=
3,tim=568738374
Here, the EXECUTE call completed by tim=568738370.
This is then followed by a wait on log_file_sync which consumed 0 sec, followed by couple of Sqlnet waits consuming 0 seconds and then 3 db file sequential single block reads consuming a total of 4 micro seconds "during" the FETCH. The FETCH call completed by tim=568738374 , which is the same as
568738370 + 4(the waits). Those 3 waits that consumed some time happened during the FETCH.
-Thiru
|
|
|
|
| Re: Different way of execute [message #64990 is a reply to message #64987] |
Wed, 24 March 2004 20:00 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
|
Do you want to say that expression tim=568738374 seem that event has ended at this time(not started)? Then this seem that in first query 'log file sync' are happened during a first fetch, but in second query during a second fetch - yet one problem that I could not understand. Generally, 'log file sync' must occur when session commits(XCTEND marker in trace files), but in my database this event occur almost in every query. I understand that this is possible problem in tuning of redo logs but at fist I want to clarify with this inexactness.
|
|
|
|
| Re: Different way of execute [message #64991 is a reply to message #64990] |
Thu, 25 March 2004 04:18 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
|
Yet one interesting thing. I am started a number of queries day and at night to see their traces. I result, in trace of some queries day there was at one fetch in plus(at night for example 2 execs, afterwards wait 'log file sync', afterwards one fetch but day 2 execs, afterwards one fetch, afterwards wait 'log file sync', afterwards yest one fetch ). Why this difference occur, I don't understand.
|
|
|
|
| Re: Different way of execute [message #64993 is a reply to message #64990] |
Thu, 25 March 2004 09:43 |
Thiru
Messages: 1089
Registered: May 2002
|
Senior Member |
|
|
Yes, thats right.
Regarding the log file sync , I believe you have another thread open and I wanted you to present a test case and also perform a full table scan on the tables touched by the queries and run the application again to see if there are these waits still.
|
|
|
|
| Re: Different way of execute [message #64994 is a reply to message #64991] |
Thu, 25 March 2004 09:47 |
Thiru
Messages: 1089
Registered: May 2002
|
Senior Member |
|
|
|
I cannot answer why there is a difference until I know in detail about your environment,applications,statistics gathering etc etc.. Maybe you could query Oracle support.
|
|
|
|
|
|
| Re: Different way of execute [message #64996 is a reply to message #64995] |
Fri, 26 March 2004 01:52 |
Thiru
Messages: 1089
Registered: May 2002
|
Senior Member |
|
|
You must be kidding. Did I say it was tough!?
Paid Oracle support can collect all the information required and spend time with you...
BTW,your welcome ;-)
|
|
|
|
| Re: Different way of execute [message #64999 is a reply to message #64996] |
Fri, 26 March 2004 03:05 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
|
All is good. I am thinking that this is really problem for support. Possible taht here even is no problem - only need a good explanation. I understand that this wait in general is problem of log files and of log_buffer but at first, before tuning them, I want to clarify with way of execute of queries - possible that here must be important part of resolving problem.
|
|
|
|
| Re: Different way of execute [message #65000 is a reply to message #64999] |
Fri, 26 March 2004 05:38 |
Anatol Ciolac
Messages: 113
Registered: December 2003
|
Senior Member |
|
|
|
Yet one interest thing that I cannot explain. I am scanned all waits that occur in my system every 5 minutes and am observed that when volume of waits log_file_sync is big(>1/5 of all time), quotient log_file_sync/log_file_parallel_write ~ 3.7(possible 3.7 or 3.6 on different times) . When system are not so busy this is not correct(quotient can be very big or very small). I know that this need to make writes by LGWR to log files much faster, but WHY this quotent occur? What can mean this?
|
|
|
|
Goto Forum:
Current Time: Fri Apr 19 06:35:21 CDT 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
