Welcome, Guest
Username: Password: Remember me

TOPIC: Forward attribution of SQL*Net message events

Forward attribution of SQL*Net message events 2 years 2 months ago #339

Hi everybody,

Recently, I had access to a 11gR2 trace file and Its corresponding analysis report by Profiler.

When looking into raw trace data, I could infer that the "between calls" for the so called PSEUDO CURSOR (#0) seems to be attributed to the cursor #N of the next db call in the trace file.

However, my final count for the "between events" of some statements is still wrong so, because, some SQL*Net messages for a given cursor #N seems to be attributed to the next db call of cursor #M.

So I must review my understanding about “forward attribution” of the btw calls:

which cursor will be blamed by the btw events of cursor #0?
Is it possible to "migrate" the btw of cursor #N to the profile of another statement, (cursor #M)?
The administrator has disabled public write access.

Re:Forward attribution of SQL*Net message events 2 years 2 months ago #340

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 103
  • Thank you received: 2
Are you asking what happens if a trace file's last line begins with the following?

WAIT #0: nam='SQL*Net message from client' ...

BTW, you said you "had" a trace file. Do you truly no longer have it? If you still have the file, can you attach a compressed version of it here?

The reason I ask is that if the Profiler is not properly accounting for something, then we need to know enough to reproduce the problem. It's often the case that we can't get enough information about the problem if we do NOT have the trace file.
The administrator has disabled public write access.

Re:Forward attribution of SQL*Net message events 2 years 2 months ago #341

Hi Jeff,

My question is: what is happening with all the lines like: WAIT #0: nam='SQL Net message from client', ..., not only to the last one. More precisely, which sql statement profile is being overloaded with these waits?

The second question is: is it possible for a line like:

WAIT #3445344234: nam='SQL Net message from client' ...

to be accounted for in the profile of a SQL statement in another cursor than #3445344234? Or, may be, to the profile of another SQL statement in a future instance of the same cursor #3445344234?
The administrator has disabled public write access.

Re:Forward attribution of SQL*Net message events 2 years 2 months ago #342

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 103
  • Thank you received: 2
Waits for SNMFC for cursor #0 should be attributed backward to the statement referred to in the prior dbcall (e.g., PARSE,EXEC,FETCH) regardless of its cursor slot/address.

If the slot/address is non-zero, then it's attributed to the statement referred to in the next dbcall of the same slot/address.

The answer to your second question is difficult because the question is loaded (it's really more than one question).

If the SNMFC for #3445344234 is followed by a dbcall for #3445344234, then forward attribution (next dbcall) has the same affect as backward attribution (prior dbcall). But when you continue your question, you describe, I think, the following trace excerpt.
WAIT #3445344234: nam='SQL Net message from client' ...
PARSING IN CURSOR #3445344234...
new one
END OF STMT
PARSE #3445344234...

In this excerpt, forward attribution and backward attribution produce different results if the statement for #3445344234 prior to the P.I.C. is different than the statement after the P.I.C. But just to be clear, in this case the SNMFC is attributed to "new one".

I hope this answers your questions but if you have more just post them and I'll see what I can do.
Last Edit: 1 week 7 hours ago by Jeff Holt.
The administrator has disabled public write access.

Re:Forward attribution of SQL*Net message events 2 years 2 months ago #343

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 103
  • Thank you received: 2
I received your trace file. What version of the Profiler are you using?
The administrator has disabled public write access.

Re:Forward attribution of SQL*Net message events 2 years 2 months ago #344

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 103
  • Thank you received: 2
Using our Profiler version 5.2.7.8, the resulting profile shows all SQL*Net message from client lines are accounted for. Of the 565354 lines, 565353 are on line 1 of the profile as "SQL*Net message from client". The other line has an elapsed time greater than 1 second and therefore, by default, it is considered "SQL*Net message from client [think time]" and it appears on line 6 of the profile.

Additionally, the total elapsed time for all 565354 lines is 286.341899s, which is consistent with the sum of the two aforementioned profile lines, which is 286.342s. The Profiler by default shows millisecond resolution which explains that latter number being rounded to milliseconds.

In the statement sections, all 565354 lines are attributed to some statement. None are lost in the accounting.

The profile of program that generated this trace file shows a program that parses each SQL statement twice and fetches one row per fetch. It is a highly inefficient program. It could be that it could be improved by changing some configuration parameters to make it stop parsing twice and to fetch 100 rows per fetch operation.

BTW, I haven't seen a trace file like this in a long time. It brought back some fond memories.
The administrator has disabled public write access.