Custom parameters in Method-R Workbench

 Method-R Workbench is a leading tool to analyze many aspects of Oracles SQL-Trace files. 

It can use parameters in its commands and let users fill their values there. In the picture there are even 2 parameters, properly labeled and predefined. 

But when I run my own statement which also uses a "variable" of the same format, it only generates an error message:

mrskew --name='cell single block physical read$' --where='$obj==@OBJECT-ID@' --group='sprintf("%-16s %-16s", $p1, $p2 )'   --group-label='sprintf("%-16s %-16s", "p1", "p2" )'

Array found where operator expected at (eval 26) line 1, near "ID@)"
syntax error at (eval 26) line 1, near "ID@) "

To tell the Workbench how to use my variable, some entries in a xml file are required:

In the .method-r\workbench\9.5.2.0 directory, there is the file reports.xml. 

(This file gets copied from Workbenchs installation directory etc\config to your users directory if it doesn't exist.) Be careful to topy your changes whenever a new version of Workbench arrives!

By default it contains only one example which is also its documentation. To make my query work with a parameter, I add this XML block:

	<diagnostic label="Response time time by p1 and p2 call name for a given OBJECT ID filtered for only 'cell single block physical read$'">	<!-- This is the name that the application will use for the report. -->
		<commandline>mrskew --name='cell single block physical read$' --where='$obj==@OBJECT-ID@' --group='sprintf("%-16s %-16s", $p1, $p2 )' --group-label='sprintf("%-16s %-16s", "p1", "p2" )'</commandline>				<!-- This is the command line. The token @SQLID@ is defined on the following line. -->
		<param token="@OBJECT-ID@" label="Object ID" hint="obj=" default="-1"/>				<!-- This element causes the app to pop a dialog using the field label, data entry tip, and default value. -->
		<sample><![CDATA[
p1               p2                DURATION       %  CALLS      MEAN       MIN       MAX
---------------------------------  --------  ------  -----  --------  --------  --------
4239709683       2452482353        0.341465    7.9%     12  0.028455  0.005255  0.209957
4239709683       560937342         0.235909    5.4%      7  0.033701  0.010636  0.122802
3429896051       3039011478        0.224350    5.2%      4  0.056088  0.008659  0.186996
4156894774       425700738         0.221344    5.1%      8  0.027668  0.010023  0.077580
437579672        4090241319        0.177895    4.1%      9  0.019766  0.000978  0.072990
3429896051       3648465545        0.166973    3.8%      8  0.020872  0.009399  0.029454
4156894774       203886304         0.164699    3.8%      7  0.023528  0.002680  0.097812
4156894774       1302812366        0.160810    3.7%      8  0.020101  0.007712  0.080382
4239709683       2857786178        0.159647    3.7%      9  0.017739  0.005672  0.068118
3429896051       2540343800        0.146400    3.4%      4  0.036600  0.018622  0.074485
                        37 others  2.340060   53.9%    157  0.014905  0.000342  0.128323
---------------------------------  --------  ------  -----  --------  --------  --------
                       TOTAL (47)  4.339552  100.0%    233  0.018625  0.000342  0.209957

		]]></sample>																<!-- This is what shows up in the Sample Output tab as you scroll through the reports list. -->
	</diagnostic>

In the current (9.5.2.0) version, there is a bug in the example: the html element tooltip is used, but it should be hint!

With this modification, now I have my own action defined and the parameter can be added as expected! 

---

Special thanks to Cary and Jeff for explaining these details so I can document it. 

Method R Profiler on x86_64 Linux with HiDPI

For a new installed Linux Laptop I tried to install Method R Profiler (and Tools).
But it was not as smooth as expected.

mrprop_wrapper failed with

/opt/mrprof/mrprof_wrapper: line 45: /opt/mrprof-7.1.1.3-linux32/bin/mrprof.exe: No such file or directory

But the file is there, and it's executable.
So the Error is slightly misleading.
Also strace showed a similar error:

execve("/opt/mrprof-7.1.1.3-linux32/bin/mrprof.exe", ["/opt/mrprof-7.1.1.3-linux32/bin/"...], [/* 62 vars */]) = -1 ENOENT (No such file or directory)

but execve(2) is slightly more clear:

ENOENT The file filename or a script or ELF interpreter does not exist, or a shared library needed for the file or interpreter cannot be found

As I'm very sure the file exists, let's check the other possibility:

$ file mrprof.exe 
mrprof.exe: ELF 32-bit LSB executable, Intel 80386, version 1 (SYSV), for GNU/Linux 2.2.5, dynamically linked, interpreter \004, stripped

The file is a ELF 32-bit

$ uname -m
x86_64

The system is 64-bit

$ readelf -l -d  mrprof.exe 

Elf file type is EXEC (Executable file)
Entry point 0x804a878
There are 8 program headers, starting at offset 52

Program Headers:
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  PHDR           0x000034 0x08048034 0x08048034 0x00100 0x00100 R E 0x4
  INTERP         0x000134 0x08048134 0x08048134 0x00013 0x00013 R   0x1
      [Requesting program interpreter: /lib/ld-linux.so.2]
  LOAD           0x000000 0x08048000 0x08048000 0x10a60 0x10a60 R E 0x1000
  LOAD           0x011000 0x08059000 0x08059000 0x014e8 0x015c8 RW  0x1000
  DYNAMIC        0x011014 0x08059014 0x08059014 0x000f8 0x000f8 RW  0x4
  NOTE           0x000148 0x08048148 0x08048148 0x00020 0x00020 R   0x4
  GNU_EH_FRAME   0x010a10 0x08058a10 0x08058a10 0x00014 0x00014 R   0x4
  GNU_STACK      0x000000 0x00000000 0x00000000 0x00000 0x00000 RW  0x4

Dynamic section at offset 0x11014 contains 26 entries:
  Tag        Type                         Name/Value
 0x00000001 (NEEDED)                     Shared library: [libnsl.so.1]
 0x00000001 (NEEDED)                     Shared library: [libdl.so.2]
 0x00000001 (NEEDED)                     Shared library: [libm.so.6]
 0x00000001 (NEEDED)                     Shared library: [libcrypt.so.1]
 0x00000001 (NEEDED)                     Shared library: [libutil.so.1]
 0x00000001 (NEEDED)                     Shared library: [libpthread.so.0]
 0x00000001 (NEEDED)                     Shared library: [libc.so.6]
 0x0000000c (INIT)                       0x804a3b0
 0x0000000d (FINI)                       0x8057070
 0x00000004 (HASH)                       0x8048168
 0x00000005 (STRTAB)                     0x8049460
 0x00000006 (SYMTAB)                     0x80487b0
 0x0000000a (STRSZ)                      2697 (bytes)
 0x0000000b (SYMENT)                     16 (bytes)
 0x00000015 (DEBUG)                      0x0
 0x00000003 (PLTGOT)                     0x8059110
 0x00000002 (PLTRELSZ)                   592 (bytes)
 0x00000014 (PLTREL)                     REL
 0x00000017 (JMPREL)                     0x804a160
 0x00000011 (REL)                        0x804a140
 0x00000012 (RELSZ)                      32 (bytes)
 0x00000013 (RELENT)                     8 (bytes)
 0x6ffffffe (VERNEED)                    0x804a080
 0x6fffffff (VERNEEDNUM)                 3
 0x6ffffff0 (VERSYM)                     0x8049eea
 0x00000000 (NULL)                       0x0

The required program interpreter is missing:

# ls  /lib/ld-linux.so.2
ls: cannot access '/lib/ld-linux.so.2': No such file or directory

Unfortunately, the documentation is slightly unspecific regarding the requirements: glibc 2.14 is met, but in my system only 64 bit by default.
With a glimpse at this part of the installation path mrprof-7.1.1.3-linux32 it should be obvious, but it wasn't for me, and the error-message was not helpful at first stage.

The solution is quite simple. As root:

dpkg --add-architecture i386
apt-get update
apt-get install libc6:i386 

---

With this issue solved, the Profiler started, but with incredible tiny fonts. This is a known effect for HiDPI screens. As it's a java- program, one additional line to my profile solves the problem:

export _JAVA_OPTIONS='-Dsun.java2d.uiScale=2'

The start screen still looks like a stamp, but the fonts and windows are fine.

---

At last, I want to start the profiler from any location, not only it's home directory. So the Profiler.sh is extended to

script="$0"
WORK_DIR="$(dirname $script)"
java -jar "${WORK_DIR}/jlib/com.methodr.profiler.gui.jar" $@

(the WORK_DIR related stuff is new.)

All together nothing special, but it can cost some time when you want to use a tool for the first time - probably for urgent reasons - and first have to fix such obstacles.
So it's collected here, to save me some time when I hit it again.

digging into mrskew internals

I'm spending some time working with Method-Rs trace file analyzer mrskew.
As the requirements are beyond simple analyses (here an example about the uncommon things to do) I'm consulting the documentation and all available information in detail. After many readings I started to take this part of the documentation serious:

EXPRESSIONS
Wherever mrskew requires an expression (such as in --group and --where option arguments), you may use any valid Perl expression consisting of:
Perl operators
Operators such as or xor and not , = ?: || && | ^ < > <= >= lt gt le ge == != <=> eq ne cmp + - . * / % =~ !~ ! ~ ** ...and so on. See http://perldoc.perl.org/perlop.html for details.
Perl builtin functions
Functions such as lc uc s/// int join split sprintf substr ...and so on. See http://perldoc.perl.org/perlfunc.html for details.
File::Basename functions
The functions fileparse, basename, and dirname. See http://perldoc.perl.org/File/Basename.html for details.
mrskew expression variables
Any of the variable names described in "EXPRESSION VARIABLES".
For more information about Perl expression syntax, see http://perldoc.perl.org/perl.html#Tutorials.

It's written "any valid Perl expression" and Jeff showed me a very clever example on StackOverflow. But that's not the end, it raised some questions:
Where in the work of mrskew is the specific expression executed?
What's the order of these expressions?
Can they interact?

A small testcase can answer some of these questions.

I used a very simple artificial tracefile:

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

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

a small rc file (rc file is used here to store parameters whenever it's boring to type them on command line):

--init='
 my $trace_string = "trace: ";
 my $test_string;
    sub xfrm {
   if ($_[0] eq "where0") {
     $test_string = $test_string . "x";}
   if ($_[0] eq "where1") {
     $test_string =~ s/x/u/g ;}  
      $trace_string = $trace_string . "$_[0]" . "{ $test_string } " . "[$line] -> ";
   
   if ($_[0] eq "group") {
     return $trace_string;}
  else {
    return $_[1]}
    }
'

this uses the --init parameter:

--init=stringExecute string, which must contain syntactically correct Perl code, before beginning file processing. The default value is --init=''.

There I'm setting 2 variables which will be used later.
Also a function xfrm is defined. Depending of the 1st parameter it does different things, always it extends the variable $trace_string with some additional parameters. When the 1st parameter is "group", this $trace_string is returned - my dirty hack for a print of a debug value.

Checking the manpage where an expression ls allowed for a parameter gives me this execution:
(slightly modified for better readability

mrskew --rc martin3.rc  \
  --select='xfrm( "select", 1)' \
  --where0='xfrm( "where0", 1)==1' \
  --where1='xfrm( "where1", 1)==1' \
  --group='xfrm( "group",1)' \
  berx2.trc

The idea is simple: wherever a expression is allowed, my generic function xfrm is called with the name of the mrskew-parameter as it's 1st parameter.

It's result provides some interesting insights:

Summary information by file (modified)
mrskew --rc martin3.rc  --select='xfrm( "select", 1)' --where0='xfrm( "where0", 1)==1' --where1='xfrm( "where1", 1)==1' --group='xfrm( "group",1)' berx2.trc "D:\TEMP\berx2.trc"
Run began 2017-09-25T09:54:40, lasted 0,445000 seconds

input files:
 'D:\TEMP\berx2.trc'

where expression:
 ((xfrm( "where0", 1)==1) and (xfrm( "where1", 1)==1)) and ($nam=~/(?^:(?i).+)/)

group expression:
 xfrm( "group",1)

matched call names:
 'EXEC'

'xfrm( "group",1)'                                                                                                                                                                                                                                                                                                 'xfrm( "select", 1)'       %  CALLS      MEAN       MIN       MAX
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] ->                                                                                                          1.000000   50.0%      1  1.000000  1.000000  1.000000
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->               1.000000   50.0%      1  1.000000  1.000000  1.000000
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
TOTAL (2)                                                                                                                                                                                                                                                                                                                      2.000000  100.0%      2  1.000000  1.000000  1.000000
mrskew: file 'berx2.trc' does not exist

As the $trace_string is quite long I cut it down into pieces and my interpretation:

trace: where0{ x } [1] -> where1{ u } [1] -> 

where0 is called before where1
where1 can modify a variable set by where0 (the x becomes an u).

where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> 

where0 and where1 are NOT used in lines 2 & 3 of the trace file (PARSING IN CURSOR and the insert statement)

where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> 

in line 6 (EXEC) where0, where1, select and group functions are used (in that order)

where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->

the same is true for line 7.

There is probably more to identify as my simplified tracefile did not show all possible lines and their combination. But the possibility to run code inside mrskew at different positions, and even manipulate some values is shown. Even manipulating mrskews own variables might be of some interest, but it must be identified first where/when they are set and changed. This is open for the readers exercise, the method is shown here :-)

Method R Profiler 7.0 available

I'm seldom doing product announcements on my blog. So there must be a reason why I do not follow this rule.

Method-R recently released a new version of it's powerful SQL-Trace profiler.
Of course there are many improvements on the profiler engine itself, but as the prodict was very stable already they will only help in rare edge cases, most people would not benefit dramatically.

But there is a new featuere which brings a lot of added value to the tool and improves time to repair/fix/enlightenment for many readers of the trace file:
They added an explanatory text to many sections.
Here an example (from their sample file - slightly edited to better fit the size of this blog):

Your experience duration was dominated by “cell single block physical read” and “CPU: FETCH dbcalls” calls. These are all high-productivity calls; their dominance means that the Oracle Database is working hard for your application. Now you should determine whether all of that work is actually necessary. Consult the Profile by Cursor and Profile by Statement sections for the next step of your diagnosis.

	Subroutine	Duration		Calls	Duration per call (seconds)
		seconds	% R		mean	min	skew	max
1	cell single block physical read	4.644	69.9%	6,899	0.0007	0.0005	▁▁▁█▁▁▁▁▁▁▁	0.028
2	CPU: FETCH dbcalls	2.381	35.8%	7,947	0.0003	0.0000	▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁█▁▁	2.071

Unfortunately I did not manage to copy all the nice formatting into this blog, so i created a screenshot to show the original picture.

As you can see there is a new text with more in detail explanation about the Subroutine and where to go next for deeper analysis. I see this as a big advantage for everyone who does not work with SQL-Trace files every day. (well, even for those it's helpful).

There is a very nice demo version available, so if you have a trace file to analyze and want to check, if you see added value by this suggestion, give it a try.

Beside the new Profiler, Method-R has redone their web page as well (and I expect more news to follow). It's worth to invest some minutes and have a glimpse.