Enabling tracing to aid in troubleshooting
To identify the cause of failures or errors, you can enable tracing (logging) for Cassandra queries or all operations. Only enable tracing during problem identification and disable immediately upon resolution.
About this task
Important: Tracing affects performance negatively. Never enable tracing in a production environment unless advised by an IBM® Support Engineer.
You can set logging properties in the server configuration file (server.xml)
by adding a logging element to the server configuration file as
follows:
<logging traceSpecification = "*=audit:com.myco.mypackage.*=finest" />
The
format of the log detail level specification
is:<component> = <level>
Where <component> is the component for which
to set a log detail level, and <level> is one of the valid logger levels (off, fatal, severe,
warning, audit, info, config, detail, fine, finer, finest, all). Separate multiple log detail level
specifications with colons (:).Tracing for Cassandra query language (CQL) is enabled by setting the logging level of a Cassandra Data Access Object (DAO) to ALL. Cassandra DAOs are in the following Java™ package:
com.ibm.mailbox.database.dao.cassandra
To enable tracing:
Procedure
Results
[2015-03-13T18:05:08.695-0500] 00000001 DatacenterDAO >
com.ibm.mailbox.database.dao.cassandra.DatacenterDAO listAllDatacenters ENTRY
[2015-03-13T18:05:08.729-0500] 00000001 CassandraDAO
I com.ibm.mailbox.database.dao.cassandra.CassandraDAO cqlTrace
Statements:
SELECT * FROM gatekeeper.datacenters;
Host (queried): localhost/127.0.0.1:44952
Host (tried): localhost/127.0.0.1:44952
Trace id: 64f51d80-c9d5-11e4-996d-7d8ea8b489ab
------------------------------------------------------------------------------------------------+---------------------------+------------+---------------
Determining replicas to query | 2015-03-13T18:05:08-05:00 | /127.x.0.x |xx
Executing seq scan across 0 sstables for [min(-9223372036854775808),
min(-9223372036854775808)] | 2015-03-13T18:05:08-05:00 | /127.x.0.x | yyy
Scanned 0 rows and matched 0 | 2015-03-13T18:05:08-05:00 | /127.0.0.1 | zzz
The Statements section shows the CQL statements executed (in the case
of a Batch, there might be more than one CQL statement executed), followed by a table. The Queried
host is the host that coordinated (performed) the query. The Tried host is the host (or hosts) that
the query is performed against. This is usually the same as the queried host but if connection
failures occur, this is a list of all hosts that were tried. The Events table shows a list of query
events (oldest to youngest). Each row contains:
- Event description
- Event time stamp
- Event host - the host that generated the event
- Event elapsed time - the amount of time, in microseconds, taken from the start of query processing to when the event was raised.
Sometimes, the tracing information cannot be retrieved from Cassandra. Five attempts are made by the Cassandra driver logic to retrieve the tracing information. If the information cannot be retrieved, a log entry similar to the following message is created:
[2015-03-13T18:05:08.775-0500] 00000001 DatacenterDAO >
com.ibm.mailbox.database.dao.cassandra.DatacenterDAO listAllDatacenters ENTRY
[2015-03-13T18:04:52.806-0500] 00000001 CassandraDAO
I com.ibm.mailbox.database.dao.cassandra.CassandraDAO cqlTrace
Statements:
SELECT * FROM gatekeeper.datacenters;
Failed to retrive trace for statement(s)
The tracing information from mediated DAO methods looks similar to the following excerpt:
[2015-03-18T11:51:09.640-0700] 00000001 CassandraAtom I com.ibm.mailbox.database.mediator.CassandraAtomicityMediator$CQL cqlTrace
Statements:
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
INSERT INTO gatekeeper.password_vault(id,password) VALUES (?,?);
Host (queried): localhost/127.0.0.1:47195
Host (tried): localhost/127.0.0.1:47195
Trace id: bdc3afd0-cd9f-11e4-a376-f51d2de36ca2
-----------------------------------------------------+---------------------------+------------+---------------
Determining replicas for atomic batch | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 557
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 4163
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 4190
Adding to batchlog memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 4216
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 8058
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 8133
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 8253
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 8637
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 8726
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 8817
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 9109
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 9217
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 9462
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 10697
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 10755
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 10791
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 10852
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 10888
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 10992
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11464
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11511
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11618
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11642
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11730
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11750
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11832
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11856
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11937
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 11959
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 12021
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 12043
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 12131
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 12151
Adding to password_vault memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 18755
Acquiring switchLock read lock | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 19153
Appending to commitlog | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 19167
Adding to batchlog memtable | 2015-03-18T11:51:09-07:00 | /127.0.0.1 | 19202