Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Derby Development" <derby-dev@db.apache.org>
Received-SPF: neutral (hermes.apache.org: local policy)
Date: Mon, 04 Oct 2004 16:04:30 -0700
Message-Id: <m3u0taqe4h.fsf@yesco.org>
From: "Jonas S Karlsson" <jsk@yesco.org>
In-Reply-To: <41617803.7040304@Yngvi.Org>
To: Derby Development <derby-dev@db.apache.org>
Subject: Re: Query Optimization Tool


Sunitha Kambhampati <skambha@yngvi.org> wrote:
> It is not very user friendly, but it helps to give an idea of which
> indexes have been used.

Yes, reading that very wide output is a lot of fun, so fun that I
wrote a script to do it a while back, it picks out the major structure
of the query, gives some index/join info of the plan and shows the
general outline. My query had 15 nested joins so it was really
impossible to read the output by hand. You may need to modify it
for your queries...

Example output:

--- join using no index ---
select * from foo, bar where c=e
***** Hash Join ResultSet:
 Table Scan ResultSet for FOO
  start position:
  stop position:
With:
 Hash Scan ResultSet for BAR
 Number of opens = 0
  start position:
  stop position:
  next qualifiers:
    Operator: =

--- join USING index ---
select * from foo, bar where c=e
***** Project-Restrict ResultSet (4):
 Hash Join ResultSet:
  Table Scan ResultSet for BAR
   start position:
   stop position:
 With:
  Hash Scan ResultSet for FOO using index FOOI
  Number of opens = 0
   start position:
   stop position:
   next qualifiers:
     Operator: =

--- This is the input to the first query (as in derby.log):
2004-10-04 22:49:41.560 GMT Thread[main,5,main] (XID = 422), (SESSIONID = 0), select * from foo, bar where c=e ******* Hash Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count:            3.60
        optimizer estimated cost:          200.91

Left result set:
        Table Scan ResultSet for FOO at read committed isolation level using instantaneous share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 0
        Rows filtered = 0
        Fetch Size = 16
                constructor time (milliseconds) = 0
                open time (milliseconds) = 0
                next time (milliseconds) = 0
                close time (milliseconds) = 0

        scan information:
                Bit set of columns fetched=All
                Number of columns fetched=1
                Number of pages visited=1
                Number of rows qualified=0
                Number of rows visited=0
                Scan type=heap
                start position:
null            stop position:
null            qualifiers:
None
                optimizer estimated row count:            6.00
                optimizer estimated cost:          100.40

Right result set:
        Hash Scan ResultSet for BAR at read committed isolation level using instantaneous share row locking:
        Number of opens = 0
        Hash table size = 0
        Hash key is column number 1
        Rows seen = 0
        Rows filtered = 0
                constructor time (milliseconds) = 0
                open time (milliseconds) = 0
                next time (milliseconds) = 0
                close time (milliseconds) = 0

        scan information:
                start position:
null            stop position:
null            scan qualifiers:
None
                next qualifiers:
Column[0][0] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false

                optimizer estimated row count:            3.60
                optimizer estimated cost:          100.50


-------------------------------------

Here is my hack, a nasty perl script:
--------------------------------------------------
# qparse.pl
#
# qparse.pl parses the derby.log file from stdin, extracting
# and "beutifying" the query plan generated by the property:
#
#   java -Dderby.language.logQueryPlan=true org.apache.derby.tools.ij test.sql
#
# Derby, jsk@yesco.org
#
# "Some people, when confronted with a problem, think
#  >>I know, I'll use regular expressions.<<
#  Now they have two problems. "
#       -Jamie Zawinski, in comp.lang.emacs


my $lastline;
my $lastindent;

while($lastline=$_, $_=<>) {
 redo:
  $lastindent = $1 if $lastline =~ /^( +)/;
  # - less wide "make a tab 1 spc"
  s/    / /g; # four spaces
  s/\t/ /g; # tab
  # - new query format
  (print, next) if s/.*\(SESSIONID.*?\),\s*(.*?)\s*\*\*\*\*\*\*\s*(.*)/\n$1\n****$2/;
  # - ignore lines
  next if /\*\* Sort ResultSet:/;
  next if /Index Row/;
  next if /Ordered null semantics/;
  # - modify/cleanup bad formatting
  s/^null(\s+)/$1/;
  # - print
  (print, next) if s/(Scan.*) at (.*)/$1/;
  (print, next) if /ResultSet/;
  (print, next) if /Number of opens/ && !/Number of opens = 1/;
  (print, next) if /Indexes updated/ && !/updated = 0/;
  (print, next) if s/.*\*\*\*+(.*)/$1/ms;
  (print, next) if s/\s*(\S+\s+on.*column.*)/$lastindent  $1/; # prints scan operator, doesn't have much indent!
  (print, next) if s/^null(\s+(start|stop) position:)/$1/;
  (print, next) if /(start|stop) position:/;
  # - special processing
  if (/Right/) {
    s/Right.*/With:/;
    print;
  }
  if (/qualifiers:/) {
    $lastindent = $1 if /^( +)/;
    my $first = $_; # avoid printing if nothing follows
    while (($_ = <>) && !/^[\s\t ]/) { # read nonindented lines
      if (/Operator:/) { # add more here with &&
	print $first; $first = ""; # print once
	print "$lastindent  $_";
      }
    }
    goto redo;
  }
  # - ignore rest
}