There are several problems with this query and your configuration. The
ONCONFIG first. There are a couple of parameters that I would configure
differently, however, the only one that is affecting this query severely is:
DS_NONPDQ_QUERY_MEM 128
This controls how much memory is available for sorting in memory when
PDQPRIORITY is zero or unset. In earlier engines (before 11.xx) the
environment variable DBUPSPACE controlled this and the default was 15MB. In
the onconfig.std the default setting for this new parameter, which overrides
DBUPSPACE BTW, is 128KB and that is the setting which you have retained.
That means that you have about 1/120th the space in memory for sorting data
for ORDER BY and other requirements. This query required between 700KB and
1MB of memory to sort the results. That means that this query must do its
sorting to the tempdbspaces and disk is MUCH slower than memory. That may
be the main cause of the IO waits. Increase DS_NONPDQ_QUERY_MEM to 15360
(15MB) to get back to the default for the IDS version you came from or,
better, increase it to 51240 (50MB) to allow even larger sorts to happen in
memory.
Next, the table posicion had to be index scanned to determine which rows
satisfied the secondary filter criteria on the eventoid and fechaposicion
columns. You would do better with an index on those two columns along with
the join column holderid in this order: (holderid, eventoid,
fechaposicion). Without this index to filter, the engine had to scan over
800,000 rows in order to return just 50,000 rows. Another major source or
excess IO processing. If that index exists already and wasn't used, that
may be due to the next problem I see:
Looking at the SET EXPLAIN output, I notice in the statistics section that
while the engine had to scan almost 50000 rows it estimated that it would
only have to scan just over 9000 rows. This indicates that the data
distributions for the index key and filter columns are not sufficient to
give the optimizer the data it needs to formulate a good query plan.
If you relied on the IDS 11.50's ability to build minimal data distributions
on key columns during the index build process to gather the statistics, you
should know that only the first column of each index key is used to build
those statistical distributions which is not sufficient for more complex
queries like this one. Look in the Performance Guide manual for details of
the recommended suite of commands that you need to run to gather a useful
level of statistics with minimal effort and time. You can also use my
dostats utility which implements those recommendations automatically for
you. Dostats is free and is contained in the package utils2_ak which you
can download from either the Oninit web site (www.oninit.com/utils) or the
IIUG Software Repository (www.iiug.org/software)
Art
Art S. Kagel
Oninit (www.oninit.com)
IIUG Board of Directors (art@iiug.org)
Disclaimer: Please keep in mind that my own opinions are my own opinions and
do not reflect on my employer, Oninit, the IIUG, nor any other organization
with which I am associated either explicitly or implicitly. 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, Sep 15, 2009 at 10:56 AM, Emiliano Romero <eromero@sitrack.com>wrote:
> Hi list,
>
> First sorry about my english,
>
> I have migrate my informix server from 10.0 to 11.5FC5 and also migrate
> hardware. I move to a new 2xQuad Xeon+4x150 Gb Disk 10000RPM+8Gb of Ram.
> In tests it seems to be a much faster, but when i go to my production
> enviroment I see some Queries taking too much to be resolved.
>
> My plataform is Linux.
>
> Syntoms when I execute theses queries:
> 1) Like 35% of CPU in Waiting (I/O)
> 2) Status of session changing between "IO WAIT" and "yield bufwait-"
>
> Example of query:
> Explain out:
> QUERY: (OPTIMIZATION TIMESTAMP: 09-14-2009 15:27:32)
> ------
> SELECT posicion.fechaposicion as fechaposicion , posicion.holderid as^M
>
> holderid , posicion.eventoid as eventoid , holder.dominio as
> dominio ^M
>
> FROM posicion INNER JOIN holder ON
> (holder.holderid=posicion.holderid) ^M
>
> WHERE ( posicion.holderid in^M
>
>
>
> (14273,14440,14448,14274,14442,15171,14275,14271,14443,14253,13045,14278,14292,14279,14250,13044,13011,13002,14306,14305,14291)
> ) AND (^M
>
> posicion.eventoid in (7, 6, 4) ) AND ( posicion.fechaposicion >=^M
>
> '2009-09-08 04:00:00' ) AND ( posicion.fechaposicion <= '2009-09-14
> 03:59:00' ) ORDER BY fechaposicion
>
> Estimated Cost: 87861
> Estimated # of Rows Returned: 9117
> Temporary Files Required For: Order By
>
> 1) informix.holder: INDEX PATH
>
> (1) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14273
>
> (2) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14440
>
> (3) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14448
>
> (4) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14274
>
> (5) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14442
>
> (6) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 15171
>
> (7) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14275
>
> (8) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> (9) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14443
>
> (10) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14253
>
> (11) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 13045
>
> (12) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14278
>
> (13) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14292
>
> (14) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14279
>
> (15) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14250
>
> (16) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 13044
>
> (17) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 13011
>
> (18) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 13002
>
> (19) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14306
>
> (20) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14305
>
> (21) Index Name: root. 216_289
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid = 14291
>
> 2) informix.posicion: INDEX PATH
>
> Filters: ((informix.posicion.fechaposicion >=
> datetime(2009-09-08 04:00:00) year to second AND
> informix.posicion.eventoid IN (7 , 6 , 4 )) AND
> informix.posicion.fechaposicion <= datetime(2009-09-14 03:59:00) year to
> second )
>
> (1) Index Name: root. 100_909
>
> Index Keys: holderid (Serial, fragments: ALL)
>
> Lower Index Filter: informix.holder.holderid =
> informix.posicion.holderid
> NESTED LOOP JOIN
>
> Query statistics:
> -----------------
>
> Table map :
> ----------------------------
> Internal name Table name
> ----------------------------
> t1 holder
> t2 posicion
>
> type table rows_prod est_rows rows_scan time est_cost
> -------------------------------------------------------------------
> scan t1 21 21 21 00:00.00 5
>
> type table rows_prod est_rows rows_scan time est_cost
> -------------------------------------------------------------------
> scan t2 49511 9117 844729 06:31.26 4006
>
> type rows_prod est_rows time est_cost
> -------------------------------------------------
> nljoin 49511 9118 06:31.27 87861
>
> type rows_sort est_rows rows_cons time
> -------------------------------------------------
> sort 49511 9118 49511 06:32.55
>
> # onstat -g ses 5382
>
> IBM Informix Dynamic Server Version 11.50.FC5 -- On-Line -- Up
> 01:39:11 -- 6651320 Kbytes
>
> session effective #RSAM
> total used dynamic
> id user user tty pid hostname threads
> memory memory explain
> 5382 informix - reflex 8 Emiliano 1
> 253952 225008 off
>
> tid name rstcb flags curstk status
> 5532 sqlexec 19ee4ebd8 ---PR-- 13488 *IO Wait-*
>
> Memory pools count 3
> name class addr totalsize freesize #allocfrag
> #freefrag
> 5382 V 1a027b040 167936 17168 240
> 16
> 5382*O0 V 1a1131040 4096 808 1
> 1
> 5382_SORT_0 V 1a23e8040 81920 10968 19
> 3
>
> name free used name free
> used
> overhead 0 9864 scb 0
> 144
> opentable 0 8096 filetable 0
> 2240
> ru 0 600 log 0
> 16536
> temprec 0 2320 keys 0
> 216
> ralloc 0 74160 gentcb 0
> 1584
> ostcb 0 2920 sort 0
> 67488
> sqscb 0 21736 sql 0
> 72
> srtmembuf 0 200 rdahead 0
> 1120
> hashfiletab 0 552 osenv 0
> 2072
> sqtcb 0 8528 fragman 0
> 3640
> shmblklist 0 776 sapi 0
> 64
>
> sqscb info
> scb sqscb optofc pdqpriority sqlstats
> optcompind directives
> 1a15dd028 19f728028 0 0 0
> 2 1
>
> Sess SQL Current Iso Lock SQL ISAM F.E.
> Id Stmt type Database Lvl Mode ERR ERR
> Vers Explain
> 5382 SELECT db3g CR Not Wait 0 0
> 9.29 On
>
> Current statement name : _ixceb
>
> #onstat -g ses 5382
> IBM Informix Dynamic Server Version 11.50.FC5 -- On-Line -- Up
> 01:39:20 -- 6651320 Kbytes
>
> session effective #RSAM
> total used dynamic
> id user user tty pid hostname threads
> memory memory explain
> 5382 informix - reflex 8 Emiliano 1
> 253952 225008 off
>
> tid name rstcb flags curstk status
> 5532 sqlexec 19ee4ebd8 B--PR-- 12432 *yield bufwait-*
>
> Memory pools count 3
> name class addr totalsize freesize #allocfrag
> #freefrag
> 5382 V 1a027b040 167936 17168 240
> 16
> 5382*O0 V 1a1131040 4096 808 1
> 1
> 5382_SORT_0 V 1a23e8040 81920 10968 19
> 3
>
> name free used name free
> used
> overhead 0 9864 scb 0
> 144
> opentable 0 8096 filetable 0
> 2240
> ru 0 600 log 0
> 16536
> temprec 0 2320 keys 0
> 216
> ralloc 0 74160 gentcb 0
> 1584
> ostcb 0 2920 sort 0
> 67488
> sqscb 0 21736 sql 0
> 72
> srtmembuf 0 200 rdahead 0
> 1120
> hashfiletab 0 552 osenv 0
> 2072
> sqtcb 0 8528 fragman 0
> 3640
> shmblklist 0 776 sapi 0
> 64
>
> sqscb info
> scb sqscb optofc pdqpriority sqlstats
> optcompind directives
> 1a15dd028 19f728028 0 0 0
> 2 1
>
> Sess SQL Current Iso Lock SQL ISAM F.E.
> Id Stmt type Database Lvl Mode ERR ERR
> Vers Explain
> 5382 SELECT db3g CR Not Wait 0 0
> 9.29 On
>
> Current statement name : _ixceb
>
> # onstat -g iof
> gfd pathname bytes read page reads bytes write page
> writes io/s
> 3 rootdbs 1521664 743 751740928
> 367061 79.1
>
> op type count avg. time
>
> seeks 0 N/A
>
> reads 0 N/A
>
> writes 0 N/A
>
> kaio_reads 464 0.0106
>
> kaio_writes 238035 0.0126
>
> 4 tempdbs1 510468096 249252 541411328
> 264361 108.7
>
> op type count avg. time
>
> seeks 0 N/A
>
> reads 0 N/A
>
> writes 0 N/A
>
> kaio_reads 10944 0.0091
>
> kaio_writes 15505 0.0093
>
> 5 tempdbs2 510189568 249116 534435840
> 260955 73.7
>
> op type count avg. time
>
> seeks 0 N/A
>
> reads 0 N/A
>
> writes 0 N/A
>
> kaio_reads 11252 0.0143
>
> kaio_writes 15417 0.0130
>
> 6 datadbs 5195923456 2537072 291811328
> 142486 71.0
>
> op type count avg. time
>
> seeks 0 N/A
>
> reads 0 N/A
>
> writes 0 N/A
>
> kaio_reads 2006322 0.0136
>
> kaio_writes 103883 0.0227
>
> online.log:
> 13:48:38 IBM Informix Dynamic Server Started.
>
> Mon Sep 14 13:48:39 2009
>
> 13:48:39 pid 31174: can't get real path of
> 13:48:40 Event alarms enabled. ALARMPROG =
> '/opt/informix/etc/alarmprogram.sh'
> 13:48:40 Booting Language <c> from module <>
> 13:48:40 Loading Module <CNULL>
> 13:48:40 Booting Language <builtin> from module <>
> 13:48:40 Loading Module <BUILTINNULL>
> 13:48:40 Affinitied VP 1 to phys proc 1
> 13:48:40 Affinitied VP 3 to phys proc 2
> 13:48:40 Affinitied VP 4 to phys proc 3
> 13:48:45 DR: DRAUTO is 0 (Off)
> 13:48:45 DR: ENCRYPT_HDR is 0 (HDR encryption Disabled)
> 13:48:45 Event notification facility epoll enabled.
> 13:48:47 IBM Informix Dynamic Server Version 11.50.FC5 Software
> Serial Number AAA#B000000
> 13:48:49 IBM Informix Dynamic Server Initialized -- Shared Memory
> Initialized.
>
> 13:48:49 Started 1 B-tree scanners.
> 13:48:49 B-tree scanner threshold set at 5000.
> 13:48:49 B-tree scanner range scan size set to -1.
> 13:48:49 B-tree scanner ALICE mode set to 6.
> 13:48:49 B-tree scanner index compression level set to med.
> 13:48:49 Physical Recovery Started at Page (1:1207439).
> 13:48:49 Physical Recovery Complete: 0 Pages Examined, 0 Pages Restored.
> 13:48:49 Logical Recovery Started.
> 13:48:49 10 recovery worker threads will be started.
> 13:48:50 Logical Recovery has reached the transaction cleanup phase.
> 13:48:50 Logical Recovery Complete.
>
> 0 Committed, 0 Rolled Back, 0 Open, 0 Bad Locks
> 13:48:51 Onconfig parameter PHYSFILE modified from 2500000 to 20000.
> 13:48:51 Onconfig parameter LOGFILES modified from 58 to 12.
> 13:48:51 Dataskip is now OFF for all dbspaces
> 13:48:52 Checkpoint Completed: duration was 1 seconds.
> 13:48:52 Mon Sep 14 - loguniq 45, logpos 0x5507018, timestamp:
> 0x89c892e1 Interval: 1321
>
> 13:48:52 Maximum server connections 0
> 13:48:52 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 0, Plog used 2, Llog used 1
>
> 13:48:52 On-Line Mode
> 13:48:53 SCHAPI: Started dbScheduler thread.
> 13:48:53 Booting Language <spl> from module <>
> 13:48:53 Loading Module <SPLNULL>
> 13:48:53 SCHAPI: Started 2 dbWorker threads.
> 13:49:26 Loading Module </opt/informix/lib/libcubi.so>
> 13:49:26 pid 31177: can't get real path of
> 13:49:26 The C Language Module </opt/informix/lib/libcubi.so> loaded
> 13:49:58 Loading Module </opt/informix/lib/libcheckzona.so>
> 13:49:58 pid 31174: can't get real path of
> 13:49:58 The C Language Module </opt/informix/lib/libcheckzona.so> loaded
> 13:53:55 Explain file for session 5382 : /home/informix/sqexplain.out
> 13:54:00 Checkpoint Completed: duration was 9 seconds.
> 13:54:00 Mon Sep 14 - loguniq 45, logpos 0x8489018, timestamp:
> 0x89cd46e1 Interval: 1322
>
> 13:54:00 Maximum server connections 65
> 13:54:00 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 1, Plog used 6439, Llog used 12265
>
> 13:59:15 Checkpoint Completed: duration was 13 seconds.
> 13:59:15 Mon Sep 14 - loguniq 45, logpos 0xae6d018, timestamp:
> 0x89d3045e Interval: 1323
>
> 13:59:15 Maximum server connections 65
> 13:59:15 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 2, Plog used 5533, Llog used 11095
>
> 14:01:13 Logical Log 45 Complete, timestamp: 0x89d4ddc9.
> 14:01:14 Process exited with return code 126: /bin/sh /bin/sh -c
> /opt/informix/etc/alarmprogram.sh 2 23 "" "Logical Log 45 Complete,
> timestamp: 0x89d4ddc9." ""
> 14:04:30 Checkpoint Completed: duration was 14 seconds.
> 14:04:30 Mon Sep 14 - loguniq 46, logpos 0x1ed3018, timestamp:
> 0x89d7be90 Interval: 1324
>
> 14:04:30 Maximum server connections 65
> 14:04:30 Checkpoint Statistics - Avg. Txn Block Time 0.065, # Txns
> blocked 5, Plog used 6429, Llog used 13539
>
> I upload my onconfig file to: http://pastebin.com/f1295b23d
>
> Any idea of how could I tune that times? In my another instance of
> Informix 10.0 with older hardware that queries works much better.
>
> Regards and thanks for any help.
>
> Emiliano Romero
>
> This email and any attachments thereof may contain confidential,
> privileged,
> proprietary, or otherwise private information. This email is intended
> solely
> for the use of the individual to whom it is addressed. If you are not the
> intended recipient of the email and its attachments please inform the
> sender
> immediately and do not disclose the contents to any other person, use it
> for
> any purpose or store or copy the information in any way and delete this
> e-mail
> and its attachments from your system. Any views or opinions expressed are
> solely those of the author.
>
>
>
> *******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--0015174a047a3ae19e0473a15756
