oncheck & BTS index

Hi All, Informix 11.50.FC9 on Sun sparc 10 BTS 2.00 Index size 82598929 (execute function bts_index_info('bts_name_dtl', '<size/>'); Our production server crashed two nights ago. Restarted and all is well. We are investigating why it crashed, and the evidence points to an issue with a BTS index. Every night we run 'oncheck -cIy' against all of our databases. When it hits the database with the BTS index, we see a massive hit to Logical Logs (25 Meg each). The crash happend during this oncheck. There were 75MB available on the sbspace for the index. We don't do deletes usually, and the following oncheck was run 5 minutes after a previous oncheck, so no real activity on the index in that timeframe. *** Why would oncheck on a non-busy system cause so much Logical Log usage, and in the case of the crash, so much usage of the sbspace? *** A normal oncheck (one I just ran) looks like this: 10:58:36 Checkpoint Completed: duration was 0 seconds. 10:58:36 Wed Apr 1 - loguniq 36624, logpos 0x19dc018, timestamp: 0xa561a029 Interval: 545032 10:58:36 Maximum server connections 115 10:58:36 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 254, Llog used 119 11:01:58 Logical Log 36624 Complete, timestamp: 0xa5629376. 11:02:01 Logical Log 36624 - Backup Started 11:02:15 Logical Log 36625 Complete, timestamp: 0xa5640eba. 11:02:23 Logical Log 36624 - Backup Completed 11:02:23 Logical Log 36625 - Backup Started 11:02:31 Logical Log 36626 Complete, timestamp: 0xa5656a20. 11:02:31 Logical Log 36625 - Backup Completed 11:02:31 Logical Log 36626 - Backup Started 11:02:39 Logical Log 36626 - Backup Completed 11:02:46 Logical Log 36627 Complete, timestamp: 0xa566e56c. 11:02:49 Logical Log 36627 - Backup Started 11:02:51 Logical Log 36628 Complete, timestamp: 0xa5685258. 11:02:54 Logical Log 36629 Complete, timestamp: 0xa5699c0b. 11:02:57 Logical Log 36627 - Backup Completed 11:02:57 Logical Log 36628 - Backup Started 11:02:58 Logical Log 36630 Complete, timestamp: 0xa56b2e0b. 11:03:01 Logical Log 36631 Complete, timestamp: 0xa56c9595. 11:03:05 Logical Log 36628 - Backup Completed 11:03:05 Logical Log 36629 - Backup Started 11:03:13 Logical Log 36629 - Backup Completed 11:03:13 Logical Log 36630 - Backup Started 11:03:21 Logical Log 36630 - Backup Completed 11:03:21 Logical Log 36631 - Backup Started 11:03:29 Logical Log 36631 - Backup Completed 11:03:38 Checkpoint Completed: duration was 2 seconds. 11:03:38 Wed Apr 1 - loguniq 36632, logpos 0xa44018, timestamp: 0xa56cd21a Interval: 545033 11:03:38 Maximum server connections 115 11:03:38 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 533, Llog used 96008 When the crash happened, the log registered this: 22:27:16 Logical Log 36517 Complete, timestamp: 0xa4842a4f. 22:27:18 Logical Log 36517 - Backup Started 22:27:24 Logical Log 36518 Complete, timestamp: 0xa485ad82. 22:27:26 Logical Log 36517 - Backup Completed 22:27:26 Logical Log 36518 - Backup Started 22:27:27 Logical Log 36519 Complete, timestamp: 0xa486ef12. 22:27:31 Logical Log 36520 Complete, timestamp: 0xa4888b8e. 22:27:33 Freeing reserve space from chunk 62 to Userdata 22:27:33 WARNING: sbspace bts_sbspace is full 22:27:33 BTS[31110]: BTS DataBlade IO Error detected with BTS DataBlade Index 'informix.bts_name_dtl' in database 'char' 22:27:33 BTS[31110]: The BTS DataBlade Index files were deleted. 22:27:33 BTS[31110]: BTS DataBlade IO Error was probably caused by either an aborted long transaction or 22:27:33 BTS[31110]: no free data or metadata space available in the sbspace for the index 22:27:33 BTS[31110]: Possible Action: drop and recreate the index with enough data and metadata space in the sbspace 22:27:33 Assert Failed: Dynamic Server must abort 22:27:33 IBM Informix Dynamic Server Version 11.50.FC9 22:27:33 Who: Session(31110, root@area51, 3449, 19c4c3790) Thread(358996, oncheckm, 1970bac40, 1) File: rslog.c Line: 3640 22:27:33 Results: Dynamic Server must abort 22:27:33 Action: Reinitialize shared memory 22:27:33 stack trace for pid 1706 written to /soft/informix/foghorn/tmp/af.7e3c2234 22:27:33 See Also: /soft/informix/foghorn/tmp/af.7e3c2234, shmem.7e3c2234.0 22:27:34 Logical Log 36518 - Backup Completed 22:27:34 Logical Log 36519 - Backup Started 22:27:42 Logical Log 36519 - Backup Completed 22:27:42 Logical Log 36520 - Backup Started 22:27:59 Logical Log 36520 - Backup Completed 22:29:39 rslog.c, line 3640, thread 358996, proc id 1706, Dynamic Server must abort. 22:29:39 The Master Daemon Died 22:29:39 The Master Daemon Died 22:29:40 Fatal error in ADM VP at mt.c:14033 22:29:40 Unexpected virtual processor termination, pid = 1710, exit = 0x100 Thanks, Michael Hoffman

Hi Michael, The bts index "knows" if deletes were performed so the first oncheck -cIy on the bts index will compact the index. Provided there are no deletes (or updates, since an update is implemented effectively but not exactly as a delete followed by an insert in BTS since there isn't a native update operation in the underlying text engine), after the first compact operation, the second oncheck -cIy will not compact the index and it becomes a no-op. There is not a way currently to run an oncheck -cIy and disable the compact operation begin performed on the bts index. Compacting the index was a necessary operation in the first release of BTS given the version of the underlying search engine it used. By 11.50,xC4 or so, we had moved to a newer version where it will reuse the space from deleted documents. It does not release the space back to the sbspace. If, for example, you delete half the rows from the table, the index will still retain the space used in the sbspace. The way to release that unused space back to the sbspace is with a compact operation. Otherwise if you do not compact, then when more documents are inserted into the index, that unused space is used instead of allocating new space. The online log indicates that an a write operation in the index failed. Since we see the message: 22:27:33 WARNING: sbspace bts_sbspace is full which comes from the server (not bts) , the io operation failed there was no free space in the sbspace to write more data. The error is caught and is being handled by BTS since we see the additional online.log messages from BTS. I have not not seen any similar reports of such an issue leading to an AF. -- Mark. Mark Ashworth Office phone: +1 (905) 413-5033 Email: mailto:ashworth@ca.ibm.com Check out my blog From: "MICHAEL HOFFMAN" <offdisc@gmail.com> To: ids@iiug.org Date: 04/01/2015 01:26 PM Subject: oncheck & BTS index [34910] Sent by: ids-bounces@iiug.org Hi All, Informix 11.50.FC9 on Sun sparc 10 BTS 2.00 Index size 82598929 (execute function bts_index_info('bts_name_dtl', '<size/>'); Our production server crashed two nights ago. Restarted and all is well. We are investigating why it crashed, and the evidence points to an issue with a BTS index. Every night we run 'oncheck -cIy' against all of our databases. When it hits the database with the BTS index, we see a massive hit to Logical Logs (25 Meg each). The crash happend during this oncheck. There were 75MB available on the sbspace for the index. We don't do deletes usually, and the following oncheck was run 5 minutes after a previous oncheck, so no real activity on the index in that timeframe. *** Why would oncheck on a non-busy system cause so much Logical Log usage, and in the case of the crash, so much usage of the sbspace? *** A normal oncheck (one I just ran) looks like this: 10:58:36 Checkpoint Completed: duration was 0 seconds. 10:58:36 Wed Apr 1 - loguniq 36624, logpos 0x19dc018, timestamp: 0xa561a029 Interval: 545032 10:58:36 Maximum server connections 115 10:58:36 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 254, Llog used 119 11:01:58 Logical Log 36624 Complete, timestamp: 0xa5629376. 11:02:01 Logical Log 36624 - Backup Started 11:02:15 Logical Log 36625 Complete, timestamp: 0xa5640eba. 11:02:23 Logical Log 36624 - Backup Completed 11:02:23 Logical Log 36625 - Backup Started 11:02:31 Logical Log 36626 Complete, timestamp: 0xa5656a20. 11:02:31 Logical Log 36625 - Backup Completed 11:02:31 Logical Log 36626 - Backup Started 11:02:39 Logical Log 36626 - Backup Completed 11:02:46 Logical Log 36627 Complete, timestamp: 0xa566e56c. 11:02:49 Logical Log 36627 - Backup Started 11:02:51 Logical Log 36628 Complete, timestamp: 0xa5685258. 11:02:54 Logical Log 36629 Complete, timestamp: 0xa5699c0b. 11:02:57 Logical Log 36627 - Backup Completed 11:02:57 Logical Log 36628 - Backup Started 11:02:58 Logical Log 36630 Complete, timestamp: 0xa56b2e0b. 11:03:01 Logical Log 36631 Complete, timestamp: 0xa56c9595. 11:03:05 Logical Log 36628 - Backup Completed 11:03:05 Logical Log 36629 - Backup Started 11:03:13 Logical Log 36629 - Backup Completed 11:03:13 Logical Log 36630 - Backup Started 11:03:21 Logical Log 36630 - Backup Completed 11:03:21 Logical Log 36631 - Backup Started 11:03:29 Logical Log 36631 - Backup Completed 11:03:38 Checkpoint Completed: duration was 2 seconds. 11:03:38 Wed Apr 1 - loguniq 36632, logpos 0xa44018, timestamp: 0xa56cd21a Interval: 545033 11:03:38 Maximum server connections 115 11:03:38 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 533, Llog used 96008 When the crash happened, the log registered this: 22:27:16 Logical Log 36517 Complete, timestamp: 0xa4842a4f. 22:27:18 Logical Log 36517 - Backup Started 22:27:24 Logical Log 36518 Complete, timestamp: 0xa485ad82. 22:27:26 Logical Log 36517 - Backup Completed 22:27:26 Logical Log 36518 - Backup Started 22:27:27 Logical Log 36519 Complete, timestamp: 0xa486ef12. 22:27:31 Logical Log 36520 Complete, timestamp: 0xa4888b8e. 22:27:33 Freeing reserve space from chunk 62 to Userdata 22:27:33 WARNING: sbspace bts_sbspace is full 22:27:33 BTS[31110]: BTS DataBlade IO Error detected with BTS DataBlade Index 'informix.bts_name_dtl' in database 'char' 22:27:33 BTS[31110]: The BTS DataBlade Index files were deleted. 22:27:33 BTS[31110]: BTS DataBlade IO Error was probably caused by either an aborted long transaction or 22:27:33 BTS[31110]: no free data or metadata space available in the sbspace for the index 22:27:33 BTS[31110]: Possible Action: drop and recreate the index with enough data and metadata space in the sbspace 22:27:33 Assert Failed: Dynamic Server must abort 22:27:33 IBM Informix Dynamic Server Version 11.50.FC9 22:27:33 Who: Session(31110, root@area51, 3449, 19c4c3790) Thread(358996, oncheckm, 1970bac40, 1) File: rslog.c Line: 3640 22:27:33 Results: Dynamic Server must abort 22:27:33 Action: Reinitialize shared memory 22:27:33 stack trace for pid 1706 written to /soft/informix/foghorn/tmp/af.7e3c2234 22:27:33 See Also: /soft/informix/foghorn/tmp/af.7e3c2234, shmem.7e3c2234.0 22:27:34 Logical Log 36518 - Backup Completed 22:27:34 Logical Log 36519 - Backup Started 22:27:42 Logical Log 36519 - Backup Completed 22:27:42 Logical Log 36520 - Backup Started 22:27:59 Logical Log 36520 - Backup Completed 22:29:39 rslog.c, line 3640, thread 358996, proc id 1706, Dynamic Server must abort. 22:29:39 The Master Daemon Died 22:29:39 The Master Daemon Died 22:29:40 Fatal error in ADM VP at mt.c:14033 22:29:40 Unexpected virtual processor termination, pid = 1710, exit = 0x100 Thanks, Michael Hoffman ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

Thanks Mark! That sort of explains what we are seeing -- except that the second running of the oncheck, within minutes of the first, still grabbed a bunch of logical logs even though it should have been a no-op. However, there was no dbspace usage changes, so that seems correct. From your explanation, the crash occurred because several updates had happened that day, so the BTS index was compacted. Can I safely assume that "compacting" really means "rebuilding", so there should be enough space for at least 60% of the index to be copied? (If you have better space numbers, please let me know!!) The sbspace only had about 120MB available when the oncheck kicked off, for an index that is over 1.4GB. Ate up that space in about 45 seconds. OUCH! We have added another 2GB chunk to the sbspace :-) Thanks, Michael