RE: Long Parse Time

  • From: Yong Huang <yong321@xxxxxxxxx>
  • To: tanel@xxxxxxxxxx, riyaj.shamsudeen@xxxxxxxxx, ric.van.dyke@xxxxxxxxxx
  • Date: Fri, 8 May 2009 10:30:18 -0700 (PDT)

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.



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


Other related posts: