You are viewing a plain text version of this content. The canonical link for it is here.
Posted to derby-user@db.apache.org by John English <jo...@gmail.com> on 2012/12/20 12:47:27 UTC
Ideas for optimisation needed
I have a table representing a logfile, with a timestamp for each entry. There
are currently about 90,000 entries. When I display the log, I normally want to
see the most recent entries first, so the default order is by timestamp
descending. This typically takes about 20-25 seconds. If I want to know the
number of entries as well, I seek to the last row of the results set, get the
row number and seek back to the beginning again:
res.last();
nrows = res.getRow(); // no. of rows in result
res.beforeFirst();
This adds about another 10 seconds.
The only thing I've come up with as a way of speeding things up is to create an
index for the timestamp:
CREATE INDEX log_index ON system_log (time DESC);
but this seems to make little or no difference to the timing.
Can anyone suggest how I can reorganise things so that I can view the log
without having to wait for upwards of 30 seconds at a time?
TIA,
--
John English
Re: Ideas for optimisation needed
Posted by John English <jo...@gmail.com>.
On 21/12/2012 15:20, Jean-Yves Linet wrote:
> Do you have the same results if you exclude "details" field from your columns list ?
Yes. No significant change.
But: I'm trying it on my development system (127.0.0.1) since I can't play
around the live system, and the time varies by what other applications I have
open at the time, which suggests to me that there's a lot of swapping going on...
--
John English
Re: Ideas for optimisation needed
Posted by Jean-Yves Linet <jy...@gmail.com>.
Do you have the same results if you exclude "details" field from your
columns list ?
2012/12/21 John English <jo...@gmail.com>
> On 20/12/2012 14:12, Jean-Yves Linet wrote:
>
>> Hi,
>> May you could give more details about the structure of your table.
>>
>
> The table looks like this:
>
> CREATE TABLE system_log (
> id INTEGER GENERATED ALWAYS AS IDENTITY,
> time TIMESTAMP DEFAULT NULL,
> username VARCHAR(15),
> facility VARCHAR(15) NOT NULL,
> event VARCHAR(31) NOT NULL,
> module VARCHAR(15),
> test VARCHAR(255),
> details VARCHAR(32000),
> CONSTRAINT systemlog_pk PRIMARY KEY (id)
> );
>
> I'm actually displaying a formatted view of the table:
>
> CREATE VIEW system_log_view AS
> SELECT TimeFormat(time) AS t_time,
> facility,
> event,
> details,
> NameFormat(username) AS name,
> username,
> module,
> test,
> id AS time
> FROM system_log;
>
> I had also suspected my formatting routines (TimeFormat, NameFormat), but
> I removed them and used "time as t_time" and "username as name" in place of
> the existing definitions of t_time and name. It made no noticeable
> difference.
>
>
> Anyway the response delay you have seams to be very slow compare with
>> what I
>> have with Derby.
>>
>
> It's much slower than I would expect too!
>
>
> I always read my resultset as forward only.
>> Try to make a first request with select count(*) to have the number of
>> rows.
>> and then a second request with an order by on time field and use only
>> next() method.
>>
>
> Yes, I tried that too, and it also made no noticeable difference.
>
> Thanks,
> --
> John English
>
Re: Ideas for optimisation needed
Posted by John English <jo...@gmail.com>.
On 21/12/2012 19:40, Knut Anders Hatlen wrote:
> If you run the query with derby.language.logQueryPlan=true and check
> derby.log, does the query plan say that log_index is used?
It seems to use it:
Sat Dec 22 18:44:54 IST 2012 Thread[qtp9851452-34,5,main] (XID = 5645972),
(SESSIONID = 18), SELECT DateTimeFormat(t_time,null) AS
t_time,facility,event,details,name,username,module,test FROM system_log_view
ORDER BY time DESC ******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 20
Number of reads from hash table = 21
Number of writes to hash table = 95103
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 95105.00
optimizer estimated cost: 237241.89
Source result set:
Project-Restrict ResultSet (4):
Number of opens = 1
Rows seen = 95103
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: 95105.00
optimizer estimated cost: 237241.89
Source result set:
Project-Restrict ResultSet (3):
Number of opens = 1
Rows seen = 95103
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: 95105.00
optimizer estimated cost: 237241.89
Source result set:
Index Row to Base Row ResultSet for SYSTEM_LOG:
Number of opens = 1
Rows seen = 95103
Columns accessed from heap = {2, 3, 4, 5, 6, 7}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 95105.00
optimizer estimated cost: 237241.89
Index Scan ResultSet for SYSTEM_LOG using index LOG_INDEX at read
uncommitted isolation level using share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 95103
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=715
Number of rows qualified=95103
Number of rows visited=95103
Scan type=btree
Tree height=3
start position:
None
stop position:
None
qualifiers:
None
optimizer estimated row count: 95105.00
optimizer estimated cost: 237241.89
> Does it change anything if you access the table directly instead of via
> the view? I think we've had reports that the optimizer cannot always see
> through the views and misses out on some opportunities for optimization.
It cuts it down to about 9 seconds, which is much more acceptable. The time is
no longer formatted, but when I tried taking that out before it didn't seem to
make much difference, so maybe it is the view. I'll try some more experiments
with different variations of formatting and views and see what I can find out.
Thanks,
--
John English
Re: Ideas for optimisation needed
Posted by Bryan Pendleton <bp...@gmail.com>.
> The change in timing is spectacular: it now takes about 0.4 seconds
Great news!
I think it would be cool if you could write up a short summary of
your findings and put it on the "hints and tips" section of the
Derby community wiki.
thanks,
bryan
Re: Ideas for optimisation needed
Posted by John English <jo...@gmail.com>.
On 21/12/2012 19:40, Knut Anders Hatlen wrote:
> Does it change anything if you access the table directly instead of via
> the view? I think we've had reports that the optimizer cannot always see
> through the views and misses out on some opportunities for optimization.
Aha; what seems to happen is that in order to count the number of rows it reads
though the entire result set from the view, which seems to involve formatting
every single row...
I've ended up basically rewriting most of the code involved; I now count the
rows in a separate query (as suggested earlier by Jean-Yves Linet), which allows
me to use an offset/fetch clause (which are new in Derby since this code was
originally written). The change in timing is spectacular: it now takes about 0.4
seconds if I only want the first 20 rows, which is about 50 times faster than
before.
So, problem solved it seems; many thanks for the advice!
--
John English
Re: Ideas for optimisation needed
Posted by Knut Anders Hatlen <kn...@oracle.com>.
John English <jo...@gmail.com> writes:
> On 20/12/2012 14:12, Jean-Yves Linet wrote:
>> Hi,
>> May you could give more details about the structure of your table.
>
> The table looks like this:
>
> CREATE TABLE system_log (
> id INTEGER GENERATED ALWAYS AS IDENTITY,
> time TIMESTAMP DEFAULT NULL,
> username VARCHAR(15),
> facility VARCHAR(15) NOT NULL,
> event VARCHAR(31) NOT NULL,
> module VARCHAR(15),
> test VARCHAR(255),
> details VARCHAR(32000),
> CONSTRAINT systemlog_pk PRIMARY KEY (id)
> );
>
> I'm actually displaying a formatted view of the table:
If you run the query with derby.language.logQueryPlan=true and check
derby.log, does the query plan say that log_index is used?
Does it change anything if you access the table directly instead of via
the view? I think we've had reports that the optimizer cannot always see
through the views and misses out on some opportunities for optimization.
--
Knut Anders
Re: Ideas for optimisation needed
Posted by John English <jo...@gmail.com>.
On 20/12/2012 14:12, Jean-Yves Linet wrote:
> Hi,
> May you could give more details about the structure of your table.
The table looks like this:
CREATE TABLE system_log (
id INTEGER GENERATED ALWAYS AS IDENTITY,
time TIMESTAMP DEFAULT NULL,
username VARCHAR(15),
facility VARCHAR(15) NOT NULL,
event VARCHAR(31) NOT NULL,
module VARCHAR(15),
test VARCHAR(255),
details VARCHAR(32000),
CONSTRAINT systemlog_pk PRIMARY KEY (id)
);
I'm actually displaying a formatted view of the table:
CREATE VIEW system_log_view AS
SELECT TimeFormat(time) AS t_time,
facility,
event,
details,
NameFormat(username) AS name,
username,
module,
test,
id AS time
FROM system_log;
I had also suspected my formatting routines (TimeFormat, NameFormat), but I
removed them and used "time as t_time" and "username as name" in place of the
existing definitions of t_time and name. It made no noticeable difference.
> Anyway the response delay you have seams to be very slow compare with what I
> have with Derby.
It's much slower than I would expect too!
> I always read my resultset as forward only.
> Try to make a first request with select count(*) to have the number of rows.
> and then a second request with an order by on time field and use only next() method.
Yes, I tried that too, and it also made no noticeable difference.
Thanks,
--
John English
Re: Ideas for optimisation needed
Posted by Jean-Yves Linet <jy...@gmail.com>.
Hi,
May you could give more details about the structure of your table.
Anyway the response delay you have seams to be very slow compare with what
I have with Derby.
I always read my resultset as forward only.
Try to make a first request with select count(*) to have the number of rows.
and then a second request with an order by on time field and use only
next() method.
JYL
2012/12/20 John English <jo...@gmail.com>
> I have a table representing a logfile, with a timestamp for each entry.
> There are currently about 90,000 entries. When I display the log, I
> normally want to see the most recent entries first, so the default order is
> by timestamp descending. This typically takes about 20-25 seconds. If I
> want to know the number of entries as well, I seek to the last row of the
> results set, get the row number and seek back to the beginning again:
> res.last();
> nrows = res.getRow(); // no. of rows in result
> res.beforeFirst();
> This adds about another 10 seconds.
>
> The only thing I've come up with as a way of speeding things up is to
> create an index for the timestamp:
> CREATE INDEX log_index ON system_log (time DESC);
> but this seems to make little or no difference to the timing.
>
> Can anyone suggest how I can reorganise things so that I can view the log
> without having to wait for upwards of 30 seconds at a time?
>
> TIA,
> --
> John English
>