cluster is slow

Need help? - Post here and we will find a solution for you.
Post Reply
w9mdb
Old Man
Posts: 119
Joined: 13 Jul 2014, 12:05

cluster is slow

Post by w9mdb » 29 Sep 2019, 03:47

I have about 33,000 QSOs in my log.

Trying to connect to dxc.w3lpl.net:7373 to use the CW Skimmer spots but the updates to the cluster spotting in Log4OM is horribly slow -- about two records per second being processed which really can't even keep up with the skimmer spots during a contest like this weekends.

I see about 470ms between

2019-09-29 03:19:26.4313 DEBUG: MySQLDatabaseManagement: SELECT QsoId, log.Call, QsoDate, TimeOn, QsoDateOff, TimeOff, RstSent, RstRcvd, Mode, Country, Band, SrxString, StxString, Iota, IotaIslandId, Name, ContestId, Stx, Srx, Contest FROM log WHERE log.call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 03:19:26.4400 DEBUG: MySQLDatabaseManagement: SQL PARAM Call LIKE %W6RC%
2019-09-29 03:19:26.7603 TRACE: ClusterForm: Cluster notification W6RC not fired. No alerts enabled
2019-09-29 03:19:26.8716 TRACE: MySQLDatabaseManagement: Server=localhost;Port=3306;Database=log;User ID=logUser;Password=logUser;Pooling=false;SslMode=None
2019-09-29 03:19:26.9067 DEBUG: MySQLDatabaseManagement: SELECT QsoId, log.Call, QsoDate, TimeOn, QsoDateOff, TimeOff, RstSent, RstRcvd, Mode, Country, Band, SrxString, StxString, Iota, IotaIslandId, Name, ContestId, Stx, Srx, Contest FROM log WHERE log.call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 03:19:26.9165 DEBUG: MySQLDatabaseManagement: SQL PARAM Call LIKE %K9CT%
2019-09-29 03:19:27.2211 TRACE: ClusterForm: Cluster notification K9CT not fired. No alerts enabled
2019-09-29 03:19:27.3294 TRACE: MySQLDatabaseManagement: Server=localhost;Port=3306;Database=log;User ID=logUser;Password=logUser;Pooling=false;SslMode=None
2019-09-29 03:19:27.3694 DEBUG: MySQLDatabaseManagement: SELECT QsoId, log.Call, QsoDate, TimeOn, QsoDateOff, TimeOff, RstSent, RstRcvd, Mode, Country, Band, SrxString, StxString, Iota, IotaIslandId, Name, ContestId, Stx, Srx, Contest FROM log WHERE log.call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 03:19:27.3772 DEBUG: MySQLDatabaseManagement: SQL PARAM Call LIKE %K1SFA%

User avatar
G4POP
Moderator
Posts: 5865
Joined: 21 Jan 2013, 14:55
Location: Burnham on Crouch, Essex UK

Re: cluster is slow

Post by G4POP » 29 Sep 2019, 07:28

Is it slow with other clusters?
73 Terry G4POP

w9mdb
Old Man
Posts: 119
Joined: 13 Jul 2014, 12:05

Re: cluster is slow

Post by w9mdb » 29 Sep 2019, 13:03

It's not the cluster site that is slow -- it's Log4OM doing it's thing on each spot. You can see the internal time delays in Log4OM as it process the spot.

I discovered this as I'm trying to make the cluster spotting useful so I wrote a queuing program which talks to the cluster site and sends the data to Log4OM once per minute. I even limited it to 100 spots per minute because of this problem which is till too may spots per minute (RTTY contest is keeping it busy). Without queuing you never get a chance to click on a spot as they are moving around too fast.
My queuing program gets the data just fine and dumps it all to Log4OM in a fraction of second.
I've tested this with sqlite3 and mysql and mysql Log4OM mysql is slightly faster than sqlite3 which are the numbers in my first email.

w9mdb
Old Man
Posts: 119
Joined: 13 Jul 2014, 12:05

Re: cluster is slow

Post by w9mdb » 29 Sep 2019, 13:05

And I can send you my log database if you want to test it yourself.

Mike

w9mdb
Old Man
Posts: 119
Joined: 13 Jul 2014, 12:05

Re: cluster is slow

Post by w9mdb » 29 Sep 2019, 15:07

Note also that when sqlite is the database the Log4OM is using 100% CPU during the spot updates.

Here's the log from the sqlite database -- it's about 700ms per query

2019-09-29 15:06:21.7177 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:21.7226 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %EA8ZS%
2019-09-29 15:06:22.3543 TRACE: ClusterForm: Cluster notification EA8ZS not fired. No alerts enabled
2019-09-29 15:06:22.4588 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:22.4637 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %WC7Q%
2019-09-29 15:06:23.1255 TRACE: ClusterForm: Cluster notification WC7Q not fired. No alerts enabled
2019-09-29 15:06:23.2481 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:23.2540 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %K5LY%
2019-09-29 15:06:23.9013 TRACE: ClusterForm: Cluster notification K5LY not fired. No alerts enabled
2019-09-29 15:06:24.0663 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:24.0702 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %CO2AME%
2019-09-29 15:06:24.7063 TRACE: ClusterForm: Cluster notification CO2AME not fired. No alerts enabled
2019-09-29 15:06:24.8280 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:24.8348 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %IK4GNI%
2019-09-29 15:06:25.4772 TRACE: ClusterForm: Cluster notification IK4GNI not fired. No alerts enabled
2019-09-29 15:06:26.6233 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:26.6282 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %AG4W%
2019-09-29 15:06:27.4063 TRACE: ClusterForm: Cluster notification AG4W not fired. No alerts enabled
2019-09-29 15:06:27.5772 DEBUG: SQLiteDatabaseManagement: SELECT QSOID, CALL, QSODATE, TIMEON, QSODATEOFF, TIMEOFF, RSTSENT, RSTRCVD, MODE, COUNTRY, BAND, SRXSTRING, STXSTRING, IOTA, IOTAISLANDID, NAME, CONTESTID, STX, SRX, CONTEST FROM LOG WHERE call LIKE @Call ORDER BY QsoDate DESC, TimeOn DESC
2019-09-29 15:06:27.5821 DEBUG: SQLiteDatabaseManagement: SQL PARAM Call LIKE %VE2GSO%

sp9wpn
Novice Class
Posts: 6
Joined: 27 May 2019, 22:52

Re: cluster is slow

Post by sp9wpn » 04 Oct 2019, 22:56

I've run this query through "EXPLAIN QUERY PLAN" and it appears SQLite is ignoring indexes for it - thus making full, slow db scan.

The problem lays in the LIKE '%CALL%' part - SQLite will not use indexes for such LIKE queries. No easy solution for Log4OM, as we probably need those double wildcards for weird prefixes/suffixes.

Article to read: https://www.sqlite.org/optoverview.html ... timization

w9mdb
Old Man
Posts: 119
Joined: 13 Jul 2014, 12:05

Re: cluster is slow

Post by w9mdb » 08 Oct 2019, 17:33

But why do we care about prefix/suffix?
Seems we should have an option to turn this off so the query can be done with "=" instead of LIKE as I don't care about matching prefixes/suffixes.

There's no database I know of that does anything but a full scan for LIKE selections. No way to index it unless you do a full text search capability.

As it stands now what I've done is write a queuing program that takes the spots and removes duplicates (rounded to nearest 1kHz frequency and cached for 10 minutes) and that has reduced the # of spots coming in to about 18% of what it was. I just zero the cache every 10 minutes and let it start over again.

Plus...I queue up the spots and only send them to Log4OM on the minute so the spotting isn't constantly updating and it makes working with the spots MUCH easier.

Without these two changes the CW Skimmer spots made using the cluster spotting absolutely useless.

If you're interested I can send you code and you can consider putting in the next version. I assume somebody is working on making the cluster spots useful.

Mike

User avatar
IW3HMH
Site Admin
Posts: 2382
Joined: 21 Jan 2013, 14:20
Location: Quarto d'Altino - Venezia (ITA)
Contact:

Re: cluster is slow

Post by IW3HMH » 09 Oct 2019, 11:26

Those queries are used to detect "worked before", and it's necessary to use wildcards because IW3HMH/P and IW3HMH are the same callsign, and users are usually very artistic choosing their callsign prefixes... wildcards doesn't make use of indexes (as SP9WPN said)

Anyway, times seems really slow, i don't experience that kind of timings here.
I'll investigate.
In V2 we keep an hashset in memory for previous callsign in order to avoid constant pollings on database, but those timings are from low level functions that are working directly with datasets...
Daniele Pistollato - IW3HMH

sp9wpn
Novice Class
Posts: 6
Joined: 27 May 2019, 22:52

Re: cluster is slow

Post by sp9wpn » 11 Oct 2019, 10:58

If we extract "core callsign", prefix and suffix then copy them to separate columns in the DB, this would allow to return to indexed search. Of course, this is not what they teach you on "how to manage relational database".

w9mdb
Old Man
Posts: 119
Joined: 13 Jul 2014, 12:05

Re: cluster is slow

Post by w9mdb » 19 Oct 2019, 15:22

In V2 the caching will solve most of the problem.
The other problem besides being slow is the constant updating that takes places when hooked to one of the CW Skimmer cluster sites. They come in so often as to make clicking on anything impossible.
So that's why I have my queueing program just dumping the spots every minute instead of constantly. Works much much better.
Not so much a problem with non-CW skimmer spots which are less frequent though still annoying when they update too often.

Mike

Post Reply