7.1.3
I am getting a ton of these - com.inductiveautomation.ignition.gateway.history.stores.HSQLDataStore Store of 1 records took 880 milliseconds
I have turned this off in the “levels” but it is still showing up.
That message should probably not be “info” level - it has been changed. You should be able to turn it off by switching the level of “HSQLDataStore” logger to WARN.
Let’s look at a different problem though: your history is being logged to the cache instead of directly to the database and is taking 880 ms per row?!? That can’t be good.
There are a few scenarios that come to mind:
- Database is down, so data is being logged to cache, but the cache system is just being slow (there’s a possibility that the 1 record represents a transaction with many rows, but still - 800ms is a long time).
- The database is up, but something happened that caused data to not be written as quickly as expected- which caused it to be sent to the data cache. Given that data is pulled first from the data cache, you’ve now entered a cycle where all data must be written to and then pulled from the cache.
Go to the Status section and take a look at the store and forward system, and see what kind of stats you have. Also, are your store and forward settings at the default values? By default it only gives the data 1 second to go from the memory store to the database before moving to the cache- this should probably be bumped up quite a bit to avoid the cache more of the time and give it a chance to catch up when unexpected things happen.
Regards,
Ok this does seem to be the case. Basically it is always into the “store and forward”. it builds to 25 then writes constantly.All settings are default except for the one you told me to change and I set it to 10 seconds, but this did not help. What next?
What next?
Well, does the number of records in the internal store ever go down, or does it eventually just max out?
If you make the memory buffer bigger, and then make the “write time” and “write size” bigger under “Store Settings” - not Forward settings, which should be small - do you ever see the data count in the store shrink?
I’m curious- what kind of numbers are we talking about going into the pipeline? If you go to status>store and forward, what do you see for “store throughput”?
Regards,
Ok, I followed up with David, and it turned out to be a simple issue of getting the settings right.
However, I wanted to follow up here with what we ended up with, because the settings can be tricky, and in particular I noticed one phenomenon that I don’t believe is documented.
Problem:
Data is being constantly passing through the data store (internal database) before being forwarded on to MySQL.
Original Settings:
Buffer Size : 500
Store Write Size: 50
Store Write Time: 10000
Forward Write Size: 25
Forward Write Time: 10000
What’s wrong:
Data forwarded to the database from the store first, if there’s data, and then from the buffer. With these settings, it is forwarded once there are 25 rows, or if the latest row is older than 10 seconds.
Data would be forwarded from the memory buffer to the store if there were more than 50 records, or a record was older than 10 seconds. The fact that both parts were set to 10 seconds mean that data was equally as likely to be written to the database as it was to the store. The problem is that once written to the store, it is likely to continue to be written to the store, due to the added delay of reading and writing to the internal database (at least several hundred milliseconds).
Not at the core of the problem, the write size and write time settings meant that all data was being delayed by some amount before being forwarded. Normally (including this case), people want the data to be forwarded as quickly as possible.
New Settings:
Buffer Size : 500
Store Write Size: 250
Store Write Time: 10000
Forward Write Size: 100
Forward Write Time: 100
The goal is to write data as quickly as possible, only using the cache when the target DB is down. We switched store write size to 250- 1/2 of the available buffer. This could be a bit lower, but 25 isn’t big enough: I observed that he was getting bursts of data nearly that size, meaning that a big burst could trigger a write to the store.
The “forward” settings are where it’s interesting. Setting the write time to a low number (I chose 100ms, but it could be made lower) causes the data to be forwarded quickly. The forward write size is the really interesting point. Why so high? It turns out that the data store uses this number as a hint for the forward transaction size. Many users trying to get data to forward immediately will set this to 1, which is what we did initially. The problem is that then the data store is only querying 1 row at a time, which is really inefficient. The forward of data is triggered by either the write size or the write time, so using these settings basically means “once data is 100ms old, grab it in 100 row blocks from the store”. This turned out to work very well for his system and we saw data the data get cleared from the cache very quickly, and then only write from the memory store.
Colby,
Update. Today we added/doubled our Ram to 8 Gig. Afterwards the store and forward started acting normally. Ram usage is still around 2 to 3 Gigs normally. I know you are still working on this and thought I would let you know.
Thanks for the update. If I had to make a quick guess, I would say that the RAM helped MySQL, which in turned helped us.
I’ve been looking at the store and forward system a lot the last few days, and everything seems to be in order. My main goal has been to re-work the logging system so that we could get a better picture of what your system is up to.
The best I can come with so far to describe the situation we saw on your system is that MySQL was right on the edge of what it could handle from Ignition. The transactions it receives are different depending on whether they come from the memory store (fewer points per transaction) or the data cache (more points per transaction). Going from memory it was backing up, going from the cache it could keep up. This is all just conjecture, but it seems to make sense.
Anyhow, we’ll just keep an eye on it. Like I said, the next update will have some better logging, which hopefully should help us get a more precise idea of what’s going on. I’m also going to look into accelerating some optimizations in the memory store that have always been planned but not yet implemented which should make the transactions from that look more like the transactions from the cache.
Regards,