IDS Forum

Too much IO Wait time

Posted By: Emiliano Romero
Date: Tuesday, 15 September 2009, at 10:56 a.m.

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.

Messages In This Thread

• Too much IO Wait time
  Emiliano Romero -- Tuesday, 15 September 2009, at 10:56 a.m.
  • Re: Too much IO Wait time
    Alexandre Marini -- Tuesday, 15 September 2009, at 12:21 p.m.
    • Re: Too much IO Wait time
      Emiliano Romero -- Tuesday, 15 September 2009, at 1:36 p.m.
      • Re: Too much IO Wait time
        Alexandre Marini -- Tuesday, 15 September 2009, at 1:44 p.m.
  • Re: Too much IO Wait time
    Art Kagel -- Tuesday, 15 September 2009, at 1:45 p.m.
    • Re: Too much IO Wait time
      Emiliano Romero -- Wednesday, 16 September 2009, at 9:26 a.m.

IDS Forum is maintained by Administrator with WebBBS 5.12.