RE: Long Parse Time

Very interesting thread so far!

> And yep, as 10053 trace doesn't have timing info in it, it's
> impossible to

In this case, you can add your own timing info like this:

tail -f the_trace_file | perl -nle 'print time, $_'

If you really need human readable time, fiddle with localtime in place of time. If you need nanosecond resolution (actually it may not be that accurate), Time::HiRes is needed but Heisenberg effect seriously kicks in.

> Btw I didn't intend to bash the non-systematic approach here, there is
...
> I dumped pstack in a loop to see where the time is spent and I
> realized that it was in kk*

My first response to this type of problem would be like you both said, check function call stack. Just run pstack <shadow process ID> a couple of times during the long parse, and you'll know what function it repeatedly hangs on. Pstack or equivalent is available on many OS's.

Quick troubleshooting needs both systematic work and insight from experience. Here's an example I come up with (it really happened to me, and I took the second approach 'cause I was dumb at the moment):

Difference between using insight and using knowledge to solve a problem

Using insight:

C:\temp>del test.txt
C:\temp\test.txt
Access is denied.
Check the file attribute. Aha, it's set to Read-only.

Using knowledge:

C:\temp>del test.txt
C:\temp\test.txt
Access is denied.
C:\temp>strace cmd /c del test.txt | grep STATUS Access is denied.
...
483 1060 428 NtSetInformationFile (76, 1241211, 1, Disposition, ... ) == STATUS_CANNOT_DELETE

Look up "STATUS_CANNOT_DELETE" on Google and the first hit lists three possibilities returning this status. One of them is read-only file.       

--
http://www.freelists.org/webpage/oracle-l