Nous allons faire une passe sur les différents problèmes récurrents que nous avons rencontrés et établir une checklist en cas de problème.
1/ ReadTimeoutException sur un INSERT IF NOT EXISTS :
Description :
Des timeouts apparaissent suite à un changement de code applicatif : Il a été rajouté un INSERT IF NOT EXISTS.
Message d’erreur dans les logs Cassandra:
FAILED : save nom_table com.datastax.driver.core.exceptions.WriteTimeoutException: Cassandra timeout during write query at consistency TWO (2 replica were required but only 1 acknowledged the write)
Le code de la requête :
[INSERT INTO nom_table (champ1,champ2,champX…..) VALUES (valeur1,valeur2,valeurX,….) IF NOT EXISTS USING TTL 691200;];
Message d’erreur dans l’application:
ERROR [Native-Transport-Requests-110] 2018-10-02 09:30:58,813 ErrorMessage.java:384 - Unexpected exception during request
com.google.common.util.concurrent.UncheckedExecutionException: java.lang.RuntimeException: org.apache.cassandra.exceptions.ReadTimeoutException: Operation timed out - received only 0 responses.
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203) ~[guava-18.0.jar:na]...
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
Caused by: java.lang.RuntimeException: org.apache.cassandra.exceptions.ReadTimeoutException: Operation timed out - received only 0 responses.
... 14 common frames omitted
Caused by: org.apache.cassandra.exceptions.ReadTimeoutException: Operation timed out - received only 0 responses.
at org.apache.cassandra.service.ReadCallback.awaitResults(ReadCallback.java:138) ~[apache-cassandra-3.11.2.jar:3.11.2]
Explication :
Le IF NO EXISTS entraine des chutes de performances (Datastax estime qu’une Lightweight transaction prend 4 fois plus de temps qu’une opération classique), il n’est donc pas étonnant de voir des timeouts. De plus l’utilisation d’un timestamp est interdit avec la clause IF NOT EXISTS.
Solution :
- Trouver un moyen de contournement côté applicatif pour cesser d’utiliser les IF NOT EXISTS.
- Augmenter la RAM / CPU des serveurs.
2/ READ messages were dropped
Description :
Problèmes de performances remontés par le client, on s’aperçoit dans la log qu’il y a énormément de messages comme ci-dessous.
Message d’information dans la log système :
INFO [ScheduledTasks:1] 2018-10-02 08:12:14,992 MessagingService.java:1238 - READ messages were dropped in last 5000 ms: 0 internal and 2 cross node. Mean internal dropped latency: 0 ms and Mean cross-node dropped latency: 6610 ms
Explication :
Ce message d’information indique que le serveur est surchargé.
Solution :
- Vérifier le modèle de donnée
- Si le modèle est optimal, alors on peut considérer un ajout de CPU/RAM ou de nœuds
3/ Problème de write timeout et de compteur
Description :
Le client a remonté le problème suivant : Le compteur s’incrémenterait malgré un time out.
Message d’erreur :
Cassandra timeout during write query at consistency ONE (1 replica were required but only 0 acknowledged the write)Cassandra timeout during write query at consistency ONE (1 replica were required but only 0 acknowledged the write)
Rappel 1:
Une table contenant un compteur doit respecter certaines conditions:
- La colonne du compteur ne doit pas être indexé
- La table doit contenir UNIQUEMENT la colonne du COUNTER et la PRIMARY KEY (qui peut être composite), rien d’autre
Rappel 2:
Un update sur un counter qui se solde par un time out ne veut pas forcément dire un échec.
Le compteur peut être incrémenté malgré le time out renvoyé au client.
Lien : https://www.datastax.com/dev/blog/cassandra-error-handling-done-right
Solution :
- Vérifier que la table respecte bien les pré-requis (https://docs.datastax.com/en/cql/3.3/cql/cql_using/useCountersConcept.html)
- Tunner l’instance (https://www.datastax.com/dev/blog/cassandra-error-handling-done-right)
4/ OperationTimedOutException
Description :
L’application du client rencontre un timeout et il n’y aucune information dans les logs de cassandra.
Message d’erreur:
<org.springframework.data.cassandra.CassandraConnectionFailureException: Query; CQL [SELECT * FROM ...]; [/IP:9042] Timed out waiting for server response; nested exception is com.datastax.driver.core.exceptions.OperationTimedOutException: [/IP:9042] Timed out waiting for server response
Caused by: com.datastax.driver.core.exceptions.OperationTimedOutException: [/IP:9042] Timed out waiting for server response
Caused by: com.datastax.driver.core.exceptions.OperationTimedOutException: [/IP:9042] Timed out waiting for server response
...
Explication :
C’est un timeout qui se règle/déclenche côté client (https://docs.datastax.com/en/latest-java-driver-api/com/datastax/driver/core/exceptions/OperationTimedOutException.html)
Solution :
Changer la valeur du seuil (côté applicatif) ou optimiser si possible la requête/modèle de la table concernée.
5/ Lecture massives de tombstones
Description :
On peut voir dans les logs qu’on lit massivement des tombstones, ce qui dégrade les performances.
Message d’erreur :
NoSpamLogger.java:91 - Some operations were slow, details available at debug level (debug.log)
Read 5000 live rows and 34385 tombstone cells for query SELECT * FROM keyspace.table1 WHERE code_x = 4 AND code_z = 6X LIMIT 5000 (see tombstone_warn_threshold)
Read 5000 live rows and 34389 tombstone cells for query SELECT * FROM keyspace.table1 WHERE code_x = 2 AND code_z = LIMIT 5000 …
Autre :
Les pauses du GC restent relativement correctes.
Solution :
- Il faut investiguer sur :
- Pourquoi il y a autant de tombsones ?
- Purge ponctuelle/récurrente ?
- Suppression via des TTLs ?
- Insertions de valeurs nulles ?
- S’il s’agit d’un comportement « normal » alors on peut modifier le gc_grace_seconds est positionné à 10 jours (valeur par défaut), diminuez cette valeur afin de ne plus lire autant de tombsones.
- Attention il faut s’assurer au préalable qu’il y ait bien un repair complet avant l’échéance du gc_grace_seconds.
6/ RepairException
Description :
Nous avons maintenant un problème de repair qui ne fonctionne pas sur plusieurs serveurs du cluster.
Message d’erreur :
ERROR [Repair#9:1] 2018-09-12 09:31:37,486 CassandraDaemon.java:185 - Exception in thread Thread[Repair#9:1,5,RMI Runtime]
com.google.common.util.concurrent.UncheckedExecutionException: org.apache.cassandra.exceptions.RepairException: [repair #e1fb0ba0-b65d-11e8-ae71-7fd804ddec0f on cglib2/jetonsauthentification, (9118716275087714883,9125322504241681923]] Validation failed in /X.X.X.X
....
ERROR [ValidationExecutor:57] 2018-09-12 09:31:37,575 CompactionManager.java:1086 - Cannot start multiple repair sessions over the same sstables
ERROR [ValidationExecutor:57] 2018-09-12 09:31:37,576 Validator.java:246 - Failed creating a merkle tree for ...
Sur un autre noeud :
ERROR [ValidationExecutor:21] 2018-09-12 09:31:37,482 Validator.java:246 - Failed creating a merkle tree for [repair #e1fb0ba0-b65d-11e8-ae71-7fd804ddec0f on cglib2/jetonsauthentification, (9118716275087714883,9125322504241681923]], /X.X.X.X (see log for details)
ERROR [ValidationExecutor:21] 2018-09-12 09:31:37,483 CassandraDaemon.java:185 - Exception in thread Thread[ValidationExecutor:21,1,main]
java.lang.RuntimeException: Cannot start multiple repair sessions over the same sstables
at org.apache.cassandra.db.compaction.CompactionManager.doValidationCompaction(CompactionManager.java:1087) ~[apache-cassandra-2.2.5.jar:2.2.5]
....
Explication:
Il y a plusieurs repairs en parallèle, c’est ce qui pose problème.
Solution :
Afin de résoudre cette problématique :
- Killer l’ensemble des repairs.
- Faire un rolling-restart des différents nœuds pour s’assurer qu’il n’y a plus d’opérations qui trainent.
- Relancer les repairs nœud par nœud.
7/ Repair en erreur sur un nœud absent trop longtemps
Description : Problème de repair sur un nœud.
Sur un cluster de 3 nœuds (le nœud d’où provient l’erreur était down depuis plus d’un mois), tous les repairs depuis cette date sont en erreur puisqu’il manquait un membre du cluster. Depuis hier, ce nœud est de nouveau dans le cluster mais les repairs ne passent toujours pas mais cette fois-ci avec une autre erreur.
Message d’erreur dans les logs Cassandra:
[2018-10-11 14:27:59,999] Starting repair command #2 (1730f690-cd51-11e8-8ba1-a39abca26af3), repairing keyspace pi_premiss_aa with repair options (parallelism: parallel, primary range: true, incremental: false, job threads: 1, ColumnFamilies: [], dataCenters: [], hosts: [], # of ranges: 256, pull repair: false)
error: Repair job has failed with the error message: [2018-10-11 14:28:00,101] Got negative replies from endpoints [X.X.X.X, X.X.X.X]
Solution :
Sur un nœud down depuis longtemps il est souvent préférable et plus efficace de le réintégrer comme un nouveau nœud plutôt que de faire un repair.
On préfèrera faire un remplacement (paramètre -Dcassandra.replace_address de la JVM) pour éviter d’échanger les tokens plutôt que faire un décommissionnement puis un ajout.
Au-delà de la question des perfs, le nœud étant down depuis plus de gc_grace_seconds, cette méthode permettra aussi d’éviter la réapparition de lignes supprimées.
8/ Maximum memory usage reached (512.000MiB), cannot allocate chunk of 1.000MiB
Message d’erreur dans les logs Cassandra:
INFO [Thread-5] 2018-08-06 01:10:00,646 NoSpamLogger.java:91 - Maximum memory usage reached (512.000MiB), cannot allocate chunk of 1.000MiB
Explication:
Il n’y a pas d’impact majeur lié à ces messages (d’où le level INFO et non WARN) mais il peut y avoir un impact sur les performances (notamment si les messages sont fréquents).
Il est possible d’augmenter la mémoire allouée en modifiant le paramètre file_cache_size_in_mb (cet espace est en dehors du HEAP de la JVM et va occuper de la mémoire système, il faut vérifier que les ressources sont suffisantes). Cela étant dit, il est fréquent que ces messages apparaissent parce que les clés de partitions ne sont pas optimales et les partitions trop volumineuses et/ou qu’on exécute des requêtes sans filtrer sur une partition. Une étude et une optimisation du modèle et des requêtes resterait pour moi la première étape.
9/ Repair en échec
Problème :
ERROR [GossipTasks:1] 2018-08-05 02:25:24,219 RepairRunnable.java:277 - Repair session b59bac40-983f-11e8-bb12-d580bbb229b2 for range [(130782004664277475,586273752728790552], (6913626821581233097,7706956824238605934]] failed with error Endpoint /10.X.X.X died
WARN [Service Thread] 2018-08-05 02:25:25,868 GCInspector.java:282 - ConcurrentMarkSweep GC in 19259ms. CMS Old Gen: 3788860768 -> 2461020864; Par Eden Space: 167772160 -> 0; Par Survivor Space: 6690128 -> 0
Explication:
Le repair a échoué en raison d’une pause longue du Garbage collector.
10/ Checklist en cas de problème
Visualiser le log d’erreur
Visualiser le log du garbage collector
Visualiser le debug log
Les différents options de nodetool :
- nodetool status
- nodetool netstats
- nodetool tpstats
- nodetool proxyhistograms
- nodetool gcstats
- nodetool compactionstats
- …
Visualiser le log côté applicatif
Visualiser les différents graphiques de votre supervision.
Si vous souhaitez un support technique sur Cassandra, n’hésitez pas à nous contacter.