Hi all, I am trying to debug some high-latency outliers (99th percentile) in an application I'm working on. I thought that I could turn on route tracing, print the route traces to logs, and then examine my logs after a load test to find the highest-latency paths and figure out what is going on.
I did something similar to what is described here: http://www.datastax.com/documentation/developer/java-driver/2.1/java-driver/tracing_t.html Under low amounts of traffic, this looks great and I can see nice trace logs: Total duration: 599 us (id: ae159110-6dd8-11e4-a6a1-cd4ac3ad1896) Executing single-partition query on lg_users_C | 13:36:52.898 | /10.29.2.9 | 204 Acquiring sstable references | 13:36:52.898 | /10.29.2.9 | 207 Merging memtable tombstones | 13:36:52.898 | /10.29.2.9 | 213 Bloom filter allows skipping sstable 40 | 13:36:52.898 | /10.29.2.9 | 231 Bloom filter allows skipping sstable 38 | 13:36:52.898 | /10.29.2.9 | 237 Bloom filter allows skipping sstable 37 | 13:36:52.898 | /10.29.2.9 | 243 Key cache hit for sstable 39 | 13:36:52.898 | /10.29.2.9 | 251 Seeking to partition indexed section in data file | 13:36:52.898 | /10.29.2.9 | 251 Skipped 0/4 non-slice-intersecting sstables, included 0 due to tombstones | 13:36:52.898 | /10.29.2.9 | 455 Merging data from memtables and 1 sstables | 13:36:52.898 | /10.29.2.9 | 457 Read 0 live and 0 tombstoned cells | 13:36:52.898 | /10.29.2.9 | 472 Under heavier load, however, things seem to fall over, and I get a lot of exceptions like: 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.9:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.8:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.9:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.12:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.9:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.9:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.10:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.11:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying xwing07.ul.wibidata.net/10.29.2.7:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.10:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.9:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.8:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying xwing07.ul.wibidata.net/10.29.2.7:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.8:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 DEBUG com.datastax.driver.core.RequestHandler: Error querying /10.29.2.11:9042, trying next host (error is: com.datastax.driver.core.exceptions.DriverException: Timeout during read) 14/11/16 13:39:41 WARN com.datastax.driver.core.Connection: Timeout while setting keyspace on connection to /10.29.2.11:9042. This should not happen but is not critical (it will retried) Is this expected? I am running only ~100 reads per second on this load test, which I didn't think should be too much. One thing I noticed is that the example I referenced above explicitly calls: insert.disableTracing(); do I need to do that in my application for a statement that is not used again? What if I have a prepared statement that I issue several time consecutively? Thanks! -Clint
