prepared statements cache size issues in cassandra logs

[kapil-ksolves]

I found below logs in the Cassandra logs -

2607 prepared statements discarded in the last minute because cache limit reached

We can see this very frequently in Cassandra logs.

And according to Cassandra documentation, the first reason for this can be the improper use of prepared statements and the other could be a very small amount of memory size is assigned to prepared statement cache.

Is there anything that can be done on Achilles side to resolve this issue or there could be any other reason for this?

Thanks in advance for help! Kapil Kaushik

[doanduyhai]

Which version of Achilles are you using ?

Which API are your using ? CRUD ? DSL ?

Achilles has a prepared statement cache and automatically prepare statements for you, especially if you use crud().update(...) or if you use crud().insert(...) with Insert strategy NOT NULL FIELDS

[kapil-ksolves]

We are using 6.0.0 version.

We are using both CRUD and DSL.

[doanduyhai]

Which DSL ? Update ? Insert ?

Indeed for each combination of fields, Achilles will generate a prepared statement and stores it in its own internal Guava cache

In your case, you may have a lot of entities with a lot of columns right ?

[kapil-ksolves]

We are using Insert mostly. Very less Update.

I am assuming if we are using the query in below way, Cassandra will keep it once in the prepared statement cache. (And we may be running below query 5 times in 10 seconds).

manager.indexed().select().allColumns_FromBaseTable() .where().indexed_FIELD_NAME().Eq(VALUE) .indexed_FIELD_NAME().Eq(VALUE) .getList();

[doanduyhai]

How many distinct indexed field names are there ?

Normally you should have only 1 prepared statement generated for your select if it is always the same indexed field name being queried

[kapil-ksolves]

We are using only 2 fields as mentioned in the above query. That means even this query is fired 5 times per seconds there will be only 1 prepared statement for that. *The values may be changed.

[doanduyhai]

The code putting new prepared statement in the cache is here: https://github.com/doanduyhai/Achilles/blob/master/achilles-core/src/main/java/info/archinnov/achilles/internals/cache/StatementsCache.java#L53

Try to put this class info.archinnov.achilles.internals.cache.StatementsCache log level to DEBUG and check your logs to see why there are so many prepared statements being created

[doanduyhai]

The default LRU cache size for prepared statements in Achilles is set to 10 000 which is way above Cassandra limits

[doanduyhai]

The code preparing dynamically new statements is here

public PreparedStatement getDynamicCache(final String queryString, Session session) {
        AtomicBoolean displayStats = new AtomicBoolean(false);
        try {
            final PreparedStatement preparedStatement = dynamicCache.get(queryString, () -> {
                displayStats.getAndSet(true);
                if (LOGGER.isDebugEnabled()) {
                    LOGGER.debug("Preparing dynamic query : " + queryString);
                }
                return session.prepare(queryString);
            });

            if (displayStats.get()) displayCacheStatistics();
            return preparedStatement;
        } catch (ExecutionException e) {
            throw new AchillesException(e);
        }
    }

[kapil-ksolves]

I will check that by putting the logs in the way you mentioned and will come back here after my findings.

[kapil-ksolves]

Getting below WARN in the logs -

com.datastax.driver.core.Cluster Re-preparing already prepared query is generally an anti-pattern and will likely affect performance. Consider preparing the statement only once.

[doanduyhai]

Ok but which statement is "re-prepared" ? We need to have more details

[kapil-ksolves]

Here is the logs

2019-02-19 09:03:08,524 DEBUG [Timer-Driven Process Thread-293] i.a.a.internals.cache.StatementsCache Putting static cache for key CacheKey{entityClass=class package1.ClassName, operation=INSERT} 2019-02-19 09:01:32,284 DEBUG [Timer-Driven Process Thread-31] i.a.a.internals.cache.StatementsCache Preparing dynamic query : SELECT FROM db.table1 WHERE field1=:value AND field2=:value AND field3 IN :values; 2019-02-19 09:01:32,285 WARN [cluster10-worker-30] com.datastax.driver.core.Cluster Re-preparing already prepared query is generally an anti-pattern and will likely affect performance. Consider preparing the statement only once. Query='SELECT FROM db.table1 WHERE field1=:value AND field2=:value AND field3 IN :values;'

[kapil-ksolves]

After enabling the logs for the *.StatementsCache, I can see the logs but I am not getting exact Idea when cache is getting full. What is the expected log to be printed in this log statement.

Total LRU cache size ?

[doanduyhai]

Yes Total LRU cache size

[doanduyhai]

So according to the StatementCache logs, your application is attempting to prepare multiple times the query SELECT * FROM db.table1 WHERE field1=:value AND field2=:value AND field3 IN :values;

Is your application multi-threaded ?

[kapil-ksolves]

Yes Total LRU cache size

What value will be printed in this log when the prepared_statement cache reached its limit. Currently, I can see # prepared statements discarded in the last minute because cache limit reached log in cassandra.log file, but I can see only Total LRU cache size {1, 2 or 3}.

[kapil-ksolves]

So according to the StatementCache logs, your application is attempting to prepare multiple times the query SELECT * FROM db.table1 WHERE field1=:value AND field2=:value AND field3 IN :values;

Is your application multi-threaded ?

Yes, our application is multi-threaded.

[doanduyhai]

Let's me check the code, maybe we have racing conditions when accessing the cache and preparing statements

[kapil-ksolves]

okay, thanks!

For below error, do you think there is something in our application code on which we should work?

prepared statements discarded in the last minute because cache limit reached

[doanduyhai]

You're mixing cassandra log with Achilles logs.

The statement cache in Achilles is not necessarily full. The statement cache in Cassandra server is full.

How many clients (instances of Achilles) is connecting to your Cassandra cluster ?

Because maybe, each instance of Achilles has only 2/3 statements in its cache but if you have 1000 instances of Achilles connecting to the same cluster, the same statements will be prepared 1000 times and may fill up Cassandra server cache quickly

[kapil-ksolves]

Okay, so that is the problem. We are having more than 5 Achilles clients for the Cassandra cluster. Am I understanding it correctly? that Cassandra creates a prepared statement again in its prepared statment cache if it is from a new Achilles client even if it has the same prepared statement in the cache.

[kapil-ksolves]

Okay, so that is the problem. We are having more than 5 Achilles clients for the Cassandra cluster. Am I understanding it correctly? that Cassandra creates a prepared statement again in its prepared statment cache if it is from a new Achilles client even if it has the same prepared statement in the cache.

If it is the case then is there any solution that we can do from Achilles side or increasing of prepared statement cache is the only option.

One thing I want to add, we also have cassandra cluster where we have only one Achilles client. There also we are getting below error.

prepared statements discarded in the last minute because cache limit reached

[doanduyhai]

I don't know how Cassandra manages its cache of prepared statements but what is sure is that if you have different Achilles clients, it can occurs that the same statement can be prepared by different Achilles instances and sent to the cluster.

Now, if you tell me that you have only 5 instances of Achilles and the cache size of each Achilles client is around 3/4, the maths do not add up to 1000s of prepared statement so there is also another problem

[doanduyhai]

You best bet is right now activate DEBUG log on the StatementCache class from Achilles and let it run for some times and see how many statements are prepared over time

[kapil-ksolves]

okay, but again as you said earlier, the logs after activating the DEBUG log on StatementCache class will be the one for which prepared statements are created in Achilles cache, not in the Cassandra cache. Right?

Below is the sample log. can I assume the each log says that a prepared statement is created? What is the meaning of operation in the logs?

DEBUG [Timer-Driven Process Thread-4] i.a.a.internals.cache.StatementsCache Putting static cache for key CacheKey{entityClass=class CLASS_NAME-1, operation=INSERT} DEBUG [Timer-Driven Process Thread-4] i.a.a.internals.cache.StatementsCache Putting static cache for key CacheKey{entityClass=class CLASS_NAME-1, operation=INSERT_IF_NOT_EXISTS} DEBUG [Timer-Driven Process Thread-4] i.a.a.internals.cache.StatementsCache Putting static cache for key CacheKey{entityClass=class CLASS_NAME-1, operation=INSERT_JSON} DEBUG [Timer-Driven Process Thread-4] i.a.a.internals.cache.StatementsCache Putting static cache for key CacheKey{entityClass=class CLASS_NAME-1, operation=INSERT_IF_NOT_EXISTS_JSON}

[doanduyhai]

okay, but again as you said earlier, the logs after activating the DEBUG log on StatementCache class will be the one for which prepared statements are created in Achilles cache, not in the Cassandra cache. Right?

1 prepared statement in Achilles cache == 1 prepared statement also in Cassandra server cache

The logs (static cache) say that Achilles prepare ahead of time some statements that are used very often. Those are:

• INSERT
• INSERT IF NOT EXISTS
• INSERT JSON
• INSERT JSON IF NOT EXISTS ...

Those statements are always prepared when Achilles bootstrap. On the contrary, dynamically prepared statements are done when you use manager.dsl() API

[kapil-ksolves]

1. As we are having more than one Achilles Instances and you said this can be one of the reason for re preparation of Prepared statements. Can we do something to avoid this?
2. And prepared statement cache size is assigned independently to the kespaces we have in cassandra. Is it correct?
3. Can It be a reason for this or Achilles is doing this for us? https://docs.datastax.com/en/developer/java-driver/3.0/manual/statements/prepared/

[doanduyhai]

1. Why do you have multiple instances of Achilles in one application ? Or do you have multiple applications using Achilles ?

2. Yes, statements prepared by Achilles always include the keyspace name so the cache size is independent of the keyspace

3. Achilles is doing this for you

[kapil-ksolves]

1. You can understand this in a way that, multiple builds of the same application is running as different processes. And it is necessary for us. Is there a way to share same cache within multiple Achilles instances? It may not be possible within different VMs ie. VM 1 and VM 2 in below example. But if we can use it between multiple instances of Achilles at single VM ie. All three instances of Achilles can share same cache on VM1 below.

[doanduyhai]

You can share, within the same VM, the same statement cache between different Achilles instances:

StatementCache sharedCache = new StatementCache(10000);
Cluster cluster = ...

ManagerFactory_For_xxx factory1 = ManagerFactoryBuilder_For_xxx
                .builder(cluster)
                 ...
                .withStatementsCache(sharedCache)
                .build()

ManagerFactory_For_yyy factory2 = ManagerFactoryBuilder_For_yyy
                .builder(cluster)
                 ...
                .withStatementsCache(sharedCache)
                .build()

[kapil-ksolves]

okay thanks. Will check it. I think this will help by consuming less prepared cache then it is using now.

[kapil-ksolves]

Will this work for different processes what I explained above? How the other Achilles will get to know it has to pick the existing one?

[doanduyhai]

No, it will work inside the same JVM only. For processes running in different JVM, you need a different statement cache.

But this problem is universal and not related to Achilles. If you were using the plain Java Driver, you would have the same problem e.g. you would have to prepare the same statements in different JVM