Example 1: Create Index Taking Too Long
Problem Description
CustomerA was creating indexes for a large table in its database, but the time required to create the index appeared to be excessive. The following is the db2batch output, which shows the time required to create the index:
--------------------------------------------- Statement number: 1 create index x1 on staff (id) Elapsed Time is: 1068.922 seconds ---------------------------------------------
Problem Analysis and Resolution
Step 1: Examine the Database and Database Manager Configuration Parameters
Database manager configuration
The three parameters in the database manager configuration that typically have a big impact on the create index operation are the SHEAPTHRES, MAX_QUERYDEGREE, and INTRA_PARALLEL, and these parameters are highlighted in bold below. In this case, intra-partition parallelism was disabled; therefore, the index creation could not take advantage of the multiple CPUs in the server. If intra-partition parallelism is enabled, there will be sort heap used during the index creation in all subagent processes; therefore, the sort heap threshold (SHEAPTHRES) may also need to be increased.
Node type = Database Server with local clients Database manager configuration release level = 0x0a00 CPU speed (millisec/instruction) (CPUSPEED) = 4.000000e-05 Max number of concurrently active databases (NUMDB) = 8 Data Links support (DATALINKS) = NO Federated Database System Support (FEDERATED) = NO Transaction processor monitor name (TP_MON_NAME) = Default charge-back account (DFT_ACCOUNT_STR) = Java Development Kit installation path (JDK_PATH) = /wsdb/v81/ bldsupp/AIX/jdk1.3.0 Diagnostic error capture level (DIAGLEVEL) = 3 Notify Level (NOTIFYLEVEL) = 3 Diagnostic data directory path (DIAGPATH) = Default database monitor switches Buffer pool (DFT_MON_BUFPOOL) = OFF Lock (DFT_MON_LOCK) = OFF Sort (DFT_MON_SORT) = OFF Statement (DFT_MON_STMT) = OFF Table (DFT_MON_TABLE) = OFF Timestamp (DFT_MON_TIMESTAMP) = ON Unit of work (DFT_MON_UOW) = OFF Monitor health of instance and databases (HEALTH_MON) = OFF SYSADM group name (SYSADM_GROUP) = BUILD SYSCTRL group name (SYSCTRL_GROUP) = SYSMAINT group name (SYSMAINT_GROUP) = Database manager authentication (AUTHENTICATION) = SERVER Cataloging allowed without authority (CATALOG_NOAUTH) = YES Trust all clients (TRUST_ALLCLNTS) = YES Trusted client authentication (TRUST_CLNTAUTH) = CLIENT Use SNA authentication (USE_SNA_AUTH) = NO Bypass federated authentication (FED_NOAUTH) = NO Default database path (DFTDBPATH) = /home/dsnow Database monitor heap size (4KB) (MON_HEAP_SZ) = 90 Java Virtual Machine heap size (4KB) (JAVA_HEAP_SZ) = 1024 Audit buffer size (4KB) (AUDIT_BUF_SZ) = 0 Size of instance shared memory (4KB) (INSTANCE_MEMORY) = AUTOMATIC Backup buffer default size (4KB) (BACKBUFSZ) = 1024 Restore buffer default size (4KB) (RESTBUFSZ) = 1024 Sort heap threshold (4KB) (SHEAPTHRES) = 20000 Directory cache support (DIR_CACHE) = YES Application support layer heap size (4KB) (ASLHEAPSZ) = 15 Max requester I/O block size (bytes) (RQRIOBLK) = 32767 Query heap size (4KB) (QUERY_HEAP_SZ) = 1000 DRDA services heap size (4KB) (DRDA_HEAP_SZ) = 128 Priority of agents (AGENTPRI) = SYSTEM Max number of existing agents (MAXAGENTS) = 200 Agent pool size (NUM_POOLAGENTS) = 100(calculated) Initial number of agents in pool (NUM_INITAGENTS) = 0 Max number of coordinating agents (MAX_COORDAGENTS) = MAXAGENTS Max no. of concurrent coordinating agents (MAXCAGENTS) = MAX_COORDAGENTS Max number of client connections (MAX_CONNECTIONS) = MAX_COORDAGENTS Keep fenced process (KEEPFENCED) = YES Number of pooled fenced processes (FENCED_POOL) = MAX_COORDAGENTS Initialize fenced process with JVM (INITFENCED_JVM) = NO Initial number of fenced processes (NUM_INITFENCED) = 0 Index re-creation time (INDEXREC) = RESTART Transaction manager database name (TM_DATABASE) = 1ST_CONN Transaction resync interval (sec) (RESYNC_INTERVAL) = 180 SPM name (SPM_NAME) = SPM log size (SPM_LOG_FILE_SZ) = 256 SPM resync agent limit (SPM_MAX_RESYNC) = 20 SPM log path (SPM_LOG_PATH) = TCP/IP Service name (SVCENAME) = Discovery mode (DISCOVER) = SEARCH Discovery communication protocols (DISCOVER_COMM) = Discover server instance (DISCOVER_INST) = ENABLE Maximum query degree of parallelism (MAX_QUERYDEGREE) = ANY Enable intra-partition parallelism (INTRA_PARALLEL) = NO No. of int. communication buffers(4KB)(FCM_NUM_BUFFERS) = 512
Database configuration for database sample
The three parameters in the database manager configuration that typically have a big impact on the create index operation are the LOGBUFSZ, SORTHEAP, and BUFFPAGE, and these parameters are highlighted in bold below.
The log buffer size (LOGBUFSZ) is important because the create index operation will cause log records to be created. In this case, the log buffer was very small and had to be increased.
The sort list heap (SORTHEAP) is used to sort the index keys while creating an index. Because the table was large, the sort heap was also increased so that the sorting need not spill to a temp table.
On AIX, also verify the ulimit for the instance owner to ensure it is not too small, causing sort overflows. In this case, the operating system was not AIX, so this was not the cause.
In this case, the default buffer pool size (BUFFPAGE) is 1,000 4-KB pages. To determine the real size of the buffer pool, use the following statement:
select * from syscat.bufferpoolsIn this case, there was only one buffer pool (IBMDEFAULTBP), and it had a size of 300,000 4-KB pages.
This was done on a 32-bit instance of DB2, so the size of the buffer pool could not have been increased much higher without hitting the operating system limitations.
[View full width]Database configuration release level = 0x0a00 Database release level = 0x0a00 Database territory = US Database code page = 819 Database code set = ISO8859-1 Database country/region code = 1 Dynamic SQL Query management (DYN_QUERY_MGMT) = DISABLE Discovery support for this database (DISCOVER_DB) = ENABLE Default query optimization class (DFT_QUERYOPT) = 5 Degree of parallelism (DFT_DEGREE) = 1 Continue upon arithmetic exceptions (DFT_SQLMATHWARN) = NO Default refresh age (DFT_REFRESH_AGE) = 0 Number of frequent values retained (NUM_FREQVALUES) = 10 Number of quantiles retained (NUM_QUANTILES) = 20 Backup pending = NO Database is consistent = NO Rollforward pending = NO Restore pending = NO Multi-page file allocation enabled = NO Log retain for recovery status = NO User exit for logging status = NO Data Links Token Expiry Interval (sec) (DL_EXPINT) = 60 Data Links Write Token Init Expiry Intvl(DL_WT_IEXPINT) = 60 Data Links Number of Copies (DL_NUM_COPIES) = 1 Data Links Time after Drop (days) (DL_TIME_DROP) = 1 Data Links Token in Uppercase (DL_UPPER) = NO Data Links Token Algorithm (DL_TOKEN) = MAC0 Database heap (4KB) (DBHEAP) = 1200 Size of database shared memory (4KB) (DATABASE_MEMORY) = AUTOMATIC Catalog cache size (4KB) (CATALOGCACHE_SZ) = (MAXAPPLS*4) Log buffer size (4KB) (LOGBUFSZ) = 8 Utilities heap size (4KB) (UTIL_HEAP_SZ) = 5000 Buffer pool size (pages) (BUFFPAGE) = 1000 Extended storage segments size (4KB) (ESTORE_SEG_SZ) = 16000 Number of extended storage segments (NUM_ESTORE_SEGS) = 0 Max storage for lock list (4KB) (LOCKLIST) = 100 Max size of appl. group mem set (4KB) (APPGROUP_MEM_SZ) = 20000 Percent of mem for appl. group heap (GROUPHEAP_RATIO) = 70 Max appl. control heap size (4KB) (APP_CTL_HEAP_SZ) = 128 Sort heap thres for shared sorts (4KB) (SHEAPTHRES_SHR) = (SHEAPTHRES) Sort list heap (4KB) (SORTHEAP) = 256 SQL statement heap (4KB) (STMTHEAP) = 4096 Default application heap (4KB) (APPLHEAPSZ) = 256 Package cache size (4KB) (PCKCACHESZ) = (MAXAPPLS*8) Statistics heap size (4KB) (STAT_HEAP_SZ) = 4384 Interval for checking deadlock (ms) (DLCHKTIME) = 10000 Percent. of lock lists per application (MAXLOCKS) = 10 Lock timeout (sec) (LOCKTIMEOUT) = -1 Changed pages threshold (CHNGPGS_THRESH) = 60 Number of asynchronous page cleaners (NUM_IOCLEANERS) = 1 Number of I/O servers (NUM_IOSERVERS) = 1 Index sort flag (INDEXSORT) = YES Sequential detect flag (SEQDETECT) = YES Default prefetch size (pages) (DFT_PREFETCH_SZ) = 32 Track modified pages (TRACKMOD) = OFF Default number of containers = 1 Default tablespace extentsize (pages) (DFT_EXTENT_SZ) = 32 Max number of active applications (MAXAPPLS) = AUTOMATIC Average number of active applications (AVG_APPLS) = 1 Max DB files open per application (MAXFILOP) = 64 Log file size (4KB) (LOGFILSIZ) = 1000 Number of primary log files (LOGPRIMARY) = 3 Number of secondary log files (LOGSECOND) = 2 Changed path to log files (NEWLOGPATH) = Path to log files = /home/dsnow/dsnow/NODE0000/SQL00001/SQLOGDIR/ Overflow log path (OVERFLOWLOGPATH) = Mirror log path (MIRRORLOGPATH) = First active log file = Block log on disk full (BLK_LOG_DSK_FUL) = NO Percent of max active log space by transaction(MAX_LOG) = 0 Num. of active log files for 1 active UOW(NUM_LOG_SPAN) = 0 Group commit count (MINCOMMIT) = 1 Percent log file reclaimed before soft chckpt (SOFTMAX) = 100 Log retain for recovery enabled (LOGRETAIN) = OFF User exit for logging enabled (USEREXIT) = OFF Auto restart enabled (AUTORESTART) = ON Index re-creation time (INDEXREC) = SYSTEM (RESTART) Default number of loadrec sessions (DFT_LOADREC_SES) = 1 Number of database backups to retain (NUM_DB_BACKUPS) = 12 Recovery history retention (days) (REC_HIS_RETENTN) = 366 TSM management class (TSM_MGMTCLASS) = TSM node name (TSM_NODENAME) = TSM owner (TSM_OWNER) = TSM password (TSM_PASSWORD) =
Step 2: Adjust Relevant Parameters and Determine Values for the Task Being Optimized
The relevant database manager and database configuration parameters were adjusted, based on the analysis of their currently set values, and the appropriate values for the task being organized were determined. The configurations were updated as follows:
update dbm cfg using intra_parallel on update dbm cfg using sheapthres 60000 update db cfg for sample using logbufsz 256 update db cfg for sample using sortheap 1000
The instance was stopped and restarted.
Step 3: Rerun the CREATE INDEX Statement
The db2batch output showing the timing of the create index is below. Although the create index time was improved, it was still higher than expected.
--------------------------------------------- Statement number: 1 create index x1 on staff (id) Elapsed Time is: 897.214 seconds ---------------------------------------------
Step 4: Check the System for I/O Bottlenecks, Excess Paging, or Other Processes/Applications Using Excessive System Resources
This required operating system tools such as vmstat, iostat, and/or top to capture the memory, I/O, and process level information.
NOTE
It is important to capture the snapshots from these tools over a period of time, not taking just one snapshot, especially because the first line of the output of the vmstat and iostat tools contains average information since the server was started and is not really useful in analyzing a problem.
While the create index statement is running, capture vmstat output, as follows:
vmstat 5 > vmstat.out
This will capture a vmstat snapshot every 5 seconds and write the output to the file vmstat.out. This command will run until a Ctrl-C is issued on the terminal where the command was run. After this, examine the vmstat.out file.
Below is the vmstat.out file that was captured while the create index statement was running:
kthr memory page faults cpu ----- ----------- ------------------------ ------------ ----------- r b avm fre re pi po fr sr cy in sy cs us sy id wa 1 1 16243 29168 0 0 0 0 0 0 305 2890 870 14 6 80 0 2 1 16243 29165 0 0 0 0 0 0 212 2010 550 25 7 68 0 0 1 16243 29165 0 0 0 0 0 0 217 1175 584 24 2 74 0 0 1 16243 29165 0 0 0 0 0 0 224 1970 563 25 6 63 2 2 1 16243 29165 0 0 0 0 0 0 217 1171 583 23 2 75 0 2 1 16243 29165 0 0 0 0 0 0 211 1968 550 25 7 68 0 0 1 16243 29165 0 0 0 0 0 0 217 1175 584 24 1 75 0 2 1 16328 29072 0 0 0 0 0 0 217 1202 584 23 3 74 0
The analysis of the vmstat output above did not indicate any problems. The run queue was small and did not grow over time. There was no paging occurring at any time during the run (as indicated by pi = 0). The CPUs were not waiting for I/O (as indicated by the wa column).
While the create index statement was running, the iostat information was captured, as follows:
iostat 5 > iostat.out
The iostat.out file was created as follows:
Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 12.6 13.2 7.3 46 0 hdisk1 8.8 9.6 6.4 28 0 cd0 0.0 0.0 0.0 0 0 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 10.6 11.3 6.9 37 0 hdisk1 9.8 10.9 6.8 33 0 cd0 0.0 0.0 0.0 0 0 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 12.9 13.7 7.8 49 0 hdisk1 8.4 9.3 6.2 30 0 cd0 0.0 0.0 0.0 0 0
The iostat showed that the disks were relatively inactive. The most active disk was busy only 12.9% of the time. In addition, the amount of data read (Kb_read) for the disks was quite low.
In this case each of the Hdisks was actually a disk array that could support much higher throughput. Disk arrays make the disk volume look like one disk to the OS tools; therefore, it was important to understand the physical disk implementation when examining the output of these tools.
In reexamining the database and database manager configurations, the NUM_IOSERVERS configuration parameter warranted further investigation. The parameter was set as follows:
Number of I/O servers (NUM_IOSERVERS) = 1
DB2 was not taking advantage of I/O parallelism and was not reading from the disks in parallel. In addition, because the containers were on a RAID-5 disk, we checked the DB2_PARALLEL_IO registry variable to determine whether it was set for the table space(s) where the table was created. In this, case it was not enabled.
The number of prefetchers (I/O servers) was increased as follows:
update db cfg for sample using num_ioservers 6
In this case, the number of prefetchers was set to six because the disk volume is using RAID-5 technology with six data disks and one parity disk per array. Therefore, there were six disks servicing the table space for the data.
Parallel I/O was enabled as follows:
db2set DB2_PARALLEL_IO=*
The DB2 instance was stopped and restarted to enable the registry variable.
Step 5: Rerun the CREATE INDEX Statement
The db2batch output showing the timing of the create index is below. Although the create index time was improved, it was still higher than expected.
--------------------------------------------- Statement number: 1 create index x1 on staff (id) Elapsed Time is: 437.391 seconds ---------------------------------------------
Step 6: Recheck the System Resource Usage
In this case, two sessions were opened, and the vmstat and iostat were captured for the entire time the index was being created.
Some of the entries from the beginning and end of the vmstat.out and iostat.out files are below:
kthr memory page faults cpu ----- ----------- ------------------------ ------------ ----------- r b avm fre re pi po fr sr cy in sy cs us sy id wa 1 1 16243 29168 0 0 0 0 0 0 305 2890 870 14 6 80 0 2 1 16243 29165 0 0 0 0 0 0 212 2010 550 35 7 58 0 0 1 16243 29165 0 0 0 0 0 0 217 1175 584 34 2 64 0 0 1 16243 29165 0 0 0 0 0 0 224 1970 563 35 6 53 2 . . . 2 1 16243 29165 0 0 0 0 0 0 211 1968 550 25 7 61 7 0 1 16243 29165 0 0 0 0 0 0 217 1175 584 24 1 66 9 2 1 16328 29072 0 0 0 0 0 0 217 1202 584 23 3 67 7 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 12.6 13.2 7.3 46 0 hdisk1 8.8 9.6 6.4 28 0 cd0 0.0 0.0 0.0 0 0 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 10.6 11.3 6.9 37 0 hdisk1 9.8 10.9 6.8 33 0 cd0 0.0 0.0 0.0 0 0 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 12.9 13.7 7.8 49 0 hdisk1 8.4 9.3 6.2 30 0 cd0 0.0 0.0 0.0 0 0 . . . Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 24.7 36.1 16.3 1 317 Hdisk1 24.5 36.0 16.1 2 311 cd0 0.0 0.0 0.0 0 0 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 24.6 36.1 16.3 1 315 Hdisk1 24.9 36.9 16.4 2 321 cd0 0.0 0.0 0.0 0 0 Disks: % tm_act Kbps tps Kb_read Kb_wrtn Hdisk0 24.5 36.0 16.2 1 315 Hdisk1 24.6 36.4 16.5 2 323 cd0 0.0 0.0 0.0 0 0
An analysis of this information shows differences in the processing between the beginning and end of the create index processing. At the beginning of the processing, all of the I/O activity was shown to be reading the data file. At the end of the create index processing, all of the activity is write activity. This was due to the manner in which DB2 creates indexes.
Because DB2 logs only the creation of index pages and not the creation of every index key value, it must flush all of the new log pages to disk at the end of the index creation. With a CHNGPGS_THRESH setting of 60% and a 1.2-GB buffer pool, at the end of the index creation, there can be up to 720 MB of pages in the buffer pool that needs to be flushed to disk. By decreasing the value of the CHNGPGS_THRESH configuration parameter to 20%, there will be a maximum of only 240 MB of pages in the buffer pool to be flushed to disk. This can result in greatly improved index creation times.
Step 7: Adjust Relevant Parameters and Determine Values for the Task Being Optimized
The relevant database manager and database configuration parameters were adjusted, based on the analysis of their currently set values, and the appropriate values for the task being organized were determined. The changed pages threshold was updated as follows:
update db cfg for sample using chngpgs_thresh 20
Step 8: Rerun the CREATE INDEX Statement
The db2batch output showing the timing of the create index improved dramatically.
--------------------------------------------- Statement number: 1 create index x1 on staff (id) Elapsed Time is: 38.451 seconds ---------------------------------------------
