on 2022 Nov 29 6:41 AM
Today the client (SQL Anywhere Network Server Version 17.0.10.5963) encountered the following situation when connecting to the database. For example:
I. 11/29 12:01:59. Connection from 10.2.2.70:50753 assigned connection ID 1302
I. 11/29 12:02:29. Connection ID 1302: disconnecting unused connection
I. 11/29 12:02:29. Connection ID 1302: Client disconnected
orI. 11/29 12:03:20. Connection from 10.2.2.68:51685 assigned connection ID 1515
I. 11/29 12:03:50. Connection ID 1515: disconnecting unused connection
I. 11/29 12:03:50. Connection ID 1515: disconnecting unused connection
...total 246 identical messages...
I. 11/29 12:04:35. Connection ID 1515: disconnecting unused connection
I. 11/29 12:04:35. Connection ID 1515: Client disconnected
Why did "disconnecting unused connection" happen and what does "disconnecting unused connection" repetition mean? In less than 10 minutes, the client received more than 1.4 million "disconnecting unused connection" messages (((
ps At the same time, at 12:02:30 there was the following warning:
W. 11/29 12:02:30. Task 0000022235E5FB70(Request task 1201) is trying get forbid mutex held by task 0000022235F10970(Request task 1409) for more than 60000 ms
W. 11/29 12:02:30. Task 0000022235F10970(Request task 1409) state: worker=0000022235F20280 wakend=0 waiting=8
W. 11/29 12:02:30. Worker 0000022235F20280 state: wakend=0 waiting=0 in_atomic=0 is_dedicated=0 in_critical_section=0 allow_forbid=0
This disconnect happens when the server has not received a packet from the client in the past 30 seconds (the default setting) after initiating a connect. Something has prevented the client from sending or the server from receiving a packet.
The maximum number of seconds between the connection acceptance and the receipt of the first packet is 30 seconds. If the first packet is not received within this time period, the connection is dropped.
The message about the forbid mutex might indicate that a thread in the server is blocking other threads from running, including the thread that addresses incoming packets in a timely manner.
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.
I formulated incorrectly. More than 1.4 million messages were received by the SQL Anywhere log (-o).
The first message does arrive after 30 seconds, and then they start pouring in without interruption.
At first glance, the connections are trying to establish real users. In 10 minutes:
- about 3K such attempts were made:
I. 11/29 12:00:02. Connection from XX.X.X.XX:XXXXX assigned connection ID 1208
I. 11/29 12:00:21. Connection from XX.X.X.YY:YYYYY assigned connection ID 1209
...
I. 11/29 12:10:48. Connection from XX.X.X.ZZ:ZZZZZ assigned connection ID 4142
- about 3.4K client disconnect messages:
I. 11/29 12:00:02. Connection ID 1208: Client disconnected
I. 11/29 12:00:31. Connection ID 1211: Client disconnected
...
I. 11/29 12:11:19. Connection ID 4142: Client disconnected
- and 1422K messages that I can't interpret:
I. 11/29 12:01:58. Connection ID 1249: disconnecting unused connection
I. 11/29 12:01:58. Connection ID 1250: disconnecting unused connection
..
I. 11/29 12:11:19. Connection ID 4142: disconnecting unused connection
I can send you a server log or a summary of these disconnects.
There are events in the database ("Connect" and "Disconnect") that write information about the connection and disconnection to a special table. The last entry before the database restart was at 12:01:22.440:
233357433,,2022-11-29 12:01:22.440,,567,,5457,,'d4w97.exe',5029,1244,5457,567,'Connect to D4W',...
The further life of this connection (already without recording information about the disconnect in a special table):
I. 11/29 12:01:22. Connection from XX.X.X.XX:52400 assigned connection ID 1244
I. 11/29 12:01:23. Connection ID 1244: "dba" connected to database "D4w" from SQL Anywhere 17.0.10 (5963) client over TCPIP
I. 11/29 12:01:23. Connection ID 1244: AppInfo is IP=XX.X.X.XX;HOST=...;OSUSER=...;OS='Windows 2012 Build 9200 ';EXE=C:\\D4w\\d4w97.exe;PID=0x1810;THREAD=0x4f8c;VERSION=17.0.10.5963;API=ODBC;TIMEZONEADJUSTMENT=660
I. 11/29 12:01:23. Connection ID 1244: Server character set conversion will occur
I. 11/29 12:01:26. Connection ID 1244: Character set changed to "none"
I. 11/29 12:05:07. Connection ID 1244: disconnecting client - 217 seconds since last contact
I. 11/29 12:05:07. Connection ID 1244: Disconnected TCPIP client's AppInfo is IP=XX.X.X.XX;HOST=...;OSUSER=...;OS='Windows 2012 Build 9200 ';EXE=C:\\D4w\\d4w97.exe;PID=0x1810;THREAD=0x4f8c;VERSION=17.0.10.5963;API=ODBC;TIMEZONEADJUSTMENT=660
ps Maybe it's time for a checkpoint and everything is frozen?
I. 11/29 11:39:54. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:39
I. 11/29 11:40:31. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:40
I. 11/29 11:48:33. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:48
I. 11/29 11:48:33. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:48
I. 11/29 11:54:48. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:54
I. 11/29 11:54:48. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:54
I. 11/29 12:20:11. Database recovery in progress
I. 11/29 12:20:11. Last checkpoint at Tue Nov 29 2022 11:54
I. 11/29 12:20:46. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 12:20
I. 11/29 12:20:46. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 12:20
"When a checkpoint of a database occurs all of the database connections get (temporarily) locked out so that changes to the database do not occur. Normally the lock out time is very short but if you have a very large cache and there are a lot of dirty (changed) database pages then the time it takes to write all of the dirty pages to disk could take a long time..." (Mark Culp https://sqlanywhere-forum.sap.com/questions/20132/sqla0001tmp-server-unresponsive)
User | Count |
---|---|
73 | |
10 | |
8 | |
7 | |
7 | |
6 | |
6 | |
6 | |
6 | |
6 |
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.