Welcome, Guest
Username: Password: Remember me

TOPIC: uafwc ? what is happening?

uafwc ? what is happening? 1 year 6 months ago #387

At the moment I am digging is some performance issues and normally tracing is a great help. Now I have an issue where mrls reports a time and mrskew misses almost half of that time.

For example:
EXEC #18446744071467885488:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=1028580536,tim=2778384272289
FETCH #18446744071467885488:c=0,e=43,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=4,plh=1028580536,tim=2778384272403
CLOSE #18446744071467885488:c=0,e=29,dep=2,type=3,tim=2778384272499

*** 2013-06-20 15:15:26.677
CLOSE #18446744071527996664:c=0,e=17,dep=1,type=0,tim=2778405777083
=====================
PARSING IN CURSOR #18446744071527996664 len=612 dep=1 uid=2507 oct=3 lid=2507 tim=2778405778091 hv=2716993015 ad='5e5660c00' sqlid='8s1cwwuhz41gr'
/* SQL Analyze(3151,0) */ /* RWE */ select parameter_id
, optional, internal_search_condition, r_owner, r_table_name
, r_column_name, prequery_rows, computed
, r_descriptor_column_name, parameter_name
, c.constraint_id constraint_id, c.name name
, display_sequence
, gui_refetch
from
"SYSJCS".rs_script_constraints c, "SYSJCS".rs_script_constraint_columns cc
where
c.script_owner=cc.script_owner and c.script_name=cc.script_name
and cc.constraint_id (+) = c.constraint_id
and c.script_owner=:owner and c.script_name=:name and cc.parameter_id<1000
order by
c.name, cc.position
END OF STMT
PARSE #18446744071527996664:c=0,e=634,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=2778405778088
PARSE #18446744071467885488:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=1028580536,tim=2778405815978

between tim=2778384272499
and tim=2778405777083
difference about 21,5s.

What is happening here? It looks like Oracle does not trace a few things here ....
BTW: Solaris 10 non global zone
Oracle 11.2.0.3.6 EE
(same with 11.2.0.3.2)

Do you have a clue for me?
(I DE-personalized the trc file)

Attachment OURS_ora_4599_01.gz not found

Attachments:
The administrator has disabled public write access.

Re:uafwc ? what is happening? 1 year 6 months ago #388

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 106
  • Thank you received: 2
The reason mrskew and mrls are reporting different accounted-for times is that they use vastly different methods for accounting for time in a trace file.

The method used by mrls is to, for the most part, calculate R=(t1-t0)/1,000,000; where t1 is the ending tim from the last dbcall in the trace file and t0 is the beginning tim of the "earliest" dbcall in the trace file. It then reports R as the maximum number of seconds that **could be** found inside the trace file if every line were to be inspected.

The method used by mrskew is to inspect every line in the file to see how much time it finds.

What you have pointed to looks like lines 12809 through 12812, which demonstrate an interval of 21.504567 seconds=((2778405777083-17)-2778384272499)/1,000,000 when no trace data are emitted.

My initial conclusion is that it is time spent consuming only CPU at recursive depth 0 or 1.

It appears as though you have a PL/SQL block that is getting SQL Analyze output repeatedly for SQL statement 8s1cwwuhz41gr and each time it is finished there's a significant gap of no trace data before emitting the cursor close line. Sometimes the gap is really wide and other times it's not so wide.

Without trying to reproduce the problem, I would say that it's most likely CPU time consumed trying analyze the statement and I'm not at all surprised that such activity is not traced. After all, such activity probably won't be executing SQL statements. Oracle is not nearly as pedantic about being a pure RDBMS as it used to be 20+ years ago.
The administrator has disabled public write access.

Re:uafwc ? what is happening? 1 year 6 months ago #389

yes, I understand the ways mrls and mrskew use to calculate the total time. That is clear.

It looks like Dtrace will be my tool of choice for this job. The - probably - CPU only action takes an awful lot of time and currently it looks as if nothing is happening, at the same time the CPU is red-hot.

What is happening is mostly browsing though a kind of object tree, interactive .... taking minutes instead of seconds.

Now I found the gaps by grep|sed|awk the tim=XXX to a csv file, create the deltas, sort on descending delta and search in the tracefile for that timestamp.

How could I have used mrskew to do that smarter? I have tried a few things with $uafwc but ended up confusing myself because sometimes I got more unaccounted for time than that really is not accounted for.

thanks,
Ronald.
The administrator has disabled public write access.

Re:uafwc ? what is happening? 1 year 5 months ago #390

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 106
  • Thank you received: 2
The method you used has flaws. You didn't show all of the code to produce the output from the csv file so all I can assume at this point is that it **might** be useful for finding chunks of time that **might** be using only CPU. If you show all your work, then I can determine if flaws exist. Maybe they don't but it sure sounds like they exist.

The reason you won't be able to use mrskew to do the same thing is that we have to properly handle the following situation. I have elided some of the trace data to make it easier to demonstrate the problem we have to solve.

EXEC #1:c=100,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=100
EXEC #2:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=155
EXEC #3:c=100,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=200

The second line, executed at recursive depth 1, makes it look like there are 150 units of unaccounted-for time between line 2 and line 1. Line 3 reconciles this problem by showing cursor 3 was doing work from 100-150 and again from 155-200 with a short 5 unit handoff to cursor #2.

This is nearly exactly what is going on in your trace data except that it appears as though the recursive depth 0 call that finished on line 12826 doesn't fully account for the time that it should if it really started on line 9406 like it appears it should have started. This is a very strange trace file that you attached. Maybe you made some mistakes when you obfuscated it?
The administrator has disabled public write access.

Re:uafwc ? what is happening? 1 year 5 months ago #391

If you are interested I can get you the original file to verify that I only changed a few names. This file is a bit strange indeed, why I wanted to share it with someone who is used digging in traces to check my mental health ;-) I just don't want it for public...
grep "tim=" ${TRC} |sed "s/ /,/"|awk -F"," '{if (NF > 5) print NR, $NF}'
should produce the tim= parts for csv. A bit rough but effective. Should include ela to get better offsets.
The administrator has disabled public write access.