 |
IDS Forum
Re: Too much IO Wait time
Posted By: Alexandre Marini
Date: Tuesday, 15 September 2009, at 1:44 p.m.
In Response To: Re: Too much IO Wait time (Emiliano Romero)
Ok any additional tip could be 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:
> Alexandre, thanks for your reply.
> I have do a full update statistics after migration, dbimport do that for
> me. And I do an update statistics this morning.
>
> I add more cpu's vps. Now I have 7. I have KAIO support. I also add a
> BTSCANNER and change alice mode to 11. After restart of informix now i
> have 80% of cpu in Waiting.
>
> As I read in Informix information center, with KAIO, my cpu vps are used
> for IO. Maybe that's why I have 80% of my cpu in waiting state.
>
> I open a ticket in informix support, so I keep you updated with what
> they say.
>
> Thanks again and Regards
>
> Alexandre Marini escribió:
>
>> 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.
>>>
>>>
>>>
>>>
>>>
>>>
>>
>>
> *******************************************************************************
>
>> Forum Note: Use "Reply" to post a response in the discussion forum.
>>
>>
>>
>>
>
> 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
IDS Forum is maintained by Administrator with WebBBS 5.12.
|
|
