Hi,

I have a strange behaviour, Our application / DataBase runs for years and since some time we suffer strange errors. Admitted we have some settings (max_statement_count=0) against the adviced policy, but again this hase been working for years!!

It seems/ i think prepared statements are not executed and thus not closed and this generated an error within out application. So after a few hours users are getting these errors and after a restart of the application and being disconnected from the DB, the errors might return very soon? The next day they can work again for a few hours a.s.o.

During the night BI/BO connects using idriver / sybdriver.

error in application:
Error Occurred: S1000 [Sybase][ODBC Driver][SQL Anywhere]SQL statement error

error in sybase log:
I. 02/21 11:57:41. E,553449,-132,SQL statement error

error in appliciation

==============================================
application log
02B1CH(5) 11:57:41.130 Describing Column 47 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Auto-increment state for Column 47 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Searchable state for Column 47 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Describing Column 48 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Auto-increment state for Column 48 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Searchable state for Column 48 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Describing Column 49 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Auto-increment state for Column 49 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Searchable state for Column 49 for Statement 07857238H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Allocating Statement 07857A80H on Connection 07ADC10H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Setting Concurrency to Read Only for Statement 07857A80H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Setting Cursor Type to Forward Only for Statement 07857A80H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Resetting Parameters Statement 07857A80H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Preparing Statement 07857A80H : SELECT OWNER,CREATED,MODIFIER,MODIFIED,DEPARTMENTID,COSTITEMID,CODEFLD,DESCRIPTION,ICONLARGE,ICONSMALL,NOMINALID,ONINVOICE,CREDITORATTR,CREDITORPROMPT,QUANTITYATTR,QUANTITYPROMPT,RATETYPE,PROMPT1,PICTURE1,ATTRIBUTE1,PROMPT2,PICTURE2,ATTRIBUTE2,PROMPT3,PICTURE3,ATTRIBUTE3,PROMPT4,PICTURE4,ATTRIBUTE4,PROMPT5,PICTURE5,ATTRIBUTE5,MEMO,DISPLAYQUERY1,DISPLAYQUERY2,DISPLAYQUERY3,DISPLAYQUERY4,DISPLAYQUERY5,UPDATERATE,DISPLAYDESCRIPTIONQUERY,MAXIMUMAMOUNT,NOLONGERINUSE,CATEGORYID,SYSTEMCOSTITEM,USEINORDERSIGNALING,CALCULATEMAUT,DWGROUPID,INVOICESPECIFICATIONID,DESCRIPTIONQUERYEXPLANATION FROM CostItem WHERE COSTITEMID = ? 
02B1CH(5) 11:57:41.130 Error Occurred: S1000 [Sybase][ODBC Driver][SQL Anywhere]SQL statement error
02B1CH(5) 11:57:41.130  Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Connection Information for Connection 0784EC38H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Allocating Statement 07857DA8H on Connection 07ADC10H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Closing Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Setting Concurrency to Read Only for Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Setting Cursor Type to Forward Only for Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Resetting Parameters Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Preparing Statement 07857DA8H : SELECT * FROM Currency WHERE 0 = 1
02B1CH(5) 11:57:41.130 Error Occurred: S1000 [Sybase][ODBC Driver][SQL Anywhere]SQL statement error
02B1CH(5) 11:57:41.130  Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Number of columns for Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Freeing Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Allocating Statement 07857DA8H on Connection 07ADC10H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Closing Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Setting Concurrency to Read Only for Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Setting Cursor Type to Forward Only for Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Resetting Parameters Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Preparing Statement 07857DA8H : SELECT * FROM usr.ClarionErrorLog WHERE 0 = 1
02B1CH(5) 11:57:41.130 Error Occurred: S1000 [Sybase][ODBC Driver][SQL Anywhere]SQL statement error
02B1CH(5) 11:57:41.130  Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Getting Number of columns for Statement 07857DA8H Time Taken:0.00 secs
02B1CH(5) 11:57:41.130 Freeing Statement 07857DA8H Time Taken:0.00 secs
02B1CH(1) 11:57:58.867 Allocating Statement 07857DA8H on Connection 07ADEF0H Time Taken:0.00 secs
02B1CH(1) 11:57:58.867 Allocating Statement 078580D0H on Connection 07ADEF0H Time Taken:0.00 secs
02B1CH(1) 11:57:58.867 Setting Concurrency to Read Only for Statement 078580D0H Time Taken:0.00 secs
02B
========================================
log from sybase - CALL sa_server_option('RequestLogging','SQL');
I. 02/21 11:57:41. >,546196,DROP_STMT
I. 02/21 11:57:41. <,546196,PREPARE,select OM.RouteId ||'@@'|| OM.Status from OrdModality OM where OrderId = 1802110 and Shunt = 0 and NoTankContainer = 0 and       BrowseSequence < (select BrowseSequence from OrdModality where OrdModalityId = 12301706) and       OrdModalityId <> 12301706 order by BrowseSequence desc
I. 02/21 11:57:41. >,546196,PREPARE,64725133
I. 02/21 11:57:41. <,546196,OPEN,64725133
I. 02/21 11:57:41. >,546196,OPEN,368782
I. 02/21 11:57:41. <,546196,CLOSE,368782
I. 02/21 11:57:41. I,546196,0,1,0,NOSCROLL*+READONLY+HOLD
I. 02/21 11:57:41. >,546196,CLOSE
I. 02/21 11:57:41. <,546196,COMMIT
I. 02/21 11:57:41. >.,546196
I. 02/21 11:57:41. <,546196,DROP_STMT,64725133
I. 02/21 11:57:41. >,546196,DROP_STMT
I. 02/21 11:57:41. <,546196,PREPARE,select OM.OrdModalityId from OrdModality OM left outer join      OrdModProduct OMP left outer join      OrdProduct OP where OM.OrdModalityId = 12301706 and Om.DepotId = OP.DAddressId
I. 02/21 11:57:41. >,546196,PREPARE,64725135
I. 02/21 11:57:41. <,553449,PREPARE,SELECT OWNER,CREATED,MODIFIER,MODIFIED,DEPARTMENTID,COSTITEMID,CODEFLD,DESCRIPTION,ICONLARGE,ICONSMALL,NOMINALID,ONINVOICE,CREDITORATTR,CREDITORPROMPT,QUANTITYATTR,QUANTITYPROMPT,RATETYPE,PROMPT1,PICTURE1,ATTRIBUTE1,PROMPT2,PICTURE2,ATTRIBUTE2,PROMPT3,PICTURE3,ATTRIBUTE3,PROMPT4,PICTURE4,ATTRIBUTE4,PROMPT5,PICTURE5,ATTRIBUTE5,MEMO,DISPLAYQUERY1,DISPLAYQUERY2,DISPLAYQUERY3,DISPLAYQUERY4,DISPLAYQUERY5,UPDATERATE,DISPLAYDESCRIPTIONQUERY,MAXIMUMAMOUNT,NOLONGERINUSE,CATEGORYID,SYSTEMCOSTITEM,USEINORDERSIGNALING,CALCULATEMAUT,DWGROUPID,INVOICESPECIFICATIONID,DESCRIPTIONQUERYEXPLANATION FROM CostItem WHERE COSTITEMID = ? 
I. 02/21 11:57:41. >,553449,PREPARE,0
I. 02/21 11:57:41. E,553449,-132,SQL statement error
I. 02/21 11:57:41. <,546196,OPEN,64725135
I. 02/21 11:57:41. <,553449,DROP_STMT,0
I. 02/21 11:57:41. >,553449,DROP_STMT
I. 02/21 11:57:41. <,553449,COMMIT
I. 02/21 11:57:41. >.,553449
I. 02/21 11:57:41. >,546196,OPEN,368784
I. 02/21 11:57:41. <,553449,PREPARE,SELECT * FROM Currency WHERE 0 = 1
I. 02/21 11:57:41. >,553449,PREPARE,0
I. 02/21 11:57:41. E,553449,-132,SQL statement error
I. 02/21 11:57:41. <,553449,DROP_STMT,0
I. 02/21 11:57:41. >,553449,DROP_STMT
I. 02/21 11:57:41. <,553449,COMMIT
I. 02/21 11:57:41. >.,553449
I. 02/21 

regards,

marc

asked 21 Feb '17, 09:44

Inforit_Marc's gravatar image

Inforit_Marc
101569
accept rate: 0%

edited 21 Feb '17, 10:05

Mark%20Culp's gravatar image

Mark Culp
24.9k10141297


The most likely cause for this error (and the most likely reason you found a need to set max_statement_count=0 originally) is because of a statement leak somewhere in your system.

While setting max_statement_count to zero (0) does disable the prepared statement resource governor it is not the same as setting the shared resource to unlimited. There will be limits and it seems you have exceed those limits.

Without going into great painful details about how many free statements each connection gets by default (20) and how, once you exceed that, you start dipping into a common pool and how there is an upper limit to that (65535) or even how other resource limits might reduce that even further . . . . . .

. . . it is probably best to assume the error means you will need to start periodically start killing the 'most' offending connections or cycling the database server. Either approach should help to reset things for you.


You should probably start monitoring the database properties

  • Prepares Returns the number of statement prepares performed for the database.
  • PrepStmt Returns the number of prepared statements currently being maintained by the database server.

to track the usage and to help determine when approaching this limit. This can be done using sa_db_properties( ) system stored procedure, the Windows Performance Monitor, SNMP tools, directly using the db_property( ) system function or SQL Central.

To identify the connections most responsible for this problem you should monitor the connection properties for the PrepStmt counter there. Look at sa_conn_properties( ), connection_property( ), Windows Performance Monitor, SQL Central, or Perfmon as well.

If after doing that monitoring if you find you see these errors when the PrepStmt counters are low ... do report back and you should probably open up an incident.


Given the off-chance that this is a change of behavior in the product, and not tied to a possibly small change of usage, you should note the version, build and connection parameters used. Also include any connection pooling frameworks/features that may be in use.

Best of luck

---------- Correction ---------- 1 correction in the text above was made ... To clarify, the database PrepStmt counter should indicate the current level the database resource is reaching and monitoring this for when you see the -132 errors should confirm that you've maxed out this resource.

Monitoring the per connection PrepStmt counters, should indicate the heavier users of this resource and establish the trends and identify application(s) that may be leaking this resource and would deserve a code review. From there you can trace for just these applications to see what queries are the biggest contributors to the undropped prepared statements.

permanent link

answered 21 Feb '17, 18:56

Nick%20Elson%20SAP%20SQL%20Anywhere's gravatar image

Nick Elson S...
7.3k35107
accept rate: 32%

edited 22 Feb '17, 08:52

Thank you very much for your time. It makes sense, but i am not sure what must worry me. Is it the number of Prepares per connection or the total number of prepstmt, or both. I think the problem starts whenever a user has over 65535 prepares, is that correct? So i could set the public.max_statement_count below that number so that the user get's an error and stays below the limit. Is that correct for now? I can fix the leak later.

I created the next select statement to have an overview. Number of connections is by the way ~450

SELECT dateformat(current time,'hh:nn') as CurrentTime, saconninfo.Number as ConnNumber, saconninfo.Userid as ConnUserName, saconninfo.NodeAddr as ConnIP, dbproperty('Prepares') DBprepares, dbproperty('prepstmt') DPprepstmt, cast (CONNECTIONPROPERTY ( 'prepares', saconninfo.Number ) as int) AS ConnPrepares, cast (CONNECTIONPROPERTY ( 'prepstmt', saconninfo.Number ) as int) AS ConnPrepstmt FROM saconninfo() order by ConnPrepares desc

the result is https://www.screencast.com/t/uAqU80Qb

so top lines: CurrentTime,ConnNumber,ConnUserName,ConnIP,DBprepares,DPprepstmt,ConnPrepares,ConnPrepstmt '11:24',564438,'lscrot','192.168.1.179','163051249','69387',53211,558 '11:24',539578,'schiltme','192.168.1.108','163051249','69387',48796,357

amost bottom line CurrentTime,ConnNumber,ConnUserName,ConnIP,DBprepares,DPprepstmt,ConnPrepares,ConnPrepstmt '11:24',568501,'hoegenja','192.168.1.112','163051249','69387',70,10

CurrentTime,ConnNumber,ConnUserName,ConnIP,DBprepares,DPprepstmt,ConnPrepares,ConnPrepstmt '12:36',564438,'lscrot','192.168.1.179','163593051','72213',67388,612

I see a user has over 65535 prepares and around that time other user(s) get the error(s).

Regards,

Marc

(22 Feb '17, 07:51) Inforit_Marc
2

You found a small flaw in my original answer. It is just "PrepStmt" counters per connection and per database that matters here. The "Prepare" counter is a usage count over the lifetime of the connection/database instance and while informative in other ways (context especially) it is not the critical counter to mind here. {MIA Culpa there}

The total pool of prepared statements is the limit I believe you are hitting there. That is a resource across all connections. After each connection uses up it's local pool of connections (currently 20), it draws from the shared pool. So your connections with 612, 357, 558, ... are definitely drawing from this pool. ORDER*-ing your query by "ConnPrepstmt" DESC will help you find your 'TOP 10'*** offenders quicker.

Re-engaging the resource governor for this would be a valid approach to finding those connections (and applications) that are leaking those prepared statements as well as preventing them from causing issues for other connections. So YES!, that is a good approach for this.

From a quick 'on the arm' calculation: at ~450 connections it would take an average of only something around 165 "PrepStmt"s per connection to cause the database "PrepStmt" count to reach the maximum database resource limit and start showing this error.

`I'll correct my original posting

(22 Feb '17, 08:40) Nick Elson S...

Thanks again....

So the sum of the prepstmt's must not exceed 65535. And the sum of the current connections is equal to: db_property('prepstmt') According to your explanation, and based on 450 users, we should set the max_statement_count to 165.

I was hoping the first connection having 65353 prepares (hitting the limit ) would couse the problem, because setting the max_statement_count to 65353 would fix that.

Seems bad news, and also suprises me that we run into this after all these years. Ok, we have some more users and thus connections. Our main application is responsible for this (language Clarion - driver ODBC). I guess we have to figure this out. When we set the max_statement_count to 165 the resource governer comes around and the application stops.

Is there a way to select all these prepared statements to figure out where they come from. Maybe we have a few "bugs"? And is there a way to get the statements getting the -132 error, or do we have to write a parcer on the logfile for this?

Regards,

Marc

(22 Feb '17, 14:39) Inforit_Marc

If you are good at Perl scripting you can maybe go old-school and modify the tracetime.pl sample to extract that information (see %sqlanysamp12%\samples\SQLAnywhere\PerformanceTraceTime* ). With that approach, much of the heavy lifting parsing the (-zr SQL -zo tracefile.out) request log is done and you just need to add your own special logic.

The -zo format is just a CVS-style format and you can maybe import that into a database or other tool but I would filter out all but 1 connection you know that is leaking a lot of prepared statements. That should help to minimize the size of things. One caveat, the number of fields varies so tools (other than those mentioned here) may not like that.

You should probably resample with "client statement caching" disabled so you won't miss something. Also disabling all forms and sources of connection pooling (framework, IIS, application implemented, ADO.Net, ODBC and CPOOL) is probably a good idea to help see if one of those is contributing.

I was thinking I could get the sa_get_request_times() procedure and stamp_request_time Global Temporary Table to help but too much processing has already gone on by the time you have access to that information. If you think you can discover a combination of statement 'usages' counts to match the undropped count then you might be able to utilize sa_get_request_profile() and it's stamp_request_profile GTT for some of this.

Finally, matching statements back to application would require the AppInfo from the -z output in the console log. Wanting to have that information readily available may possibly be why you have avoided using -zo ... but having that information inside the request log will confuse the above 'parsers' and break with the CVS-style format.

HTH

(22 Feb '17, 18:45) Nick Elson S...

Good morning,

The problem is solved. I am glad to share this with you. Thank you all for your time! Below the summary.

Our main application had a single DataBase connection. This was not a problem for our application(s) for the last 20 years. But a "large" customer added a (significant) number of users, so the problem was initiated.

I did not know, but the number of prepared statements is limited to ~65000 + (Number of Connections * 20). In case of 450 connections ~74000

So on busy hours we experienced these S1000 errors, because we hit the limit and the database was no longer able to handle (and close) the statements in a proper way.

Now i force the application(s) to create more connections for each user to enlarge the pool.

In our case ~65000 + (450 * X * 20). X is between 1 and 10, so more users might be added.

Regards,

Marc

permanent link

answered 06 Apr '17, 04:42

Inforit_Marc's gravatar image

Inforit_Marc
101569
accept rate: 0%

Feel free to "accept" your own answer then:)

(06 Apr '17, 04:51) Volker Barth
Your answer
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "title")
  • image?![alt text](/path/img.jpg "title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Question tags:

×145
×95
×16

question asked: 21 Feb '17, 09:44

question was seen: 3,232 times

last updated: 06 Apr '17, 04:51