 |
IDS Forum
Re: Too much IO Wait time
Posted By: Alexandre Marini
Date: Tuesday, 15 September 2009, at 12:21 p.m.
In Response To: Too much IO Wait time (Emiliano Romero)
Mr. Romero,
1) It is always recommended doing a full update statistics after a
version migration. Did you do it?
2) If you new machine has 8 cores (2 quad cores), you could optimize
your cpu´s vps
3) are you using KAIO modes to improve the IO transfers ???
4) After all above, check on manuals how to optimize the b-tree index
scanning (alice mode is great!!!!)
Regards.
Alexandre Marini
Tecnologia da Informação - DBA
SEFAZ-MS / SGI-UIMP / Sistemas IBM-Informix
IIUG Member
<http://www.iiug.org>
Emiliano Romero escreveu:
> 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.
>
>
>
>
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
Art Kagel -- Tuesday, 15 September 2009, at 1:45 p.m.
IDS Forum is maintained by Administrator with WebBBS 5.12.
|
|
