What to deal with Idle connections

[Vlad]

Hello everyone,

I have decided to use the SQL Profiler today, and my goal was to identify requests that take longer than 1 sec, for the execution or the blocking. This is the conditions that I have set up for the SA Profiler:

The profiler has recorded a multiple similar statements with the following properties:

What worries me is the high "Idle" value, plus these requests are called from the multiple connections that are still (I think) alive:

I have found the old thread that says that the idle connections consume memory, and a little CPU when they send "ping" packets: http://sqlanywhere-forum.sap.com/questions/6524/whats-the-performance-downside-to-having-a-lot-of-id...

But I think that this is bad, because it looks like the statement wasn't finished yet (you see, the execution time was still "Unknown") and/or the connection was not returned to the server's connection pool.

A short update. The profiler has also shown me the following warning:

Can you please confirm that I am right in my assumption? Because it is only you who can stop me from the creation of the support ticket to people, who developed the server 🙂

p.s. I am using SA 17.0.4.2053 (Windows 2012R2 Build 9600, 4 cores). Just in case:
Auto multiprogramming level - 1
Current multiprogramming level - 20
Min multiprogramming level - 4
Max multiprogramming level - 80

update #2: I have decided to start demo.db and check it with the SQL Profiler (Profiling options: comprehensive). It showed me that dbisql.exe (I use 64-bit version), gets the number of locks, but probably doesn't close the connection:

Here you see my simple select:

SELECT @@version;

And then immediately you see the "idle" connection. The source code of com.sybase.saisqlplugin.SAISQLPlugin.getLockedTableCount (I apologize for doing this, but I wanted to know how the "universe" works!) creates the SQL statement object, and then closes it later, but ResultSet is not closed. Am I correct that this is the way where we have the "connection leak" or whatever? Can someone take a look at my observation, are either the profiler, or dbisql, or me wrong? To reproduce the issue, you should simply start the profiler (comprehensive mode), dbisql and execute any SELECT.

Thank you in advance,
Vlad

[VolkerBarth]

I guess I can confirm that behaviour with DBISQL:

In the "Operations" tab several operations that have run on the current connection in the last minutes still are displayed as "active" (i.e. within the time chart, their "blocks" continue, and their "idle" times increases each time I re-check their properties). That comes as a surprise to me as I would expect that only one statement per connection could be active at any time, and these short queries like "SELECT @@VERSION" or "SELECT CURRENT TIMESTAMP" against an empty server would not require any noticeable time...

When doing another statement several minutes later, the so far "idle" operations seem to get finished, and the next set of operations seem to enter idle state.

I usually don't use the profiler but that output makes me think I would misinterpret these counts.

Here's a view of the profiler filtered for the according connection, with the set of operations in similar "idle" mode marked with red:

[VolkerBarth]

FWIW, the same is shown when using dbisqlc - although that one uses way less meta statements...

Say, for a "select @@version" run at '08:27:56' and fetched within a few seconds (surprisingly long, I guess because it was the only statement run so far), the idle count now tells about more than 3 minutes, and that fits nearly to the "LastReqTime" shown for the connection with sa_conn_info.

---

Should we conclude that the "Idle" property within an operations properties's "Statement timing" values is not related to the operation itself but to the connection as a whole?

[Vlad]

I have written a simple Java application to test the profiler. The code is pretty simple:

public static void main(String[] args) throws SQLException, IOException {
    Connection con = DriverManager.getConnection("jdbc:sqlanywhere:UserID=DBA;Password=sql;");
    System.in.read();
    con.close();
}

It is interesting, but the profiler logged the "SET TEMPORARY OPTION ...." (many calls) as an idle connection. dbjdbc17.dll sets temporary options, and.... doesn't close them?! I do not know. You can write the Java application and profile it with the same settings what you used for dbisql.exe

Thanks

[Breck_Carter]

By default, a new connection will call the sp_login_environment procedure, and if the connection uses TDS (which jConnect does) that procedure will call sp_tsql_environment which does a whole sackload of SET TEMPORARY OPTION statements, which may be what the SQL Profiler is capturing.

For the full Penny Dreadful story see "Danger Will Robinson".

ALTER PROCEDURE "dbo"."sp_tsql_environment"()
begin
  if "db_property"('IQStore') = 'Off' then
    -- SQL Anywhere datastore
    set temporary option "close_on_endtrans" = 'OFF'
  end if;
  set temporary option "ansinull" = 'OFF';
  set temporary option "tsql_variables" = 'ON';
  set temporary option "ansi_blanks" = 'ON';
  set temporary option "chained" = 'OFF';
  set temporary option "quoted_identifier" = 'OFF';
  set temporary option "allow_nulls_by_default" = 'OFF';
  set temporary option "on_tsql_error" = 'CONTINUE';
  set temporary option "isolation_level" = '1';
  set temporary option "date_format" = 'YYYY-MM-DD';
  set temporary option "timestamp_format" = 'YYYY-MM-DD HH:NN:SS.SSS';
  set temporary option "time_format" = 'HH:NN:SS.SSS';
  set temporary option "date_order" = 'MDY';
  set temporary option "escape_character" = 'OFF'
end

[Vlad]

I didn't use jConnect. My example looks different with the profiler. This temporary option is captured as idle. I know it sounds weird, but you see several calls that are blazing fast, and this statement that never ends. I will post the screenshot later.

[Breck_Carter]

"statement that never ends" - what statement is that, and exactly how are you determining that it "never ends"?

[Vlad]

I apologize that I wasn't precise, because I thought you understood what kind of statement I recorded with SQL Profiler (that comes with SA17):

set temporary option "time_format" = 'hh:nn:ss';
set temporary option "timestamp_format" = 'yyyy-mm-dd hh:nn:ss.ssssss';
set temporary option "date_format" = 'yyyy-mm-dd';
set temporary option "date_order" = 'ymd';
set temporary option "isolation_level" = '0';
set temporary option "timestamp_with_time_zone_format" = 'yyyy-mm-dd hh:nn:ss.ssssss +hh:nn';
set temporary option "auto_commit" = 'ON'

"Never ends" means that no matter how long I am starring at the profiler, it still shows me that after I establish the new connection with the demo database server, its "grey line" never ends:

This image is wide, because I have the HD display, but if you want to see it closer, simply open the img URL in the new tab. On my artificial example, the idle time equals to 8 min, and I do not know whether this is correct, or not.

[VolkerBarth]

This image is wide.

You can probably decrease the size of the window panes - that's what I have done with my sample...:)

When I did my tests in the morning, I tried to find out whether DBISQL's result set options would make a difference (say, "Automatically refetch results", "Automatically release database locks") or DBISQL's auto_commit option, but that seems not to be the case...

Strange behaviour. With v12 and below, I'm really used to see that "LastReqTime" stays unchanged for all connections that do not issue new statements. Could it be that this has changed with v17 (according to Breck's test result)?

[Vlad]

I like the wide screen, so I prefer to use all the advantages that it provides 🙂 Even if it can destroy the HTML layout. Nevertheless, I have adjusted the image width in the image tag.

Regarding the change that you have noticed... Well, I do not have much experience with different servers. So I cannot help here much. Maybe Mark or Nick can find a developer who can take a look at what we observed.

At the present, I cannot rely on this tool much. Because it draws these bars without any obvious reason.

Update: oh, I have interrupted my Java sample and closed the IDE, but SQL Profiler still displays me the connection I posted above as idle 😞

[Breck_Carter]

Breck's test result does NOT show any change in SQL Anywhere behavior in this area 🙂

LastReqTime is the moment-in-time timestamp at which the last request for the specified connection started. It remains unchanged when no more requests have been started. That is expected behavior for idle connections. Foxhound uses LastReqTime and CURRENT TIMESTAMP to calculate and display the duration "Time Since Last Request" which is a more useful way to look at it; for example, if a connection displays "Idle" in the "Current Request Status" and the "Time Since Last Request" is 3h, that (probably) means this connection has been idle for three hours... of course, that request three hours ago might have run for a while, in which case the idle time is less than three hours.

Other than that, Time Since Last Request is not nearly as valuable as, for example, Transaction Time, or CPU %, or Waiting Time, or Busy/Wait/Idle %.

If SQL Profiler is showing that an idle connection is not idle, I would say that's a problem with the SQL Profiler. The SQL Anywhere server does not have any bugs in this area, as far as I know, nor does dbisql.exe.

[MarkCulp]

When a connection is idle it is, um, idle. Not doing anything. It does not consume any CPU but depending on what has happened on the connection prior to being idle it could be consuming some resources within the server including memory and locks (on rows, tables, etc).

(I believe) that the query execution time will be "unknown" if the query has not completed. There are two cases (that I can think of):

• the query is still actively executing (i.e. query parsing + optimization + execution has not got to the point of computing the initial set of rows to return to the client), or
• a cursor was opened and the client has not yet fetched all of the rows from the cursor.

In the first case the server will show that the connection is active. In the second case the connection may be marked as "idle" but the query will not yet be "completed". Until the cursor is closed the server cannot know how the total execution time and therefore will show "unknown".

Note that another reason for a query to not yet be complete (but "idle") is that it is blocked. For example, some other connection has a lock on a row that it is trying to read/update.

Regarding the warning about connections with non-default values, this is not necessarilly a problem. It is perfectly reasonable to use connection options which are not the default. The point of the warning is for you, the DBA, to look at the options and verify that the connection is using the connection options that you are expecting.

HTH

[Vlad]

Thank you Nick and Mark for your detailed explanation. I will find the code of the server and verify how it accesses the table. I have a small question to ask, if possible:

When I run dbisql and executed the query:
SELECT * from sa_conn_info() where number <> connection_property('number')

I found out that it lists 17 connections only, but SQL Profiler displays much more connections with the status "Still Connected". Is it possible that the profiler knows something what sa_conn_info doesn't know?

[Breck_Carter]

> another reason for a query to not yet be complete (but "idle") is that it is blocked.

Does that mean the Profiler gets "idle" from some source other than the connection-level ReqStatus property (which returns 'Idle' OR 'BlockedLock' OR ...)

Quick! I gotta fix Foxhound! ...

[MarkCulp]

I was not explicitly referring to the connection property status when I used the word "idle" in that sentence. I was instead using the term "idle" to mean anytime that the connection is "not doing work", and hence the "execution time" of the connection/query is not increasing.

Thanks for raising the point... hopefully I did not confuse too many readers?

[Breck_Carter]

Update... Disclaimer: This answer deals only with actual SQL Anywhere server and dbisql.exe behavior, not the behavior of the SQL Anywhere Profiler which is a brand-new feature of SQL Anywhere 17.

It is entirely possible this answer completely misunderstands the question, but here goes...

... probably doesn't close the connection ... we have the "connection leak" or whatever?

It is highly highly highly highly highly ( five "highly"s, the maximum number 🙂 unlikely that SQL Anywhere or Interactive SQL has anything remotely like a "connection leak".

By default, the Interactive SQL program dbisql.exe connects to the target database when it is started (assuming the -c "whatever" option is correct), and then holds that single connection open until the executable is stopped. This is intentional... it is a GUI tool, after all.

If you want to close that connection but keep dbisql.exe running, try using the special ISQL-only command DISCONNECT... the connection will then disappear from the server, and, presumably, from the Profiler display. You can then use the ISQL-only CONNECT statement to open a (re)connection dialog.

[Vlad]

Breck, thank you for your reply. I know that I might be wrong. I have feeling that the profiler behaves in a way that I cannot explain. Something suspicious. I don't lie, and the screenshots I made were checked multiple times before I uploaded them.

Have you tried to reproduce my steps? Use SQL profiler with dbisql.exe? I know you have SA 17. Profiler shows me a never ending statement.

Thanks.

[Breck_Carter]

Please accept my apologies for not actually running the SQL Profiler to reproduce your results. Volker is doing a great job there, and I've added a "Disclaimer" to my answer.

FWIW an idle dbisql.exe connection in SQL Anywhere 17 has an ever-increasing CONNECTION_PROPERTY ( 'LastReqTime' ) value, as shown in the "Time Since Last Request" column in this Foxhound 4 screenshot:

Perhaps the SQL Profiler is using that value.

[VolkerBarth]

Thanks for beta-testing your disclaimers, Breck. (Personally, I had not noticed anything to improve there.)

[Vlad]

Ok, thank you for the disclaimer. I know that I am probably chasing the shadows, because in the past I used the tracing functionality in scjview, and know the SQL Profiler have replaced it.