query runs longer on informix 11.50 than on 9.40
Hi,
I have the same query running less than 1s on 9.40 instance that runs during
23s on 11.50 instance with the same plan, as shown below :
informix@dmba01:dcoidcoi_tcp:/home/informix> onstat -
IBM Informix Dynamic Server Version 9.40.FC9 -- On-Line -- Up 86 days 00:05:05
-- 9935392 Kbytes
informix@dmba01:dcoidcoi_tcp:/home/informix> time dbaccess sysmaster << EOF> set explain on;> SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> FROM sysmaster:systabnames
> WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
> AND sysmaster:systabnames.tabname = 'i1_bkeve';
> EOF
Database selected.
Explain set.
(expression) hisidx1dbs1
1 row(s) retrieved.
Database closed.
real 0m0.65s
user 0m0.02s
sys 0m0.00s
informix@dmba01:dcoidcoi_tcp:
QUERY:
------
SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
FROM sysmaster:systabnames
WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
AND sysmaster:systabnames.tabname = 'i1_bkeve'
Estimated Cost: 8
Estimated # of Rows Returned: 1
1) informix.systabnames: SEQUENTIAL SCAN
Filters: (informix.systabnames.tabname = 'i1_bkeve' AND
informix.systabnames.dbsname = 'sgbci99000' )
informix@dmba01:dcoidcoi_tcp:/home/informix> dbaccess sysmaster << EOF
> select count(*) from systabnames;> EOF
Database selected.
(count(*))
34634
informix@dmba01:dtgodtgo_tcp:/produits/informix/115FC9/etc> onstat -
IBM Informix Dynamic Server Version 11.50.FC9 -- On-Line -- Up 00:00:28 --709344 Kbytes
informix@dmba01:dtgodtgo_tcp:/home/informix> time dbaccess sysmaster << EOF
> SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> FROM sysmaster:systabnames
> WHERE sysmaster:systabnames.dbsname = 'eng'
> AND sysmaster:systabnames.tabname = 'i1_bkeve';
> EOF
Database selected.
(expression) domix1dbs1
1 row(s) retrieved.
Database closed.
real 0m23.20s
user 0m0.01s
sys 0m0.00s
QUERY: (OPTIMIZATION TIMESTAMP: 06-17-2014 16:49:40)
------
SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
FROM sysmaster:systabnames
WHERE sysmaster:systabnames.dbsname = 'eng'
AND sysmaster:systabnames.tabname = 'i1_bkeve'
Estimated Cost: 9
Estimated # of Rows Returned: 1
1) informix.systabnames: SEQUENTIAL SCAN
Filters: (informix.systabnames.tabname = 'i1_bkeve' AND
informix.systabnames.dbsname = 'eng' )
Query statistics:
-----------------
Table map :
----------------------------
Internal name Table name
----------------------------
t1 systabnames
type table rows_prod est_rows rows_scan time est_cost
-------------------------------------------------------------------
scan t1 1 1 63998 00:34.83 9
Can someone, please explain why ?
Original Post:
Hi,
I have the same query running less than 1s on 9.40 instance that runs during
23s on 11.50 instance with the same plan, as shown below :
informix@dmba01:dcoidcoi_tcp:/home/informix> onstat -
IBM Informix Dynamic Server Version 9.40.FC9 -- On-Line -- Up 86 days 00:05:05
-- 9935392 Kbytes
informix@dmba01:dcoidcoi_tcp:/home/informix> time dbaccess sysmaster << EOF> set explain on;> SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> FROM sysmaster:systabnames
> WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
> AND sysmaster:systabnames.tabname = 'i1_bkeve';
> EOF
Database selected.
Explain set.
(expression) hisidx1dbs1
1 row(s) retrieved.
Database closed.
real 0m0.65s
user 0m0.02s
sys 0m0.00s
informix@dmba01:dcoidcoi_tcp:
QUERY:
------
SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
FROM sysmaster:systabnames
WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
AND sysmaster:systabnames.tabname = 'i1_bkeve'
Estimated Cost: 8
Estimated # of Rows Returned: 1
1) informix.systabnames: SEQUENTIAL SCAN
Filters: (informix.systabnames.tabname = 'i1_bkeve' AND
informix.systabnames.dbsname = 'sgbci99000' )
informix@dmba01:dcoidcoi_tcp:/home/informix> dbaccess sysmaster << EOF
> select count(*) from systabnames;> EOF
Database selected.
(count(*))
34634
informix@dmba01:dtgodtgo_tcp:/produits/informix/115FC9/etc> onstat -
IBM Informix Dynamic Server Version 11.50.FC9 -- On-Line -- Up 00:00:28 --709344 Kbytes
informix@dmba01:dtgodtgo_tcp:/home/informix> time dbaccess sysmaster << EOF
> SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> FROM sysmaster:systabnames
> WHERE sysmaster:systabnames.dbsname = 'eng'
> AND sysmaster:systabnames.tabname = 'i1_bkeve';
> EOF
Database selected.
(expression) domix1dbs1
1 row(s) retrieved.
Database closed.
real 0m23.20s
user 0m0.01s
sys 0m0.00s
QUERY: (OPTIMIZATION TIMESTAMP: 06-17-2014 16:49:40)
------
SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
FROM sysmaster:systabnames
WHERE sysmaster:systabnames.dbsname = 'eng'
AND sysmaster:systabnames.tabname = 'i1_bkeve'
Estimated Cost: 9
Estimated # of Rows Returned: 1
1) informix.systabnames: SEQUENTIAL SCAN
Filters: (informix.systabnames.tabname = 'i1_bkeve' AND
informix.systabnames.dbsname = 'eng' )
Query statistics:
-----------------
Table map :
----------------------------
Internal name Table name
----------------------------
t1 systabnames
type table rows_prod est_rows rows_scan time est_cost
-------------------------------------------------------------------
scan t1 1 1 63998 00:34.83 9
Can someone, please explain why ?
Response:
Well, your 9.40 instance has nearly 10Gb of memory for it, the 11 instance has
less then 1 Gb...Both plans take the same path, as you mention, so my guess is
in your 9.40 instance all the pages required for the sysmaster query are in
the buffer pool, but on 11 they are not, so the query has to pull pages from
disk.
That might be more obvious if you looked at thread profile outout and compare
disk and buffer reads between the 2 versions.
The other possible difference is the 11.50 instance has more databases and
tables created then your 9.40 instance...since it is going to do a scan of all
partition pages on the instance looking for the partition page for the table
you are looking for....so if you have more used partition pages because of
more databases and tables, that would take more time.
But best bet is likely the IO and in 9.40 all the partition pages are in
memory but in 11 they are not.
Jacques Renaut
IBM Informix Advanced Support
APD Team
Gilles:
Could be a combination of a number of things:
1. Your 9.40 systabnames has 34,634 objects in it, your 11.50
systabnames has 63,998 objects. This difference might be caused by
older legacy attached indexes in 9.40 (was the default prior to v7.30/9.11)
being created as detached indexes (the default now) in 11.50 when you
imported your database. More objects, more time to scan the tables' and
indexes' partition pages.
2. It may also be that you have fragmented (partitioned) your tables
and indexes in 11.50 more aggressively than you did in 9.40. Again, more
objects, more time to scan the tables' and indexes' partition pages.
3. Your dbspace layout may be different between the two servers. Each
object (table, index, table fragment, or index fragment) has a partition
header page (possibly more than one in 11.70+, but you are using 11.50, so
one) which lives in the dbspace that contains that partition. If the
number of partitions in a dbspace was large, and you did not increase the
size of the tablespace tablespace (the virtual table that contains the
partition header pages) at the time you created the dbspace, then the
tablespace tablespace may be fragmented (bad kind) across several extents
and possible across multiple chunks. The layout may be different in 11.50
than it was in 9.40 due to the order in which objects were created and
space was consumed as the database was imported into 11.50 versus how it
was initially created in 9.40. As bad as fragmentation is for user tables,
its effects can be worse for system objects like the tablespace tablespace,
especially when you are querying it directly as you are in this query.
Art
Art S. Kagel, Principal Consultant
ASK Database Management
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions
and do not reflect on the IIUG, nor any other organization with which I am
associated either explicitly, implicitly, or by inference. Neither do
those opinions reflect those of other individuals affiliated with any
entity with which I am affiliated nor those of the entities themselves.
On Tue, Jun 17, 2014 at 11:29 AM, GILLES TCHAPPI <giltfr@yahoo.fr> wrote:
> Hi,
>
> I have the same query running less than 1s on 9.40 instance that runs
> during
> 23s on 11.50 instance with the same plan, as shown below :
>
> informix@dmba01:dcoidcoi_tcp:/home/informix> onstat -
>
> IBM Informix Dynamic Server Version 9.40.FC9 -- On-Line -- Up 86 days
> 00:05:05
> -- 9935392 Kbytes
>
> informix@dmba01:dcoidcoi_tcp:/home/informix> time dbaccess sysmaster <<> EOF
> > set explain on;> > SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> > FROM sysmaster:systabnames
> > WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
> > AND sysmaster:systabnames.tabname = 'i1_bkeve';
> > EOF
>
> Database selected.
>
> Explain set.
>
> (expression) hisidx1dbs1
>
> 1 row(s) retrieved.
>
> Database closed.
>
> real 0m0.65s
> user 0m0.02s
> sys 0m0.00s
>
> informix@dmba01:dcoidcoi_tcp:
>
> QUERY:
> ------
> SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> FROM sysmaster:systabnames
> WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
> AND sysmaster:systabnames.tabname = 'i1_bkeve'
>
> Estimated Cost: 8
> Estimated # of Rows Returned: 1
>
> 1) informix.systabnames: SEQUENTIAL SCAN
>
> Filters: (informix.systabnames.tabname = 'i1_bkeve' AND
> informix.systabnames.dbsname = 'sgbci99000' )
>
> informix@dmba01:dcoidcoi_tcp:/home/informix> dbaccess sysmaster << EOF
> > select count(*) from systabnames;> > EOF
>
> Database selected.
>
> (count(*))
>
> 34634
>
> informix@dmba01:dtgodtgo_tcp:/produits/informix/115FC9/etc> onstat -
>
> IBM Informix Dynamic Server Version 11.50.FC9 -- On-Line -- Up 00:00:28 --> 709344 Kbytes
>
> informix@dmba01:dtgodtgo_tcp:/home/informix> time dbaccess sysmaster <<
> EOF
> > SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> > FROM sysmaster:systabnames
> > WHERE sysmaster:systabnames.dbsname = 'eng'
> > AND sysmaster:systabnames.tabname = 'i1_bkeve';
> > EOF
>
> Database selected.
>
> (expression) domix1dbs1
>
> 1 row(s) retrieved.
>
> Database closed.
>
> real 0m23.20s
> user 0m0.01s
> sys 0m0.00s
>
> QUERY: (OPTIMIZATION TIMESTAMP: 06-17-2014 16:49:40)
> ------
> SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
> FROM sysmaster:systabnames
> WHERE sysmaster:systabnames.dbsname = 'eng'
> AND sysmaster:systabnames.tabname = 'i1_bkeve'
>
> Estimated Cost: 9
> Estimated # of Rows Returned: 1
>
> 1) informix.systabnames: SEQUENTIAL SCAN
>
> Filters: (informix.systabnames.tabname = 'i1_bkeve' AND
> informix.systabnames.dbsname = 'eng' )
>
> Query statistics:
> -----------------
>
> Table map :
> ----------------------------
> Internal name Table name
> ----------------------------
> t1 systabnames
>
> type table rows_prod est_rows rows_scan time est_cost
> -------------------------------------------------------------------
> scan t1 1 1 63998 00:34.83 9
>
> Can someone, please explain why ?
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--047d7b3a8f588719d604fc0a2075
Hi,
and thanks for ur answer.
As this 11.50 instance is migrated from an earlier 9.40 instance. I just
modifyed the BUFFERPOOL parameter in my 11.5 instance
from
BUFFERPOOL
size=4K,buffers=50000,lrus=8,lru_min_dirty=50.000000,lru_max_dirty=60.000000to
BUFFERPOOL
size=4K,buffers=1101004,lrus=8,lru_min_dirty=50.000000,lru_max_dirty=60.000000
I ran the query again. And i have this now :
informix@dmba01:dtgodtgo_tcp:/produits/informix/115FC9/etc> onstat -
IBM Informix Dynamic Server Version 11.50.FC9 -- On-Line -- Up 00:27:43 --5635664 Kbytes
informix@dmba01:dtgodtgo_tcp:/produits/informix/115FC9/etc> time dbaccess
sysmaster << EOF
set explain on;SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
FROM sysmaster:systabnames
WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
AND sysmaster:systabnames.tabname = 'i1_bkeve'
EOF
Database selected.
Explain set.
(expression) domix1dbs1
1 row(s) retrieved.
Database closed.
real 0m0.38s
user 0m0.01s
sys 0m0.00s
informix@dmba01:dtgodtgo_tcp:/produits/informix/115FC9/etc> time dbaccess
sysmaster << EOF
set explain on;SELECT dbinfo('DBSPACE',sysmaster:systabnames.partnum)
FROM sysmaster:systabnames
WHERE sysmaster:systabnames.dbsname = 'sgbci99000'
AND sysmaster:systabnames.tabname = 'i1_bkeve'
EOF
Database selected.
Explain set.
(expression) domix1dbs1
1 row(s) retrieved.
Database closed.
real 0m0.44s
user 0m0.02s
sys 0m0.01s
Best regards