Attachment OURS_ora_4599_01.gz not found

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.

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.

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.

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?

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.