分析诊断进程跟踪文件工具ASS.AWK(3)

2/9/2008来源:Oracle教程人气:5281


  ##############################################################################
  #          S T A R T  O F  P R O C E S S I N G          #
  #                                      #
  # BEGIN Section: Can amend 'interactive', 'verbose' and 'eventdetail'.    #
  ##############################################################################
  BEGIN      { version="1.0.8"; lwidth=79; interactive=1; verbose=1;
  eventdetail=1; skipbranch=1; seqinfo=1;
  tx1="Above is a list of all the PRocesses. If they are waiting for a resource";
  tx2="then it will be given in square brackets. Below is a summary of the";
  tx3="waited upon resources, together with the holder of that resource.";
  tx4="Notes:\n\t~~~~~";
  tx5=" o A process id of '???' implies that the holder was not found in the";
  tx6="  systemstate.";
  br1="WARNING: The following is a list of process id's that have state";
  br2="     objects that are NOT owned by the parent state object and as"
  br3="     sUCh have been SKIPPED during processing. (These are typically";
  br4="     SQL*Net loopback sessions).";
  
  cmdtab[1]="Create Table"; cmdtab[2]="Insert";cmdtab[3]="Select";
  cmdtab[4]="Create Cluster";cmdtab[5]="Alter Cluster";cmdtab[6]="Update";
  cmdtab[7]="Delete";cmdtab[8]="drop Cluster";cmdtab[9]="Create Index";
  cmdtab[10]="Drop Index";cmdtab[11]="Alter Index";cmdtab[12]="Drop Table";
  cmdtab[13]="Create Sequence";cmdtab[14]="Alter Sequence";
  cmdtab[17]="Grant";cmdtab[18]="Revoke"; cmdtab[40]="Alter Tablespace";
  cmdtab[42]="Alter Session";cmdtab[44]="Commit";cmdtab[45]="Rollback";
  cmdtab[47]="PL/SQL Execute";
  cmdtab[62]="Analyze Table"; cmdtab[63]="Analyze Index";
  cmdtab[67]="Alter Profile"; cmdtab[85]="Truncate Table";
  }
  
  # Start of trace file
  # ~~~~~~~~~~~~~~~~~~~
  # Oracle7 Server Release 7.1.6.2.0
  # Oracle8 Enterprise Edition Release 8.0.5.0.0
  /^Oracle7 Server Release 7\./  { rdbms_ver = $4; next }
  /^Oracle8 .* .* Release 8\./  { rdbms_ver = $5; next }
  
  # Start of Systemstate
  # ~~~~~~~~~~~~~~~~~~~~
  /^SYSTEM STATE/     { printf("\nStarting Systemstate %d\n", ++sstate);
  lcount=1; insystate=1; inbranch=0; next }
  
  # Skipped Lines
  # ~~~~~~~~~~~~~
  insystate!=1          { next }
  # Used for PQO--flds 1 and two are good enuf
  # Do NOT skip additional processing (ie no next)
  /^ *SO:/            { getline; sub("
  ","");; sotype=$1 " " $2; }
  
  /PROCESS STATE/         { insystate=0; next }
  /SHUTDOWN: waiting for logins to complete/   { next }
  
  # Code to skip 'branch of' state objects which are caused by silly things
  # such as SQLNET loopback sessions
  skipbranch && inbranch > 0   { tmp = $0;
  sub(branchstr, "", tmp);
  if (tmp !
~ "^ ")
  inbranch = 0;
  }
  
  /^ *branch of *$/       { if (skipbranch)
  {
  sub("branch of.*", ""); branchstr="^" $0;
  inbranch=length(branchstr);
  branchlst[sstate]=branchlst[sstate] " " pid;
  next
  }
  }
  
  # Strip Carriage returns
  /
  /                { sub("
  ",""); }
  
  # Start of New Process
  # ~~~~~~~~~~~~~~~~~~~~
  /PROCESS [0-9]*:/        { pid=$2; inbranch=0;
  # Need to use pidarray to avoid "holes"
  # in processes causing us problems.
  pidarray[sstate, ++pidcnt[sstate]] = pid;
  handle=""; inpq = 0;
  if (!interactive) next;
  if (++lcount > lwidth) lcount=1;
  printf("%s", lcount==1? "\n.":".");
  next }
  # Oracle Command
  # ~~~~~~~~~~~~~~
  # oct: 3, prv: 0, user: 221/MRCHTMH
  /^ *oct: .*, prv:/       { tmp=$2; sub(",", "",tmp);
  # Only output the parent session's command.
  if (!oct[sstate, pid]) oct[sstate, pid]=tmp;
  next }
  
  # Capture Seq
  # ~~~~~~~~~~~
  # last wait for 'db file sequential read' seq=39279 wait_time=4
  
  /waiting for .*seq=.*wait_time/ { if (seqinfo)
  seq[sstate, pid] = $(NF-1);
  }
  
  # Wait Event Information
  # ~~~~~~~~~~~~~~~~~~~~~~
  # Gather the current wait event information for a simple overview of the
  # 'Waiter' information summarised at the end.
  #
  $0 ~ "last wait for .*'" 
  $0 ~ "acquiring .*'"  
  $0 ~ "waiting for .*'"
  $0 ~ "holding .*'"       { sub("' .*$", "'"); # Just keep event name
  sub("^ *","");
  wait_event[sstate, pid] = procevent($0);
  next }
  
  # Spot Dead Processes
  # ~~~~~~~~~~~~~~~~~~~
  # (process) Oracle pid=6, calls cur/top: 22060e34/22060e34, flag: (3) DEAD
  /(process).*flag:.*DEAD/    { isdead[sstate,pid]=1; }
  
  # RESOURCE: Latch
  # ~~~~~~~~~~~~~~~
  # Example:
  #  waiting for 80108e04 shared pool level=7 state=free
  #   wtr=80108e04, next waiter 0
  #  holding   80108eec library cache pin level=6 state=busy
  #
  /waiting for *[a-f0-9]* /    { waitres[sstate, pid] = "Latch " $3;
  if (verbose && !objname[sstate, "Latch " $3])
  {
  tmp = $3;
  sub("^ *waiting for *[a-f0-9]* ","");
  sub(" level.*$","");
  objname[sstate, "Latch " tmp] = $0;
  }
  next }
  /holding *[a-f0-9]* /      { tb = blkres[sstate, "Latch " $2];
  tb = add_resource(tb,pid);
  blkres[sstate, "Latch " $2] = tb;
  if (verbose && !objname[sstate, "Latch " $3])
  {
  tmp = $3;
  sub("^ *waiting for *[a-f0-9]* ","");
  sub(" level.*$","");
  objname[sstate, "Latch " tmp] = $0;
  }
  next }
  /acquiring *[a-f0-9]* /     { tb = blkres[sstate, "Latch " $2];
  tb = add_resource(tb,pid);
  blkres[sstate, "Latch " $2] = tb;
  if (verbose && !
objname[sstate, "Latch " $3])
  {
  tmp = $3;
  sub("^ *waiting for *[a-f0-9]* ","");
  sub(" level.*$","");
  objname[sstate, "Latch " tmp] = $0;
  }
  next }
  
  # RESOURCE: Enqueue
  # ~~~~~~~~~~~~~~~~~
  # Example:
  # (enqueue) TX-00030007-00004170
  # lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  # res:c07c3e90, mode: X, prv: c07c3e98, sess: c1825fc8, proc: c180d338
  #
  /\(enqueue\) /   { next }  # Skip this
  
  /\(enqueue\)/          { tmp = $2;
  getline; getline; sub("
  ","");
  if ($2 == "mode:")
  {
  tb = blkres[sstate, "Enqueue " tmp];
  tb = add_resource(tb , pid);
  blkres[sstate, "Enqueue " tmp] = tb;
  if (substr(tmp,1,2)=="PS")
  {
  tb = pqenq_cnt[sstate, pid]++;
  tmp1 = tmp;
  gsub("-0*","-0", tmp1);
  pqenq[pid, tb] = tmp1;
  }
  }
  
  if ($2 == "req:" $4 == "req:")
  waitres[sstate, pid] = "Enqueue " tmp;
  mode[sstate, pid, tmp] = $3;
  next }
  
  # RESOURCE: Row Cache Enqueue
  # ~~~~~~~~~~~~~~~~~~~~~~~~~~~
  # Example:
  # row cache enqueue: count=1 session=c1825fc8 object=c146e960, request=S
  # row cache parent object: address=c146e960 type=9(dc_tables)
  #
  /row cache enqueue:.*mode/   { tb = blkres[sstate, "Rcache " $6];
  tb = add_resource(tb, pid);
  blkres[sstate, "Rcache " $6] = tb;
  if (verbose && !objname[sstate, "Rcache " $6])
  {
  mode[sstate, pid, $6] = $7;
  tmp = $6; getline; sub("
  ","");
  objname[sstate, "Rcache " tmp] = $6;
  sub(".*type=.", "",
  objname[sstate, "Rcache " tmp]);
  }
  next }
  
  /row cache enqueue:/      { waitres[sstate, pid] = "Rcache " $6;
  if (verbose && !objname[sstate, "Rcache " $6])
  {
  mode[sstate, pid, $6] = $7;
  tmp = $6;
  getline; sub("
  ","");
  objname[sstate, "Rcache " tmp] = $6;
  sub(".*type=.", "",
  objname[sstate, "Rcache " tmp]);
  }
  next }
  
  # RESOURCE: Library Object Pin/Lock
  # ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  # Example:
  # LIBRARY OBJECT PIN: pin=c0f3aa90 handle=c15bcac0 mode=S lock=c0f3b840
  # LIBRARY OBJECT LOCK: lock=c0f3b840 handle=c15bcac0 mode=N
  #
  /LIBRARY OBJECT .*mode/     { tb = blkres[sstate, $3 " " $5];
  tb = add_resource(tb, pid);
  blkres[sstate, $3 " " $5] = tb;
  mode[sstate, pid, $5] = $6; next }
  
  /LIBRARY OBJECT .*request/   { waitres[sstate, pid] = $3 " " $5;
  mode[sstate, pid, $5] = $6; next }
  
  # RESOURCE: Cache Buffer
  # ~~~~~~~~~~~~~~~~~~~~~~
  # Example:
  #  (buffer) (CR) PR: 37290 FLG:  0
  #  kcbbfbp  : [BH: befd8, LINK: 7836c] (WAITING)
  #  BH #1067 (0xbefd8) dba: 5041865 class 1 ba: a03800
  #   hash: [7f2d8,b47d0], lru: [16380,b1b50]
  #   use: [78eb4,78eb4], wait: [79cf4,78664]
  #   st: READING, md: EXCL, rsop: 0
  #   cr:[[scn: 0.00000000],[xid: 00.00.00],[uba: 00.00.00], sfl: 0]
  #   flags: only_sequential_access
  #   L:[0.0.0] H:[0.0.0] R:[0.0.0]
  #   Using State Objects
  #
  /^  kcbbfbp/     { blmode = $7;
  getline; sub("
  ","");
  dba = $5;
  if ( blmode == "(WAITING)" blmode == "EXCLUSIVE" )
  waitres[sstate, pid] = "Buffer " dba;
  else
  {
  tb = blkres[sstate, "Buffer " dba];
  tb = add_resource(tb, pid);
  blkres[sstate, "Buffer " dba] = tb;
  }
  mode[sstate, pid, dba] = blmode;
  next }
  
  # RESOURCE: Lock Element Dump
  # ~~~~~~~~~~~~~~~~~~~~~~~~~~~
  # Example:
  #  LOCK CONTEXT DUMP (address: 0x90ceab20):
  #  op: 2 nmd: EXCLUSIVE dba: 0x5400004f cls: DATA    cvt: 0 cln: 1
  #   LOCK ELEMENT DUMP (number: 14048, address: 0x91212498):
  #   mod: NULL    rls:0x00 acq:03 inv:0 lch:0x921a366c,0x921a366c
  #   lcp: 0x90ceab20 lnk: 0x90ceab30,0x90ceab30
  
  #
  # Complete: Always assumes waiting AND just identifies one resource !
!
  #
  /LOCK CONTEXT DUMP/   { getline; sub("
  ",""); isnull = 0;
  if ($4 == "NULL") isnull = 1;
  wantmode = $4;
  getline; sub("
  ","");
  tmp = "Elem " $5;
  if (!isnull)
  waitres[sstate, pid] = tmp;
  else
  blkres[sstate, tmp] = pid;
  if (!verbose) next;
  getline; sub("
  ","");
  mode[sstate, pid, tmp] = $2;
  getline; getline; getline; getline;getline;getline;
  sub("
  ","");
  tb = objname[sstate, tmp] " ";
  tb = tb $2;
  objname[sstate, tmp] = tb;
  next }
  
  ##
  ## Verbose Processing
  ##
  verbose != 1      { next }
  
  # Handle to Object Mapping (Verbose mode)
  # ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  # Example:
  #   LIBRARY OBJECT HANDLE: handle=40e25e08
  #   name=TEST.CRSMESSAGELOG
  #   hash=e2deff52 timestamp=11-22-1995 17:53:55
  #   namespace=TABL/PRCD flags=TIM/SML/[02000000]
  
  /LIBRARY OBJECT HANDLE:/    { # next; # Just skip for now
  handle=$4; getline; sub("
  ","");
  if (objname[sstate, handle]) next;
  # Skip child cursors for now.
  if ($0 ~ "namespace=") next;
  sub("^ *name=","");
  if (!$0) getline; sub("
  ","");
  txt = $0;
  while ($0 !~ "namespace") getline;
  sub("
  ",""); type=$1;
  sub("namespace=","",type);
  objname[sstate, handle] = type ":" txt;
  next }
  
  # PQO QC <-> QS Code (verbose)
  # ~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  # o A QC can be identified within a systemstate by any of the following
  #  methods :
  #   - Look for 'flags' being set to ISQC when dumped as part of the Process
  #    Queue state object dump (not the Message Buffer state object dump).
  #   - Look for PS enqueues being held in EXCLUSIVE mode.
  #    (Null is used for the query slaves).
  #    We can then pick up the 'proc:' address of the enqeueue s.o. and link
  
  #   - Check to see whether the Process Queue state object hangs under the
  #    Session state object (QC) rather than the process state object (Slave).
  #
  # Notes:
  # o One QC can have TWO Process Queue state objects with flag ISQC if the QC
  #  manipulates two query slave sets (producer/consumer).
  #
  # Here we maintain the following variables :
  # o qclist - This is a space delimited list of processes that are recognised
  #       as QC's. The queue descriptor is also used to differentiate
  #       seperate slave sets for the same QC pid.
  #
  # o qcid  - The pid of the last QC processed.
  #
  # o qc_cnt - Count of Opposite Qrefs we have seen for a particular QC. This
  #       is indexed by [sstate, qcid]. (This is one HIGHER than the actual
  #       count found).
  #
  #
  # TODO: Complete descriptions !!
  #
  
  #Queue Reference--kxfpqr: 0x67d4244, ser: 23040, seq: 31066, error: 0
  /Queue Reference--kxfpqr/    { # printf("DBG slave[%d, qref=%s] saved\n",
  #   sstate, $3);
  slave[sstate, $3] = pid;
  qreferr[sstate, $3] = $9; next }
  
  # We need to skip processing if we are dealing with a QC that we have ALREADY
  # seen (Eg a QC with 2 slave sets).
  # (We have to check for this in two phases because of Sequent 'feature'
  /flags: ISQC/          { if (sotype ~ "Process Queue")
  {
  inpq=1;
  if (qc_cnt[sstate, pid]) next;
  qclist[sstate]=qclist[sstate] " " pid;
  qcid = pid; ++qc_cnt[sstate, qcid]; next;
  }
  }
  
  #opp qref: 0x67dd950, process: 0x7046ae4, bufs: {0x0, 0x65ff6f8}
  # (We have to check for this in two phases because of Sequent 'feature'
  /opp qref:.*process:/      { if (inpq==1)
  {
  qc[sstate, qcid, qc_cnt[sstate, qcid]++]=$3;
  next;
  }
  }
  
  #client 1, detached proc: 0x726899c, QC qref 0x67dd950, flags: -none-
  /client.*QC qref 0x0/      { next; }            # Skip QC qref's
  /client.*QC qref/        { qref=$8; slave[sstate, $8] = pid; next }
  #state: 00000, flags: SMEM OPEN COPE, nulls 0, hint 0x0
  /state.*hint/          { pqostate=$2; next }
  #ser: 23040, seq: 1, flags: DIAL CLR, status: FRE, err: 0
  /^ *ser:.*seq:.*flags:.*err:/  { gsub(" ","_");
  split($0, tmparr, ",");
  sub("^.*:_", "", tmparr[3]);
  sub("^.*:_", "", tmparr[4]);
  sub("^.*:_", "", tmparr[5]);
  pqomode=tmparr[3]; pqostatus=tmparr[4];
  pqoerr=tmparr[5]; next }
  
  /Message Buffer--/       { pqotype = $5; pqobufnum = $7; next }
  /to qref.*from qref/      { tmp=sprintf("%5s %10s %10s %5s %7s %7s %4s",
  pqostate, $6, $3, pqotype, pqostatus,pqomode,
  pqoerr);
  pqdetail[sstate,pid,pqobufnum] = tmp; next}
  #    "QC", "Slave", "Msg", "State", "From", "To", "Type", "Status", "Err");
  
  # END Processing
  # ~~~~~~~~~~~~~~
  # Ok - Let's put all the pieces together and you never know.....It just may
  # make sense !
!
  #
  END   { printf("\nAss.Awk Version %s - Processing %s\n", version, FILENAME);
  for (i=1; i<=sstate; i++)
  {
  printf("\nSystem State %d\n~~~~~~~~~~~~~~~~\n", i);
  blocking = "";
  blkcnt = 0; objcnt = 0;
  for (j=1; j<=pidcnt; j++)
  {
  pid = pidarray[i,j];
  tmp = waitres[i, pid];
  tmp1 = "";
  if (tmp) tmp1 = "["tmp"]";
  printf("%-4s%-35s%s%s %s\n", pid, wait_event[i,pid],tmp1,
  isdead[i, pid]?" [DEAD]":"",seq[i, pid]);
  if (seqinfo && i > 1 &&
  sameseq(wait_event[i,pid], wait_event[i-1,pid],
  seq[i, pid], seq[i-1, pid]) )
  {
  #printf("DBG: Process %s seq (%s)\n", pid, seq[i, pid]);
  seq_stuck = seq_stuck?min(seq_stuck, j):j;
  }
  
  if (oct[i,pid] && oct[i,pid]!=0)
  {
  if (cmdtab[oct[i,pid]]) printf("   Cmd: %s\n",
  cmdtab[oct[i,pid]]);
  else
  printf("   Cmd: Unknown(%s)\n", oct[i,pid]);
  }
  #
  # Verbose: Need to describe wait_event details as well !!
  #
  
  sub(" ", "_", tmp);
  if (!index(blocking, tmp) && waitres[i,pid])
  {
  blocking = blocking " " tmp;
  blklist[++blkcnt] = waitres[i,pid];
  if (verbose)
  {
  objid[++objcnt] = waitres[i, pid];
  } # end verbose
  }
  } # end j
  #
  # Summary of the blocking resources
  #
  if (blkcnt)
  {
  printf("Blockers\n~~~~~~~~\n\n\t%s\n\t%s\n\t%s\n", tx1, tx2, tx3);
  printf("\t%s\n\t%s\n\t%s\n\n", tx4, tx5, tx6);
  printf("%28s %6s %s\n", "Resource", "Holder", "State");
  }
  else
  printf("\nNO BLOCKING PROCESSES FOUND\n");
  
  for (k=1; k<=blkcnt; k++)
  {
  pidlist = blkres[i, blklist[k]];
  #       Someone must be waiting for the resource if we got this far.
  if (!pidlist) pidlist = "???";
  numpids = split(pidlist, tpid, " ");
  for (z=1; z<=numpids; z++)
  {
  printf("%28s %6s ", blklist[k], tpid[z]);
  # -- Handle self deadlocks !!
  if (waitres[i, tpid[z]])
  {
  # What if blker is multiple blockers ? Need to handle this case as well
  # (and tidy code up [use functions?]). Currently just lists it in the following
  # format :
  # Enqueue TM-000008EC-00000000       7:  7: is waiting for 7: 13:
  #
  blker = blkres[i, waitres[i, tpid[z]]];
  # D>on't know holder so let's print the resource
  if (!sub("^ ", "", blker)) blker = waitres[i, tpid[z]];
  if (tpid[z] == blker)
  printf("Self-Deadlock\n");
  else
  printf("%s is waiting for %s\n", tpid[z], blker);
  }
  else if (wait_event[i, tpid[z]])
  printf("%s\n", wait_event[i, tpid[z]]);
  else
  printf("Blocker\n");
  } # end z
  } # end k
  
  pq_qc2slave(i);
  if (!verbose !blkcnt) continue;
  
  printf("\nObject Names\n~~~~~~~~~~~~\n");

  for (y=1; y<=objcnt; y++)
  {
  tmp = objid[y];
  sub("^PIN: ","", tmp);
  sub("^LOCK: ","", tmp);
  #printf("DBG: objname[%d, %s] = '%s'\n", i, tmp, objname[i,tmp]);
  printf("%12s\t%-30s\n", objid[y], substr(objname[i, tmp],1,50));
  } # End y
  # Print out skipped branches
  if (branchlst[sstate])
  printf("\n%s\n%s\n%s\n%s\n%s\n", br1,br2,br3,br4, branchlst);
  } # end i
  
  # Highlight processes that seem to be stuck
  # Note that we do not care if it is stuck across ALL iterations
  # of the systemstate dump - just across any TWO adjacent
  # systemstates. This is because the user may have dumped the
  # systemstate before the problem started, or killed the process.
  #
  # TODO: Remember that we may actually have a different OS process
  #    But unlikely to have the same seq# anyway
  #    Also, the wait_event string may actually comprise of more
  #    than just the wait event string itself. In some cases it
  #    also includes the p1,p2,p3 info as well.
  if (seq_stuck)
  {
  printf("\nList of Processes That May Be Stuck");
  printf("\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n");
  for (i=2; i<=sstate; i++)
  {
  for (j=seq_stuck; j<=pidcnt; j++)
  {
  pid = pidarray[i,j];
  #printf("DBG: wait_event[%d,%s] = (%s)\n", i, pid,
  #wait_event[i,pid]);
  #printf("KDBG: seq[%d, %s] = %s\n", i, pid, seq[i, pid]);
  if (sameseq(wait_event[i,pid], wait_event[i-1,pid],
  seq[i, pid], seq[i-1, pid]) )
  {
  printf("%s %s %s\n", pid, wait_event[i,pid], seq[i,pid]);
  ## Stop duplicate printouts
  seq[i,pid] = "";
  }
  
  } # end for j
  } # end for i
  } # end seq_stuck
  
  if (print_pqo) pq_details(rdbms_ver);
  
  printf("\n\n%d Lines Processed.\n", NR);
  
  } # end END