mirror of https://github.com/apache/cassandra
248 lines
13 KiB
Plaintext
248 lines
13 KiB
Plaintext
= Cassandra Logs
|
|
|
|
Cassandra has rich support for logging and attempts to give operators
|
|
maximum insight into the database while at the same time limiting noise
|
|
to the logs.
|
|
|
|
== Common Log Files
|
|
|
|
Cassandra has three main logs, the `system.log`, `debug.log` and
|
|
`gc.log` which hold general logging messages, debugging logging
|
|
messages, and java garbage collection logs respectively.
|
|
|
|
These logs by default live in `${CASSANDRA_HOME}/logs`, but most Linux
|
|
distributions relocate logs to `/var/log/cassandra`. Operators can tune
|
|
this location as well as what levels are logged using the provided
|
|
`logback.xml` file.
|
|
|
|
=== `system.log`
|
|
|
|
This log is the default Cassandra log and is a good place to start any
|
|
investigation. Some examples of activities logged to this log:
|
|
|
|
* Uncaught exceptions. These can be very useful for debugging errors.
|
|
* `GCInspector` messages indicating long garbage collector pauses. When
|
|
long pauses happen Cassandra will print how long and also what was the
|
|
state of the system (thread state) at the time of that pause. This can
|
|
help narrow down a capacity issue (either not enough heap or not enough
|
|
spare CPU).
|
|
* Information about nodes joining and leaving the cluster as well as
|
|
token metadata (data ownersip) changes. This is useful for debugging
|
|
network partitions, data movements, and more.
|
|
* Keyspace/Table creation, modification, deletion.
|
|
* `StartupChecks` that ensure optimal configuration of the operating
|
|
system to run Cassandra
|
|
* Information about some background operational tasks (e.g. Index
|
|
Redistribution).
|
|
|
|
As with any application, looking for `ERROR` or `WARN` lines can be a
|
|
great first step:
|
|
|
|
[source, bash]
|
|
----
|
|
$ # Search for warnings or errors in the latest system.log
|
|
$ grep 'WARN\|ERROR' system.log | tail
|
|
...
|
|
|
|
$ # Search for warnings or errors in all rotated system.log
|
|
$ zgrep 'WARN\|ERROR' system.log.* | less
|
|
...
|
|
----
|
|
|
|
=== `debug.log`
|
|
|
|
This log contains additional debugging information that may be useful
|
|
when troubleshooting but may be much noiser than the normal
|
|
`system.log`. Some examples of activities logged to this log:
|
|
|
|
* Information about compactions, including when they start, which
|
|
sstables they contain, and when they finish.
|
|
* Information about memtable flushes to disk, including when they
|
|
happened, how large the flushes were, and which commitlog segments the
|
|
flush impacted.
|
|
|
|
This log can be _very_ noisy, so it is highly recommended to use `grep`
|
|
and other log analysis tools to dive deep. For example:
|
|
|
|
[source, bash]
|
|
----
|
|
# Search for messages involving a CompactionTask with 5 lines of context
|
|
$ grep CompactionTask debug.log -C 5
|
|
|
|
# Look at the distribution of flush tasks per keyspace
|
|
$ grep "Enqueuing flush" debug.log | cut -f 10 -d ' ' | sort | uniq -c
|
|
6 compaction_history:
|
|
1 test_keyspace:
|
|
2 local:
|
|
17 size_estimates:
|
|
17 sstable_activity:
|
|
----
|
|
|
|
=== `gc.log`
|
|
|
|
The gc log is a standard Java GC log. With the default `jvm.options`
|
|
settings you get a lot of valuable information in this log such as
|
|
application pause times, and why pauses happened. This may help narrow
|
|
down throughput or latency issues to a mistuned JVM. For example you can
|
|
view the last few pauses:
|
|
|
|
[source, bash]
|
|
----
|
|
$ grep stopped gc.log.0.current | tail
|
|
2018-08-29T00:19:39.522+0000: 3022663.591: Total time for which application threads were stopped: 0.0332813 seconds, Stopping threads took: 0.0008189 seconds
|
|
2018-08-29T00:19:44.369+0000: 3022668.438: Total time for which application threads were stopped: 0.0312507 seconds, Stopping threads took: 0.0007025 seconds
|
|
2018-08-29T00:19:49.796+0000: 3022673.865: Total time for which application threads were stopped: 0.0307071 seconds, Stopping threads took: 0.0006662 seconds
|
|
2018-08-29T00:19:55.452+0000: 3022679.521: Total time for which application threads were stopped: 0.0309578 seconds, Stopping threads took: 0.0006832 seconds
|
|
2018-08-29T00:20:00.127+0000: 3022684.197: Total time for which application threads were stopped: 0.0310082 seconds, Stopping threads took: 0.0007090 seconds
|
|
2018-08-29T00:20:06.583+0000: 3022690.653: Total time for which application threads were stopped: 0.0317346 seconds, Stopping threads took: 0.0007106 seconds
|
|
2018-08-29T00:20:10.079+0000: 3022694.148: Total time for which application threads were stopped: 0.0299036 seconds, Stopping threads took: 0.0006889 seconds
|
|
2018-08-29T00:20:15.739+0000: 3022699.809: Total time for which application threads were stopped: 0.0078283 seconds, Stopping threads took: 0.0006012 seconds
|
|
2018-08-29T00:20:15.770+0000: 3022699.839: Total time for which application threads were stopped: 0.0301285 seconds, Stopping threads took: 0.0003789 seconds
|
|
2018-08-29T00:20:15.798+0000: 3022699.867: Total time for which application threads were stopped: 0.0279407 seconds, Stopping threads took: 0.0003627 seconds
|
|
----
|
|
|
|
This shows a lot of valuable information including how long the
|
|
application was paused (meaning zero user queries were being serviced
|
|
during the e.g. 33ms JVM pause) as well as how long it took to enter the
|
|
safepoint. You can use this raw data to e.g. get the longest pauses:
|
|
|
|
[source, bash]
|
|
----
|
|
$ grep stopped gc.log.0.current | cut -f 11 -d ' ' | sort -n | tail | xargs -IX grep X gc.log.0.current | sort -k 1
|
|
2018-08-28T17:13:40.520-0700: 1.193: Total time for which application threads were stopped: 0.0157914 seconds, Stopping threads took: 0.0000355 seconds
|
|
2018-08-28T17:13:41.206-0700: 1.879: Total time for which application threads were stopped: 0.0249811 seconds, Stopping threads took: 0.0000318 seconds
|
|
2018-08-28T17:13:41.638-0700: 2.311: Total time for which application threads were stopped: 0.0561130 seconds, Stopping threads took: 0.0000328 seconds
|
|
2018-08-28T17:13:41.677-0700: 2.350: Total time for which application threads were stopped: 0.0362129 seconds, Stopping threads took: 0.0000597 seconds
|
|
2018-08-28T17:13:41.781-0700: 2.454: Total time for which application threads were stopped: 0.0442846 seconds, Stopping threads took: 0.0000238 seconds
|
|
2018-08-28T17:13:41.976-0700: 2.649: Total time for which application threads were stopped: 0.0377115 seconds, Stopping threads took: 0.0000250 seconds
|
|
2018-08-28T17:13:42.172-0700: 2.845: Total time for which application threads were stopped: 0.0475415 seconds, Stopping threads took: 0.0001018 seconds
|
|
2018-08-28T17:13:42.825-0700: 3.498: Total time for which application threads were stopped: 0.0379155 seconds, Stopping threads took: 0.0000571 seconds
|
|
2018-08-28T17:13:43.574-0700: 4.247: Total time for which application threads were stopped: 0.0323812 seconds, Stopping threads took: 0.0000574 seconds
|
|
2018-08-28T17:13:44.602-0700: 5.275: Total time for which application threads were stopped: 0.0238975 seconds, Stopping threads took: 0.0000788 seconds
|
|
----
|
|
|
|
In this case any client waiting on a query would have experienced a
|
|
56ms latency at 17:13:41.
|
|
|
|
Note that GC pauses are not _link:[only] garbage collection, although
|
|
generally speaking high pauses with fast safepoints indicate a lack of
|
|
JVM heap or mistuned JVM GC algorithm. High pauses with slow safepoints
|
|
typically indicate that the JVM is having trouble entering a safepoint
|
|
which usually indicates slow disk drives (Cassandra makes heavy use of
|
|
memory mapped reads which the JVM doesn't know could have disk latency,
|
|
so the JVM safepoint logic doesn't handle a blocking memory mapped read
|
|
particularly well).
|
|
|
|
Using these logs you can even get a pause distribution with something
|
|
like
|
|
https://github.com/bitly/data_hacks/blob/master/data_hacks/histogram.py[histogram.py]:
|
|
|
|
[source, bash]
|
|
----
|
|
$ grep stopped gc.log.0.current | cut -f 11 -d ' ' | sort -n | histogram.py
|
|
# NumSamples = 410293; Min = 0.00; Max = 11.49
|
|
# Mean = 0.035346; Variance = 0.002216; SD = 0.047078; Median 0.036498
|
|
# each ∎ represents a count of 5470
|
|
0.0001 - 1.1496 [410255]: ∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
|
|
1.1496 - 2.2991 [ 15]:
|
|
2.2991 - 3.4486 [ 5]:
|
|
3.4486 - 4.5981 [ 1]:
|
|
4.5981 - 5.7475 [ 5]:
|
|
5.7475 - 6.8970 [ 9]:
|
|
6.8970 - 8.0465 [ 1]:
|
|
8.0465 - 9.1960 [ 0]:
|
|
9.1960 - 10.3455 [ 0]:
|
|
10.3455 - 11.4949 [ 2]:
|
|
----
|
|
|
|
We can see in this case while we have very good average performance
|
|
something is causing multi second JVM pauses ... In this case it was
|
|
mostly safepoint pauses caused by slow disks:
|
|
|
|
[source, bash]
|
|
----
|
|
$ grep stopped gc.log.0.current | cut -f 11 -d ' ' | sort -n | tail | xargs -IX grep X gc.log.0.current| sort -k 1
|
|
2018-07-27T04:52:27.413+0000: 187831.482: Total time for which application threads were stopped: 6.5037022 seconds, Stopping threads took: 0.0005212 seconds
|
|
2018-07-30T23:38:18.354+0000: 514582.423: Total time for which application threads were stopped: 6.3262938 seconds, Stopping threads took: 0.0004882 seconds
|
|
2018-08-01T02:37:48.380+0000: 611752.450: Total time for which application threads were stopped: 10.3879659 seconds, Stopping threads took: 0.0004475 seconds
|
|
2018-08-06T22:04:14.990+0000: 1113739.059: Total time for which application threads were stopped: 6.0917409 seconds, Stopping threads took: 0.0005553 seconds
|
|
2018-08-14T00:04:06.091+0000: 1725730.160: Total time for which application threads were stopped: 6.0141054 seconds, Stopping threads took: 0.0004976 seconds
|
|
2018-08-17T06:23:06.755+0000: 2007670.824: Total time for which application threads were stopped: 6.0133694 seconds, Stopping threads took: 0.0006011 seconds
|
|
2018-08-23T06:35:46.068+0000: 2526830.137: Total time for which application threads were stopped: 6.4767751 seconds, Stopping threads took: 6.4426849 seconds
|
|
2018-08-23T06:36:29.018+0000: 2526873.087: Total time for which application threads were stopped: 11.4949489 seconds, Stopping threads took: 11.4638297 seconds
|
|
2018-08-23T06:37:12.671+0000: 2526916.741: Total time for which application threads were stopped: 6.3867003 seconds, Stopping threads took: 6.3507166 seconds
|
|
2018-08-23T06:37:47.156+0000: 2526951.225: Total time for which application threads were stopped: 7.9528200 seconds, Stopping threads took: 7.9197756 seconds
|
|
----
|
|
|
|
Sometimes reading and understanding java GC logs is hard, but you can
|
|
take the raw GC files and visualize them using tools such as
|
|
https://github.com/chewiebug/GCViewer[GCViewer] which take the Cassandra
|
|
GC log as input and show you detailed visual information on your garbage
|
|
collection performance. This includes pause analysis as well as
|
|
throughput information. For a stable Cassandra JVM you probably want to
|
|
aim for pauses less than 200ms and GC throughput greater
|
|
than 99%.
|
|
|
|
Java GC pauses are one of the leading causes of tail latency in
|
|
Cassandra (along with drive latency) so sometimes this information can
|
|
be crucial while debugging tail latency issues.
|
|
|
|
== Getting More Information
|
|
|
|
If the default logging levels are insuficient, `nodetool` can set higher
|
|
or lower logging levels for various packages and classes using the
|
|
`nodetool setlogginglevel` command. Start by viewing the current levels:
|
|
|
|
[source, bash]
|
|
----
|
|
$ nodetool getlogginglevels
|
|
|
|
Logger Name Log Level
|
|
ROOT INFO
|
|
org.apache.cassandra DEBUG
|
|
----
|
|
|
|
Perhaps the `Gossiper` is acting up and we wish to enable it at `TRACE`
|
|
level for even more insight:
|
|
|
|
[source, bash]
|
|
----
|
|
$ nodetool setlogginglevel org.apache.cassandra.gms.Gossiper TRACE
|
|
|
|
$ nodetool getlogginglevels
|
|
|
|
Logger Name Log Level
|
|
ROOT INFO
|
|
org.apache.cassandra DEBUG
|
|
org.apache.cassandra.gms.Gossiper TRACE
|
|
|
|
$ grep TRACE debug.log | tail -2
|
|
TRACE [GossipStage:1] 2018-07-04 17:07:47,879 Gossiper.java:1234 - Updating
|
|
heartbeat state version to 2344 from 2343 for 127.0.0.2:7000 ...
|
|
TRACE [GossipStage:1] 2018-07-04 17:07:47,879 Gossiper.java:923 - local
|
|
heartbeat version 2341 greater than 2340 for 127.0.0.1:7000
|
|
----
|
|
|
|
Note that any changes made this way are reverted on next Cassandra
|
|
process restart. To make the changes permanent add the appropriate rule
|
|
to `logback.xml`.
|
|
|
|
[source,diff]
|
|
----
|
|
diff --git a/conf/logback.xml b/conf/logback.xml
|
|
index b2c5b10..71b0a49 100644
|
|
--- a/conf/logback.xml
|
|
+++ b/conf/logback.xml
|
|
@@ -98,4 +98,5 @@ appender reference in the root level section below.
|
|
</root>
|
|
|
|
<logger name="org.apache.cassandra" level="DEBUG"/>
|
|
+ <logger name="org.apache.cassandra.gms.Gossiper" level="TRACE"/>
|
|
</configuration>
|
|
----
|
|
|
|
|
|
Note that if you want more information than this tool provides, there
|
|
are other live capture options available such as
|
|
xref:cassandra:troubleshooting/use_tools.adoc#packet-capture[`packet-capture`].
|