Re: Found a possible bug in IDS 11.x... and a nasty one at that... has anyone suffered this?
Fernando Nunes wrote:
> fandelau wrote:
>> Hello to all!
>> I think I've found a nasty bug in IDS 11.xx on Solaris (SunOS 5.10)
>> (yes I got the same results in both 11.10.FC3 and 11.50.FC3)... here
>> are the details:
>>
>> I got a table 402 bytes wide, 78 columns all but 1 are either integer
>> or float/decimal, with 13.1 million records in it (please find the
>> schema below). Table has 1 extent and it is not fragmented. I was
>> requested to index 13 of the columns, all single column indexes
>> indexes, which were created in a separate dbspace from the data. One
>> of the indexes is on a column that has 11 million nulls, the other 2.1
>> million records have what I would call normal cardinality. A simple
>> query (on a freshly bounced instance) with a range filter on that
>> column returns in about 45 minutes on 11.10 and 22 minutes on 11.50,
>> having the query optimizer choose an index path on the index in
>> question. When the index was dropped and the same query ran on a seq
>> scan, it took 1.5 minutes on either version (freshly bounced)...
>>
>> select kic_kepler_id, ra, dec, kic_teff from kicplus where>> kic_teff>5000 and kic_teff<6500
>> being kic_teff the indexed column.
>>
>> I have ran the query as a count, as opposed to fetching any columns
>> and it comes back in a few seconds...
>>
>> select count(*) from kicplus where kic_teff>5000 and>> kic_teff<6500
>>
>> So the index is being used correctly and finds the data requested.
>>
>> I know the cardinality of the column is skewed, but 44/22 minutes?
>>
>> I have already opened a call with IBM, and they were able to duplicate
>> this behavior, and they tried to blame it on engine config. While they
>> were doing their thing, I tried this in 2 other servers with different
>> configurations (same platform) and gotten the exact same results...
>> I'm willing to grant that engine config would slow down the query a
>> bit, perhaps from a few seconds to a couple of minutes, 5 minutes
>> max... but 44/22 minutes? I'm sorry but I refuse to believe it is
>> engine config.
>>
>> While all this was happening, the appl team ran the same test on a
>> vanilla installation of Oracle, no fancy stuff, and it comes back in a
>> few seconds. When I told this to the IBM engineer, he stopped on his
>> tracks and replied that he was going to involve more resources into
>> investigating this issue.
>>
>> I hope they are really looking into this. Meanwhile, we have decided
>> to drop the index on that column and opted for the seq scan, but
>> nonetheless this behavior is not acceptable.
>>
>> Has anyone suffered this issue? Any hints? let me know if I can
>> provide anymore details.
>>
>> Happy Thanksgiving Day to y'all!
>>
>>
>> Ramon
>>
>> create table "informix".kicplus
>> (
>> kic_kepler_id integer,
>> kic_tmid integer,
>> kic_tm_designation char(50),
>> kic_fov_flag integer,
>> kct_ktc_flag integer,
>> kic_ra float,
>> ra float,
>> dec float,
>> kic_glon float,
>> kic_glat float,
>> kic_parallax smallfloat,
>> kic_pmtotal smallfloat,
>> kic_pmra smallfloat,
>> kic_pmdec smallfloat,
>> kic_umag smallfloat,
>> kic_gmag smallfloat,
>> kic_rmag smallfloat,
>> kic_imag smallfloat,
>> kic_zmag smallfloat,
>> kic_kepmag smallfloat,
>> kic_gredmag smallfloat,
>> kic_d51mag smallfloat,
>> kic_jmag smallfloat,
>> kic_hmag smallfloat,
>> kic_kmag smallfloat,
>> kic_grcolor smallfloat,
>> kic_gkcolor smallfloat,
>> kic_jkcolor smallfloat,
>> kic_teff integer,
>> kic_logg smallfloat,
>> kic_feh smallfloat,
>> kic_radius smallfloat,
>> kic_ebminusv smallfloat,
>> kic_av smallfloat,
>> kic_galaxy integer,
>> kic_blend integer,
>> kic_variable integer,
>> kic_scpid integer,
>> kic_altid integer,
>> kic_altsource integer,
>> kic_cq char(10),
>> kic_pq integer,
>> kic_aq integer,
>> kic_catkey integer,
>> kic_scpkey integer,
>> kct_sky_group_id integer,
>> kct_crowding smallfloat,
>> kct_num_sonccd integer,
>> kct_contamination smallfloat,
>> kct_edge_dist0 integer,
>> kct_edge_dist1 integer,
>> kct_edge_dist2 integer,
>> kct_edge_dist3 integer,
>> kct_channel_s0 integer,
>> kct_module_s0 integer,
>> kct_output_s0 integer,
>> kct_row_s0 integer,
>> kct_column_s0 integer,
>> kct_channel_s1 integer,
>> kct_module_s1 integer,
>> kct_output_s1 integer,
>> kct_row_s1 integer,
>> kct_column_s1 integer,
>> kct_channel_s2 integer,
>> kct_module_s2 integer,
>> kct_output_s2 integer,
>> kct_row_s2 integer,
>> kct_column_s2 integer,
>> kct_channel_s3 integer,
>> kct_module_s3 integer,
>> kct_output_s3 integer,
>> kct_row_s3 integer,
>> kct_column_s3 integer,
>> x decimal(17,16),
>> y decimal(17,16),
>> z decimal(17,16),
>> spt_ind integer,
>> cntr serial not null
>> ) extent size 2500000 next size 250000 lock mode row;
>> revoke all on "informix".kicplus from "public" as "informix";>>
>>
>> create index "informix".idx_kicplus_cntr on "informix".kicplus
>> (cntr) using btree in koa ;
>> create index "informix".idx_kicplus_kic_gkcolor on "informix".kicplus
>> (kic_gkcolor) using btree in koa ;
>> create index "informix".idx_kicplus_kic_gmag on "informix".kicplus
>> (kic_gmag) using btree in koa ;
>> create index "informix".idx_kicplus_kic_grcolor on "informix".kicplus
>> (kic_grcolor) using btree in koa ;
>> create index "informix".idx_kicplus_kic_hmag on "informix".kicplus
>> (kic_hmag) using btree in koa ;
>> create index "informix".idx_kicplus_kic_imag on "informix".kicplus
>> (kic_imag) using btree in koa ;
>> create index "informix".idx_kicplus_kic_jkcolor on "informix".kicplus
>> (kic_jkcolor) using btree in koa ;
>> create index "informix".idx_kicplus_kic_jmag on "informix".kicplus
>> (kic_jmag) using btree in koa ;
>> create index "informix".idx_kicplus_kic_kepmag on "informix".kicplus
>> (kic_kepmag) using btree in koa ;
>> create index "informix".idx_kicplus_kic_kmag on "informix".kicplus
>> (kic_kmag) using btree in koa ;
>> create index "informix".idx_kicplus_kic_rmag on "informix".kicplus
>> (kic_rmag) using btree in koa ;
>> create index "informix".idx_kicplus_spt_ind on "informix".kicplus
>> (spt_ind) using btree in koa ;
>> create unique index "informix".pk_kicplus_kic_kepler_id on "informix"
>> .kicplus (kic_kepler_id) using btree in koa ;
>>
>
> It's impossible to tell without further information, and nothing I could
> get here would be more relevant than the work suppo
I have to say that this issue is very interesting.
I've tried to do some more digging and I have some more observations:
- On a VMWare the same query (simple index without any trick) runs in 7m if
I start the VM and in 7s (!) if after the first query I stop the instance
and restart it.
This gives you an idea of the importance of caching in this issue. I even
tried to flush the Linux file system cache using;
echo 3 > /proc/sys/vm/drop_caches
but sometimes it doesn't matter. So I believe it's the host operating system
(windows) making the cache. In a real scenario this could be equivalent to
the hardware cache.
I measured the number of page reads (pages effectively read from the disk)
and it's very similar between the two queries using the index ( ~79k-80k).
The sequentila scan reads much more. This implies that the engine is not
doing anything wrong when using the index without further tricks... I think
the performance improvement using the trick is achieved because when we do a
pageread (2k) the disk system effectively reads more. And on consequent
(sequential) attempts to read the next pages we take advantage of that.
I also asked some Oracle DBAs to do some testing and several things poped up
that may be interesting:
- The oracle tends to privilege the full scan
- The full scan works marginally faster than the index scan
- The default block size in the database used for testing is 8K (4 times the
Informix default page size for Solaris). This can be very relevant, because
it reduces the number of data pages that mus be fetched
- The number of bufgets is higher when the index is forced
- The Oracle is probably running in file system so it may be taking
advantage of the file system cache
Nevertheless I still think the engine could do a better job by either:
- sort the rowids
- understand in which cases a sequential scan is effectively better and
choose it (I've seen lot's of situations in where this happens, but given
that in this case the cache seems to be the key to performance it's probably
very hard to give this level of "intelligence" to the optimizer)
Regards and thanks a lot for a good exercise of optimization you provided.
On Sat, Dec 5, 2009 at 3:39 PM, Fernando Nunes <domusonline@gmail.com>wrote:
> Fernando Nunes wrote:
> > fandelau wrote:
> >> Hello to all!
> >> I think I've found a nasty bug in IDS 11.xx on Solaris (SunOS 5.10)
> >> (yes I got the same results in both 11.10.FC3 and 11.50.FC3)... here
> >> are the details:
> >>
> >> I got a table 402 bytes wide, 78 columns all but 1 are either integer
> >> or float/decimal, with 13.1 million records in it (please find the
> >> schema below). Table has 1 extent and it is not fragmented. I was
> >> requested to index 13 of the columns, all single column indexes
> >> indexes, which were created in a separate dbspace from the data. One
> >> of the indexes is on a column that has 11 million nulls, the other 2.1
> >> million records have what I would call normal cardinality. A simple
> >> query (on a freshly bounced instance) with a range filter on that
> >> column returns in about 45 minutes on 11.10 and 22 minutes on 11.50,
> >> having the query optimizer choose an index path on the index in
> >> question. When the index was dropped and the same query ran on a seq
> >> scan, it took 1.5 minutes on either version (freshly bounced)...
> >>
> >> select kic_kepler_id, ra, dec, kic_teff from kicplus where> >> kic_teff>5000 and kic_teff<6500
> >> being kic_teff the indexed column.
> >>
> >> I have ran the query as a count, as opposed to fetching any columns
> >> and it comes back in a few seconds...
> >>
> >> select count(*) from kicplus where kic_teff>5000 and> >> kic_teff<6500
> >>
> >> So the index is being used correctly and finds the data requested.
> >>
> >> I know the cardinality of the column is skewed, but 44/22 minutes?
> >>
> >> I have already opened a call with IBM, and they were able to duplicate
> >> this behavior, and they tried to blame it on engine config. While they
> >> were doing their thing, I tried this in 2 other servers with different
> >> configurations (same platform) and gotten the exact same results...
> >> I'm willing to grant that engine config would slow down the query a
> >> bit, perhaps from a few seconds to a couple of minutes, 5 minutes
> >> max... but 44/22 minutes? I'm sorry but I refuse to believe it is
> >> engine config.
> >>
> >> While all this was happening, the appl team ran the same test on a
> >> vanilla installation of Oracle, no fancy stuff, and it comes back in a
> >> few seconds. When I told this to the IBM engineer, he stopped on his
> >> tracks and replied that he was going to involve more resources into
> >> investigating this issue.
> >>
> >> I hope they are really looking into this. Meanwhile, we have decided
> >> to drop the index on that column and opted for the seq scan, but
> >> nonetheless this behavior is not acceptable.
> >>
> >> Has anyone suffered this issue? Any hints? let me know if I can
> >> provide anymore details.
> >>
> >> Happy Thanksgiving Day to y'all!
> >>
> >>
> >> Ramon
> >>
> >> create table "informix".kicplus
> >> (
> >> kic_kepler_id integer,
> >> kic_tmid integer,
> >> kic_tm_designation char(50),
> >> kic_fov_flag integer,
> >> kct_ktc_flag integer,
> >> kic_ra float,
> >> ra float,
> >> dec float,
> >> kic_glon float,
> >> kic_glat float,
> >> kic_parallax smallfloat,
> >> kic_pmtotal smallfloat,
> >> kic_pmra smallfloat,
> >> kic_pmdec smallfloat,
> >> kic_umag smallfloat,
> >> kic_gmag smallfloat,
> >> kic_rmag smallfloat,
> >> kic_imag smallfloat,
> >> kic_zmag smallfloat,
> >> kic_kepmag smallfloat,
> >> kic_gredmag smallfloat,
> >> kic_d51mag smallfloat,
> >> kic_jmag smallfloat,
> >> kic_hmag smallfloat,
> >> kic_kmag smallfloat,
> >> kic_grcolor smallfloat,
> >> kic_gkcolor smallfloat,
> >> kic_jkcolor smallfloat,
> >> kic_teff integer,
> >> kic_logg smallfloat,
> >> kic_feh smallfloat,
> >> kic_radius smallfloat,
> >> kic_ebminusv smallfloat,
> >> kic_av smallfloat,
> >> kic_galaxy integer,
> >> kic_blend integer,
> >> kic_variable integer,
> >> kic_scpid integer,
> >> kic_altid integer,
> >> kic_altsource integer,
> >> kic_cq char(10),
> >> kic_pq integer,
> >> kic_aq integer,
> >> kic_catkey integer,
> >> kic_scpkey integer,
> >> kct_sky_group_id integer,
> >> kct_crowding smallfloat,
> >> kct_num_sonccd integer,
> >> kct_contamination smallfloat,
> >> kct_edge_dist0 integer,
> >> kct_edge_dist1 integer,
> >> kct_edge_dist2 integer,
> >> kct_edge_dist3 integer,
> >> kct_channel_s0 integer,
> >> kct_module_s0 integer,
> >> kct_output_s0 integer,
> >> kct_row_s0 integer,
> >> kct_column_s0 integer,
> >> kct_channel_s1 integer,
> >> kct_module_s1 integer,
> >> kct_output_s1 integer,
> >>