The timestamp on each line is when that event STARTED. To get duration you have to subtract that time from the next event.
In this case the SQL statement started running at line 02 (08:25:23.5178) The SQL finished at line 03 (08:25:24.6918) So the SQL took 1.174 secs. Note that since the next line after the COMMIT is the finish of the API line, the difference there ( line 04 minus line 03 ) will include both the commit time AND the rest of the API call time. So the line by line durations are: API start -- .0014 ( Line 02 minus Line 01 ) Select -- 1.174 ( Line 03 minus Line 02 ) Commit & API Finish -- 0.112 ( Line 04 minus Line 03 ) The total duration of the API call can be found by API finish ( -GLEWF ) minus API start ( +GLEWF ). ( Line 04 minus Line 01 ) 1.2874 seconds in this case That duration matches up with sum of the other durations: 1.2874 = .0014 + 1.174 + 0.112 This method should work across all ARS versions, although it is simplified to ignore multiple threads and the possibility of actions being intertwined with others. Juan Ingles On Fri, Apr 16, 2010 at 8:54 AM, Grooms, Frederick W <[email protected]> wrote: > > Just looking at your example below > > Line03 - Line02 would be the SQL to the database > > Line04 - Line01 would be the API call wrapper around the SQL call > > Fred > > -----Original Message----- > From: Action Request System discussion list(ARSList) > [mailto:[email protected]] On Behalf Of Ben Chernys > Sent: Friday, April 16, 2010 9:35 AM > To: [email protected] > Subject: Re: Interpreting ARS server SQL logs > > I seem to recall that you may be right. It may be a new ARS feature (since > 5x). I doubt that I have any 5.x logs around any more. > > In effect that means you cannot tell the duration of the SQL call. You can > probably "come close" by using any next line in the log - but you have no > idea how much time the intervening ARS server code took or even if there > were any semaphore waits involved. > > Misi (bcc)? Am I right here? > > There's a bunch of better stuff you can do in Oracle but I am not an Oracle > guy. Axton (bcc)? > > Cheers > Ben > > -----Original Message----- > From: Action Request System discussion list(ARSList) > [mailto:[email protected]] On Behalf Of L G Robinson > Sent: April 16, 2010 3:41 PM > To: [email protected] > Subject: Re: Interpreting ARS server SQL logs > > Hi Ben, > > Nope... I did not edit out any lines, just the actual text of the SQL Select > statement. > My logs don't seem to have any "OK's in them. > > Thanks. > Larry > > On Apr 16, 2010, at 9:27 AM, Ben Chernys wrote: > > > For SQL logs ONLY (I presume you edited your sample log and left out the > > SQL OK) > > > > You should have had an OK immediately following every SQL Log entry > > > > Then, OK - SQL when they follow each other (and are the same thread id > > of-course) > > > > > > Cheers > > Ben Chernys > > > > Senior Software Architect > > Software Tool House Inc. > > > > Canada / Deutschland / Germany > > Mobile: +49 171 380 2329 GMT + 1 + [ DST ] > > Email: [email protected] > > Web: www.softwaretoolhouse.com > > > > Check out Software Tool House's free Diary Editor. > > > > Meta-Update, our premium ARS Data tool, lets you automate your > > imports, migrations, in no time at all, without programming, without > > staging forms, without merge workflow. > > http://www.softwaretoolhouse.com/ > > > > > > > > -----Original Message----- > > From: Action Request System discussion list(ARSList) > > [mailto:[email protected]] On Behalf Of L G Robinson > > Sent: April 16, 2010 3:04 PM > > To: [email protected] > > Subject: Interpreting ARS server SQL logs > > > > Hi Folks, > > > > I have a question about interpreting ARS server SQL logs. I am in the > > process of migrating from a Sybase database server to an Oracle server and > I > > am trying to evaluate the performance of the Oracle server. I have turned > on > > API and SQL logs and have them both written to a combined log file. When I > > complete a typical search using the Windows User tool, the following log > > entries are written: > > > > 01 /* Wed Apr 14 2010 08:25:23.5164 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 02 /* Wed Apr 14 2010 08:25:23.5178 */ SELECT ... > > 03 /* Wed Apr 14 2010 08:25:24.6918 */ COMMIT WORK > > 04 /* Wed Apr 14 2010 08:25:24.8038 */ -GLEWF OK > > 05 /* Wed Apr 14 2010 08:25:24.8097 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 06 /* Wed Apr 14 2010 08:25:24.8935 */ -GLEWF OK > > 07 /* Wed Apr 14 2010 08:25:24.8992 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 08 /* Wed Apr 14 2010 08:25:24.9841 */ -GLEWF OK > > 09 /* Wed Apr 14 2010 08:25:24.9896 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 10 /* Wed Apr 14 2010 08:25:25.0660 */ -GLEWF OK > > 11 /* Wed Apr 14 2010 08:25:25.0716 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 12 /* Wed Apr 14 2010 08:25:25.1086 */ -GLEWF OK > > 13 /* Wed Apr 14 2010 08:25:25.1146 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 14 /* Wed Apr 14 2010 08:25:25.1492 */ -GLEWF OK > > 15 /* Wed Apr 14 2010 08:25:25.1545 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 16 /* Wed Apr 14 2010 08:25:25.1810 */ -GLEWF OK > > 17 /* Wed Apr 14 2010 08:25:25.1864 */ +GLEWF ARGetListEntryWithFields -- > > schema X-Calls > > 18 /* Wed Apr 14 2010 08:25:25.1967 */ -GLEWF OK > > > > My questions is: Which times constitute the exact time that it took the > > database server to complete the select? > > > > For this particular query, 825 rows were returned. > > > > I have numbered the lines so that we can say something like: > > > > line04-line02 = whatever... > > > > Config: > > > > ARS 5.01.02 patch 1313 / Solaris 8 > > Oracle 10.2.0.4 > > > > Thanks. > > Larry > > > > Larry Robinson [email protected] > > Office of Information Technology > > NC State University 919-515-5432 Voice > > Raleigh, NC 27695-7109 919-513-0877 FAX > > _______________________________________________________________________________ > UNSUBSCRIBE or access ARSlist Archives at www.arslist.org > attend wwrug10 www.wwrug.com ARSlist: "Where the Answers Are" _______________________________________________________________________________ UNSUBSCRIBE or access ARSlist Archives at www.arslist.org attend wwrug10 www.wwrug.com ARSlist: "Where the Answers Are"
