Skip to content

Statements Logging and Tracing

Jump to bottom
DuyHai DOAN edited this page Mar 19, 2017 · 4 revisions

Global statements logging

It is possible to display CQL statements in the log. For this you need to activate the ACHILLES_DML_STATEMENT logger.

Sample log4j.xml config file

<logger name="ACHILLES_DML_STATEMENT">
	<level value="DEBUG" />
</logger>

Expected log messages:

DEBUG ACHILLES_DML_STATEMENT - Query ID 3873d787-c379-4bec-85c0-907a96b362ba : [SELECT id,date,consistencylist,simplemap,simpleset,value FROM achilles_embedded.simple WHERE id=:id AND date=:date;] with CONSISTENCY LEVEL [ONE]
DEBUG ACHILLES_DML_STATEMENT - 	 Java bound values : [5107957575091721216, Thu Oct 01 02:00:00 CEST 2015]
DEBUG ACHILLES_DML_STATEMENT - 	 Encoded bound values : [5107957575091721216, Thu Oct 01 02:00:00 CEST 2015]
DEBUG ACHILLES_DML_STATEMENT - ResultSet[ exhausted: false, Columns[id(bigint), date(timestamp), consistencylist(list<varchar>), simplemap(map<int, varchar>), simpleset(set<double>), value(varchar)]]
DEBUG ACHILLES_DML_STATEMENT - Query ID 3873d787-c379-4bec-85c0-907a96b362ba results : 
	id: 5107957575091721216, date: Thu Oct 01 02:00:00 CEST 2015, consistencylist: [QUORUM, LOCAL_ONE], simplemap: {10=ten, 20=twenty}, simpleset: [1.0, 2.0], value: 0 AM

Achilles displays in the log:

  1. the query string
  2. the bound values in raw Java
  3. the encoded bound values using the Codec System
  4. the returned first 10 rows if it is a SELECT statement

For each sent query, Achilles generates a Query ID so that you can correlate the query string with the returned results.

Dynamic statements logging

It is also possible to activate DML statements display only on specific entities, in this case, set the log level of those entities to DEBUG

	<logger name="com.project.test.MyEntity">
		<level value="DEBUG" />
	</logger>

The DML statements display is dynamic at runtime so if your logging framework allow dynamic update of log level (Logback does it) then it is possible to activate statement logging at runtime for a short period of time for debugging purposes.

Limiting the number of displayed returned rows for DML statement

By default Achilles will display the first 10 returned rows in the log if ACHILLES_DML_STATEMENT logger or your entity logger is debug-enabled. To configure the max returned rows, you can either:

  • use ManagerFactoryBuilder.withMaxDMLResultsDisplayed() when configuring Achilles
  • use manager.dsl().select()....withDMLResultsDisplaySize() at runtime
  • use manager.raw().typedQueryForSelect()....withDMLResultsDisplaySize() at runtime
  • use manager.raw().nativeQuery()....withDMLResultsDisplaySize() at runtime

Please note that there is a hard-coded limit of 100 rows so if you provide a greater value it will be capped to 100 and floor to 0 (e.g. disable returned results display)

Dynamic queries tracing

Sometime, showing statements is not enough to diagnose performance issue. We then need to activate request tracing. But how to do without changing the code ?

Achilles comes to the rescue and allow dynamic tracing activation. Again all you need to do is changing the log level of your entity to TRACE

	<logger name="com.project.test.MyEntity">
		<level value="TRACE" />
	</logger>

Example of output of a Lightweight Transaction operation:

TRACE Query tracing at host localhost/127.0.0.1:9465 with achieved consistency level null
TRACE ****************************
TRACE Description                                                                      | Source           | Source elapsed in micros | Thread na
TRACE Preparing 55b436a0-09b2-11e4-8838-4f290a9552fc                                   | /127.0.0.1       | 9501                     | Native-Tr
TRACE Parsing SELECT preferred_ip FROM system.peers WHERE peer='127.0.0.1'             | /127.0.0.1       | 14383                    | Native-Tr
TRACE Preparing statement                                                              | /127.0.0.1       | 14563                    | Native-Tr
TRACE Executing single-partition query on peers                                        | /127.0.0.1       | 14784                    | Native-Tr
TRACE Acquiring sstable references                                                     | /127.0.0.1       | 14844                    | Native-Tr
TRACE Merging memtable tombstones                                                      | /127.0.0.1       | 14887                    | Native-Tr
TRACE Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones        | /127.0.0.1       | 14973                    | Native-Tr
TRACE Merging data from memtables and 0 sstables                                       | /127.0.0.1       | 14995                    | Native-Tr
TRACE Read 0 live and 0 tombstoned cells                                               | /127.0.0.1       | 15114                    | Native-Tr
TRACE Sending message to /127.0.0.1                                                    | /127.0.0.1       | 29531                    | WRITE-/12
TRACE Message received from /127.0.0.1                                                 | /127.0.0.1       | 31056                    | Thread-3
TRACE Parsing SELECT * FROM system.paxos WHERE row_key = 0x000000000000000a AND cf_id = c06bf433-4789-38a7-b287-f5f3a889f515 | /127.0.0.1
TRACE Preparing statement                                                              | /127.0.0.1       | 36440                    | MutationS
TRACE Executing single-partition query on paxos                                        | /127.0.0.1       | 36767                    | MutationS
TRACE Acquiring sstable references                                                     | /127.0.0.1       | 36789                    | MutationS
TRACE Merging memtable tombstones                                                      | /127.0.0.1       | 36847                    | MutationS
TRACE Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones        | /127.0.0.1       | 36902                    | MutationS
TRACE Promising ballot 55b436a0-09b2-11e4-8838-4f290a9552fc                            | /127.0.0.1       | 37085                    | MutationS
TRACE Parsing UPDATE paxos USING TIMESTAMP 1405162227466000 AND TTL 864000 SET in_progress_ballot = 55b436a0-09b2-11e4-8838-4f290a9552fc WHERE r
TRACE Preparing statement                                                              | /127.0.0.1       | 37656                    | MutationS
TRACE Acquiring switchLock read lock                                                   | /127.0.0.1       | 39518                    | MutationS
TRACE Appending to commitlog                                                           | /127.0.0.1       | 39539                    | MutationS
TRACE Adding to paxos memtable                                                         | /127.0.0.1       | 39599                    | MutationS
TRACE Sending message to /127.0.0.1                                                    | /127.0.0.1       | 43320                    | WRITE-/12
TRACE Message received from /127.0.0.1                                                 | /127.0.0.1       | 0                        | Thread-4
TRACE Processing response from /127.0.0.1                                              | /127.0.0.1       | 0                        | RequestRe
TRACE Reading existing values for CAS precondition                                     | /127.0.0.1       | 46029                    | Native-Tr
TRACE Executing single-partition query on entity_with_enum                             | /127.0.0.1       | 47304                    | ReadStage
TRACE Acquiring sstable references                                                     | /127.0.0.1       | 47330                    | ReadStage
TRACE Merging memtable tombstones                                                      | /127.0.0.1       | 47389                    | ReadStage
TRACE Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones        | /127.0.0.1       | 47488                    | ReadStage
TRACE CAS precondition is met; proposing client-requested updates for 55b436a0-09b2-11e4-8838-4f290a9552fc | /127.0.0.1       | 56438
TRACE Sending message to /127.0.0.1                                                    | /127.0.0.1       | 0                        | WRITE-/12
TRACE Message received from /127.0.0.1                                                 | /127.0.0.1       | 33                       | Thread-3
TRACE Parsing SELECT * FROM system.paxos WHERE row_key = 0x000000000000000a AND cf_id = c06bf433-4789-38a7-b287-f5f3a889f515 | /127.0.0.1
...

Home

Clone this wiki locally