Welcome, Guest
Username: Password: Remember me

TOPIC: artificial bracket for uninstrumented code

artificial bracket for uninstrumented code 11 months 1 week ago #410

Hi,

I am having an uninstrumented application which is doing some tasks in a sequence like

INSERT INTO LOG {task_id, status=START}.... (sql_id:A)

<doing some work>

UPDATE LOG {task_id, status=NEXT_STEP} (sql_id:B)

<doing some more work>

UPDATE LOG {task_id, status=COMPLETED} (sql_id:B)

<some work outside of the task>


This pattern repeats very often in the trace file.
I'm aware with a proper insert-trigger on the inserts/updated I can implement a proper instrumentation. ( client_id should be task_id, probably enhanced by several other informations)

The question is if I can somehow

1) tell mrskew to see "everything between 2 occurrences of sql_id:A" as a single task?

or even more comprehensive

2) tell mrskew to see "everything between sql_id:A and the last occurrence of sql_id:B (before the next sql_id:a comes)" as a single task?


thank you for any answer,
Martin

(PS: if you want I can create a small testcase)
^/\x
The administrator has disabled public write access.

Re:artificial bracket for uninstrumented code 11 months 4 days ago #412

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 103
  • Thank you received: 2
Hi, Martin.

Let's attack just your first question in this response.

Here is the test data I used. I assumed that the two updates, in your example, have different sqlid values.
Oracle Release 11.2
PARSING IN CURSOR #1 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=1 ad='1' sqlid='A'
insert
END OF STMT
PARSING IN CURSOR #2 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=2 ad='2' sqlid='r'
update next_step
END OF STMT
PARSING IN CURSOR #3 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=3 ad='3' sqlid='B'
update complete
END OF STMT
PARSING IN CURSOR #4 len=20 dep=0 uid=7 oct=3 lid=7 tim=2 hv=4 ad='4' sqlid='X'
select X
END OF STMT
PARSING IN CURSOR #5 len=20 dep=0 uid=7 oct=3 lid=7 tim=2 hv=5 ad='5' sqlid='Y'
select Y
END OF STMT

EXEC #1:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=100
EXEC #2:c=2,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=200
EXEC #3:c=4,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=300

EXEC #4:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=310
EXEC #5:c=6,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=320

EXEC #1:c=8,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=400
EXEC #2:c=16,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=416
EXEC #3:c=32,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=448

Trace file lines 18-20 are the first transaction and lines 25-27 are the second transaction. Lines 22-23 are declared uninteresting because they are <some work outside of the task>.

To answer your question #1, I wrote this rc script, martin1.rc.
--init='
    my $xfrm_id;
    sub xfrm {
        $xfrm_id = $exec_id if ($sqlid//"") eq "A";
        return $xfrm_id//$exec_id;
    }
'
--group='xfrm()'

When you execute it, you should see this:
$ mrskew --rc martin1.rc martin.trc
 'xfrm()'  DURATION       %  CALLS      MEAN       MIN       MAX
---------  --------  ------  -----  --------  --------  --------
       25  0.000056   75.7%      3  0.000019  0.000008  0.000032
       18  0.000018   24.3%      5  0.000004  0.000001  0.000006
---------  --------  ------  -----  --------  --------  --------
TOTAL (2)  0.000074  100.0%      8  0.000009  0.000001  0.000032

This report shows two executions of the transaction. The most interesting transaction execution began on trace file line 25 and contributed 0.000056 seconds (75.7% of the total) over 3 dbcalls to the total response time. The second most interesting execution begain on line 18 and contributed the other 24.3% to the total. We know that lines 22-23 are uninteresting, but the simple method does not distinguish them. And that is why the report says the execution starting on line 18 has 5 dbcalls for 0.000018 seconds instead of 3 dbcalls for 0.000011 seconds.

Cary and Jeff
The administrator has disabled public write access.

Re:artificial bracket for uninstrumented code 11 months 4 days ago #413

Cary, Jeff,

thank you for your great answer. I am very sorry forgetting the method to implement sub functions in mrskew. :S

Your answer is a great help for all my applications which are not instrumented (yet).

(once again) mrskew is an all-purpose tool to identify performance issues in my applications.

thank you,
Martin
^/\x
The administrator has disabled public write access.