Pathologically poor query performance - advice required

View: New views

6 Messages — Rating Filter: Alert me

Pathologically poor query performance - advice required

by Matt Doran-3 :: Rate this Message:

Reply to Author | View Threaded | Show Only this Message

Hi there,

We use Derby in our print monitoring product, PaperCut NG. We've
generally had a great experience with it (fast, reliable, etc), but I've
encountered a very strange performance problem that I'm unable to
explain and would love some advice from Derby gurus or devs.

We're using the latest Derby (10.4.1.3), and the queries were initially
generated by Hibernate ORM.

When displaying print logs in our application we do a query that joins 5
tables, and selects many fields, and sorts by date descending to show
the latest logs first (see original-slow-query.sql). We also apply a
JDBC limit to only return the first 25 rows. To handle pagination we
first do a count(*) using the same join and where clause to determine
how many rows, and then perform the actual query. We have a sample
database that shows the following performance:
* Count query - takes in the order of 1-2 seconds
* Select query - takes about 1 hour !! (Even when returning only 4
rows)

The key table in this query (tbl_printer_usage_log) has about 130,000
rows. The where clause applies a filter to the date column (which is
indexed) such that only 4 columns are returned. This should be a fast
operation, but the optimizer is choosing a poor execution plan.

I did further investigation to find the cause of the slowness ... that's
where things got stranger. I removed 2 of the join table and associated
fields but the performance didn't change significantly. So I then
started removing the selected columns from the original. This produced
some dramatic and surprising results. I tried various combinations of
fields selected, but couldn't establish any real patterns. But I've
attached 2 of these modified queries and associated query plans.
* modified-slow-query.sql - removed all but 10 of the selected fields
* modified-fast-query.sql - removed a single field from
"modified-slow-query.sql"

The slow version of this modified query still takes about 1 hour to run
(for query plan see derby-log-modified-slow.log). The fast version runs
in seconds and returns 4 results (for query plan see
derby-log-modified-fast.log).

Both of these queries only return fields from 2 of the joined tables.
The slow one selects 5 fields from each of these tables. The fast one
selects 5 fields from one table and 4 fields from the other. Strange
indeed!!

So something is going on to cause the optimizer to choose completely the
wrong plan. I wonder why it isn't eliminating 99.99% of the rows using
the obvious indexed where clause. Is this example hitting some
edge-case in the optimizer making it choose the wrong path?

You can download a copy of this database from the link below (17MB
zipped). Also, to make sure things were in order and statistics were
updated, etc I ran "SYSCS_UTIL.SYSCS_COMPRESS_TABLE" on all the tables.

http://www.papercut.com/tmp/derby.zip

So does anybody understand what might be happening here? How I could go
about improving the performance? Is this something in the derby
optimizer that needs looking into?

I look forward to any insights you can provide!!

Regards,
Matt

SELECT printerusa0_.printer_usage_log_id AS printer1_0_ ,
printer1_.printer_id AS printer1_1_ ,
user2_.user_id AS user1_2_ ,
account3_.account_id AS account1_3_ ,
account4_.account_id AS account1_4_ ,
printerusa0_.usage_date AS usage2_10_0_ ,
printerusa0_.usage_day AS usage3_10_0_ ,
printerusa0_.used_by_user_id AS used4_10_0_ ,
printerusa0_.charged_to_account_id AS charged5_10_0_ ,
printerusa0_.usage_cost AS usage6_10_0_ ,
printerusa0_.usage_allowed AS usage7_10_0_ ,
printerusa0_.printer_id AS printer8_10_0_ ,
printerusa0_.job_id AS job9_10_0_ ,
printerusa0_.document_name AS document10_10_0_,
printerusa0_.client_machine AS client11_10_0_ ,
printerusa0_.total_pages AS total12_10_0_ ,
printerusa0_.copies AS copies10_0_ ,
printerusa0_.paper_size AS paper14_10_0_ ,
printerusa0_.paper_height_mm AS paper15_10_0_ ,
printerusa0_.paper_width_mm AS paper16_10_0_ ,
printerusa0_.printer_language AS printer17_10_0_ ,
printerusa0_.document_size_kb AS document18_10_0_,
printerusa0_.denied_reason AS denied19_10_0_ ,
printerusa0_.duplex AS duplex10_0_ ,
printerusa0_.gray_scale AS gray21_10_0_ ,
printerusa0_.printed AS printed10_0_ ,
printerusa0_.cancelled AS cancelled10_0_ ,
printerusa0_.refunded AS refunded10_0_ ,
printerusa0_.assoc_with_account_id AS assoc25_10_0_ ,
printerusa0_.total_color_pages AS total26_10_0_ ,
printerusa0_.color_pages_estimated AS color27_10_0_ ,
printerusa0_.job_type AS job28_10_0_ ,
printerusa0_.invoiced AS invoiced10_0_ ,
printerusa0_.job_comment AS job30_10_0_ ,
printer1_.server_name AS server2_8_1_ ,
printer1_.printer_name AS printer3_8_1_ ,
printer1_.display_name AS display4_8_1_ ,
printer1_.location AS location8_1_ ,
printer1_.notes AS notes8_1_ ,
printer1_.charge_type AS charge7_8_1_ ,
printer1_.default_cost AS default8_8_1_ ,
printer1_.deleted AS deleted8_1_ ,
printer1_.deleted_date AS deleted10_8_1_ ,
printer1_.disabled AS disabled8_1_ ,
printer1_.disabled_until AS disabled12_8_1_ ,
printer1_.total_jobs AS total13_8_1_ ,
printer1_.total_pages AS total14_8_1_ ,
printer1_.reset_by AS reset15_8_1_ ,
printer1_.reset_date AS reset16_8_1_ ,
printer1_.created_date AS created17_8_1_ ,
printer1_.created_by AS created18_8_1_ ,
printer1_.modified_date AS modified19_8_1_ ,
printer1_.modified_by AS modified20_8_1_ ,
printer1_.color_detection_mode AS color21_8_1_ ,
printer1_.device_type AS device22_8_1_ ,
printer1_.ext_device_function AS ext23_8_1_ ,
user2_.user_name AS user2_13_2_ ,
user2_.external_user_name AS external3_13_2_ ,
user2_.full_name AS full4_13_2_ ,
user2_.email AS email13_2_ ,
user2_.notes AS notes13_2_ ,
user2_.total_jobs AS total7_13_2_ ,
user2_.total_pages AS total8_13_2_ ,
user2_.reset_by AS reset9_13_2_ ,
user2_.reset_date AS reset10_13_2_ ,
user2_.deleted AS deleted13_2_ ,
user2_.deleted_date AS deleted12_13_2_ ,
user2_.created_date AS created13_13_2_ ,
user2_.created_by AS created14_13_2_ ,
user2_.modified_date AS modified15_13_2_,
user2_.modified_by AS modified16_13_2_,
user2_.department AS department13_2_ ,
user2_.office AS office13_2_ ,
user2_.card_number AS card19_13_2_ ,
user2_.disabled_printing AS disabled20_13_2_,
user2_.disabled_printing_until AS disabled21_13_2_,
user2_.net_reset_by AS net22_13_2_ ,
user2_.net_reset_date AS net23_13_2_ ,
user2_.net_total_megabytes AS net24_13_2_ ,
user2_.net_total_time_hours AS net25_13_2_ ,
user2_.disabled_net AS disabled26_13_2_,
user2_.disabled_net_until AS disabled27_13_2_,
account3_.account_type AS account2_0_3_ ,
account3_.account_name AS account3_0_3_ ,
account3_.balance AS balance0_3_ ,
account3_.restricted AS restricted0_3_ ,
account3_.overdraft AS overdraft0_3_ ,
account3_.pin AS pin0_3_ ,
account3_.use_global_overdraft AS use8_0_3_ ,
account3_.notes AS notes0_3_ ,
account3_.deleted AS deleted0_3_ ,
account3_.deleted_date AS deleted11_0_3_ ,
account3_.created_date AS created12_0_3_ ,
account3_.created_by AS created13_0_3_ ,
account3_.modified_date AS modified14_0_3_ ,
account3_.modified_by AS modified15_0_3_ ,
account3_.parent_id AS parent16_0_3_ ,
account3_.account_name_lower AS account17_0_3_ ,
account3_.sub_name AS sub18_0_3_ ,
account3_.sub_name_lower AS sub19_0_3_ ,
account3_.disabled AS disabled0_3_ ,
account3_.disabled_until AS disabled21_0_3_ ,
account3_.comments AS comments0_3_ ,
account3_.invoicing AS invoicing0_3_ ,
account3_.sub_pin AS sub24_0_3_ ,
account4_.account_type AS account2_0_4_ ,
account4_.account_name AS account3_0_4_ ,
account4_.balance AS balance0_4_ ,
account4_.restricted AS restricted0_4_ ,
account4_.overdraft AS overdraft0_4_ ,
account4_.pin AS pin0_4_ ,
account4_.use_global_overdraft AS use8_0_4_ ,
account4_.notes AS notes0_4_ ,
account4_.deleted AS deleted0_4_ ,
account4_.deleted_date AS deleted11_0_4_ ,
account4_.created_date AS created12_0_4_ ,
account4_.created_by AS created13_0_4_ ,
account4_.modified_date AS modified14_0_4_ ,
account4_.modified_by AS modified15_0_4_ ,
account4_.parent_id AS parent16_0_4_ ,
account4_.account_name_lower AS account17_0_4_ ,
account4_.sub_name AS sub18_0_4_ ,
account4_.sub_name_lower AS sub19_0_4_ ,
account4_.disabled AS disabled0_4_ ,
account4_.disabled_until AS disabled21_0_4_ ,
account4_.comments AS comments0_4_ ,
account4_.invoicing AS invoicing0_4_ ,
account4_.sub_pin AS sub24_0_4_
FROM tbl_printer_usage_log printerusa0_
INNER JOIN tbl_printer printer1_
ON printerusa0_.printer_id=printer1_.printer_id
INNER JOIN tbl_user user2_
ON printerusa0_.used_by_user_id=user2_.user_id
INNER JOIN tbl_account account3_
ON printerusa0_.charged_to_account_id=account3_.account_id
INNER JOIN tbl_account account4_
ON printerusa0_.assoc_with_account_id=account4_.account_id
WHERE printerusa0_.usage_date >='2008-06-25 00:00:00'
ORDER BY printerusa0_.usage_date DESC
SELECT account3_.account_type AS account2_0_3_ ,
account3_.account_name AS account3_0_3_ ,
account3_.balance AS balance0_3_ ,
account3_.restricted AS restricted0_3_,
account3_.overdraft AS overdraft0_3_ ,
account4_.account_type AS account2_0_4_ ,
account4_.account_name AS account3_0_4_ ,
account4_.balance AS balance0_4_ ,
account4_.restricted AS restricted0_4_
FROM tbl_printer_usage_log printerusa0_
INNER JOIN tbl_printer printer1_
ON printerusa0_.printer_id=printer1_.printer_id
INNER JOIN tbl_user user2_
ON printerusa0_.used_by_user_id=user2_.user_id
INNER JOIN tbl_account account3_
ON printerusa0_.charged_to_account_id=account3_.account_id
INNER JOIN tbl_account account4_
ON printerusa0_.assoc_with_account_id=account4_.account_id
WHERE printerusa0_.usage_date >='2008-06-25 00:00:00'
ORDER BY printerusa0_.usage_date DESC
SELECT account3_.account_type AS account2_0_3_ ,
account3_.account_name AS account3_0_3_ ,
account3_.balance AS balance0_3_ ,
account3_.restricted AS restricted0_3_,
account3_.overdraft AS overdraft0_3_ ,
account4_.account_type AS account2_0_4_ ,
account4_.account_name AS account3_0_4_ ,
account4_.balance AS balance0_4_ ,
account4_.restricted AS restricted0_4_,
account4_.overdraft AS overdraft0_4_
FROM tbl_printer_usage_log printerusa0_
INNER JOIN tbl_printer printer1_
ON printerusa0_.printer_id=printer1_.printer_id
INNER JOIN tbl_user user2_
ON printerusa0_.used_by_user_id=user2_.user_id
INNER JOIN tbl_account account3_
ON printerusa0_.charged_to_account_id=account3_.account_id
INNER JOIN tbl_account account4_
ON printerusa0_.assoc_with_account_id=account4_.account_id
WHERE printerusa0_.usage_date >='2008-06-25 00:00:00'
ORDER BY printerusa0_.usage_date DESC
----------------------------------------------------------------
2008-06-25 04:50:23.156 GMT:
Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-be0e-dea8-0000003eca50
on database directory C:\Development\pc-ng\server\working\data\internal\derby

Database Class Loader started - derby.database.classpath=''
2008-06-25 04:50:26.385 GMT Thread[main,5,main] (XID = 5924105), (SESSIONID = 0), select account3_.account_type as account2_0_3_, account3_.account_name as account3_0_3_, account3_.balance as balance0_3_, account3_.restricted as restricted0_3_, account3_.overdraft as overdraft0_3_, account4_.account_type as account2_0_4_, account4_.account_name as account3_0_4_, account4_.balance as balance0_4_, account4_.restricted as restricted0_4_ from tbl_printer_usage_log printerusa0_ inner join tbl_printer printer1_ on printerusa0_.printer_id=printer1_.printer_id inner join tbl_user user2_ on printerusa0_.used_by_user_id=user2_.user_id inner join tbl_account account3_ on printerusa0_.charged_to_account_id=account3_.account_id inner join tbl_account account4_ on printerusa0_.assoc_with_account_id=account4_.account_id where printerusa0_.usage_date>='2008-06-25 00:00:00' order by printerusa0_.usage_date desc ******* Project-Restrict ResultSet (13):
Number of opens = 1
Rows seen = 4
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 394107.71

Source result set:
Project-Restrict ResultSet (12):
Number of opens = 1
Rows seen = 4
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 394107.71

Source result set:
Hash Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 394107.71

Left result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 391594.87

Left result set:
Hash Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 137663.82

Left result set:
Hash Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 137006.80

Left result set:
Index Row to Base Row ResultSet for TBL_PRINTER_USAGE_LOG:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {1, 3, 4, 7, 24}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 136866.79

Index Scan ResultSet for TBL_PRINTER_USAGE_LOG using index IX_PRINTER_USAGE_LOG_DATE_DESC at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0

scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=2
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=-1
start position:
None
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:

qualifiers:
None
optimizer estimated row count: 43459.02
optimizer estimated cost: 136866.79

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

scan information:
Bit set of columns fetched={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=1
Number of rows qualified=38
Number of rows visited=38
Scan type=btree
Tree height=1
start position:
None
stop position:
None
scan qualifiers:
None
next qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false

optimizer estimated row count: 43459.02
optimizer estimated cost: 140.02

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

scan information:
Bit set of columns fetched={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=3
Number of rows qualified=1841
Number of rows visited=1841
Scan type=btree
Tree height=2
start position:
None
stop position:
None
scan qualifiers:
None
next qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false

optimizer estimated row count: 43459.02
optimizer estimated cost: 657.02

Right result set:
Index Row to Base Row ResultSet for TBL_ACCOUNT:
Number of opens = 4
Rows seen = 4
Columns accessed from heap = {1, 2, 3, 4, 5}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 43459.02
optimizer estimated cost: 253931.05

Index Scan ResultSet for TBL_ACCOUNT using constraint SQL080107171318410 at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 4
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0

scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=8
Number of rows qualified=4
Number of rows visited=4
Scan type=btree
Tree height=2
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
None
optimizer estimated row count: 43459.02
optimizer estimated cost: 253931.05

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

scan information:
Bit set of columns fetched={0, 1, 2, 3, 4}
Number of columns fetched=5
Number of pages visited=17
Number of rows qualified=1853
Number of rows visited=1853
Scan type=heap
start position:
null stop position:
null scan qualifiers:
None
next qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false

optimizer estimated row count: 43459.02
optimizer estimated cost: 2512.84

----------------------------------------------------------------
2008-06-25 03:25:06.344 GMT:
Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-bdc0-cb27-0000003eca50
on database directory C:\Development\pc-ng\server\working\data\internal\derby

Database Class Loader started - derby.database.classpath=''
2008-06-25 04:19:14.101 GMT Thread[main,5,main] (XID = 5924088), (SESSIONID = 0), select account3_.account_type as account2_0_3_, account3_.account_name as account3_0_3_, account3_.balance as balance0_3_, account3_.restricted as restricted0_3_, account3_.overdraft as overdraft0_3_, account4_.account_type as account2_0_4_, account4_.account_name as account3_0_4_, account4_.balance as balance0_4_, account4_.restricted as restricted0_4_, account4_.overdraft as overdraft0_4_ from tbl_printer_usage_log printerusa0_ inner join tbl_printer printer1_ on printerusa0_.printer_id=printer1_.printer_id inner join tbl_user user2_ on printerusa0_.used_by_user_id=user2_.user_id inner join tbl_account account3_ on printerusa0_.charged_to_account_id=account3_.account_id inner join tbl_account account4_ on printerusa0_.assoc_with_account_id=account4_.account_id where printerusa0_.usage_date>='2008-06-25 00:00:00' order by printerusa0_.usage_date desc ******* Project-Restrict ResultSet (16):
Number of opens = 1
Rows seen = 4
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 490215.01

Source result set:
Sort ResultSet:
Number of opens = 1
Rows input = 4
Rows returned = 4
Eliminate duplicates = false
In sorted order = false
Sort information:
Number of rows input=4
Number of rows output=4
Sort type=internal
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 490215.01

Source result set:
Project-Restrict ResultSet (14):
Number of opens = 1
Rows seen = 4
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 490215.01

Source result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 490215.01

Left result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 464822.87

Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 69958
Rows seen from the right = 4
Rows filtered = 0
Rows returned = 4
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 439430.73

Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 38
Rows seen from the right = 69958
Rows filtered = 0
Rows returned = 69958
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 79378.00
optimizer estimated cost: 26805.84

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

scan information:
Bit set of columns fetched={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=1
Number of rows qualified=38
Number of rows visited=38
Scan type=btree
Tree height=1
start position:
None
stop position:
None
qualifiers:
None
optimizer estimated row count: 43.00
optimizer estimated cost: 139.18

Right result set:
Index Scan ResultSet for TBL_USER using constraint SQL080107171322060 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 38
Rows seen = 69958
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0

scan information:
Bit set of columns fetched={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=114
Number of rows qualified=69958
Number of rows visited=69958
Scan type=btree
Tree height=2
start position:
None
stop position:
None
qualifiers:
None
optimizer estimated row count: 79378.00
optimizer estimated cost: 26666.66

Right result set:
Project-Restrict ResultSet (9):
Number of opens = 69958
Rows seen = 242439449
Rows filtered = 242439445
restriction = true
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 412624.89

Source result set:
Index Row to Base Row ResultSet for TBL_PRINTER_USAGE_LOG:
Number of opens = 69958
Rows seen = 242439449
Columns accessed from heap = {1, 3, 4, 7, 24}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 412624.89

Index Scan ResultSet for TBL_PRINTER_USAGE_LOG using constraint FK_PRINTER_USAGE_LOG_PRINTER at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 69958
Rows seen = 242439449
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0

scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=327698
Number of rows qualified=242439449
Number of rows visited=242507566
Scan type=btree
Tree height=2
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
None
optimizer estimated row count: 4345.74
optimizer estimated cost: 412624.89

Right result set:
Index Row to Base Row ResultSet for TBL_ACCOUNT:
Number of opens = 4
Rows seen = 4
Columns accessed from heap = {1, 2, 3, 4, 5}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 25392.14

Index Scan ResultSet for TBL_ACCOUNT using constraint SQL080107171318410 at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 4
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0

scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=8
Number of rows qualified=4
Number of rows visited=4
Scan type=btree
Tree height=2
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
None
optimizer estimated row count: 4345.74
optimizer estimated cost: 25392.14

Right result set:
Index Row to Base Row ResultSet for TBL_ACCOUNT:
Number of opens = 4
Rows seen = 4
Columns accessed from heap = {1, 2, 3, 4, 5}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4345.74
optimizer estimated cost: 25392.14

Index Scan ResultS