SQLite is busy

[Ian Oakes]

2020-01-28 08:30:54.025108 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:30:56.185098 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [select sip_subscriptions.proto, '10','sub.domain.com',sip_dialogs.uuid, sip_dialogs.call_id, sip_dialogs.state, sip_dialogs.direction, sip_dialogs.sip_to_user, sip_dialogs.sip_to_host, sip_dialogs.sip_from_user, sip_dialogs.sip_from_host, sip_dialogs.contact, sip_dialogs.contact_user, sip_dialogs.contact_host, sip_dialogs.sip_to_tag, sip_dialogs.sip_from_tag, sip_subscriptions.orig_proto from sip_dialogs left join sip_subscriptions on sip_subscriptions.hostname=sip_dialogs.hostname and sip_subscriptions.profile_name=sip_dialogs.profile_name and sip_subscriptions.call_id='0_4207997968@192.168.2.110' left join sip_registrations on sip_registrations.hostname=sip_dialogs.hostname and sip_registrations.profile_name=sip_dialogs.profile_name and (sip_dialogs.sip_from_user = sip_registrations.sip_user and sip_dialogs.sip_from_host = 'sub.domain.com' and (sip_dialogs.sip_from_host = sip_registrations.orig_server_host or sip_dialogs.sip_from_host = sip_registrations.sip_host) ) where sip_dialogs.hostname='fs4' and sip_dialogs.profile_name='internal' and sip_dialogs.call_info_state != 'seized' and sip_dialogs.presence_id='10@sub.domain.com' or (sip_registrations.sip_user='10' and (sip_registrations.orig_server_host='sub.domain.com' or sip_registrations.sub_host='sub.domain.com' or sip_registrations.presence_hosts like '%sub.domain.com%'))]
2020-01-28 08:30:58.365105 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:30:59.985104 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:31:00.385124 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:31:00.765093 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:31:01.605114 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:31:01.945105 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-28 08:31:02.245080 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]

Edit: Forgot to mention SQLite DB is in ramdrive. Briefly Increased the time it took to start seeing these messages, but they still came back.
Hard drives are two 1.2tb nvme, loads of ram, loads of processor on proxmox.
For sure, these messages are a backlog, as soon as we started seeing them we noticed blfs stopped updating correctly. I just didn't put that together on time...

Background: this is a newly moved and upgraded system to master with 1.10.2 for fs. Was 4.4.3, and fs 1.8.2. I understand that this message was only recently added to this version, and does represent just a warning. There are maybe only 170ish registrations on this box, with blf's a plenty. Prior to upgrading, blfs were timing out, but cant rule out an IO issue with spinning disks on kvm. New machine is really well resourced and running on LXC.

My questions:
Does this message represent queued sql? I ask this, because I saw after I pulled registrations busy messages coming for about 8 hours after the registrations were back on original machine. So, did they stack up and were just getting processed in that order? Or was that completely innocuous and should just not worry about it - nothing to see here, move along?

Would moving fs db to postgres make for a better experience? I know that blfs are problematic on FS, but that can't be the final answer. I figure someone must have bloodied their forehead trying to figure this out.

How has anyone else dealt with having lots of blfs, what steps have you taken to make sure that isn't as taxing on the system? I wouldn't normally jump to new hardware for something like this, but the io issues when we did anything on the machine were turfing registrations and causing calls to drop.

Thanks, folks!

 

[KonradSC]

I don't think this is usual behavior. Does the warning creep in after a few hours or days or weeks after FS is started?

A couple of thoughts...

The database could be corrupt. Stop FreeSWITCH. Delete the db files and restart.

It could be that you've maxed out the SIP profile with so many BLF's. Create another SIP profile and move a few phones over to it. See if that have the same issue with their BLF's.

Do a packet capture with a capture filter on your public interface. Filter on the SIP port. Capture for about 5 or 10 minutes, then go to Telephony, SIP Statistics. If you see a lot of "Resent" packets, then most likely you have a bottleneck somewhere in FS. You can dig in from there. For instance you could filter on one SIP Profile.

 

[Adrian Fretwell]

Hi Ian,
I upgraded a system on Sunday

Fusion 4.5.11 pulled on Jan 21st
Freeswitch 1.10.2
Debian 10.2

I too have SQLite DB in RAM.

When I made the new box live, I had an influx of registrations and this caused some SQLite busy warnings, but I have not seen them since.

2020-01-26 13:04:13.997896 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [216@605.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:14.117878 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [207@721.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:14.277897 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [207@700.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:14.497890 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [209@364.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:14.797895 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [301@388.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:14.917882 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [301@388.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:15.417897 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [205@724.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:16.197898 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [202@728.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:16.257880 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [BEGIN EXCLUSIVE]
2020-01-26 13:04:16.257880 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [insert into sip_subscriptions (proto,sip_user,sip_host,sub_to_user,sub_to_host,presence_hosts,event,contact,call_id,full_from,full_via,expires,user_agent,accept,profile_name,hostname,network_port,network_ip,version,orig_proto, full_to) values ('sip','202','728.mydomain.uk','*97','728.mydomain.uk','','message-summary','"Office 2" <sip:202@xxx.xxx.xxx.xxx:48628;fs_nat=yes;fs_path=sip%3Axxx.xxx.xxx.xxx%3A35657%3Btransport%3Dudp>','0_352075934@10.16.210.82','"Office 2" <sip:202@728.mydomain.uk:10200>;tag=1247904335','SIP/2.0/UDP xxx.xxx.xxx.xxx:48628;branch=z9hG4bK259725772;rport=35657',1580047456,'Yealink SIP-T42S 66.84.0.15','application/simple-message-summary ','internal','pbx7','35657','xxx.xxx.xxx.xxx',-1,'','<sip:*97@728.mydomain.uk:10200>;tag=NmHifJv3gNJp')]
2020-01-26 13:04:16.357882 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=298 [insert into sip_subscriptions (proto,sip_user,sip_host,sub_to_user,sub_to_host,presence_hosts,event,contact,call_id,full_from,full_via,expires,user_agent,accept,profile_name,hostname,network_port,network_ip,version,orig_proto, full_to) value ('sip','202','728.mydomain.uk','*97','728.mydomain.uk','','message-summary','"Office 2" <sip:202@xxx.xxx.xxx.xxx:48628;fs_nat=yes;fs_path=sip%3Axxx.xxx.xxx.xxx%3A35657%3Btransport%3Dudp>','0_352075934@10.16.210.82','"Office 2" <sip:202@728.mydomain.uk:10200>;tag=1247904335','SIP/2.0/UDP xxx.xxx.xxx.xxx:48628;branch=z9hG4bK259725772;rport=35657',1580047456,'Yealink SIP-T42S 66.84.0.15','application/simple-message-summary ','internal','pbx7','35657','xxx.xxx.xxx.xxx',-1,'','<sip:*97@728.mydomain.uk:10200>;tag=NmHifJv3gNJp')]
2020-01-26 13:04:16.457879 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [205@728.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:16.497889 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [222@614.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:16.677896 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [select call_id,expires,sub_to_user,sub_to_host,event,version, 'full',full_to,full_from,contact,network_ip,network_port from sip_subscriptions where hostname='pbx7' and profile_name='internal' and sub_to_user='206' and sub_to_host='728.mydomain.uk' and call_id='0_582316343@10.16.210.82']
2020-01-26 13:04:17.937895 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [2203@200.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:17.958319 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [987@324.mydomain.uk] from ip xxx.xxx.xxx.xxx
2020-01-26 13:04:21.437877 [WARNING] sofia_reg.c:1793 SIP auth challenge (REGISTER) on sofia profile 'internal' for [202@726.mydomain.uk] from ip xxx.xxx.xxx.xxx

From what I read on the SQLite website about result codes, it seems that the issue is SQLITE_BUSY indicating a conflict with a separate database connection, probably in a separate process; as opposed to SQLITE_LOCKED indicating a conflict within the same database connection.

https://www.sqlite.org/rescode.html

 

[Ian Oakes]

Update folks!

What I can tell is with those sqlite is busy warnings, those queries are getting queued and the more it happens, the more they get stacked. So in the case of blfs, those get more and more stale. We had pulled traffic off there at midnight, and I was still getting sqlite was busy after 8am on an empty box. The solution we used for the time being was to move to postgres from sqlite, and no more errors. However, that warning was only for sqlite, no idea if postgres is going to tell me when or if this is happening in fs_cli. I will see those errors in the postgres logs though. Also, this has likely been going on, without an warning for a long time. I will update when I know if this solves our blf issue.

 

[Ian Oakes]

I don't think this is usual behavior. Does the warning creep in after a few hours or days or weeks after FS is started?

This happens on a "new install" with an upgraded db, as well as a brand new install when enough blfs are added, and the only thing is that its 1.10.2 - prior to this there was no warning message in the code to be spit out from fs. The blf issue has been happening for a while, as every phone has a blf for every phone on the system. I am exaggerating, but it too much anyway.

really different that we saw with the previous install and fs 1.8.2 and sqlite.

So no, not normal behavior, but it isn't new aside from the warning.

It could be that you've maxed out the SIP profile with so many BLF's. Create another SIP profile and move a few phones over to it. See if that have the same issue with their BLF's.

We are seeing if we can avoid this for the time being with postgres. I have another system with 10x the registrations, 100x the traffic but few blfs. No sqlite issues to speak of.

Do a packet capture with a capture filter on your public interface. Filter on the SIP port. Capture for about 5 or 10 minutes, then go to Telephony, SIP Statistics. If you see a lot of "Resent" packets, then most likely you have a bottleneck somewhere in FS. You can dig in from there. For instance you could filter on one SIP Profile.

I do think this is happening on the server we upgraded from. Lots of resent, visible just in sngrep. IO issues were a motivation here.... this has been a big ole PITA

 

[KonradSC]

In the capture look at Statistics, IO Graph (Wireshark).That will tell you how many SIP packets/sec are coming and going. Remember that SIP Profiles are single threaded.

Your issue could definitely be somewhere else, but this is the first place I always look.

 

[markjcrane]

I think FreeSWITCH is just showing more details about it working with SQLite.

 

[DigitalDaz]

I have a test system with no more than a couple of extensions on it and am seeing a lot of this busy along with some locked too.

 

[MacKiller]

Did anybody figure this out? I am testing a new system, and getting "2020-05-27 17:08:45.730619 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=296 [BEGIN EXCLUSIVE]" about 3 times a minute. First time testing with FSDB on RAM Drive...

 

[pbxgeek]

Same here. Anyone figured it out?

 

[markjcrane]

There is nothing to figure out. The message 'SQLite is BUSY' is just how SQLite works. Its a file based database. Every time there is a write to the file the database file is locked. FreeSWITCH tries to write to the file if it is already being written to then the file is locked and FreeSWITCH reports this in the logs as 'SQLite is BUSY'. This is just how SQLite works if it is locked it waits a for a moment and then tries again.

For many people this makes them worry and think something is wrong but nothing is wrong... its normal operation. The only thing you have to worry about is if it produces the message all the time and doesn't get the opportunity to write to the database file when it needs to in a timely manner.

 

[gflow]

I found a good explanation for this on the freeswitch mailing list:

There are 300 tries to complete each request. SQLite is fast and most of the time completes requests right away, but sometimes it may be busy for a real bit. This exact line tells you that there are 299 tries left so it is OK. But if that number goes lower this may really help you measuring and understand the load. When it's 0 then that's a real problem and a request was not complete. Until that, never mind. Your machine needs to be very busy to go that low.

 

[Len]

"SQLite is BUSY" reporting can actually be very helpful. If your system gets over flooded with fs db activity, you can track down sip subscribe or notify messages accordingly.
I am not sure you would get alerted to this if you move the fs db to postgress

 

[Adrian Fretwell]

"SQLite is BUSY" reporting can actually be very helpful. If your system gets over flooded with fs db activity, you can track down sip subscribe or notify messages accordingly.
I am not sure you would get alerted to this if you move the fs db to postgress

There are better and more reliable ways of monitoring platform performance.
If you are concerned about being overloaded with NOTIFY etc. messages, get a packet capture going for a period of time and then in Wireshark under the SIP tool, look for retries. You will see some retries, this is normal given the nature of the internet but if you see many especially inbound it could indicate that your system is becoming overloaded or flooded as you say.