Locking & Logging Issue

Hi All, [Please let me know what other information I should provide] Here's the full story on our problem. First off: versions! Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 (production) Excalibur Datablade ETX.1.30.FC7 UNIX SunOS 5.9 Generic_122300-51 Issue Synopsis: We use the Excalibur Datablade to search legal documents, utilizing the etx_contains function. New documents are inserted on an as-needed basis (potentially several times a day). The users complained that 'large' documents were failing to load, since time of installation. In the last month, however, they can now only insert the smallest of documents. Coincidentally, we observed a higher load of searches on our database. Also, the Logical Log usage has increased exponentially (from roughly 6 5MB logs filled per day to over 100!). Document content is stored in an sbspace, connected to the Datablade. No code changes have been made in over 9 months. We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The searches take upwards of 1600 msecs. *** Problem1: Logical Logs are filling excessively fast, when only searches are being performed. Searches are NOT done inside of explicit transactions. However, onstat -x shows every select using the etx_contains function is creating a logged transaction. *** Problem2: Sometimes, a Select using the etx_contains function begins and then an Insert is started on the same table, while the Select is in 'prepare' mode. When the Select begins to process, the insert statement fails! onstat -k shows HDR+IS locks being placed on the Large Smart Object Header assoon as the Select kicks off: 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 Could this be blocking the Insert from exclusively locking the table? Why wouldn't one statement wait for the other to finish? SET LOCK MODE TO WAIT 30 for the insert SET LOCK MODE TO WAIT 10 for the select Both processes are using Isolation Level Committed Read -- we cannot use Dirty Read for the select due to business requirements. But we tried Dirty Read anyway, and the HDR+IS locks were still placed. There are no errors listed in the Informix message log (onstat -m). =========================== Our error logs read: ------ [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG ContentDAO - insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?)[9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR .CtDAO - java.sql.SQLException: A select is in progress, so updating the index is not allowed. [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR FileERDAO - Exception in FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error in CtDAO.create(Connection, CtVO). A select is in progress, so updating the index is not allowed.Error Code:-937 ------ Most of the inserts process without incident, but the issue arises when a different thread passes a Select to the 'ct' table at the same time. The Select statement takes about 400 msecs to Prepare, and as soon as it kicks off, the Insert is blocked and causes an error. This is from a second log file, ***compare the timestamps***: ------- [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO KeywordSearchDAO - select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol from ct p,sdoc s,ccd cc where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT & MAX_MATCHES=1000'), rc # etx_ReturnType) order by cc.ccrn_vol, p.ct_id[9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO KeywordSearchDAO - Binding keyword "silence", 100 [9/13/10 12:25:12:800 MDT] 0000003e SystemOut O [0000] anonymous INFO KeywordSearchDAO - START ROW100 [9/13/10 12:25:12:801 MDT] 0000003e SystemOut O [0000] anonymous INFO KeywordSearchDAO - total time 428 msecs -------- Thanks for any and all assistance! Michael Hoffman

To see what is filling the logs, I would suggest looking at onlog. If you can reproduce this with a single user it is usually easy to move to a new log (onmode -l), run the test, (onmode -l), then run onlog -n on the previous log id. Maybe you are creating temp tables and these temp tables are no being placed in a tempdbs, Just a thought. John F. Miller III STSM, Embedability Architect miller3@us.ibm.com 503-578-5645 IBM Informix Dynamic Server (IDS) ids-bounces@iiug.org wrote on 09/16/2010 08:38:57 AM: > From: > > "MICHAEL HOFFMAN" <mrh@panix.com> > > To: > > ids@iiug.org > > Date: > > 09/16/2010 08:39 AM > > Subject: > > Locking & Logging Issue [21317] > > Sent by: > > ids-bounces@iiug.org > > Hi All, > [Please let me know what other information I should provide] > > Here's the full story on our problem. First off: versions! > Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 > (production) > Excalibur Datablade ETX.1.30.FC7 > UNIX SunOS 5.9 Generic_122300-51 > > Issue Synopsis: We use the Excalibur Datablade to search legal documents, > utilizing the etx_contains function. New documents are inserted on an > as-needed basis (potentially several times a day). The users complained that > 'large' documents were failing to load, since time of installation. > In the last month, however, they can now only insert the smallest of > documents. Coincidentally, we observed a higher load of searches on our > database. Also, the Logical Log usage has increased exponentially (from > roughly 6 5MB logs filled per day to over 100!). > > Document content is stored in an sbspace, connected to the Datablade. > > No code changes have been made in over 9 months. > > We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The > searches take upwards of 1600 msecs. > > *** Problem1: Logical Logs are filling excessively fast, when only searches > are being performed. Searches are NOT done inside of explicit transactions. > However, onstat -x shows every select using the etx_contains function is > creating a logged transaction. > > *** Problem2: Sometimes, a Select using the etx_contains function begins and > then an Insert is started on the same table, while the Select is in 'prepare' > mode. When the Select begins to process, the insert statement fails! > > onstat -k shows HDR+IS locks being placed on the Large Smart ObjectHeader as > soon as the Select kicks off: > 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 > > Could this be blocking the Insert from exclusively locking the table? Why > wouldn't one statement wait for the other to finish? > SET LOCK MODE TO WAIT 30 for the insert > SET LOCK MODE TO WAIT 10 for the select> > Both processes are using Isolation Level Committed Read -- we cannotuse Dirty > Read for the select due to business requirements. But we tried Dirty Read > anyway, and the HDR+IS locks were still placed. > > There are no errors listed in the Informix message log (onstat -m). > > =========================== > Our error logs read: > ------ > [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG > ContentDAO - > insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?)> [9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR .CtDAO > - > java.sql.SQLException: A select is in progress, so updating the index is not > allowed. > [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR > FileERDAO - > Exception in > FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error in > CtDAO.create(Connection, CtVO). > A select is in progress, so updating the index is not allowed.Error Code:-937 > ------ > > Most of the inserts process without incident, but the issue arises when a > different thread passes a Select to the 'ct' table at the same time. > The Select statement takes about 400 msecs to Prepare, and as soon > as it kicks > off, the Insert is blocked and causes an error. > > This is from a second log file, ***compare the timestamps***: > ------- > [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - > select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol > from ct p,sdoc s,ccd cc > where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id > and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT & > MAX_MATCHES=1000'), rc # etx_ReturnType) > order by cc.ccrn_vol, p.ct_id> [9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - Binding keyword "silence", 100 > [9/13/10 12:25:12:800 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - START ROW100 > [9/13/10 12:25:12:801 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - total time 428 msecs > -------- > > Thanks for any and all assistance! > Michael Hoffman > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. >

Hi Michael. What did you mean with "since time of installation"??? Did you upgrade your system recently??? There were any architecture change??? If you can, answer these questions, ok?? How are the server configs: CPU vps, NETTYPE (how many simultaneous sessions do you have?) How is your hardware configuration (how many cpu cores, and memory do you have, and how much memory Informix is using now?) Are you using what kind of dbspaces/chunks ?? Raw devices, or cooked files??? That should explain most of your issues, ok? Best regards. Em 16/09/2010 11:38, MICHAEL HOFFMAN escreveu: > Hi All, > [Please let me know what other information I should provide] > > Here's the full story on our problem. First off: versions! > Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 > (production) > Excalibur Datablade ETX.1.30.FC7 > UNIX SunOS 5.9 Generic_122300-51 > > Issue Synopsis: We use the Excalibur Datablade to search legal documents, > utilizing the etx_contains function. New documents are inserted on an > as-needed basis (potentially several times a day). The users complained that > 'large' documents were failing to load, since time of installation. > In the last month, however, they can now only insert the smallest of > documents. Coincidentally, we observed a higher load of searches on our > database. Also, the Logical Log usage has increased exponentially (from > roughly 6 5MB logs filled per day to over 100!). > > Document content is stored in an sbspace, connected to the Datablade. > > No code changes have been made in over 9 months. > > We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The > searches take upwards of 1600 msecs. > > *** Problem1: Logical Logs are filling excessively fast, when only searches > are being performed. Searches are NOT done inside of explicit transactions. > However, onstat -x shows every select using the etx_contains function is > creating a logged transaction. > > *** Problem2: Sometimes, a Select using the etx_contains function begins and > then an Insert is started on the same table, while the Select is in 'prepare' > mode. When the Select begins to process, the insert statement fails! > > onstat -k shows HDR+IS locks being placed on the Large Smart Object Header as> soon as the Select kicks off: > 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 > > Could this be blocking the Insert from exclusively locking the table? Why > wouldn't one statement wait for the other to finish? > SET LOCK MODE TO WAIT 30 for the insert > SET LOCK MODE TO WAIT 10 for the select> > Both processes are using Isolation Level Committed Read -- we cannot use Dirty > Read for the select due to business requirements. But we tried Dirty Read > anyway, and the HDR+IS locks were still placed. > > There are no errors listed in the Informix message log (onstat -m). > > =========================== > Our error logs read: > ------ > [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG > ContentDAO - > insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?)> [9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR .CtDAO > - > java.sql.SQLException: A select is in progress, so updating the index is not > allowed. > [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR > FileERDAO - > Exception in FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error in > CtDAO.create(Connection, CtVO). > A select is in progress, so updating the index is not allowed.Error Code:-937 > ------ > > Most of the inserts process without incident, but the issue arises when a > different thread passes a Select to the 'ct' table at the same time. > The Select statement takes about 400 msecs to Prepare, and as soon as it kicks > off, the Insert is blocked and causes an error. > > This is from a second log file, ***compare the timestamps***: > ------- > [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - > select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol > from ct p,sdoc s,ccd cc > where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id > and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT& > MAX_MATCHES=1000'), rc # etx_ReturnType) > order by cc.ccrn_vol, p.ct_id> [9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - Binding keyword "silence", 100 > [9/13/10 12:25:12:800 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - START ROW100 > [9/13/10 12:25:12:801 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - total time 428 msecs > -------- > > Thanks for any and all assistance! > Michael Hoffman > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > -- Alexandre Marini Tecnologia da Informação - DBA msn: alexandre_marini@hotmail.com SEFAZ-MS / SGI-UGSR / Sistemas IBM-Informix Cert-Info-Mgmt_color <Cert-Info-Mgmt_color.jpg> IBM Informix Dynamic Server Certified Professional V10 / V11

Sorry, most important question may be: Are you updating the database statistics periodically??? Are your database check integrity also ok??? (9.40 has recommended to be checked periodically to ensure data integrity) ok? Regards! Em 16/09/2010 12:50, Alexandre Marini escreveu: > Hi Michael. > What did you mean with "since time of installation"??? > Did you upgrade your system recently??? > There were any architecture change??? > > If you can, answer these questions, ok?? > > How are the server configs: > CPU vps, NETTYPE (how many simultaneous sessions do you have?) > > How is your hardware configuration (how many cpu cores, and memory do > you have, and how much memory Informix is using now?) > > Are you using what kind of dbspaces/chunks ?? Raw devices, or cooked > files??? > > That should explain most of your issues, ok? > > Best regards. > > Em 16/09/2010 11:38, MICHAEL HOFFMAN escreveu: >> Hi All, >> [Please let me know what other information I should provide] >> >> Here's the full story on our problem. First off: versions! >> Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 >> (production) >> Excalibur Datablade ETX.1.30.FC7 >> UNIX SunOS 5.9 Generic_122300-51 >> >> Issue Synopsis: We use the Excalibur Datablade to search legal documents, >> utilizing the etx_contains function. New documents are inserted on an >> as-needed basis (potentially several times a day). The users complained that >> 'large' documents were failing to load, since time of installation. >> In the last month, however, they can now only insert the smallest of >> documents. Coincidentally, we observed a higher load of searches on our >> database. Also, the Logical Log usage has increased exponentially (from >> roughly 6 5MB logs filled per day to over 100!). >> >> Document content is stored in an sbspace, connected to the Datablade. >> >> No code changes have been made in over 9 months. >> >> We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The >> searches take upwards of 1600 msecs. >> >> *** Problem1: Logical Logs are filling excessively fast, when only searches >> are being performed. Searches are NOT done inside of explicit transactions. >> However, onstat -x shows every select using the etx_contains function is >> creating a logged transaction. >> >> *** Problem2: Sometimes, a Select using the etx_contains function begins and >> then an Insert is started on the same table, while the Select is in > 'prepare' >> mode. When the Select begins to process, the insert statement fails! >> >> onstat -k shows HDR+IS locks being placed on the Large Smart Object Header> as >> soon as the Select kicks off: >> 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 >> >> Could this be blocking the Insert from exclusively locking the table? Why >> wouldn't one statement wait for the other to finish? >> SET LOCK MODE TO WAIT 30 for the insert >> SET LOCK MODE TO WAIT 10 for the select>> >> Both processes are using Isolation Level Committed Read -- we cannot use > Dirty >> Read for the select due to business requirements. But we tried Dirty Read >> anyway, and the HDR+IS locks were still placed. >> >> There are no errors listed in the Informix message log (onstat -m). >> >> =========================== >> Our error logs read: >> ------ >> [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG >> ContentDAO - >> insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?)>> [9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR > ..CtDAO >> - >> java.sql.SQLException: A select is in progress, so updating the index is not >> allowed. >> [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR >> FileERDAO - >> Exception in FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error > in >> CtDAO.create(Connection, CtVO). >> A select is in progress, so updating the index is not allowed.Error > Code:-937 >> ------ >> >> Most of the inserts process without incident, but the issue arises when a >> different thread passes a Select to the 'ct' table at the same time. >> The Select statement takes about 400 msecs to Prepare, and as soon as it > kicks >> off, the Insert is blocked and causes an error. >> >> This is from a second log file, ***compare the timestamps***: >> ------- >> [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO >> KeywordSearchDAO - >> select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol >> from ct p,sdoc s,ccd cc >> where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id >> and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT& >> MAX_MATCHES=1000'), rc # etx_ReturnType) >> order by cc.ccrn_vol, p.ct_id>> [9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO >> KeywordSearchDAO - Binding keyword "silence", 100 >> [9/13/10 12:25:12:800 MDT] 0000003e SystemOut O [0000] anonymous INFO >> KeywordSearchDAO - START ROW100 >> [9/13/10 12:25:12:801 MDT] 0000003e SystemOut O [0000] anonymous INFO >> KeywordSearchDAO - total time 428 msecs >> -------- >> >> Thanks for any and all assistance! >> Michael Hoffman >> >> >> > ******************************************************************************* >> Forum Note: Use "Reply" to post a response in the discussion forum. >> >> -- Alexandre Marini Tecnologia da Informação - DBA msn: alexandre_marini@hotmail.com SEFAZ-MS / SGI-UGSR / Sistemas IBM-Informix Cert-Info-Mgmt_color <Cert-Info-Mgmt_color.jpg> IBM Informix Dynamic Server Certified Professional V10 / V11

Alexandre, Update statistics is run every night. Varying levels of HIGH, Medium, and Lowdepending on indexed columns. Not exactly as if dostats was used, but I'm working on changing the existing script (only been in the job a few months). Onchecks of Indexes are run nightly. Not sure about any other onchecks. Thanks, Michael Hoffman

Alexandre, No recent system or code changes... at least 9 months. "Time of Installation" was 4 years ago, but the locking issue has become more frequent (to the point of blocking nearly every insert) in the last month or so. Around the same time we noticed the increase in searches. All dbspaces are Raw disk. Wouldn't want it any other way, right? :-) We have a connection pool from the web-app that consistently keeps 25 threads open. (Last line from onstat -u: 23 active, 128 total, 27 maximum concurrent) Not sure what memory or CPU vps have to do with locking or logging issues, but since you asked, here is the rest of the info: 32GB of system memory, Informix is using 2157568 Kbytes. Server Configs: SHMBASE 0x10a000000 # Shared memory base address SHMVIRTSIZE 512000 # initial virtual shared memory segment size SHMADD 128000 # Size of new shared memory segments (Kbytes) DEADLOCK_TIMEOUT 60 # Max time to wait of lock in distributed env. LOCKS 32000 # Maximum number of locks MULTIPROCESSOR 1 # 0 for single-processor, 1 for multi-processor NUMCPUVPS 2 # Number of user (cpu) vps SINGLE_CPU_VP 0 # If non-zero, limit number of cpu vps to one NUMAIOVPS 1 # Number of IO vps DBSPACETEMP # Default temp dbspaces onstat -g glo: ----------------Virtual processor summary: class vps usercpu syscpu total cpu 2 11895.07 1210.40 13105.47 aio 1 0.00 0.05 0.05 shm 1 0.00 0.00 0.00 lio 1 0.00 0.00 0.00 pio 1 0.00 0.00 0.00 adm 1 0.00 0.00 0.00 msc 1 0.02 0.01 0.03 total 8 11895.09 1210.46 13105.55 On Thu, Sep 16, 2010 at 10:49 AM, Alexandre Marini <amarini@fazenda.ms.gov.br> wrote: Hi Michael. What did you mean with "since time of installation"??? Did you upgrade your system recently??? There were any architecture change??? If you can, answer these questions, ok?? How are the server configs: CPU vps, NETTYPE (how many simultaneous sessions do you have?) How is your hardware configuration (how many cpu cores, and memory do you have, and how much memory Informix is using now?) Are you using what kind of dbspaces/chunks ?? Raw devices, or cooked files??? That should explain most of your issues, ok? Best regards. Em 16/09/2010 11:38, MICHAEL HOFFMAN escreveu: > Hi All, > [Please let me know what other information I should provide] > > Here's the full story on our problem. First off: versions! > Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 > (production) > Excalibur Datablade ETX.1.30.FC7 > UNIX SunOS 5.9 Generic_122300-51 > > Issue Synopsis: We use the Excalibur Datablade to search legal documents, > utilizing the etx_contains function. New documents are inserted on an > as-needed basis (potentially several times a day). The users complained that > 'large' documents were failing to load, since time of installation. > In the last month, however, they can now only insert the smallest of > documents. Coincidentally, we observed a higher load of searches on our > database. Also, the Logical Log usage has increased exponentially (from > roughly 6 5MB logs filled per day to over 100!). > > Document content is stored in an sbspace, connected to the Datablade. > > No code changes have been made in over 9 months. > > We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The > searches take upwards of 1600 msecs. > > *** Problem1: Logical Logs are filling excessively fast, when only searches > are being performed. Searches are NOT done inside of explicit transactions. > However, onstat -x shows every select using the etx_contains function is > creating a logged transaction. > > *** Problem2: Sometimes, a Select using the etx_contains function begins and > then an Insert is started on the same table, while the Select is in 'prepare' > mode. When the Select begins to process, the insert statement fails! > > onstat -k shows HDR+IS locks being placed on the Large Smart Object Header as> soon as the Select kicks off: > 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 > > Could this be blocking the Insert from exclusively locking the table? Why > wouldn't one statement wait for the other to finish? > SET LOCK MODE TO WAIT 30 for the insert > SET LOCK MODE TO WAIT 10 for the select> > Both processes are using Isolation Level Committed Read -- we cannot use Dirty > Read for the select due to business requirements. But we tried Dirty Read > anyway, and the HDR+IS locks were still placed. > > There are no errors listed in the Informix message log (onstat -m). > > =========================== > Our error logs read: > ------ > [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG > ContentDAO - > insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?)> [9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR .CtDAO > - > java.sql.SQLException: A select is in progress, so updating the index is not > allowed. > [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR > FileERDAO - > Exception in FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error in > CtDAO.create(Connection, CtVO). > A select is in progress, so updating the index is not allowed.Error Code:-937 > ------ > > Most of the inserts process without incident, but the issue arises when a > different thread passes a Select to the 'ct' table at the same time. > The Select statement takes about 400 msecs to Prepare, and as soon as it kicks > off, the Insert is blocked and causes an error. > > This is from a second log file, ***compare the timestamps***: > ------- > [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - > select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol > from ct p,sdoc s,ccd cc > where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id > and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT & > MAX_MATCHES=1000'), rc # etx_ReturnType) > order by cc.ccrn_vol, p.ct_id> [9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - Binding keyword "silence", 100 > [9/13/10 12:25:12:800 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - START ROW100 > [9/13/10 12:25:12:801 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - total time 428 msecs > -------- > > Thanks for any and all assistance! > Michael Hoffman > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > -- Alexandre Marini Tecnologia da Informação - DBA msn: alexandre_marini@hotmail.com SEFAZ-MS / SGI-UGSR / Sistemas IBM-Informix Cert-Info-Mgmt_color IBM Informix Dynamic Server Certified Professional V10 / V11

John, Thanks. We think we nailed the logging issue now, but don't know *why* it was happening. Our searches utilize the Excalibur Data Blade functions: etx_contains and etx_GetHilite. Removing etx_GetHilite has stopped the searches from running inside transactions, and those stopped the excessive logging! (We still have the Locking issue when using etx_contains) Any familiarity with the Excalibur Data Blade? Any idea why the etx_GetHilite function would cause a transaction to be run? Thanks, Michael Hoffman On Thu, Sep 16, 2010 at 10:49 AM, John Miller iii <miller3@us.ibm.com> wrote: To see what is filling the logs, I would suggest looking at onlog. If you can reproduce this with a single user it is usually easy to move to a new log (onmode -l), run the test, (onmode -l), then run onlog -n on the previous log id. Maybe you are creating temp tables and these temp tables are no being placed in a tempdbs, Just a thought. John F. Miller III STSM, Embedability Architect miller3@us.ibm.com 503-578-5645 IBM Informix Dynamic Server (IDS) ids-bounces@iiug.org wrote on 09/16/2010 08:38:57 AM: > From: > > "MICHAEL HOFFMAN" <mrh@panix.com> > > To: > > ids@iiug.org > > Date: > > 09/16/2010 08:39 AM > > Subject: > > Locking & Logging Issue [21317] > > Sent by: > > ids-bounces@iiug.org > > Hi All, > [Please let me know what other information I should provide] > > Here's the full story on our problem. First off: versions! > Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 > (production) > Excalibur Datablade ETX.1.30.FC7 > UNIX SunOS 5.9 Generic_122300-51 > > Issue Synopsis: We use the Excalibur Datablade to search legal documents, > utilizing the etx_contains function. New documents are inserted on an > as-needed basis (potentially several times a day). The users complained that > 'large' documents were failing to load, since time of installation. > In the last month, however, they can now only insert the smallest of > documents. Coincidentally, we observed a higher load of searches on our > database. Also, the Logical Log usage has increased exponentially (from > roughly 6 5MB logs filled per day to over 100!). > > Document content is stored in an sbspace, connected to the Datablade. > > No code changes have been made in over 9 months. > > We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The > searches take upwards of 1600 msecs. > > *** Problem1: Logical Logs are filling excessively fast, when only searches > are being performed. Searches are NOT done inside of explicit transactions. > However, onstat -x shows every select using the etx_contains function is > creating a logged transaction. > > *** Problem2: Sometimes, a Select using the etx_contains function begins and > then an Insert is started on the same table, while the Select is in 'prepare' > mode. When the Select begins to process, the insert statement fails! > > onstat -k shows HDR+IS locks being placed on the Large Smart Object Header as > soon as the Select kicks off: > 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 > > Could this be blocking the Insert from exclusively locking the table? Why > wouldn't one statement wait for the other to finish? > SET LOCK MODE TO WAIT 30 for the insert > SET LOCK MODE TO WAIT 10 for the select > > Both processes are using Isolation Level Committed Read -- we cannotuse Dirty > Read for the select due to business requirements. But we tried Dirty Read > anyway, and the HDR+IS locks were still placed. > > There are no errors listed in the Informix message log (onstat -m). > > =========================== > Our error logs read: > ------ > [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG > ContentDAO - > insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?) > [9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR .CtDAO > - > java.sql.SQLException: A select is in progress, so updating the index is not > allowed. > [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR > FileERDAO - > Exception in > FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error in > CtDAO.create(Connection, CtVO). > A select is in progress, so updating the index is not allowed.Error Code:-937 > ------ > > Most of the inserts process without incident, but the issue arises when a > different thread passes a Select to the 'ct' table at the same time. > The Select statement takes about 400 msecs to Prepare, and as soon > as it kicks > off, the Insert is blocked and causes an error. > > This is from a second log file, ***compare the timestamps***: > ------- > [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - > select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol > from ct p,sdoc s,ccd cc > where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id > and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT & > MAX_MATCHES=1000'), rc # etx_ReturnType) > order by cc.ccrn_vol, p.ct_id > [9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - Binding keyword "silence", 100 > [9/13/10 12:25:12:800 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - START ROW100 > [9/13/10 12:25:12:801 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - total time 428 msecs > -------- > > Thanks for any and all assistance! > Michael Hoffman

Michael, I never worked with Excalibur, so maybe I saying some not true here... But, *if* they use SmartBlobs (like BTS), you probably have smart data spaces there... check if this Smart spaces need to be logged. Check the onlog like John told, check the partnum of what table is involved in this "transaction" created by Excalibur. *if* Excalibur create temporary tables, make sure you have your DBSPACETEMP configured appropriate and your Temporary dbspaces have the flag "T". (check the variable DBSPACETEMP for the session you running, with onstat -g env). Sorry, but is a little hard to believe there is no change on this environment like you say, something change .. application, parameter, informix ... happens. The easy way to trace and identify will be with the information from the onlog. Make sure your isolation is correct, don't trust on the code of the application, when they running check with "onstat -g ses" . Use the sqltrace to identify if the "begin work" is executed. ________________________________ De: MICHAEL HOFFMAN <mrh@panix.com> Para: ids@iiug.org Enviadas: Quinta-feira, 16 de Setembro de 2010 16:37:47 Assunto: Re: Locking & Logging Issue [21332] John, Thanks. We think we nailed the logging issue now, but don't know *why* it was happening. Our searches utilize the Excalibur Data Blade functions: etx_contains and etx_GetHilite. Removing etx_GetHilite has stopped the searches from running inside transactions, and those stopped the excessive logging! (We still have the Locking issue when using etx_contains) Any familiarity with the Excalibur Data Blade? Any idea why the etx_GetHilite function would cause a transaction to be run? Thanks, Michael Hoffman On Thu, Sep 16, 2010 at 10:49 AM, John Miller iii <miller3@us.ibm.com> wrote: To see what is filling the logs, I would suggest looking at onlog. If you can reproduce this with a single user it is usually easy to move to a new log (onmode -l), run the test, (onmode -l), then run onlog -n on the previous log id. Maybe you are creating temp tables and these temp tables are no being placed in a tempdbs, Just a thought. John F. Miller III STSM, Embedability Architect miller3@us.ibm.com 503-578-5645 IBM Informix Dynamic Server (IDS) ids-bounces@iiug.org wrote on 09/16/2010 08:38:57 AM: > From: > > "MICHAEL HOFFMAN" <mrh@panix.com> > > To: > > ids@iiug.org > > Date: > > 09/16/2010 08:39 AM > > Subject: > > Locking & Logging Issue [21317] > > Sent by: > > ids-bounces@iiug.org > > Hi All, > [Please let me know what other information I should provide] > > Here's the full story on our problem. First off: versions! > Informix Dynamic Server Version 11.50.FC6 (development) and 9.40.FC4 > (production) > Excalibur Datablade ETX.1.30.FC7 > UNIX SunOS 5.9 Generic_122300-51 > > Issue Synopsis: We use the Excalibur Datablade to search legal documents, > utilizing the etx_contains function. New documents are inserted on an > as-needed basis (potentially several times a day). The users complained that > 'large' documents were failing to load, since time of installation. > In the last month, however, they can now only insert the smallest of > documents. Coincidentally, we observed a higher load of searches on our > database. Also, the Logical Log usage has increased exponentially (from > roughly 6 5MB logs filled per day to over 100!). > > Document content is stored in an sbspace, connected to the Datablade. > > No code changes have been made in over 9 months. > > We noticed in our logs that the Inserts take roughly 600 - 700 msecs. The > searches take upwards of 1600 msecs. > > *** Problem1: Logical Logs are filling excessively fast, when only searches > are being performed. Searches are NOT done inside of explicit transactions. > However, onstat -x shows every select using the etx_contains function is > creating a logged transaction. > > *** Problem2: Sometimes, a Select using the etx_contains function begins and > then an Insert is started on the same table, while the Select is in 'prepare' > mode. When the Select begins to process, the insert statement fails! > > onstat -k shows HDR+IS locks being placed on the Large Smart Object Header as > soon as the Select kicks off: > 10af47ee8 0 14f0ba9c8 10af19168 HDR+IS 40000b 0 0 > > Could this be blocking the Insert from exclusively locking the table? Why > wouldn't one statement wait for the other to finish? > SET LOCK MODE TO WAIT 30 for the insert > SET LOCK MODE TO WAIT 10 for the select > > Both processes are using Isolation Level Committed Read -- we cannotuse Dirty > Read for the select due to business requirements. But we tried Dirty Read > anyway, and the HDR+IS locks were still placed. > > There are no errors listed in the Informix message log (onstat -m). > > =========================== > Our error logs read: > ------ > [9/13/10 12:25:12:558 MDT] 00000044 SystemOut O [0000] anonymous DEBUG > ContentDAO - > insert into ct(ct_id, sdoc_id, xml_1) values (?,?,?) > [9/13/10 12:25:12:801 MDT] 00000044 SystemOut O [0000] anonymous ERROR .CtDAO > - > java.sql.SQLException: A select is in progress, so updating the index is not > allowed. > [9/13/10 12:25:12:807 MDT] 00000044 SystemOut O [0000] anonymous ERROR > FileERDAO - > Exception in > FileERDAO.insertNewCt:com.rustts.model.DAO.DAOException: Error in > CtDAO.create(Connection, CtVO). > A select is in progress, so updating the index is not allowed.Error Code:-937 > ------ > > Most of the inserts process without incident, but the issue arises when a > different thread passes a Select to the 'ct' table at the same time. > The Select statement takes about 400 msecs to Prepare, and as soon > as it kicks > off, the Insert is blocked and causes an error. > > This is from a second log file, ***compare the timestamps***: > ------- > [9/13/10 12:25:12:382 MDT] 0000003e SystemOut O [0000] anonymous INFO > KeywordSearchDAO - > select p.ct_id, p.xml_1, s.sdoc_id,cc.ccrnum,cc.ccrn_vol > from ct p,sdoc s,ccd cc > where p.sdoc_id=s.sdoc_id and s.ccd_id=cc.ccd_id > and etx_contains(p.xml_1, Row(?, 'SEARCH_TYPE=PHRASE_EXACT & > MAX_MATCHES=1000'), rc # etx_ReturnType) > order by cc.ccrn_vol, p.ct_id > [9/13/10 12:25:12:383 MDT] 0000003e SystemOut O [0000] anonymous INFO@@

Thanks, Cesar. As I mentioned, the only "change" has been a spike in searches via the external web app. Mining, possibly. Yes, we are using smart data spaces (sbspaces) to hold the CLOB information. That is where we see the HDR+IS locks placed on the smart large object headers. I am trying to review the onlogs. Not as easy as it sounds, because I'm not the "production" dba. We're setting up test suites on the development boxes. Committed Read is the isolation. I would only trust the '-g ses' or '-g sql' output, not the programmers' words. :-) I'll look into the Temp spaces. Some of our DBs have them, some do not. (Don't know why... as I said earlier, I'm new to this company). Thanks, Michael On Fri, Sep 17, 2010 at 5:18 AM, Cesar Inacio Martins <cesar_inacio_martins@yahoo.com.br> wrote: Michael, I never worked with Excalibur, so maybe I saying some not true here... But, *if* they use SmartBlobs (like BTS), you probably have smart data spaces there... check if this Smart spaces need to be logged. Check the onlog like John told, check the partnum of what table is involved in this "transaction" created by Excalibur. *if* Excalibur create temporary tables, make sure you have your DBSPACETEMP configured appropriate and your Temporary dbspaces have the flag "T". (check the variable DBSPACETEMP for the session you running, with onstat -g env). Sorry, but is a little hard to believe there is no change on this environment like you say, something change .. application, parameter, informix ... happens. The easy way to trace and identify will be with the information from the onlog. Make sure your isolation is correct, don't trust on the code of the application, when they running check with "onstat -g ses" . Use the sqltrace to identify if the "begin work" is executed.